[OpenSIPS-Users] topology hiding not accepting BYE before 200 OK
Trevor Steyn
trevor at webon.co.za
Mon Jul 27 09:11:57 CEST 2015
Hi Anyone have any ideas on the below issue?
On 23/07/2015 17:12, Trevor Steyn wrote:
> 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