Hi *, <br><br>okay, this is straight after t_relay:<br><br>[INVITE] BRANCH-ROUTE[2] New branch at [<a href="mailto:sip%3AS001e310003ee@41.2.192.203">sip:S001e310003ee@41.2.192.203</a>] (RURI=[<a href="mailto:sip%3A0870000005@abcd.com">sip:0870000005@abcd.com</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c26a9340b31-2hp299m84e6x]) <br>
Jan 30 13:38:54 [19185] DBG:core:mk_proxy: doing DNS lookup...<br>Jan 30 13:38:54 [19185] DBG:core:check_via_address: params 192.168.2.174, 192.168.2.174, 0<br>Jan 30 13:38:54 [19185] DBG:tm:set_timer: relative timeout is 500000<br>
Jan 30 13:38:54 [19185] DBG:tm:insert_timer_unsafe: [4]: fbda0a64 (11100000)<br>Jan 30 13:38:54 [19185] DBG:tm:set_timer: relative timeout is 30<br>Jan 30 13:38:54 [19185] DBG:tm:insert_timer_unsafe: [0]: fbda0a80 (40)<br>
<br>********------------------------------- ROUTE(1) DONE -----------------------------------********<br><br>Jan 30 13:38:54 [19185] DBG:tm:t_unref: UNREF_UNSAFE: after is 0<br>Jan 30 13:38:54 [19185] DBG:core:destroy_avp_list: destroying list 0<br>
Jan 30 13:38:54 [19185] DBG:core:receive_msg: cleaning up<br>Jan 30 13:38:54 [19185] DBG:core:parse_msg: SIP Reply (status):<br>Jan 30 13:38:54 [19185] DBG:core:parse_msg: version: <SIP/2.0><br>Jan 30 13:38:54 [19185] DBG:core:parse_msg: status: <180><br>
Jan 30 13:38:54 [19185] DBG:core:parse_msg: reason: <Ringing><br>Jan 30 13:38:54 [19185] DBG:core:parse_headers: flags=2<br>Jan 30 13:38:54 [19185] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7215.525.0>; state=16<br>
Jan 30 13:38:54 [19185] DBG:core:parse_via: end of header reached, state=5<br>Jan 30 13:38:54 [19185] DBG:core:parse_headers: via found, flags=2<br>Jan 30 13:38:54 [19185] DBG:core:parse_headers: this is the first via<br>
Jan 30 13:38:54 [19185] DBG:core:receive_msg: After parse_msg...<br>statistics: [rcv_rpls] : [1]<br>Jan 30 13:38:54 [19185] DBG:core:forward_reply: found module tm, passing reply to it<br>Jan 30 13:38:54 [19185] DBG:tm:t_check: start=ffffffff<br>
Jan 30 13:38:54 [19185] DBG:core:parse_headers: flags=22<br>Jan 30 13:38:54 [19185] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-ubsc5bh2l33v>; state=6<br>Jan 30 13:38:54 [19185] DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16<br>
Jan 30 13:38:54 [19185] DBG:core:parse_via: end of header reached, state=5<br>Jan 30 13:38:54 [19185] DBG:core:parse_headers: via found, flags=22<br>Jan 30 13:38:54 [19185] DBG:core:parse_headers: parse_headers: this is the second via<br>
Jan 30 13:38:54 [19185] DBG:core:parse_to_param: tag=4z34qbhket<br>Jan 30 13:38:54 [19185] DBG:core:parse_to: end of header reached, state=29<br>Jan 30 13:38:54 [19185] DBG:core:parse_to: display={}, ruri={sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone}<br>
Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: <To> [67]; uri=[sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone]<br>Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: to body [<sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone>]<br>
Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE><br>Jan 30 13:38:54 [19185] DBG:core:parse_headers: flags=8<br>Jan 30 13:38:54 [19185] DBG:tm:t_reply_matching: hash 20775 label 1317 branch 0<br>
Jan 30 13:38:54 [19185] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1<br>Jan 30 13:38:54 [19185] DBG:tm:t_reply_matching: reply matched (T=fbda0910)!<br>Jan 30 13:38:54 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback type 2, id 0 entered<br>
Jan 30 13:38:54 [19185] DBG:core:parse_to_param: tag=u1iivbkwrw<br>Jan 30 13:38:54 [19185] DBG:core:parse_to: end of header reached, state=29<br>Jan 30 13:38:54 [19185] DBG:core:parse_to: display={"Bulk Create First Bulk Create Last - <a href="mailto:0870000002@abcd.com">0870000002@abcd.com</a>"}, ruri={<a href="mailto:sip%3A0870000002@abcd.com">sip:0870000002@abcd.com</a>}<br>
DBG:uac::restore_from_reply: removing <From: "Bulk Create First Bulk Create Last - <a href="mailto:0870000002@abcd.com">0870000002@abcd.com</a>" <<a href="mailto:sip%3A0870000002@abcd.com">sip:0870000002@abcd.com</a>>;tag=u1iivbkwrw<br>
><br>DBG:uac::restore_from_reply: inserting <From: "Snom Demo 3" <<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>>;tag=u1iivbkwrw<br>><br>Jan 30 13:38:54 [19185] DBG:tm:t_check: end=fbda0910<br>
Jan 30 13:38:54 [19185] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1)<br>statistics: [tm_rcv_rpls] : [1]<br>[INVITE] INCOMING-REPLY[2] (RURI=[<a href="mailto:sip%3A0870000005@abcd.com">sip:0870000005@abcd.com</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c26a9340b31-2hp299m84e6x]) <br>
[INVITE] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="mailto:sip%3A0870000005@abcd.com">sip:0870000005@abcd.com</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c26a9340b31-2hp299m84e6x]) <br>
Jan 30 13:38:54 [19185] DBG:tm:t_should_relay_response: T_code=0, new_code=180<br>Jan 30 13:38:54 [19185] DBG:tm:relay_reply: branch=0, save=0, relay=0<br>Jan 30 13:38:54 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback type 16, id 1 entered<br>
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 13:38:54 [19185] DBG:core:build_res_buf_from_sip_res: old size: 748, new size: 642<br>Jan 30 13:38:54 [19185] DBG:core:build_res_buf_from_sip_res: copied size: orig:385, new: 279, rest: 363 msg=<br>
SIP/2.0 180 Ringing<br>Via: SIP/2.0/UDP 192.168.2.174:5060;branch=z9hG4bK-ubsc5bh2l33v;rport=5060<br>Record-Route: <sip:192.168.5.46;lr=on;ftag=u1iivbkwrw;vsf=cGFzcxRndWR0YHBxfm9Xd3MPdXkwcHpuc2ljMnlzMQcfDA--><br>From: "Snom Demo 3" <<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>>;tag=u1iivbkwrw<br>
To: <sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone>;tag=4z34qbhket<br>Call-ID: 3c26a9340b31-2hp299m84e6x<br>CSeq: 1 INVITE<br>Contact: <<a href="http://sip:S001e310003ee@192.168.1.100:5060">sip:S001e310003ee@192.168.1.100:5060</a>>;flow-id=1<br>
Require: 100rel<br>RSeq: 1<br>Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO<br>Allow-Events: talk, hold, refer, call-info<br>Content-Length: 0<br><br><br>Jan 30 13:38:54 [19185] DBG:core:_shm_resize: resize(0) called<br>
statistics: [tm_rld_rpls] : [1]<br>Jan 30 13:38:54 [19185] DBG:tm:relay_reply: sent buf=8328250: SIP/2.0 1..., shmem=fbda3640: SIP/2.0 1<br>Jan 30 13:38:54 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback type 128, id 1 entered<br>
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 13:38:54 [19185] DBG:dialog:next_state_dlg: dialog fbda17c0 changed from state 1 to state 2, due event 2<br>Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: new_state = DLG_STATE_EARLY.<br>
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: old_state!=DLG_STATE_EARLY.<br>Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: Checking for RINGING [180] PARAM-CODE [180].<br>Jan 30 13:38:54 [19185] DBG:core:db_free_rows: freeing 1 rows<br>
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: row[0]=8325770<br>Jan 30 13:38:54 [19185] DBG:core:db_free_rows: 8325770=pkg_free() RES_ROWS<br>Jan 30 13:38:54 [19185] DBG:core:db_free_rows: freeing 1 rows<br>Jan 30 13:38:54 [19185] DBG:core:db_free_rows: row[0]=8325770<br>
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: 8325770=pkg_free() RES_ROWS<br><br>At this point the 180 ringings keep coming in from the far end device. Then the 200OK comes in<br><br>[PRACK] INCOMING-REPLY[2] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c26a9340b31-2hp299m84e6x]) <br>
[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c26a9340b31-2hp299m84e6x]) <br>
Jan 30 13:38:57 [19185] DBG:tm:t_should_relay_response: T_code=180, new_code=200<br>Jan 30 13:38:57 [19185] DBG:tm:relay_reply: branch=0, save=0, relay=0<br>Jan 30 13:38:57 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback type 16, id 1 entered<br>
Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 13:38:57 [19185] DBG:core:build_res_buf_from_sip_res: old size: 1090, new size: 984<br>Jan 30 13:38:57 [19185] DBG:core:build_res_buf_from_sip_res: copied size: orig:380, new: 274, rest: 710 msg=<br>
SIP/2.0 200 Ok<br>Via: SIP/2.0/UDP 192.168.2.174:5060;branch=z9hG4bK-ubsc5bh2l33v;rport=5060<br>Record-Route: <sip:192.168.5.46;lr=on;ftag=u1iivbkwrw;vsf=cGFzcxRndWR0YHBxfm9Xd3MPdXkwcHpuc2ljMnlzMQcfDA--><br>From: "Snom Demo 3" <<a href="mailto:sip%3AS000413292efd@abcd.com">sip:S000413292efd@abcd.com</a>>;tag=u1iivbkwrw<br>
To: <sip:0870000005*<a href="mailto:47870@abcd.com">47870@abcd.com</a>;user=phone>;tag=4z34qbhket<br>Call-ID: 3c26a9340b31-2hp299m84e6x<br>CSeq: 1 INVITE<br>Contact: <<a href="http://sip:S001e310003ee@41.2.192.203:5060">sip:S001e310003ee@41.2.192.203:5060</a>>;flow-id=1<br>
Require: timer<br>Session-Expires: 3600;refresher=uas<br>User-Agent: snom360/7.1.30<br>Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO<br>Allow-Events: talk, hold, refer, call-info<br>
Supported: timer, replaces, callerid<br>Content-Type: application/sdp<br>Content-Length: 222<br><br>v=0<br>o=root 1584958272 1584958273 IN IP4 41.2.192.203<br>s=call<br>c=IN IP4 41.2.192.203<br>t=0 0<br>m=audio 60852 RTP/AVP 18 101<br>
a=rtpmap:18 g729/8000<br>a=rtpmap:101 telephone-event/8000<br>a=fmtp:101 0-16<br>a=ptime:20<br>a=sendrecv<br><br>statistics: [tm_trans_2xx] : [1]<br>statistics: [tm_rld_rpls] : [1]<br>Jan 30 13:38:57 [19185] DBG:tm:update_totag_set: new totag <br>
Jan 30 13:38:57 [19185] DBG:tm:insert_timer_unsafe: [2]: fbda0958 (17)<br>Jan 30 13:38:57 [19185] DBG:tm:relay_reply: sent buf=8328250: SIP/2.0 2..., shmem=fbda71e0: SIP/2.0 2<br>Jan 30 13:38:57 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback type 128, id 1 entered<br>
Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 13:38:57 [19185] DBG:dialog:next_state_dlg: dialog fbda17c0 changed from state 2 to state 3, due event 3<br>Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: new_state==DLG_STATE_CONFIRMED_NA && old_state!=DLG_STATE_CONFIRMED_NA && old_state!=DLG_STATE_CONFIRMED.<br>
Jan 30 13:38:57 [19185] DBG:dialog:dlg_onreply: dialog fbda17c0 confirmed<br>Jan 30 13:38:57 [19185] DBG:core:parse_headers: flags=80<br>Jan 30 13:38:57 [19185] DBG:core:print_rr_body: current rr is <sip:192.168.5.46;lr=on;ftag=u1iivbkwrw;vsf=cGFzcxRndWR0YHBxfm9Xd3MPdXkwcHpuc2ljMnlzMQcfDA--><br>
Jan 30 13:38:57 [19185] DBG:core:print_rr_body: skipping 1 route records<br>Jan 30 13:38:57 [19185] DBG:core:print_rr_body: out rr []<br>Jan 30 13:38:57 [19185] DBG:core:print_rr_body: we have 1 records<br>Jan 30 13:38:57 [19185] DBG:dialog:populate_leg_info: route_set , contact <a href="http://sip:S001e310003ee@41.2.192.203:5060">sip:S001e310003ee@41.2.192.203:5060</a>, cseq 1 and bind_addr udp:<a href="http://192.168.5.46:5060">192.168.5.46:5060</a><br>
Jan 30 13:38:57 [19185] DBG:dialog:update_dialog_dbinfo: sock_info is udp:<a href="http://192.168.5.46:5060">192.168.5.46:5060</a><br>Jan 30 13:38:57 [19185] DBG:dialog:insert_dlg_timer: Setting DLG timer to 43199<br>Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: Looking up PARTNER_ID from avp sp_partner_id<br>
Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: pid_avp is NULL while looking up sp_partner_id<br>Jan 30 13:38:57 [19185] DBG:core:db_free_rows: freeing 1 rows<br>Jan 30 13:38:57 [19185] DBG:core:db_free_rows: row[0]=83264d8<br>
Jan 30 13:38:57 [19185] DBG:core:db_free_rows: 83264d8=pkg_free() RES_ROWS<br>Jan 30 13:38:57 [19185] DBG:core:db_free_rows: freeing 1 rows<br>Jan 30 13:38:57 [19185] DBG:core:db_free_rows: row[0]=83264d8<br>Jan 30 13:38:57 [19185] DBG:core:db_free_rows: 83264d8=pkg_free() RES_ROWS<br>
<br>After the ACK the call is successfully setup but the tm module still retransmits invites and eventually the timeout fr_inv_timer fires and the TM module executes the failure route.<br><br>Any ideas / pointers!!??<br><br>
Cheers<br>Jason<br><br><br><div class="gmail_quote">On Fri, Jan 30, 2009 at 1:40 PM, Jason Penton <span dir="ltr"><<a href="mailto:jason.penton@smilecoms.com">jason.penton@smilecoms.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
Hi Daniel, <br><br>Sorry - I hadnt set the debug high enough - will send another more detailed log soon!<br><br>Cheers<br><font color="#888888">Jason</font><div><div></div><div class="Wj3C7c"><br><br><div class="gmail_quote">
On Fri, Jan 30, 2009 at 12:16 PM, Jason Penton <span dir="ltr"><<a href="mailto:jason.penton@smilecoms.com" target="_blank">jason.penton@smilecoms.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">Hi *,<br><br>Here is the trace. One thing I have noticed is that the 180 Ringing being returned from the Snom phone (behind the NAT) contains the contact header still with the private IP (192.168.1.100). Theoretically though I don't see how this can affect the transaction handling - maybe you can shed some light.<br>
<br> <br>********------------------------------------- ROUTE(5) -----------------------------------********<br><br>********------------------------------------ PROXY-AUTH -----------------------------------********<br>
<snip><br>********---------------------------------- PROXY-AUTH DONE --------------------------------********<br><br>********---------------------------------- ROUTE(5) DONE --------------------------------********<br>
<br><br>********---------------------------------- ROUTE(3) -----------------------------------********<br><br>********--------------------------------- RECORD-ROUTE ---------------------------------********<br>********------------------------------- RECORD-ROUTE DONE ------------------------------********<br>
<br>********------------------------------- ROUTE(3) DONE --------------------------------********<br><br><br>********---------------------------------- ROUTE(4) -----------------------------------********<br><br>********------------------------------------ INVITE ------------------------------------********<br>
Jan 30 11:31:34 [11258] INFO:dialog:dlg_created_cb: dialog created or destroyed<br>Jan 30 11:31:34 [11258] INFO:dialog:dlg_created_cb: CALLID IS [3c268b5bbf2d-mtnq42l2osup]------------------------------------------------------------------------------------------------------<br>
********--------------------------------- INVITE DONE ----------------------------------********<br><br>********------------------------------- ROUTE(4) DONE --------------------------------********<br><br><br>********------------------------------------- ROUTE(6) --------------------------------------------********<br>
<br>********-------------------------------------- USRLOC ----------------------------------------------********<br><snip><br>********-------------------------------------- USRLOC DONE -----------------------------------------********<br>
<br>********------------------------------------ ROUTE(6) DONE ---------------------------------------********<br><br><br>********---------------------------------- ROUTE(1) ------------------------------------********<br>
<br>********--------------------------------- INVITE ---------------------------------********<br>********---------------------------------- T_RELAY -------------------------------------********<br>[INVITE] BRANCH-ROUTE[2] New branch at [<a href="mailto:sip%3AS001e310003ee@41.2.192.203" target="_blank">sip:S001e310003ee@41.2.192.203</a>] (RURI=[<a href="mailto:sip%3A0870000005@abcd.com" target="_blank">sip:0870000005@abcd.com</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
<br>********------------------------------- ROUTE(1) DONE -----------------------------------********<br>[INVITE] INCOMING-REPLY[2] (RURI=[<a href="mailto:sip%3A0870000005@abcd.com" target="_blank">sip:0870000005@abcd.com</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
[INVITE] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="mailto:sip%3A0870000005@abcd.com" target="_blank">sip:0870000005@abcd.com</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>statistics: [tm_rld_rpls] : [1]<br>Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: new_state = DLG_STATE_EARLY.<br>
Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: old_state!=DLG_STATE_EARLY.<br>Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: Checking for RINGING [180] PARAM-CODE [180].<br><snip><br>********---------------------------------- ROUTE(2) -----------------------------------********<br>
<br>********------------------------------------ TO-TAG -------------------------------------********<br>********---------------------------------- LOOSE-ROUTE ---------------------------------********<br>********---------------------------------- TO-TAG DONE ----------------------------------********<br>
<br>********-------------------------------- ROUTE(2) DONE --------------------------------********<br><br><br>********---------------------------------- ROUTE(1) ------------------------------------********<br><br>********---------------------------------- T_RELAY -------------------------------------********<br>
********------------------------------- ROUTE(1) DONE -----------------------------------********<br><br>[PRACK] INCOMING-REPLY[2] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
Jan 30 11:31:35 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>statistics: [tm_rld_rpls] : [1]<br>Jan 30 11:31:35 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 11:31:35 [11258] INFO:dialog:dlg_onreply: new_state = DLG_STATE_EARLY.<br>
statistics: [rcv_reqs] : [1]<br>********---------------------------------- ROUTE(2) -----------------------------------********<br><br>********------------------------------------ TO-TAG -------------------------------------********<br>
********---------------------------------- LOOSE-ROUTE ---------------------------------********<br>********---------------------------------- TO-TAG DONE ----------------------------------********<br><br>********-------------------------------- ROUTE(2) DONE --------------------------------********<br>
<br><br>********---------------------------------- ROUTE(1) ------------------------------------********<br><br>********---------------------------------- T_RELAY -------------------------------------********<br>[PRACK] INCOMING-REPLY[2] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
Jan 30 11:31:36 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>statistics: [tm_rld_rpls] : [1]<br>Jan 30 11:31:36 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 11:31:36 [11258] INFO:dialog:dlg_onreply: new_state = DLG_STATE_EARLY.<br>
statistics: [rcv_reqs] : [1]<br>********---------------------------------- ROUTE(2) -----------------------------------********<br><br>********------------------------------------ TO-TAG -------------------------------------********<br>
********---------------------------------- LOOSE-ROUTE ---------------------------------********<br>********---------------------------------- TO-TAG DONE ----------------------------------********<br><br>********-------------------------------- ROUTE(2) DONE --------------------------------********<br>
<br><br>********---------------------------------- ROUTE(1) ------------------------------------********<br><br>********---------------------------------- T_RELAY -------------------------------------********<br>[PRACK] INCOMING-REPLY[2] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
Jan 30 11:31:38 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>statistics: [tm_rld_rpls] : [1]<br>Jan 30 11:31:38 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 11:31:38 [11258] INFO:dialog:dlg_onreply: new_state = DLG_STATE_EARLY.<br>
statistics: [rcv_reqs] : [1]<br>********---------------------------------- ROUTE(2) -----------------------------------********<br><br>********------------------------------------ TO-TAG -------------------------------------********<br>
********---------------------------------- LOOSE-ROUTE ---------------------------------********<br>********---------------------------------- TO-TAG DONE ----------------------------------********<br><br>********-------------------------------- ROUTE(2) DONE --------------------------------********<br>
<br><br>********---------------------------------- ROUTE(1) ------------------------------------********<br><br>********---------------------------------- T_RELAY -------------------------------------********<br>[PRACK] INCOMING-REPLY[2] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>statistics: [tm_rld_rpls] : [1]<br>Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: new_state = DLG_STATE_EARLY.<br>
statistics: [rcv_reqs] : [1]<br>*******---------------------------------- ROUTE(2) -----------------------------------********<br><br>********------------------------------------ TO-TAG -------------------------------------********<br>
********---------------------------------- LOOSE-ROUTE ---------------------------------********<br>********---------------------------------- TO-TAG DONE ----------------------------------********<br><br>********-------------------------------- ROUTE(2) DONE --------------------------------********<br>
<br><br>********---------------------------------- ROUTE(1) ------------------------------------********<br><br>********---------------------------------- T_RELAY -------------------------------------********<br>[PRACK] INCOMING-REPLY[2] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[<a href="http://sip:S001e310003ee@192.168.1.100:5060" target="_blank">sip:S001e310003ee@192.168.1.100:5060</a>] F=[<a href="mailto:sip%3AS000413292efd@abcd.com" target="_blank">sip:S000413292efd@abcd.com</a>] T=[sip:0870000005*<a href="mailto:47942@abcd.com" target="_blank">47942@abcd.com</a>;user=phone] IP=[192.168.2.174] ID=[3c268b5bbf2d-mtnq42l2osup]) <br>
Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>statistics: [tm_trans_2xx] : [1]<br>statistics: [tm_rld_rpls] : [1]<br>Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called<br>Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: new_state==DLG_STATE_CONFIRMED_NA && old_state!=DLG_STATE_CONFIRMED_NA && old_state!=DLG_STATE_CONFIRMED.<br>
Jan 30 11:31:42 [11258] INFO:dialog:dlg_update_cb: ######################dialog updated##############################<br>Jan 30 11:31:42 [11258] INFO:dialog:dlg_update_cb: Confirmed DID fbda14b0 session and source ip is [<a href="http://sip:S000413292efd@192.168.2.174:5060" target="_blank">sip:S000413292efd@192.168.2.174:5060</a>] and dst ip is [<a href="http://sip:S001e310003ee@41.2.192.203:5060" target="_blank">sip:S001e310003ee@41.2.192.203:5060</a>] and callid is [3c268b5bbf2d-mtnq42l2osup]<br>
*******---------------------------------- ROUTE(2) -----------------------------------********<br><br>********------------------------------------ TO-TAG -------------------------------------********<br>********---------------------------------- LOOSE-ROUTE ---------------------------------********<br>
********---------------------------------- TO-TAG DONE ----------------------------------********<br><br>********-------------------------------- ROUTE(2) DONE --------------------------------********<br><br><br>********---------------------------------- ROUTE(1) ------------------------------------********<br>
<br>********---------------------------------- T_RELAY -------------------------------------********<br>********------------------------------- ROUTE(1) DONE -----------------------------------********<div><div></div><div>
<br><br><div class="gmail_quote">
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><div><div><br>
<br>
On 01/30/2009 09:00 AM, Jason Penton wrote:<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
Hi *,<br>
<br>
What is the logic behind the transation matching in Kamailio. I am finding a problem whereby a call setup transaction (INVITE, 180 Ringing, PRACK, 200OK, ACK). between 2 Snom phones works in normal mode. However, when one phone is behind a NAT with STUN support, everything works perfectly (i.e. call setup, 2-way audio, etc), BUT the tm module doesnt match the transaction between the original invite and the subsequent messages (180, 200ok, etc). the impact here is that the fr_inv_timer eventually fires even though the call has been answered. Note: this only happens when the call is destined for the device behind the NAT.<br>
<br>
Any ideas.<br>
<br>
Perhaps an explanation on how the tm module does transaction manager.<br>
<br>
RFC3261 states that transaction matching is done based on the via branch parameter.<br>
</blockquote></div></div>
it is the way tm does it. Can you paste the sip trace of such situation? It will help to troubleshoot.<br>
<br>
Cheers,<br>
Daniel<br><font color="#888888">
<br>
-- <br>
Daniel-Constantin Mierla<br>
<a href="http://www.asipto.com" target="_blank">http://www.asipto.com</a><br>
<br>
</font></blockquote></div><br>
</div></div></blockquote></div><br>
</div></div></blockquote></div><br>