30 Jan
2009
30 Jan
'09
1 p.m.
Hi *,
okay, this is straight after t_relay:
[INVITE] BRANCH-ROUTE[2] New branch at
[sip:S001e310003ee@41.2.192.203<sip%3AS001e310003ee@41.2.192.203>]
(RURI=[sip:0870000005@abcd.com <sip%3A0870000005(a)abcd.com>] F=[
sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
T=[sip:0870000005*47870@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(a)abcd.com;user=phone}
Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: <To> [67];
uri=[sip:0870000005*47870@abcd.com;user=phone]
Jan 30 13:38:54 [19185] DBG:core:get_hdr_field: to body [<sip:0870000005*
47870(a)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(a)abcd.com"}uot;},
ruri={sip:0870000002@abcd.com<sip%3A0870000002@abcd.com
}
DBG:uac::restore_from_reply: removing <From: "Bulk Create First Bulk Create
Last - 0870000002(a)abcd.com"
<sip:0870000002@abcd.com<sip%3A0870000002@abcd.com
From: "Snom Demo 3"
<sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com From: "Snom Demo 3"
<sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com 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@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(a)smilecoms.com>wrote;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(a)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@41.2.192.203<sip%3AS001e310003ee@41.2.192.203>]
>> (RURI=[sip:0870000005@abcd.com <sip%3A0870000005(a)abcd.com>] F=[
>> sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@abcd.com;user=phone] IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
> >
>> ********------------------------------- ROUTE(1) DONE
>> -----------------------------------********
>> [INVITE] INCOMING-REPLY[2]
(RURI=[sip:0870000005@abcd.com<sip%3A0870000005@abcd.com>]
>> F=[sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@abcd.com;user=phone] IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
> >> [INVITE] INCOMING-REPLY[2]
DLG_TIMEOUT=[43199] (RURI=[
>> sip:0870000005@abcd.com <sip%3A0870000005(a)abcd.com>] F=[
>> sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@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@192.168.1.100:5060]
>> F=[sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@abcd.com;user=phone] IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
> >> [PRACK] INCOMING-REPLY[2]
DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee@192.168.1.100:5060]
F=[sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com>]
>> T=[sip:0870000005*47942@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@192.168.1.100:5060]
>> F=[sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@abcd.com;user=phone] IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
> >> [PRACK] INCOMING-REPLY[2]
DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee@192.168.1.100:5060]
F=[sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com>]
>> T=[sip:0870000005*47942@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@192.168.1.100:5060]
>> F=[sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@abcd.com;user=phone] IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
> >> [PRACK] INCOMING-REPLY[2]
DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee@192.168.1.100:5060]
F=[sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com>]
>> T=[sip:0870000005*47942@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@192.168.1.100:5060]
>> F=[sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@abcd.com;user=phone] IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
> >> [PRACK] INCOMING-REPLY[2]
DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee@192.168.1.100:5060]
F=[sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com>]
>> T=[sip:0870000005*47942@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@192.168.1.100:5060]
>> F=[sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
>> T=[sip:0870000005*47942@abcd.com;user=phone] IP=[192.168.2.174]
>> ID=[3c268b5bbf2d-mtnq42l2osup])
> >> [PRACK] INCOMING-REPLY[2]
DLG_TIMEOUT=[43199] (RURI=[
>> sip:S001e310003ee@192.168.1.100:5060]
F=[sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com>]
>> T=[sip:0870000005*47942@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@192.168.2.174:5060] and dst
>> ip is [sip:S001e310003ee@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
>> >> >
;tag=u1iivbkwrw
DBG:uac::restore_from_reply: inserting <From: "Snom Demo 3" <
sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)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@abcd.com<sip%3A0870000005@abcd.com>]
F=[sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
T=[sip:0870000005*47870@abcd.com;user=phone] IP=[192.168.2.174]
ID=[3c26a9340b31-2hp299m84e6x])
[INVITE] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
sip:0870000005@abcd.com <sip%3A0870000005(a)abcd.com>] F=[
sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
T=[sip:0870000005*47870@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--
;tag=u1iivbkwrw
To: <sip:0870000005*47870@abcd.com;user=phone>;tag=4z34qbhket
Call-ID: 3c26a9340b31-2hp299m84e6x
CSeq: 1 INVITE
Contact: <sip:S001e310003ee@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@192.168.1.100:5060] F=[
sip:S000413292efd@abcd.com <sip%3AS000413292efd(a)abcd.com>]
T=[sip:0870000005*47870@abcd.com;user=phone] IP=[192.168.2.174]
ID=[3c26a9340b31-2hp299m84e6x])
[PRACK] INCOMING-REPLY[2] DLG_TIMEOUT=[43199] (RURI=[
sip:S001e310003ee@192.168.1.100:5060]
F=[sip:S000413292efd@abcd.com<sip%3AS000413292efd@abcd.com>]
T=[sip:0870000005*47870@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--
;tag=u1iivbkwrw
To: <sip:0870000005*47870@abcd.com;user=phone>;tag=4z34qbhket
Call-ID: 3c26a9340b31-2hp299m84e6x
CSeq: 1 INVITE
Contact: <sip:S001e310003ee@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--