[Kamailio-Devel] Strange issue in OpenSER 1.3 / TM and Timers - Help

Fri Jan 16 14:28:24 CET 2009

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