[Kamailio-Devel] [Kamailio-Users] STUN and TM

Fri Jan 30 13:00:28 CET 2009

Hi *,

okay, this is straight after t_relay:

[INVITE] BRANCH-ROUTE[2] New branch at
[sip:S001e310003ee at 41.2.192.203<sip%3AS001e310003ee at 41.2.192.203>]
(RURI=[sip:0870000005 at abcd.com <sip%3A0870000005 at abcd.com>]  F=[
sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
T=[sip:0870000005*47870 at abcd.com;user=phone]  IP=[192.168.2.174]
ID=[3c26a9340b31-2hp299m84e6x])

Jan 30 13:38:54 [19185] DBG:core:mk_proxy: doing DNS lookup...
Jan 30 13:38:54 [19185] DBG:core:check_via_address: params 192.168.2.174,
192.168.2.174, 0
Jan 30 13:38:54 [19185] DBG:tm:set_timer: relative timeout is 500000
Jan 30 13:38:54 [19185] DBG:tm:insert_timer_unsafe: [4]: fbda0a64 (11100000)
Jan 30 13:38:54 [19185] DBG:tm:set_timer: relative timeout is 30
Jan 30 13:38:54 [19185] DBG:tm:insert_timer_unsafe: [0]: fbda0a80 (40)

********------------------------------- ROUTE(1) DONE
-----------------------------------********

Jan 30 13:38:54 [19185] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jan 30 13:38:54 [19185] DBG:core:destroy_avp_list: destroying list 0
Jan 30 13:38:54 [19185] DBG:core:receive_msg: cleaning up
Jan 30 13:38:54 [19185] DBG:core:parse_msg: SIP Reply  (status):
Jan 30 13:38:54 [19185] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 30 13:38:54 [19185] DBG:core:parse_msg:  status:  <180>
Jan 30 13:38:54 [19185] DBG:core:parse_msg:  reason:  <Ringing>
Jan 30 13:38:54 [19185] DBG:core:parse_headers: flags=2
Jan 30 13:38:54 [19185] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK7215.525.0>; state=16
Jan 30 13:38:54 [19185] DBG:core:parse_via: end of header reached, state=5
Jan 30 13:38:54 [19185] DBG:core:parse_headers: via found, flags=2
Jan 30 13:38:54 [19185] DBG:core:parse_headers: this is the first via
Jan 30 13:38:54 [19185] DBG:core:receive_msg: After parse_msg...
statistics: [rcv_rpls] : [1]
Jan 30 13:38:54 [19185] DBG:core:forward_reply: found module tm, passing
reply to it
Jan 30 13:38:54 [19185] DBG:tm:t_check: start=ffffffff
Jan 30 13:38:54 [19185] DBG:core:parse_headers: flags=22
Jan 30 13:38:54 [19185] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK-ubsc5bh2l33v>; state=6
Jan 30 13:38:54 [19185] DBG:core:parse_via_param: found param type 235,
<rport> = <5060>; state=16
Jan 30 13:38:54 [19185] DBG:core:parse_via: end of header reached, state=5
Jan 30 13:38:54 [19185] DBG:core:parse_headers: via found, flags=22
Jan 30 13:38:54 [19185] DBG:core:parse_headers: parse_headers: this is the
second via
Jan 30 13:38:54 [19185] DBG:core:parse_to_param: tag=4z34qbhket
Jan 30 13:38:54 [19185] DBG:core:parse_to: end of header reached, state=29
Jan 30 13:38:54 [19185] DBG:core:parse_to: display={}, ruri={sip:0870000005*
47870 at abcd.com;user=phone}
Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: <To> [67];
uri=[sip:0870000005*47870 at abcd.com;user=phone]
Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: to body [<sip:0870000005*
47870 at abcd.com;user=phone>]
Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Jan 30 13:38:54 [19185] DBG:core:parse_headers: flags=8
Jan 30 13:38:54 [19185] DBG:tm:t_reply_matching: hash 20775 label 1317
branch 0
Jan 30 13:38:54 [19185] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Jan 30 13:38:54 [19185] DBG:tm:t_reply_matching: reply matched (T=fbda0910)!
Jan 30 13:38:54 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback
type 2, id 0 entered
Jan 30 13:38:54 [19185] DBG:core:parse_to_param: tag=u1iivbkwrw
Jan 30 13:38:54 [19185] DBG:core:parse_to: end of header reached, state=29
Jan 30 13:38:54 [19185] DBG:core:parse_to: display={"Bulk Create First Bulk
Create Last - 0870000002 at abcd.com"},
ruri={sip:0870000002 at abcd.com<sip%3A0870000002 at abcd.com>
}
DBG:uac::restore_from_reply: removing <From: "Bulk Create First Bulk Create
Last - 0870000002 at abcd.com" <sip:0870000002 at abcd.com<sip%3A0870000002 at abcd.com>
>;tag=u1iivbkwrw
>
DBG:uac::restore_from_reply: inserting <From: "Snom Demo 3" <
sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>>;tag=u1iivbkwrw
>
Jan 30 13:38:54 [19185] DBG:tm:t_check: end=fbda0910
Jan 30 13:38:54 [19185] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=0 is_invite=1)
statistics: [tm_rcv_rpls] : [1]
[INVITE] INCOMING-REPLY[2]
(RURI=[sip:0870000005 at abcd.com<sip%3A0870000005 at abcd.com>]
F=[sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
T=[sip:0870000005*47870 at abcd.com;user=phone]  IP=[192.168.2.174]
ID=[3c26a9340b31-2hp299m84e6x])

[INVITE] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
sip:0870000005 at abcd.com <sip%3A0870000005 at abcd.com>]  F=[
sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
T=[sip:0870000005*47870 at abcd.com;user=phone]  IP=[192.168.2.174]
ID=[3c26a9340b31-2hp299m84e6x])

Jan 30 13:38:54 [19185] DBG:tm:t_should_relay_response: T_code=0,
new_code=180
Jan 30 13:38:54 [19185] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 30 13:38:54 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback
type 16, id 1 entered
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: dlg_onreply called
Jan 30 13:38:54 [19185] DBG:core:build_res_buf_from_sip_res:  old size: 748,
new size: 642
Jan 30 13:38:54 [19185] DBG:core:build_res_buf_from_sip_res: copied size:
orig:385, new: 279, rest: 363 msg=
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.2.174:5060;branch=z9hG4bK-ubsc5bh2l33v;rport=5060
Record-Route:
<sip:192.168.5.46;lr=on;ftag=u1iivbkwrw;vsf=cGFzcxRndWR0YHBxfm9Xd3MPdXkwcHpuc2ljMnlzMQcfDA-->
From: "Snom Demo 3" <sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>
>;tag=u1iivbkwrw
To: <sip:0870000005*47870 at abcd.com;user=phone>;tag=4z34qbhket
Call-ID: 3c26a9340b31-2hp299m84e6x
CSeq: 1 INVITE
Contact: <sip:S001e310003ee at 192.168.1.100:5060>;flow-id=1
Require: 100rel
RSeq: 1
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK,
MESSAGE, INFO
Allow-Events: talk, hold, refer, call-info
Content-Length: 0

Jan 30 13:38:54 [19185] DBG:core:_shm_resize: resize(0) called
statistics: [tm_rld_rpls] : [1]
Jan 30 13:38:54 [19185] DBG:tm:relay_reply: sent buf=8328250: SIP/2.0 1...,
shmem=fbda3640: SIP/2.0 1
Jan 30 13:38:54 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback
type 128, id 1 entered
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: dlg_onreply called
Jan 30 13:38:54 [19185] DBG:dialog:next_state_dlg: dialog fbda17c0 changed
from state 1 to state 2, due event 2
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: new_state =
DLG_STATE_EARLY.
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: old_state!=DLG_STATE_EARLY.
Jan 30 13:38:54 [19185] INFO:dialog:dlg_onreply: Checking for RINGING [180]
PARAM-CODE [180].
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: freeing 1 rows
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: row[0]=8325770
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: 8325770=pkg_free() RES_ROWS
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: freeing 1 rows
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: row[0]=8325770
Jan 30 13:38:54 [19185] DBG:core:db_free_rows: 8325770=pkg_free() RES_ROWS

At this point the 180 ringings keep coming in from the far end device. Then
the 200OK comes in

[PRACK] INCOMING-REPLY[2] (RURI=[sip:S001e310003ee at 192.168.1.100:5060]  F=[
sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
T=[sip:0870000005*47870 at abcd.com;user=phone]  IP=[192.168.2.174]
ID=[3c26a9340b31-2hp299m84e6x])

[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
sip:S001e310003ee at 192.168.1.100:5060]
F=[sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>]
T=[sip:0870000005*47870 at abcd.com;user=phone]  IP=[192.168.2.174]
ID=[3c26a9340b31-2hp299m84e6x])

Jan 30 13:38:57 [19185] DBG:tm:t_should_relay_response: T_code=180,
new_code=200
Jan 30 13:38:57 [19185] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 30 13:38:57 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback
type 16, id 1 entered
Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: dlg_onreply called
Jan 30 13:38:57 [19185] DBG:core:build_res_buf_from_sip_res:  old size:
1090, new size: 984
Jan 30 13:38:57 [19185] DBG:core:build_res_buf_from_sip_res: copied size:
orig:380, new: 274, rest: 710 msg=
SIP/2.0 200 Ok
Via: SIP/2.0/UDP 192.168.2.174:5060;branch=z9hG4bK-ubsc5bh2l33v;rport=5060
Record-Route:
<sip:192.168.5.46;lr=on;ftag=u1iivbkwrw;vsf=cGFzcxRndWR0YHBxfm9Xd3MPdXkwcHpuc2ljMnlzMQcfDA-->
From: "Snom Demo 3" <sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>
>;tag=u1iivbkwrw
To: <sip:0870000005*47870 at abcd.com;user=phone>;tag=4z34qbhket
Call-ID: 3c26a9340b31-2hp299m84e6x
CSeq: 1 INVITE
Contact: <sip:S001e310003ee at 41.2.192.203:5060>;flow-id=1
Require: timer
Session-Expires: 3600;refresher=uas
User-Agent: snom360/7.1.30
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK,
MESSAGE, INFO
Allow-Events: talk, hold, refer, call-info
Supported: timer, replaces, callerid
Content-Type: application/sdp
Content-Length: 222

v=0
o=root 1584958272 1584958273 IN IP4 41.2.192.203
s=call
c=IN IP4 41.2.192.203
t=0 0
m=audio 60852 RTP/AVP 18 101
a=rtpmap:18 g729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

statistics: [tm_trans_2xx] : [1]
statistics: [tm_rld_rpls] : [1]
Jan 30 13:38:57 [19185] DBG:tm:update_totag_set: new totag
Jan 30 13:38:57 [19185] DBG:tm:insert_timer_unsafe: [2]: fbda0958 (17)
Jan 30 13:38:57 [19185] DBG:tm:relay_reply: sent buf=8328250: SIP/2.0 2...,
shmem=fbda71e0: SIP/2.0 2
Jan 30 13:38:57 [19185] DBG:tm:run_trans_callbacks: trans=fbda0910, callback
type 128, id 1 entered
Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: dlg_onreply called
Jan 30 13:38:57 [19185] DBG:dialog:next_state_dlg: dialog fbda17c0 changed
from state 2 to state 3, due event 3
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.
Jan 30 13:38:57 [19185] DBG:dialog:dlg_onreply: dialog fbda17c0 confirmed
Jan 30 13:38:57 [19185] DBG:core:parse_headers: flags=80
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-->
Jan 30 13:38:57 [19185] DBG:core:print_rr_body: skipping 1 route records
Jan 30 13:38:57 [19185] DBG:core:print_rr_body: out rr []
Jan 30 13:38:57 [19185] DBG:core:print_rr_body: we have 1 records
Jan 30 13:38:57 [19185] DBG:dialog:populate_leg_info: route_set , contact
sip:S001e310003ee at 41.2.192.203:5060, cseq 1 and bind_addr udp:
192.168.5.46:5060
Jan 30 13:38:57 [19185] DBG:dialog:update_dialog_dbinfo: sock_info is udp:
192.168.5.46:5060
Jan 30 13:38:57 [19185] DBG:dialog:insert_dlg_timer: Setting DLG timer to
43199
Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: Looking up PARTNER_ID from
avp sp_partner_id
Jan 30 13:38:57 [19185] INFO:dialog:dlg_onreply: pid_avp is NULL while
looking up sp_partner_id
Jan 30 13:38:57 [19185] DBG:core:db_free_rows: freeing 1 rows
Jan 30 13:38:57 [19185] DBG:core:db_free_rows: row[0]=83264d8
Jan 30 13:38:57 [19185] DBG:core:db_free_rows: 83264d8=pkg_free() RES_ROWS
Jan 30 13:38:57 [19185] DBG:core:db_free_rows: freeing 1 rows
Jan 30 13:38:57 [19185] DBG:core:db_free_rows: row[0]=83264d8
Jan 30 13:38:57 [19185] DBG:core:db_free_rows: 83264d8=pkg_free() RES_ROWS

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.

Any ideas / pointers!!??

Cheers
Jason

On Fri, Jan 30, 2009 at 1:40 PM, Jason Penton <jason.penton at smilecoms.com>wrote:

> Hi Daniel,
>
> Sorry - I hadnt set the debug high enough - will send another more detailed
> log soon!
>
> Cheers
> Jason
>
>
> On Fri, Jan 30, 2009 at 12:16 PM, Jason Penton <jason.penton at smilecoms.com
> > wrote:
>
>> Hi *,
>>
>> 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.
>>
>>
>>
>> ********------------------------------------- ROUTE(5)
>> -----------------------------------********
>>
>> ********------------------------------------ PROXY-AUTH
>> -----------------------------------********
>> <snip>
>> ********---------------------------------- PROXY-AUTH DONE
>> --------------------------------********
>>
>> ********---------------------------------- ROUTE(5) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(3)
>> -----------------------------------********
>>
>> ********--------------------------------- RECORD-ROUTE
>> ---------------------------------********
>> ********------------------------------- RECORD-ROUTE DONE
>> ------------------------------********
>>
>> ********------------------------------- ROUTE(3) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(4)
>> -----------------------------------********
>>
>> ********------------------------------------ INVITE
>> ------------------------------------********
>> Jan 30 11:31:34 [11258] INFO:dialog:dlg_created_cb: dialog created or
>> destroyed
>> Jan 30 11:31:34 [11258] INFO:dialog:dlg_created_cb: CALLID IS
>> [3c268b5bbf2d-mtnq42l2osup]------------------------------------------------------------------------------------------------------
>> ********--------------------------------- INVITE DONE
>> ----------------------------------********
>>
>> ********------------------------------- ROUTE(4) DONE
>> --------------------------------********
>>
>>
>> ********------------------------------------- ROUTE(6)
>> --------------------------------------------********
>>
>> ********-------------------------------------- USRLOC
>> ----------------------------------------------********
>> <snip>
>> ********-------------------------------------- USRLOC DONE
>> -----------------------------------------********
>>
>> ********------------------------------------ ROUTE(6) DONE
>> ---------------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(1)
>> ------------------------------------********
>>
>> ********--------------------------------- INVITE
>> ---------------------------------********
>> ********---------------------------------- T_RELAY
>> -------------------------------------********
>> [INVITE] BRANCH-ROUTE[2] New branch at [sip:S001e310003ee at 41.2.192.203<sip%3AS001e310003ee at 41.2.192.203>]
>> (RURI=[sip:0870000005 at abcd.com <sip%3A0870000005 at abcd.com>]  F=[
>> sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>>
>> ********------------------------------- ROUTE(1) DONE
>> -----------------------------------********
>> [INVITE] INCOMING-REPLY[2] (RURI=[sip:0870000005 at abcd.com<sip%3A0870000005 at abcd.com>]
>> F=[sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> [INVITE] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
>> sip:0870000005 at abcd.com <sip%3A0870000005 at abcd.com>]  F=[
>> sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> statistics: [tm_rld_rpls] : [1]
>> Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: new_state =
>> DLG_STATE_EARLY.
>> Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply:
>> old_state!=DLG_STATE_EARLY.
>> Jan 30 11:31:34 [11258] INFO:dialog:dlg_onreply: Checking for RINGING
>> [180] PARAM-CODE [180].
>> <snip>
>> ********---------------------------------- ROUTE(2)
>> -----------------------------------********
>>
>> ********------------------------------------ TO-TAG
>> -------------------------------------********
>> ********---------------------------------- LOOSE-ROUTE
>> ---------------------------------********
>> ********---------------------------------- TO-TAG DONE
>> ----------------------------------********
>>
>> ********-------------------------------- ROUTE(2) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(1)
>> ------------------------------------********
>>
>> ********---------------------------------- T_RELAY
>> -------------------------------------********
>> ********------------------------------- ROUTE(1) DONE
>> -----------------------------------********
>>
>> [PRACK] INCOMING-REPLY[2] (RURI=[sip:S001e310003ee at 192.168.1.100:5060]
>> F=[sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> [PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee at 192.168.1.100:5060]  F=[sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> Jan 30 11:31:35 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> statistics: [tm_rld_rpls] : [1]
>> Jan 30 11:31:35 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> Jan 30 11:31:35 [11258] INFO:dialog:dlg_onreply: new_state =
>> DLG_STATE_EARLY.
>> statistics: [rcv_reqs] : [1]
>> ********---------------------------------- ROUTE(2)
>> -----------------------------------********
>>
>> ********------------------------------------ TO-TAG
>> -------------------------------------********
>> ********---------------------------------- LOOSE-ROUTE
>> ---------------------------------********
>> ********---------------------------------- TO-TAG DONE
>> ----------------------------------********
>>
>> ********-------------------------------- ROUTE(2) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(1)
>> ------------------------------------********
>>
>> ********---------------------------------- T_RELAY
>> -------------------------------------********
>> [PRACK] INCOMING-REPLY[2] (RURI=[sip:S001e310003ee at 192.168.1.100:5060]
>> F=[sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> [PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee at 192.168.1.100:5060]  F=[sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> Jan 30 11:31:36 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> statistics: [tm_rld_rpls] : [1]
>> Jan 30 11:31:36 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> Jan 30 11:31:36 [11258] INFO:dialog:dlg_onreply: new_state =
>> DLG_STATE_EARLY.
>> statistics: [rcv_reqs] : [1]
>> ********---------------------------------- ROUTE(2)
>> -----------------------------------********
>>
>> ********------------------------------------ TO-TAG
>> -------------------------------------********
>> ********---------------------------------- LOOSE-ROUTE
>> ---------------------------------********
>> ********---------------------------------- TO-TAG DONE
>> ----------------------------------********
>>
>> ********-------------------------------- ROUTE(2) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(1)
>> ------------------------------------********
>>
>> ********---------------------------------- T_RELAY
>> -------------------------------------********
>> [PRACK] INCOMING-REPLY[2] (RURI=[sip:S001e310003ee at 192.168.1.100:5060]
>> F=[sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> [PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee at 192.168.1.100:5060]  F=[sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> Jan 30 11:31:38 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> statistics: [tm_rld_rpls] : [1]
>> Jan 30 11:31:38 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> Jan 30 11:31:38 [11258] INFO:dialog:dlg_onreply: new_state =
>> DLG_STATE_EARLY.
>> statistics: [rcv_reqs] : [1]
>> ********---------------------------------- ROUTE(2)
>> -----------------------------------********
>>
>> ********------------------------------------ TO-TAG
>> -------------------------------------********
>> ********---------------------------------- LOOSE-ROUTE
>> ---------------------------------********
>> ********---------------------------------- TO-TAG DONE
>> ----------------------------------********
>>
>> ********-------------------------------- ROUTE(2) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(1)
>> ------------------------------------********
>>
>> ********---------------------------------- T_RELAY
>> -------------------------------------********
>> [PRACK] INCOMING-REPLY[2] (RURI=[sip:S001e310003ee at 192.168.1.100:5060]
>> F=[sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> [PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee at 192.168.1.100:5060]  F=[sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> statistics: [tm_rld_rpls] : [1]
>> Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: new_state =
>> DLG_STATE_EARLY.
>> statistics: [rcv_reqs] : [1]
>> *******---------------------------------- ROUTE(2)
>> -----------------------------------********
>>
>> ********------------------------------------ TO-TAG
>> -------------------------------------********
>> ********---------------------------------- LOOSE-ROUTE
>> ---------------------------------********
>> ********---------------------------------- TO-TAG DONE
>> ----------------------------------********
>>
>> ********-------------------------------- ROUTE(2) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(1)
>> ------------------------------------********
>>
>> ********---------------------------------- T_RELAY
>> -------------------------------------********
>> [PRACK] INCOMING-REPLY[2] (RURI=[sip:S001e310003ee at 192.168.1.100:5060]
>> F=[sip:S000413292efd at abcd.com <sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> [PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee at 192.168.1.100:5060]  F=[sip:S000413292efd at abcd.com<sip%3AS000413292efd at abcd.com>]
>> T=[sip:0870000005*47942 at abcd.com;user=phone]  IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
>>
>> Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> statistics: [tm_trans_2xx] : [1]
>> statistics: [tm_rld_rpls] : [1]
>> Jan 30 11:31:42 [11258] INFO:dialog:dlg_onreply: dlg_onreply called
>> 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.
>> Jan 30 11:31:42 [11258] INFO:dialog:dlg_update_cb:
>> ######################dialog updated##############################
>> Jan 30 11:31:42 [11258] INFO:dialog:dlg_update_cb: Confirmed DID fbda14b0
>> session and source ip is [sip:S000413292efd at 192.168.2.174:5060] and dst
>> ip is [sip:S001e310003ee at 41.2.192.203:5060] and callid is
>> [3c268b5bbf2d-mtnq42l2osup]
>> *******---------------------------------- ROUTE(2)
>> -----------------------------------********
>>
>> ********------------------------------------ TO-TAG
>> -------------------------------------********
>> ********---------------------------------- LOOSE-ROUTE
>> ---------------------------------********
>> ********---------------------------------- TO-TAG DONE
>> ----------------------------------********
>>
>> ********-------------------------------- ROUTE(2) DONE
>> --------------------------------********
>>
>>
>> ********---------------------------------- ROUTE(1)
>> ------------------------------------********
>>
>> ********---------------------------------- T_RELAY
>> -------------------------------------********
>> ********------------------------------- ROUTE(1) DONE
>> -----------------------------------********
>>
>>
>>
>>>
>>> On 01/30/2009 09:00 AM, Jason Penton wrote:
>>>
>>>> Hi *,
>>>>
>>>> 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.
>>>>
>>>> Any ideas.
>>>>
>>>> Perhaps an explanation on how the tm module does transaction manager.
>>>>
>>>> RFC3261 states that transaction matching is done based on the via branch
>>>> parameter.
>>>>
>>> it is the way tm does it. Can you paste the sip trace of such situation?
>>> It will help to troubleshoot.
>>>
>>> Cheers,
>>> Daniel
>>>
>>> --
>>> Daniel-Constantin Mierla
>>> http://www.asipto.com
>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kamailio.org/pipermail/devel/attachments/20090130/f9744071/attachment-0001.htm 