[Kamailio-Devel] Strange issue in OpenSER 1.3 / TM and Timers - Help
Daniel-Constantin Mierla
miconda at gmail.com
Fri Jan 16 15:19:05 CET 2009
Hello Carsten,
can you send the sip trace with the log of such case?
Cheers,
Daniel
On 01/16/2009 03:28 PM, Carsten Bock wrote:
> Hi everyone,
>
> i have the following strange issue in OpenSER 1.3 (sorry, no chance to
> update this at the moment).
> I have a module, which creates it's own timer-process. The timer sends
> out "OPTION" requests to both callee and caller (the Contact of the
> INVITE and the "200 OK"). In case of a "408", the call is teared down by
> the dialog module.
>
> <code>
> // Parameters:
> str method = {"OPTIONS", "7"};
> str from = {"daemon at localhost", "16"};
> uri.s = "sip:498969300052 at 213.20.170.123:5060"
> uri.len = strlen(uri.s);
> outboundproxy.s = "sip:192.168.149.129:5060"
> outboundproxy.len = strlen(outboundproxy.s);
> // Send the request:
> tmb.t_request(&method, &uri, &uri, &from, NULL, NULL, &outboundproxy,
> options_callback, (void*)internal_id_of_call);
> </code>
>
> When i execute the code, i see the following lines of logging:
>
> For the caller:
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:t_uac: next_hop=<sip:192.168.149.129:5060>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:core:mk_proxy: doing DNS lookup...
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:dlg2hash: 2971
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:print_request_uri: sip:498969300052 at 213.20.170.123:5060
> => The retransmission timer is set to 0,5 seconds:
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:set_timer: relative timeout is 500000
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:insert_timer_unsafe: [4]: 0x77c96044 (500000)
> => The timeout-timer is set to 30 seconds:
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:set_timer: relative timeout is 30
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:insert_timer_unsafe: [0]: 0x77c96060 (270210)
>
> The same for the callee:
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:t_uac: next_hop=<sip:192.168.149.129:5060>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:core:mk_proxy: doing DNS lookup...
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:dlg2hash: 2972
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:print_request_uri: sip:498969300082 at 213.20.170.125:5060
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:set_timer: relative timeout is 500000
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:insert_timer_unsafe: [4]: 0x77cc1c5c (500000)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:set_timer: relative timeout is 30
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13925]: DBG:tm:insert_timer_unsafe: [0]: 0x77cc1c78 (270210)
>
> The the callee replies with a "200 OK":
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_msg: SIP Reply (status):
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_msg: version: <SIP/2.0>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_msg: status: <200>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_msg: reason: <OK>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_headers: flags=2
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKc9b.e516c8a5.0>; state=16
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_via: end of header reached, state=5
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_headers: via found, flags=2
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_headers: this is the first via
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:receive_msg: After parse_msg...
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:forward_reply: found module tm, passing reply to it
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:t_check: start=0xffffffff
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_headers: flags=22
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_to: end of header reached, state=10
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:parse_to: display={}, ruri={sip:498969300082 at 213.20.170.125:5060}
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:498969300082 at 213.20.170.125:5060]
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:get_hdr_field: to body [<sip:498969300082 at 213.20.170.125:5060>^M ]
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:get_hdr_field: cseq <CSeq>: <10> <OPTIONS>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:t_reply_matching: hash 2972 label 1519149406 branch 0
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:t_reply_matching: reply matched (T=0x77cc1b10)!
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:t_check: end=0x77cc1b10
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:local_reply: branch=0, save=0, winner=0
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:local_reply: local transaction completed
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:run_trans_callbacks: trans=0x77cc1b10, callback type 256, id 0 entered
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: ERROR:mccs:options_callback: Options-Request finished with code 200 (912947442)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: ERROR:mccs:options_callback: OPTIONS sip:498969300082 at 213.20.170.125:5060 (0x77cc1b10)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:insert_timer_unsafe: [2]: 0x77cc1b58 (270666)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:destroy_avp_list: destroying list (nil)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13911]: DBG:core:receive_msg: cleaning up
> (Everything's fine)
>
> And then, strangely, for the caller a local generated 408 occurs. As you
> can see, the time is not really advanced (according to syslog it is
> still "12:27:24", like when the request was executed).
>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:utimer_routine: timer routine:4,tl=0x77c96044 next=0x77cc1c5c, timeout=500000
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x77c95ef8, OPTIONS s ... )
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:set_timer: relative timeout is 1000000
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:insert_timer_unsafe: [5]: 0x77c96044 (270663000000)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:retransmission_handler: retransmission_handler : done
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:utimer_routine: timer routine:4,tl=0x77cc1c5c next=(nil), timeout=500000
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:timer_routine: timer routine:0,tl=0x77c96060 next=0x77cc1c78, timeout=270210
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:final_response_handler: stop retr. and send CANCEL (0x77c95ef8)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:t_should_relay_response: T_code=0, new_code=408
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:t_pick_branch: picked branch 0, code 408
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:local_reply: branch=0, save=0, winner=0
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:local_reply: local transaction completed
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: DBG:tm:run_trans_callbacks: trans=0x77c95ef8, callback type 256, id 0 entered
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: ERROR:mccs:options_callback: Options-Request finished with code 408 (912947442)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13924]: ERROR:mccs:options_callback: OPTIONS sip:498969300052 at 213.20.170.123:5060 (0x77c95ef8)
>
> And shortly after, still "12:27:24", the "200 OK" for the caller
> arrives; but too late, the transaction is terminated and the callback is
> no longer executed...
>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_msg: SIP Reply (status):
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_msg: version: <SIP/2.0>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_msg: status: <200>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_msg: reason: <OK>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_headers: flags=2
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKb9b.5a7f883.0>; state=16
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_via: end of header reached, state=5
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_headers: via found, flags=2
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_headers: this is the first via
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:receive_msg: After parse_msg...
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:forward_reply: found module tm, passing reply to it
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:t_check: start=0xffffffff
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_headers: flags=22
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_to: end of header reached, state=10
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:parse_to: display={}, ruri={sip:498969300052 at 213.20.170.123:5060}
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:498969300052 at 213.20.170.123:5060]
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:get_hdr_field: to body [<sip:498969300052 at 213.20.170.123:5060>^M ]
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:get_hdr_field: cseq <CSeq>: <10> <OPTIONS>
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:t_reply_matching: hash 2971 label 59307941 branch 0
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:t_reply_matching: reply matched (T=0x77c95ef8)!
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:t_check: end=0x77c95ef8
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:reply_received: org. status uas=408, uac[0]=408 local=2 is_invite=0)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:t_should_relay_response: T_code=408, new_code=200
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:local_reply: branch=0, save=0, winner=-1
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:destroy_avp_list: destroying list (nil)
> Jan 12 12:27:24 SIP02 /usr/sbin/openser[13844]: DBG:core:receive_msg: cleaning up
>
> Does anyone have a clue, what is possibly going wrong here?
> Another strange issue is, that this error only occurs on our
> preproduction environment; not on our production, heavy-loaded system.
> However, the customer complains about it and i have to tell them why...
>
> Next week, we will activate extra_debug and tm_timer_debug in order to
> find out more; but maybe someone has a clue or an idea, what else could
> possibly go/be wrong?!? I am totally clueless at the moment...
>
>
> Thanks in advance,
> Carsten
>
>
>
>
> _______________________________________________
> Kamailio (OpenSER) - Devel mailing list
> Devel at lists.kamailio.org
> http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel
> http://lists.openser-project.org/cgi-bin/mailman/listinfo/devel
>
>
--
Daniel-Constantin Mierla
http://www.asipto.com
More information about the Devel
mailing list