opensips 1.7 crash (core:del_lump: offset exceeds message size)

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

opensips 1.7 crash (core:del_lump: offset exceeds message size)

vivid333
Hello:

            I've configured Opensips with nathelper and rtpproxy, relay rtp stream to both user agents.(if 2 ua behind same nat, go P2P).

        UA1 ----> Opensips -----> UA2
        UA1, UA2 in the same nat level.

      The problem that I'm facing is when I try to use UA1 call UA2(I uncomment P2P) by relay, UA2 is ringing, I answer the call, there no voice at all. UA1(Twinkle) is display "Giving a try",  I found that Opensips is crashed.

         CRITICAL:core:del_lump: offset exceeds message size (339488 > 543) aborting...

    I change debug level 3 to 8. output is below.

    I am newer to opensips, Maybe there is something wrong with opensip.cfg. I really don't konw how does that happen,  thanks for your help in advance, any help would be appreciated!





/////////////////////////////////////// opensips.cfg begin  //////////////////////////////////////////////////////
/* uncomment and configure the following line if you want opensips to

bind on a specific interface/port/proto (default bind on all available)

*/



children = 4

debug = 8 # debug level (cmd line: -dddddddddd)

fork = yes



group = "opensips"

user = "opensips"

/* uncomment the next line to disable TCP (default on) */

disable_tcp=yes



log_facility = LOG_LOCAL0 # LOG_DAEMON

log_stderror = no # (cmd line: -E)

## tcp_children = 4



check_via=no # (cmd. line: -v)

dns=no # (cmd. line: -r)

rev_dns=no # (cmd. line: -R)

alias=122.70.185.167



/* uncomment the next line to enable the auto temporary blacklisting of

not available destinations (default disabled) */

#disable_dns_blacklist=no



/* uncomment the next line to enable IPv6 lookup after IPv4 dns

lookup failures (default disabled) */

#dns_try_ipv6=yes



/* uncomment the next line to disable the auto discovery of local aliases

based on revers DNS on IPs (default on) */

#auto_aliases=no



/* uncomment the following lines to enable TLS support (default off) */

#disable_tls = no

#listen = tls:your_IP:5061

#tls_verify_server = 1

#tls_verify_client = 1

#tls_require_client_certificate = 0

#tls_method = TLSv1

#tls_certificate = "/usr/local/etc/opensips/tls/user/user-cert.pem"

#tls_private_key = "/usr/local/etc/opensips/tls/user/user-privkey.pem"

#tls_ca_list = "/usr/local/etc/opensips/tls/user/user-calist.pem"



port=5060



/* uncomment and configure the following line if you want opensips to

bind on a specific interface/port/proto (default bind on all available)

*/

listen=udp:122.70.185.167:5060



#*** set module path

#mpath="//lib/opensips/modules/"

mpath="/usr/local/lib64/opensips/modules/"





# Modules Section

# ```````````````

# Loading moduels and

# Setting module-specific parameters







loadmodule "db_mysql.so"

loadmodule "signaling.so"

loadmodule "sl.so"

loadmodule "tm.so"

loadmodule "rr.so"

loadmodule "maxfwd.so"

loadmodule "usrloc.so"

loadmodule "registrar.so"

loadmodule "textops.so"

loadmodule "mi_fifo.so"



# !! Nathelper

loadmodule "rtpproxy.so"

loadmodule "nathelper.so"

loadmodule "uri.so"

loadmodule "acc.so"



# Uncomment this if you want digest authentication

# db_mysql.so must be loaded !

loadmodule "auth.so"

loadmodule "auth_db.so"

loadmodule "alias_db.so"

loadmodule "domain.so"



#

#**

#

loadmodule "dialog.so"

loadmodule "avpops.so"



#loadmodule "nat_traversal.so"

#loadmodule "mediaproxy.so"

#

#**

#



/* uncomment the next two lines for presence server support

NOTE: a DB (like db_mysql) module must be also loaded */

loadmodule "presence.so"

loadmodule "presence_xml.so"

loadmodule "dialplan.so"

#loadmodule "drouting.so"

####

###

##

# ----------------- setting module-specific parameters ---------------

##

###

####



# ----- mi_fifo params -----

modparam("mi_fifo", "fifo_name", "/tmp/opensips_fifo")



#**

modparam("mi_fifo", "fifo_mode", 0660)

modparam("mi_fifo", "fifo_group", "opensips")

modparam("mi_fifo", "fifo_user", "opensips")

modparam("mi_fifo", "reply_dir", "/tmp/")

modparam("mi_fifo", "reply_indent", "\t")





# ----- registrar params -----

##SIMON modparam("registrar", "method_filtering", 1)



/* uncomment the next line to disable parallel forking via location */

# modparam("registrar", "append_branches", 0)

/* uncomment the next line not to allow more than 10 contacts per AOR */

modparam("registrar", "max_contacts", 10)

#modparam("registrar", "retry_after", 10)

modparam("registrar", "received_avp", "$avp(i:42)")



# -- usrloc params --

modparam("usrloc", "db_mode", 0)

# Uncomment this if you want to use SQL database

# for persistent storage and comment the previous line

## modparam("usrloc", "db_mode", 2)



modparam("usrloc", "db_url","mysql://opensips:opensipsrw@localhost/opensips")

modparam("usrloc", "timer_interval", 20)



modparam("usrloc", "user_column", "username")

modparam("usrloc", "domain_column", "domain")

modparam("usrloc", "contact_column", "contact")

modparam("usrloc", "expires_column", "expires")

modparam("usrloc", "q_column", "q")

modparam("usrloc", "callid_column", "callid")

modparam("usrloc", "cseq_column", "cseq")

modparam("usrloc", "methods_column", "methods")

modparam("usrloc", "flags_column", "flags")

modparam("usrloc", "user_agent_column", "user_agent")

modparam("usrloc", "received_column", "received")

modparam("usrloc", "socket_column", "socket")

modparam("usrloc", "use_domain", 0)

modparam("usrloc", "desc_time_order", 0)

modparam("usrloc", "timer_interval", 60)

modparam("usrloc", "matching_mode", 0)



# ----- uri_db params -----

/* by default we disable the DB support in the module as we do not need it

in this configuration */

# modparam("uri", "use_uri_table", 1)

# modparam("uri", "db_url","mysql://opensips:opensipsrw@localhost/opensips")





# -- auth db params --

# Uncomment if you are using auth module

modparam("auth_db", "calculate_ha1", yes)



#

# If you set "calculate_ha1" parameter to yes (which true in this config),

# uncomment also the following parameter)

modparam("auth_db", "password_column", "password")

modparam("auth_db", "db_url","mysql://opensips:opensipsrw@localhost/opensips")

#modparam("auth_db", "load_credentials", "")





# ----- rr params -----

# add value to ;lr param to cope with most of the UAs

#VIVID modparam("rr", "enable_full_lr", 1)

# do not append from tag to the RR (no need for this script)

modparam("rr", "append_fromtag", 0)



#

# !! Nathelper

#

modparam("usrloc", "nat_bflag", 6)

## modparam("usrloc", "rtpproxy_bflag", 7)    # set when rtpproxy_offer or rtpproxy_anwer are called

modparam("nathelper", "ping_nated_only", 0) # Ping only clients behind NAT

modparam("nathelper", "sipping_bflag", 7)

modparam("nathelper", "received_avp", "$avp(i:42)")

modparam("nathelper", "natping_interval", 30)

modparam("nathelper", "sipping_from", "sip:pinger@122.70.185.167")

modparam("nathelper", "natping_processes", 3) # 3 ping processes

modparam("nathelper", "sipping_method", "OPTIONS")

modparam("nathelper", "nortpproxy_str", "a=nortpproxy:yes\r\n")

modparam("rtpproxy", "rtpp_notify_socket", "tcp:122.70.185.167:9998")

modparam("rtpproxy", "rtpproxy_retr", 10)





# RTPProxy setup

modparam("rtpproxy", "rtpproxy_timeout", "1")

modparam("rtpproxy", "rtpproxy_disable_tout", 1)

modparam("rtpproxy", "rtpproxy_autobridge", 1)



modparam("rtpproxy", "rtpproxy_sock", "udp:127.0.0.1:7890")

modparam("nathelper", "force_socket", "udp:127.0.0.1:7890")



# ----- acc params -----

/* what sepcial events should be accounted ? */

modparam("acc", "early_media", 1)

#VIVID modparam("acc", "report_ack", 1)

modparam("acc", "report_cancels", 1)



/* by default ww do not adjust the direct of the sequential requests.

if you enable this parameter, be sure the enable "append_fromtag"

in "rr" module */

modparam("acc", "detect_direction", 0)



/* account triggers (flags) */

modparam("acc", "failed_transaction_flag", 3)

modparam("acc", "log_flag", 1)

modparam("acc", "log_missed_flag", 2)



/* uncomment the following lines to enable DB accounting also */

modparam("acc", "db_flag", 1)

modparam("acc", "db_missed_flag", 2)





#

# ----- multi-module params -----

/* uncomment the following line if you want to enable multi-domain support

   in the modules (dafault off) */

#modparam("auth_db|usrloc|uri", "use_domain", 1)



# ----- alias_db params -----

/* uncomment the following lines if you want to enable the DB based

aliases */

modparam("alias_db", "db_url","mysql://opensips:opensipsrw@localhost/opensips")





# ----- domain params -----

/* uncomment the following lines to enable multi-domain detection support */

modparam("domain", "db_url","mysql://opensips:opensipsrw@localhost/opensips")

modparam("domain", "db_mode", 1) # Use caching



#**

modparam("domain", "domain_table", "domain")

modparam("domain", "domain_col", "domain")



#

# ------- dialog --------

#**

modparam("dialog", "db_mode", 0)

modparam("dialog", "db_update_period", 30)

# VIVID modparam("dialog", "dlg_flag", 4)

modparam("dialog", "dlg_match_mode", 1)



#

# --> avpops params -----

#**

modparam("avpops", "avp_table", "usr_preferences")

modparam("avpops", "use_domain", 1)

modparam("avpops", "db_url", "mysql://opensips:opensipsrw@localhost/opensips")





## attribute of the matched line will be store in the $avp(s:dest)

modparam("dialplan", "attrs_pvar", "$avp(dest)")

modparam("dialplan", "db_url","mysql://opensips:opensipsrw@localhost/opensips")



# --------------- setting module-specific parameters -------------

# ----- drouting params -----



#modparam("drouting", "sort_order", 0)

#modparam("drouting", "use_domain", 1)

#modparam("drouting","db_url", "mysql://opensips:opensipsrw@localhost/opensips")

modparam("tm", "fr_timer", 20 )

modparam("tm", "fr_inv_timer", 40 ) # Timer which hits if no final reply for an INVITE

modparam("tm", "wt_timer", 20 )









# ************

# ----- presence params -----

/* uncomment the following lines if you want to enable presence */

modparam("presence_xml", "db_url", "mysql://opensips:opensipsrw@localhost/opensips")

modparam("presence_xml", "force_active", 1)

modparam("presence", "server_address", "sip:122.70.185.167:5060")



# -- MAIN request routing logic



route

{

        # -- 1 -- Request Validation

        xlog("L_INFO", "New request - [M=$rm RURI=$ru ID=$ci]  F=$fu T=$tu From_IP=$si \n");

       

        # initial sanity checks -- messages with

        # max_forwards==0, or excessively long requests

        if (!mf_process_maxfwd_header("10"))

        {

                xlog("L_INFO", "Too many hops\n");

                sl_send_reply("483","Too Many Hops...");

                exit;

        };

        if (msg:len >= 2048 )

        {

                xlog("L_INFO", "Message too big - msg_len=$ml\n");

                sl_send_reply("513", "Message too big...");

                exit;

        };





        # Some systems (like Asterisk) use OPTIONS as a kind of "ping", than we

        # answer it with 200 OK.

        if ( is_method ("OPTIONS|SUBSCRIBE") ) {

                sl_send_reply("200", "OK");

                return;

        };



        # -- 2 -- Routing Preprocessing

        ## -------NAT Detaction --------------#

        force_rport();

      if ( nat_uac_test("19") )

        {

                xlog("L_INFO", "Detect in NAT\n");

                if( is_method("REGISTER") )

                        fix_nated_register();

                else

                        fix_nated_contact();

                setflag(5);

        }

        else

                xlog("L_INFO", " In Public IP\n");



        # -------Sequential requests section-----#

        if( has_totag() )

        {

                # sequential request withing a dialog should

                # take the path determined by record-routing

               

                if( loose_route() )

                {

                        if( is_method("BYE") )

                        {

                                setflag(1); #do accounting

                                setflag(3); #even if transaction fails

                        }

                        else if( is_method("INVITE") )

                        {

                                record_route();

                        }

                        xlog("L_INFO", "[Method:$rm]  has_totag and loose_route\n");

                        route(1);

                }

                else

                {

                        xlog("L_INFO", "[Method:$rm]   has_totag but strict route\n");

                        if( is_method("ACK") )

                        {

                                if(t_check_trans() )

                                {

                                        t_relay();

                                        exit;

                                }

                                else

                                        exit;

                        }

                        sl_send_reply("404", "NOT Here");

                        xlog("L_INFO", "[Method:$rm]  has_tag but not found\n");

                }



                exit;

        }



        #---- initial requests section ----#

        if( is_method("CANCEL") )

        {

                if( t_check_trans() )

                {

                        #if( isflagset(5) )

                        unforce_rtp_proxy();

                        t_relay();

                }

                xlog("L_INFO", "recevie CANCEL and unforce rtp proxy..\n");

                exit;

        }

       

        t_check_trans();





        #---- preloaded route checking ----#

        if ( loose_route() )

        {

                xlog("L_ERR", "Attempt to route with preloaded Route's[$fu/$tu/$ru/$ci]");

                if ( !is_method("ACK") )

                {

                        sl_send_reply("403","Preload Route denied");

                        exit;

                }

        }



        #---- record routing ----#

        if ( !is_method("REGISTER|MESSAGE") )

                record_route();



        # account only INVITEs

        if ( is_method("INVITE") )

        {

                setflag(1); # do accounting

        }

       

         

        ## uncomment this if you want to enable presence server

        ## and comment the next 'if' block

        ## NOTE: uncomment also the definition of route[2] from below

        ##if( is_method("PUBLISH|SUBSCRIBE"))

        ## route(2);



        if ( is_method("PUBLISH") )

        {

                sl_send_reply("503", "Service Unavailable");

                exit;

        }

 

        if ( is_method("REGISTER") )

        {

/*

                if ( !www_authorize("", "subscriber") )  

                {

            $var(reg) = $retcode;

            if ($var(reg) < 0)  

                        {

              xlog("L_INFO","www_authorize return value: $var(reg)");

              # switch ($retcode)

                                switch ($var(reg))

              {

                case -5:

                    xlog("L_INFO","Error\n");

                                                break;

                case -4:

                    xlog("L_INFO", "Please send new Register with auth info $fU\n");

                    www_challenge("", "1");

                    exit;

                case -2:

                    xlog("L_INFO", "Wrong password $fU\n");

                                                sl_send_reply("401", "Wrong password");

                    break;

                case -1:

                    xlog("L_INFO","User doesnt exist $fU\n");

                                                sl_send_reply("401", "User doesnt exist");

                    break;

                default:

                    xlog("L_INFO","Default");

              }

              sl_send_reply("403","Forbidden");

              exit;

            }

                }

*/

                if ( !www_authorize("", "subscriber") )

                {

                        www_challenge("", "1");

                        exit;

                }

/* if ( !db_check_to() )

                {

                        sl_send_reply("403","Forbidden auth ID");

                        exit;

                }

       

*/ #-- Request is behind NAT(flag5) save with bflag 6 -#

                #---- Use bflag 7 to start SIP pinging (Options) ---#

                if ( isflagset(5) )

                {

                        setbflag(6);

                        setbflag(7);

                };



                if ( !save("location") )

                {

                        sl_reply_error();

                        exit;

                }

                xlog("L_INFO", "Registration successful\n");

                exit;

        }



        if ($rU==NULL)

        {

                # request with no Username in RURI

                xlog("L_INFO", "[URI=$rU]   Address Incomplte\n");

                sl_send_reply("484","Address Incomplete");

                exit;

        }



        # apply DB based aliases (uncomment to enable)

        alias_db_lookup("dbaliases");



        route(3);



        send_reply("420", "Invalid Extension");

        exit;

}





route[1]

{

        # for INVITEs enable some additional helper routes

        #---- Helper route, if nat=yes in the R-URI set flag 6 ----#

        #---- This is used to Process REINVITES ----#

        xlog("L_INFO", "[RURI=$ru]   Into Route[1] ");

        if ( subst_uri('/(sip:.*);nat=yes/\1/') )

        {

                xlog("L_INFO", "--- ------- - [From:$fU]   URI contain nat=yes\n");

                setbflag(6);

        };



        #-- If caller(flag 5) or callee(flag 6) are behind NAT --#

        #-- Call the route(6) to force the use of the RTP Proxy --#

        if ( isflagset(5) || isbflagset(6) )

        {

                route(6);

        };



        if (isflagset(5))

                search_append('Contact:.*sip:[^>[:cntrl:]]*',  ';nat=yes');

       

        if (is_method("INVITE"))

        {

                t_on_branch("2");

                t_on_reply("2");

                t_on_failure("1");

        }



        if (!t_relay())

        {

                sl_reply_error();

        };



        exit;

}





# Presence route

/* uncomment the whole following route for enabling presence

   NOTE: do not forget to enable the call of this route from the main

     route */

##route[2]

##{

## if (!t_newtran())

## {

## sl_reply_error();

## exit;

## };

##

## if(is_method("PUBLISH"))

## {

## handle_publish();

## }

## else

## if( is_method("SUBSCRIBE"))

## {

## handle_subscribe();

## }

##

## exit;

##}



#Route for user lookups

route[3]

{

        xlog("********************** into route[3] for user lookups \n");

        if (!lookup("location", "m"))

        {

                switch ($retcode)

                {

                        case -1:

                        case -3:

                                t_newtran();

                                xlog("L_INFO", "[From:$fU]  user:$rU Not Found\n");

                                t_reply("404", "Not Found..");

                                exit;

                        case -2:

                                xlog("L_INFO", "--- ------- - [From:$fU]  Method:$rm Not Allowed\n");

                                sl_send_reply("405", "Method Not Allowed");

                                exit;

                }

        }



        # when routing via usrloc, log the missed calls also

        setflag(2);

        route(1);

}





route[5]

{

        #---- Route to media servers ----#

        xlog("L_INFO", "Come into Route[5] PSTN");

        #xlog("route to media servers");

        rewritehostport("192.168.1.202:5062");

        route(1);

}



route[6]

{

        #---- RTP Proxy handling ---#

        if (is_method("BYE|CANCEL"))

        {

                unforce_rtp_proxy();

        };



        # if client or server know to be behind a NAT, enable relay

  if( isflagset(5) || isbflagset(6) )

        {

                #Store the destination domain into an AVP

                #avp_printf("i:450", "$dd");

                #if ( avp_check("i:450", "eq/$src_ip/g") )

/* xlog("L_INFO", "dd: $dd, si : $si \n");

                if($dd == $si)

                {

                        xlog("L_INFO", "Both users behind same NAT, so we dont use RTPProxy\n");

                    resetbflag(6);  # Unset NAT flag general.

                    resetbflag(7);  # Unset NAT flag general.

                        return;

                }

*/

                if( has_body("application/sdp") )

                {

                        if (is_method("ACK"))

                        { ## if it is ACK, then answer it

                                xlog("L_INFO", "------- ACK, route, rtpproxy_answer\n");

                                if (rtpproxy_answer()) {

                                        setbflag(7);

                                        t_on_reply("1");

                                }

                        }

                        else

                        { ## If it is not ACK, then offer it

                                ## force_rtp_proxy();

                                xlog("L_INFO", "------- Non-ACK, route, rtpproxy_offer\n");

                                if( rtpproxy_offer() ) {

                                             t_on_failure("1");

                                        setbflag(7);

                                        t_on_reply("1");

                                }

                        }

                }

                else

                {

                        xlog("L_INFO", "--- route ---- : NO sdp block\n");

                        t_on_reply("2");

                }



        };

}



branch_route[2]

{

        xlog("new branch at $ru\n");

}





# !! Nathelper

onreply_route[1]

{

        #NATed transaction ?

        xlog("L_INFO", "Incoming reply route1: M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci, status=$rs\n");

        if( isflagset(5) )

        {

                fix_nated_contact();   #maybe used for behind same nat

        }



        if ( isbflagset(6) && status=~"(183)|(2[0-9][0-9])" )

  {

                fix_nated_contact();

                #fix_nated_contact();

                if (has_body("application/sdp"))

                {

                        #force_rtp_proxy();

                        rtpproxy_answer();

                        setbflag(7);

                        xlog("L_INFO", "[From:$fU]:  onreply_route 1, rtpproxy_answer\n");

                };

                #append_hf("P-hint: onreply_route1|rtpproxy_answer \r\n");

        };

 

        #----  the CALLEE is behind NAT, fix the CONTACT HF ----#

        if (isbflagset(6))

        {

                #-- Insert nat=yes at the end of the Contact header --#

                #-- This helps with REINVITEs, --#

                #- nat=yes will be included in the R-URI for seq.requests-#

                search_append('Contact:.*sip:[^>[:cntrl:]]*', ';nat=yes');

                append_hf("P-hint: Onreply-route1 - fixcontact \r\n");

                fix_nated_contact();

        };



        exit;

}





onreply_route[2]

{

        xlog("L_INFO", "Incoming reply route2: Status Code=$rs\n");

        #---- Handling of the SDP for the 200 or 183 reply ----#

        #---- If behind nat (flags 5 or 6) start RTP Proxy ----#

        #---- Activates the RTP Proxy for the CALLER ----#

       

        # ----May Be Same Nat

        if( isflagset(5) )

        {

                fix_nated_contact();

        }



        if ( isbflagset(6) && status=~"(183)|(2[0-9][0-9])" )

        {

                fix_nated_contact();

                #force_rtp_proxy();

                if (has_body("application/sdp"))

                {

                rtpproxy_offer();

                        t_on_failure("1");

                        setbflag(7);

                xlog("L_INFO", "[From:$fU]:  onreply_route 2, rtpproxy_offer\n");

                }

                #append_hf("P-hint: onreply_route2|rtpproxy_offer \r\n");

        }



        #---- If the CALLEE is behind NAT, fix the CONTACT HF ----#

        if (isbflagset(6))

        {

                #-- Insert nat=yes at the end of the Contact header --#

                #-- This helps with REINVITEs, --#

                #- nat=yes will be included in the R-URI for seq.requests-#

                search_append('Contact:.*sip:[^>[:cntrl:]]*', ';nat=yes');

                #append_hf("P-hint: Onreply-route2 - fixcontact \r\n");

                fix_nated_contact();

        }



        exit;

}



failure_route[1]

{

        #---- If a failure has ocurred, deactivate the RTP Proxy ----#

        if ( isflagset(5) || isbflagset(6) )

        {

                unforce_rtp_proxy();

        }

        if ( t_was_cancelled() )

        {

                exit;

        }



        #- if the failure comes from a PSTN route, handle properly -#

        xlog("L_ERR", "Failre_route deeply into: M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci, status=$rs\n");



}

/////////////////////////////////////////// opensips.cfg end ////////////////////////////////////////////////////////





********************************/var/log/syslog  output*****************************
///////////////////////////////////////////////////////////opensips.cfg/////////////////////////////////////////////////
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_msg: SIP Request:
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_msg:  method:  <INVITE>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_msg:  uri:     <sip:+8613693536889@223.5.3.137>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_msg:  version: <SIP/2.0>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=2
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKhcuoomsf>; state=16
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_via: end of header reached, state=5
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: via found, flags=2
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: this is the first via
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:receive_msg: After parse_msg...
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:receive_msg: preparing to run routing scripts...
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=40
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_to: end of header reached, state=10
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_to: display={}, ruri={sip:+8613693536889@223.5.3.137}
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:get_hdr_field: <To> [34]; uri=[sip:+8613693536889@223.5.3.137]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:get_hdr_field: to body [<sip:+8613693536889@223.5.3.137>#015#012]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_to_param: tag=qivus
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_to: end of header reached, state=29
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_to: display={"+18601036574"}, ruri={sip:+8618601036574@223.5.3.137}
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: New request - [M=INVITE RURI=sip:+8613693536889@223.5.3.137 ID=lnxwooprkrdmzpj@vivid]  F=sip:+8618601036574@223.5.3.137 T=sip:+8613693536889@223.5.3.137 From_IP=114.249.130.248
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:maxfwd:is_maxfwd_present: value = 70
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:check_ip_address: params 114.249.130.248, 192.168.1.118, 0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: Detect in NAT
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:get_hdr_field: cseq <CSeq>: <312> <INVITE>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:get_hdr_field: content_length=311
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:get_hdr_field: found end of header
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:uri:has_totag: no totag
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=78
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:t_lookup_request: start searching: hash=28244, isACK=0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:t_lookup_request: no transaction found
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=200
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:rr:find_first_route: No Route headers found
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:rr:loose_route: There is no Route HF
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7e9da8
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:db_allocate_columns: allocate 56 bytes for result columns at 0x7e9df0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7e9e00)[0]=[username]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7e9e10)[1]=[domain]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:alias_db:alias_db_query: no alias found for R-URI
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:db_free_columns: freeing result columns at 0x7e9df0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:db_free_rows: freeing 0 rows
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:db_free_result: freeing result set at 0x7e9da8
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: ********************** into route[3] for user lookups
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:registrar:lookup: setting as ruri <sip:+8613693536889@114.249.130.248:15764;rinstance=947adae50d8917ff>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:registrar:lookup: looking for branches
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: [RURI=sip:+8613693536889@114.249.130.248:15764;rinstance=947adae50d8917ff]   Into Route[1]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:subst_run: running. r=1
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:subst_str: no match
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: ------- Non-ACK, route, rtpproxy_offer
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:dialog:build_new_dlg: new dialog 0x7fd427936f20 (c=lnxwooprkrdmzpj@vivid,f=sip:+8618601036574@223.5.3.137,t=sip:+8613693536889@223.5.3.137,ft=qivus) on hash 3817
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:dialog:init_leg_info: route_set , contact sip:+8618601036574@114.249.130.248:5062, cseq 312 and bind_addr udp:223.5.3.137:5060
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0x7fd427936f20: tag=<qivus> rcseq=<0>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:dialog:link_dlg: ref dlg 0x7fd427936f20 with 3 -> 3
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:rr:add_rr_param: adding (;did=9ee.8197f6b5) 0x7e9930
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=40
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=twinkle 2096395829 1503996579 IN IP4 192.168.1.118#015#012s=-#015#012c=IN IP4 192.168.1.118#015#012t=0 0#015#012m=audio 9000 RTP/AVP 98 97 8 0 3 101#015#012a=rtpmap:98 speex/16000#015#012a=rtpmap:97 speex/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:3 GSM/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=ptime:20#015#012]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 41904 223.5.3.137#012
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:t_newtran: transaction on entrance=(nil)
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=78
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:t_lookup_request: start searching: hash=28244, isACK=0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:t_lookup_request: no transaction found
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:run_reqin_callbacks: trans=0x7fd427933bc8, callback type 1, id 1 entered
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:run_reqin_callbacks: trans=0x7fd427933bc8, callback type 1, id 0 entered
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=78
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:check_ip_address: params 114.249.130.248, 192.168.1.118, 0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:_shm_resize: resize(0) called
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:_reply_light: reply sent out. buf=0x7ea3e8: SIP/2.0 1..., shmem=0x7fd427935f88: SIP/2.0 1
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:_reply_light: finished
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: new branch at sip:+8613693536889@114.249.130.248:15764;rinstance=947adae50d8917ff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:_shm_resize: resize(0) called
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:mk_proxy: doing DNS lookup...
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=2000
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:clen_builder: content-length: 328 (328)
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:set_timer: relative timeout is 500000
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:insert_timer_unsafe: [4]: 0x7fd427933de8 (75200000)
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:set_timer: relative timeout is 20
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:insert_timer_unsafe: [0]: 0x7fd427933e18 (94)
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:t_relay_to: new transaction fwd'ed
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fd427933bc8] after is 0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:dialog:unref_dlg: unref dlg 0x7fd427936f20 with 1 -> 2
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:destroy_avp_list: destroying list (nil)
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: DBG:core:receive_msg: cleaning up
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_msg: SIP Reply  (status):
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_msg:  version: <SIP/2.0>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_msg:  status:  <180>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_msg:  reason:  <Ringing>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: flags=2
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK45e6.a025fcd2.0>; state=16
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_via: end of header reached, state=5
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: via found, flags=2
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: this is the first via
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:receive_msg: After parse_msg...
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:forward_reply: found module nathelper, passing reply to it
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: flags=4
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_via_param: found param type 234, <received> = <114.249.130.248>; state=6
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_via_param: found param type 235, <rport> = <5062>; state=6
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKhcuoomsf>; state=16
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_via: end of header reached, state=5
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: via found, flags=4
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: parse_headers: this is the second via
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:forward_reply: found module tm, passing reply to it
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:tm:t_check: start=0xffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: flags=22
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_to_param: tag=e65d3f06
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_to: end of header reached, state=29
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_to: display={}, ruri={sip:+8613693536889@223.5.3.137}
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:+8613693536889@223.5.3.137]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:get_hdr_field: to body [<sip:+8613693536889@223.5.3.137>]
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:get_hdr_field: cseq <CSeq>: <312> <INVITE>
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: flags=8
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:tm:t_reply_matching: hash 28244 label 768561674 branch 0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fd427933bc8] after is 1
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:tm:t_reply_matching: reply matched (T=0x7fd427933bc8)!
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:tm:run_trans_callbacks: trans=0x7fd427933bc8, callback type 2, id 1 entered
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: flags=2000
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:get_hdr_field: content_length=0
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:tm:t_check: end=0x7fd427933bc8
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: Incoming reply route2: Status Code=180
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:get_hdr_field: found end of header
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: DBG:core:parse_headers: flags=ffffffffffffffff
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3487]: CRITICAL:core:del_lump: offset exceeds message size (339488 > 543) aborting...
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:core:handle_sigs: status = 6
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: INFO:core:handle_sigs: child process 3487 exited by a signal 6
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: INFO:core:handle_sigs: core was not generated
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: INFO:core:handle_sigs: terminating due to SIGCHLD
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3490]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3486]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3485]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3488]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3484]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3492]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3489]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3491]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3493]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3494]: INFO:core:sig_usr: signal 15 received
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:dialplan:destroy_rule: destroying rule with priority 1
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:presence_xml:destroy: start
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: NOTICE:presence:destroy: destroy module ...
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:core:pool_remove: connection still kept in the pool
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:core:pool_remove: removing connection from the pool
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:tm:tm_shutdown: tm_shutdown : start
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:tm:unlink_timer_lists: emptying DELETE list
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:tm:tm_shutdown: emptying hash table
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:tm:tm_shutdown: releasing timers
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:tm:tm_shutdown: removing semaphores
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:tm:tm_shutdown: destroying callback lists
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:tm:tm_shutdown: tm_shutdown : done
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:core:shm_mem_destroy:
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:core:shm_mem_destroy: destroying the shared memory lock
Sep 20 20:38:50 daliboxin2 /sbin/opensips[3483]: DBG:core:handle_sigs: terminating due to SIGCHLD