[OpenSIPS-Users] topology hiding not accepting BYE before 200 OK

Trevor Steyn trevor at webon.co.za
Thu Jul 23 17:12:29 CEST 2015


Hi Guys,

I seem to be having some trouble with the new topology_hiding module in
opensips 2.1

here is the call scenario

UAC --> Opensips --> UAS

UAC Sends Invite to UAS with topology hiding module
UAS sends 180 with to-tag
UAC sends BYE

When the Bye is sent opensips loops the call till max forwards is reached

from what i can see from the debugs the  Bye from UAC is accepted and
matches the topology_hiding_match function but does not rewrite the
destination IP so when the message passes t_relay() its sending the Bye
to Itself from Itself.

I have tried this without topology hiding and the BYE is relayed as it
should
.

My route looks as follows


route{
    script_trace( 3, "$rm from $si, ruri=$ru", "me");

    if (!mf_process_maxfwd_header("10")) {
        sl_send_reply("483","Too Many Hops");
        exit;
    }

    if ( check_source_address("1","$avp(trunk_attrs)") ) {
        # request comes from trunks
        setflag(IS_TRUNK);
    } else if ( is_from_gw() ) {
        # request comes from GWs
    } else {
#        send_reply("403","Forbidden");
    xlog("Message is not from Trunk or GW $si");
#        exit;
    }

    if (has_totag()) {
        # sequential request withing a dialog should
        # take the path determined by record-routing
        #if (loose_route()) {
        if(topology_hiding_match()) {
           
            # validate the sequential request against dialog
            if ( $DLG_status!=NULL && !validate_dialog() ) {
                xlog("In-Dialog $rm from $si (callid=$ci) is not valid
according to dialog\n");
                ## exit;
            }
           
            if (is_method("BYE")) {
                setflag(ACC_DO); # do accounting ...
                setflag(ACC_FAILED); # ... even if the transaction fails
            } else if (is_method("INVITE")) {
                # even if in most of the cases is useless, do RR for
                # re-INVITEs alos, as some buggy clients do change route set
                # during the dialog.
                record_route();
            }

            # lets handle re-invites and offer proxy
            if (has_body("application/sdp"))  {
                # Begin rtp session update gyrations
                if (method == "INVITE") {
                    # INVITE w/ SDP, so early neg
                    # This is offer, reply is answer
                    rtpproxy_offer("iewlz20");
                    t_on_reply("1");
                } else if (method == "ACK") {
                    # ACK w/ SDP, so late neg (done now)
                    # This is answer
                    rtpproxy_answer("iewlz20");
                }
        }


            # route it out to whatever destination was set by loose_route()
            # in $du (destination URI).
            route(RELAY);
        } else {
            if ( is_method("ACK") ) {
                if ( t_check_trans() ) {
                    # non loose-route, but stateful ACK; must be an ACK
after
                    # a 487 or e.g. 404 from upstream server
                    t_relay();
                    exit;
                } else {
                    # ACK without matching transaction ->
                    # ignore and discard
                    exit;
                }
            }
            sl_send_reply("404","Not here");
        }
        exit;
    }

    #### INITIAL REQUESTS

    if ( !isflagset(IS_TRUNK) ) {
        ## accept new calls only from trunks
        send_reply("403","Not from trunk");
        exit;
    }

    # CANCEL processing
    if (is_method("CANCEL")) {
        if (t_check_trans())
            t_relay();
        exit;
    } else if (!is_method("INVITE")) {
        send_reply("405","Method Not Allowed");
        exit;
    }

    if ($rU==NULL) {
        # request with no Username in RURI
        sl_send_reply("484","Address Incomplete");
        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
    record_route();

    setflag(ACC_DO); # do accounting


   
    # create dialog with timeout
    if ( !create_dialog("B") ) {
        send_reply("500","Internal Server Error");
        exit;
    }

   
    if (is_avp_set("$avp(trunk_attrs)") && $avp(trunk_attrs)=~"^[0-9]+$") {
        get_profile_size("trunkCalls","$si","$var(size)");
        if ( $(var(size){s.int}) >= $(avp(trunk_attrs){s.int}) ) {
            send_reply("486","Busy Here");
            exit;
        }
    }
    set_dlg_profile("trunkCalls","$si");
   
   

   
    # apply transformations from dialplan table
    dp_translate("0","$rU/$rU");

    # route calls based on prefix
    if ( !do_routing("1") ) {
        send_reply("404","No Route found");
        exit;
    }

    t_on_failure("GW_FAILOVER");

    if (is_method("INVITE")) {
        force_send_socket(udp:XXX.XXX.XXX.XXX:5060);
        #rtpproxy_engage('ierz20');
        topology_hiding();
    }

    if (has_body("application/sdp")) {
        if (rtpproxy_offer('iewz20')) {
            t_on_reply("1");
        } else {
            t_on_reply("2");
        }
    }


    route(RELAY);
}


route[RELAY] {
    if (!t_relay()) {
        sl_reply_error();
    };
    exit;
}


failure_route[GW_FAILOVER] {
    if (t_was_cancelled()) {
        exit;
    }

    # detect failure and redirect to next available GW
    if (t_check_status("(408)|([56][0-9][0-9])")) {
        xlog("Failed GW $rd detected \n");

        if ( use_next_gw() ) {
            t_on_failure("GW_FAILOVER");
            t_relay();
            exit;
        }
       
        send_reply("500","All GW are down");
    }
}


local_route {
    if (is_method("BYE") && $DLG_dir=="UPSTREAM") {
       
        acc_db_request("200 Dialog Timeout", "acc");
       
    }
}

onreply_route[1]
{
    if (has_body("application/sdp"))
        if ($DLG_status) {      # Update
                rtpproxy_answer('eilz20');
        } else {
                rtpproxy_answer('eiz20');
        }
}

onreply_route[2]
{
    if (has_body("application/sdp"))
        rtpproxy_offer('iewz20');
}


Debug below


[Script Trace][/etc/opensips/opensips.cfg:176][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:171][me][module
mf_process_maxfwd_header] -> (BYE from 10.10.16.1,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=100
Jul 23 16:01:16 [22780] DBG:core:parse_to_param: tag=6pou4pvn6xe2phuk.i
Jul 23 16:01:16 [22780] DBG:core:parse_to: end of header reached, state=29
Jul 23 16:01:16 [22780] DBG:core:parse_to: display={},
ruri={sip:27111000626 at 10.10.16.1:5060;user=phone}
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: <To> [70];
uri=[sip:27111000626 at 10.10.16.1:5060;user=phone]
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: to body
[<sip:27111000626 at 10.10.16.1:5060;user=phone>]
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
Jul 23 16:01:16 [22780] DBG:maxfwd:is_maxfwd_present: value = 67
[Script Trace][/etc/opensips/opensips.cfg:185][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:176][me][module
check_source_address] -> (BYE from 10.10.16.1,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:permissions:check_src_addr_3: Looking for :
<1, 10.10.16.1, 5060, 1> in tables
Jul 23 16:01:16 [22780] DBG:permissions:hash_match: no pattern to match
Jul 23 16:01:16 [22780] DBG:permissions:hash_match: match found in the
hash table
[Script Trace][/etc/opensips/opensips.cfg:178][me][core setflag] -> (BYE
from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:248][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:187][me][module has_totag] ->
(BYE from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:uri:has_totag: totag found
[Script Trace][/etc/opensips/opensips.cfg:242][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:191][me][module
topology_hiding_match] -> (BYE from 10.10.16.1,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=200
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: content_length=0
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: found end of header
Jul 23 16:01:16 [22780] DBG:core:grep_sock_info: checking if host==us:
13==13 &&  [10.10.16.2] == [10.10.16.2]
Jul 23 16:01:16 [22780] DBG:core:grep_sock_info: checking if port 5060
matches port 5060
Jul 23 16:01:16 [22780] DBG:dialog:w_match_dialog: We found DID param in
R-URI with value of dbf.d239f4f3
Jul 23 16:01:16 [22780] DBG:dialog:dlg_onroute: route param is
'dbf.d239f4f3' (len=12)
Jul 23 16:01:16 [22780] DBG:dialog:lookup_dlg: ref dlg 0x7f81e1b3c2f8
with 1 -> 4
Jul 23 16:01:16 [22780] DBG:dialog:lookup_dlg: dialog id=1062179629
found on entry 4029
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=58
Jul 23 16:01:16 [22780] DBG:core:parse_to_param:
tag=SDl3i7c02-55B0F3A1-1DDB4E1-0ADE2C1B
Jul 23 16:01:16 [22780] DBG:core:parse_to: end of header reached, state=29
Jul 23 16:01:16 [22780] DBG:core:parse_to: display={},
ruri={sip:27115138000 at 10.10.17.55;user=phone}
Jul 23 16:01:16 [22780] DBG:dialog:next_state_dlg: dialog 0x7f81e1b3c2f8
changed from state 2 to state 2, due event 7
[Script Trace][/etc/opensips/opensips.cfg:199][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:194][me][module
validate_dialog] -> (BYE from 10.10.16.1,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:dialog:dlg_validate_dialog: CSEQ validation
passed
[Script Trace][/etc/opensips/opensips.cfg:210][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:199][me][module is_method] ->
(BYE from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:200][me][core setflag] -> (BYE
from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:201][me][core setflag] -> (BYE
from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:227][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:210][me][module has_body] ->
(BYE from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:sipmsgops:has_body_f: content length is zero
[Script Trace][/etc/opensips/opensips.cfg:227][me][route RELAY] -> (BYE
from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:340][me][core if] -> (BYE from
10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:338][me][module t_relay] ->
(BYE from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:tm:t_newtran: transaction on
entrance=0xffffffffffffffff
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=78
Jul 23 16:01:16 [22780] DBG:tm:t_lookup_request: start searching:
hash=40946, isACK=0
Jul 23 16:01:16 [22780] DBG:tm:matching_3261: RFC3261 transaction
matching failed
Jul 23 16:01:16 [22780] DBG:tm:t_lookup_request: no transaction found
Jul 23 16:01:16 [22780] DBG:tm:run_reqin_callbacks:
trans=0x7f81e1b41548, callback type 1, id 1 entered
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=78
Jul 23 16:01:16 [22780] DBG:tm:run_reqin_callbacks:
trans=0x7f81e1b41548, callback type 1, id 0 entered
Jul 23 16:01:16 [22780] DBG:dialog:ref_dlg: ref dlg 0x7f81e1b3c2f8 with
1 -> 5
Jul 23 16:01:16 [22780] DBG:core:mk_proxy: doing DNS lookup...
Jul 23 16:01:16 [22780] DBG:core:check_ip_address: params 10.10.16.1,
10.10.16.1, 0
Jul 23 16:01:16 [22780] DBG:tm:set_timer: relative timeout is 500000
Jul 23 16:01:16 [22780] DBG:tm:insert_timer_unsafe: [4]: 0x7f81e1b41768
(15800000)
Jul 23 16:01:16 [22780] DBG:tm:insert_timer_unsafe: [0]: 0x7f81e1b41798 (20)
Jul 23 16:01:16 [22780] DBG:tm:t_relay_to: new transaction fwd'ed
[Script Trace][/etc/opensips/opensips.cfg:341][me][core exit] -> (BYE
from 10.10.16.1, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:tm:t_unref: UNREF_UNSAFE: [0x7f81e1b41548]
after is 0
Jul 23 16:01:16 [22780] DBG:dialog:unref_dlg: unref dlg 0x7f81e1b3c2f8
with 1 -> 4 in entry 0x7f81e1b35838
Jul 23 16:01:16 [22780] DBG:core:destroy_avp_list: destroying list (nil)
Jul 23 16:01:16 [22780] DBG:core:receive_msg: cleaning up
Jul 23 16:01:16 [22780] DBG:core:parse_msg: SIP Request:
Jul 23 16:01:16 [22780] DBG:core:parse_msg:  method:  <BYE>
Jul 23 16:01:16 [22780] DBG:core:parse_msg:  uri:    
<sip:10.10.16.2;did=dbf.d239f4f3>
Jul 23 16:01:16 [22780] DBG:core:parse_msg:  version: <SIP/2.0>
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=2
Jul 23 16:01:16 [22780] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK2ff9.7dfac551.0>; state=16
Jul 23 16:01:16 [22780] DBG:core:parse_via: end of header reached, state=5
Jul 23 16:01:16 [22780] DBG:core:parse_headers: via found, flags=2
Jul 23 16:01:16 [22780] DBG:core:parse_headers: this is the first via
Jul 23 16:01:16 [22780] DBG:core:receive_msg: After parse_msg...
Jul 23 16:01:16 [22780] DBG:core:receive_msg: preparing to run routing
scripts...
[Script Trace][/etc/opensips/opensips.cfg:176][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:171][me][module
mf_process_maxfwd_header] -> (BYE from 10.10.16.2,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=100
Jul 23 16:01:16 [22780] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK53eneb00a89gqfc5m0o0.1>; state=16
Jul 23 16:01:16 [22780] DBG:core:parse_via: end of header reached, state=5
Jul 23 16:01:16 [22780] DBG:core:parse_headers: via found, flags=100
Jul 23 16:01:16 [22780] DBG:core:parse_headers: parse_headers: this is
the second via
Jul 23 16:01:16 [22780] DBG:core:parse_to_param: tag=6pou4pvn6xe2phuk.i
Jul 23 16:01:16 [22780] DBG:core:parse_to: end of header reached, state=29
Jul 23 16:01:16 [22780] DBG:core:parse_to: display={},
ruri={sip:27111000626 at 10.10.16.1:5060;user=phone}
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: <To> [70];
uri=[sip:27111000626 at 10.10.16.1:5060;user=phone]
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: to body
[<sip:27111000626 at 10.10.16.1:5060;user=phone>]
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
Jul 23 16:01:16 [22780] DBG:maxfwd:is_maxfwd_present: value = 66
[Script Trace][/etc/opensips/opensips.cfg:185][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:176][me][module
check_source_address] -> (BYE from 10.10.16.2,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:permissions:check_src_addr_3: Looking for :
<1, 10.10.16.2, 5060, 1> in tables
Jul 23 16:01:16 [22780] DBG:permissions:hash_match: no match in the hash
table
Jul 23 16:01:16 [22780] DBG:permissions:match_subnet_table: subnet table
is empty
[Script Trace][/etc/opensips/opensips.cfg:185][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:179][me][module is_from_gw] ->
(BYE from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:183][me][core xlog] -> (BYE
from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:core:buf_init: initializing...
Message is not from Trunk or GW 10.10.16.2[Script
Trace][/etc/opensips/opensips.cfg:248][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:187][me][module has_totag] ->
(BYE from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:uri:has_totag: totag found
[Script Trace][/etc/opensips/opensips.cfg:242][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:191][me][module
topology_hiding_match] -> (BYE from 10.10.16.2,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=200
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: content_length=0
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: found end of header
Jul 23 16:01:16 [22780] DBG:core:grep_sock_info: checking if host==us:
13==13 &&  [10.10.16.2] == [10.10.16.2]
Jul 23 16:01:16 [22780] DBG:core:grep_sock_info: checking if port 5060
matches port 5060
Jul 23 16:01:16 [22780] DBG:dialog:w_match_dialog: We found DID param in
R-URI with value of dbf.d239f4f3
Jul 23 16:01:16 [22780] DBG:dialog:dlg_onroute: route param is
'dbf.d239f4f3' (len=12)
Jul 23 16:01:16 [22780] DBG:dialog:lookup_dlg: ref dlg 0x7f81e1b3c2f8
with 1 -> 5
Jul 23 16:01:16 [22780] DBG:dialog:lookup_dlg: dialog id=1062179629
found on entry 4029
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=58
Jul 23 16:01:16 [22780] DBG:core:parse_to_param:
tag=SDl3i7c02-55B0F3A1-1DDB4E1-0ADE2C1B
Jul 23 16:01:16 [22780] DBG:core:parse_to: end of header reached, state=29
Jul 23 16:01:16 [22780] DBG:core:parse_to: display={},
ruri={sip:27115138000 at 10.10.17.55;user=phone}
Jul 23 16:01:16 [22780] DBG:dialog:next_state_dlg: dialog 0x7f81e1b3c2f8
changed from state 2 to state 2, due event 7
[Script Trace][/etc/opensips/opensips.cfg:199][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Trevor
[Script Trace][/etc/opensips/opensips.cfg:194][me][module
validate_dialog] -> (BYE from 10.10.16.2,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:dialog:dlg_validate_dialog: CSEQ validation
passed
[Script Trace][/etc/opensips/opensips.cfg:210][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:199][me][module is_method] ->
(BYE from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:200][me][core setflag] -> (BYE
from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:201][me][core setflag] -> (BYE
from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:227][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:210][me][module has_body] ->
(BYE from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:sipmsgops:has_body_f: content length is zero
[Script Trace][/etc/opensips/opensips.cfg:227][me][route RELAY] -> (BYE
from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:340][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:338][me][module t_relay] ->
(BYE from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:tm:t_newtran: transaction on
entrance=0xffffffffffffffff
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=78
Jul 23 16:01:16 [22780] DBG:tm:t_lookup_request: start searching:
hash=40946, isACK=0
Jul 23 16:01:16 [22780] DBG:tm:matching_3261: RFC3261 transaction
matching failed
Jul 23 16:01:16 [22780] DBG:tm:t_lookup_request: no transaction found
Jul 23 16:01:16 [22780] DBG:tm:run_reqin_callbacks:
trans=0x7f81e1b446a0, callback type 1, id 1 entered
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=78
Jul 23 16:01:16 [22780] DBG:tm:run_reqin_callbacks:
trans=0x7f81e1b446a0, callback type 1, id 0 entered
Jul 23 16:01:16 [22780] DBG:dialog:ref_dlg: ref dlg 0x7f81e1b3c2f8 with
1 -> 6
Jul 23 16:01:16 [22780] DBG:core:mk_proxy: doing DNS lookup...
Jul 23 16:01:16 [22780] DBG:core:check_ip_address: params 10.10.16.2,
10.10.16.2, 0
Jul 23 16:01:16 [22780] DBG:tm:set_timer: relative timeout is 500000
Jul 23 16:01:16 [22780] DBG:tm:insert_timer_unsafe: [4]: 0x7f81e1b448c0
(15800000)
Jul 23 16:01:16 [22780] DBG:tm:insert_timer_unsafe: [0]: 0x7f81e1b448f0 (20)
Jul 23 16:01:16 [22780] DBG:tm:t_relay_to: new transaction fwd'ed
[Script Trace][/etc/opensips/opensips.cfg:341][me][core exit] -> (BYE
from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:tm:t_unref: UNREF_UNSAFE: [0x7f81e1b446a0]
after is 0
Jul 23 16:01:16 [22780] DBG:dialog:unref_dlg: unref dlg 0x7f81e1b3c2f8
with 1 -> 5 in entry 0x7f81e1b35838
Jul 23 16:01:16 [22780] DBG:core:destroy_avp_list: destroying list (nil)
Jul 23 16:01:16 [22780] DBG:core:receive_msg: cleaning up
Jul 23 16:01:16 [22780] DBG:core:parse_msg: SIP Request:
Jul 23 16:01:16 [22780] DBG:core:parse_msg:  method:  <BYE>
Jul 23 16:01:16 [22780] DBG:core:parse_msg:  uri:    
<sip:10.10.16.2;did=dbf.d239f4f3>
Jul 23 16:01:16 [22780] DBG:core:parse_msg:  version: <SIP/2.0>
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=2
Jul 23 16:01:16 [22780] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK2ff9.8dfac551.0>; state=16
Jul 23 16:01:16 [22780] DBG:core:parse_via: end of header reached, state=5
Jul 23 16:01:16 [22780] DBG:core:parse_headers: via found, flags=2
Jul 23 16:01:16 [22780] DBG:core:parse_headers: this is the first via
Jul 23 16:01:16 [22780] DBG:core:receive_msg: After parse_msg...
Jul 23 16:01:16 [22780] DBG:core:receive_msg: preparing to run routing
scripts...
[Script Trace][/etc/opensips/opensips.cfg:176][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:171][me][module
mf_process_maxfwd_header] -> (BYE from 10.10.16.2,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:core:parse_headers: flags=100
Jul 23 16:01:16 [22780] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK2ff9.7dfac551.0>; state=16
Jul 23 16:01:16 [22780] DBG:core:parse_via: end of header reached, state=5
Jul 23 16:01:16 [22780] DBG:core:parse_headers: via found, flags=100
Jul 23 16:01:16 [22780] DBG:core:parse_headers: parse_headers: this is
the second via
Jul 23 16:01:16 [22780] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK53eneb00a89gqfc5m0o0.1>; state=16
Jul 23 16:01:16 [22780] DBG:core:parse_via: end of header reached, state=5
Jul 23 16:01:16 [22780] DBG:core:parse_headers: via found, flags=100
Jul 23 16:01:16 [22780] DBG:core:parse_to_param: tag=6pou4pvn6xe2phuk.i
Jul 23 16:01:16 [22780] DBG:core:parse_to: end of header reached, state=29
Jul 23 16:01:16 [22780] DBG:core:parse_to: display={},
ruri={sip:27111000626 at 10.10.16.1:5060;user=phone}
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: <To> [70];
uri=[sip:27111000626 at 10.10.16.1:5060;user=phone]
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: to body
[<sip:27111000626 at 10.10.16.1:5060;user=phone>]
Jul 23 16:01:16 [22780] DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
Jul 23 16:01:16 [22780] DBG:maxfwd:is_maxfwd_present: value = 65
[Script Trace][/etc/opensips/opensips.cfg:185][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:176][me][module
check_source_address] -> (BYE from 10.10.16.2,
ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Jul 23 16:01:16 [22780] DBG:permissions:check_src_addr_3: Looking for :
<1, 10.10.16.2, 5060, 1> in tables
Jul 23 16:01:16 [22780] DBG:permissions:hash_match: no match in the hash
table
Jul 23 16:01:16 [22780] DBG:permissions:match_subnet_table: subnet table
is empty
[Script Trace][/etc/opensips/opensips.cfg:185][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:179][me][module is_from_gw] ->
(BYE from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
[Script Trace][/etc/opensips/opensips.cfg:183][me][core xlog] -> (BYE
from 10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)
Message is not from Trunk or GW 10.10.16.2[Script
Trace][/etc/opensips/opensips.cfg:248][me][core if] -> (BYE from
10.10.16.2, ruri=sip:10.10.16.2;did=dbf.d239f4f3)


Regards
Trevor Steyn




More information about the Users mailing list