[OpenSER-Devel] TM: API: t_request: Timeouts too short?!?

[Carsten Bock]

Hi,

i am investigating a much too short timeout when using the method
t_request from the TM-Module-API of OpenSER 1.3.2.
In my module i am creating a new request using t_request(...).
As a parameter for TM, i have set the fr_timer to 15 Seconds
("modparam("tm", "fr_timer", 15)"), so i would expect the request to
timeout after 15 seconds. According to the docs, the fr_timers are still
set to seconds, while the retransmission-timers are in milliseconds.
And according to the logs and to the source, this does happen correctly
(if i understand the TM-Timers correctly):

This is the debug-output when i execute t_request:
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]: DBG:tm:t_uac:
next_hop=<sip:192.168.149.129:5060> 
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]: DBG:core:mk_proxy: doing
DNS lookup... 
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]: DBG:tm:dlg2hash: 24340 
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]:
DBG:tm:print_request_uri: sip:4952411234567 at 11.22.33.44:5060 
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]: DBG:tm:set_timer:
relative timeout is 500000 
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]:
DBG:tm:insert_timer_unsafe: [4]: 0x77db3c3c (500000) 
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]: DBG:tm:set_timer:
relative timeout is 15 
Jun 10 17:45:55 SIP01 /usr/sbin/openser[31731]:
DBG:tm:insert_timer_unsafe: [0]: 0x77db3c58 (1841815) 

So i see, the retransmission timer is set to 500ms (T1) and the timeout
is set to 15 seconds (fr_timer=15).
Next fires now the retransmission-timer:

Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:utimer_routine:
timer routine:4,tl=0x77db5724 next=0x77db3c3c, timeout=500000 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:utimer_routine:
timer routine:4,tl=0x77db3c3c next=(nil), timeout=500000 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]:
DBG:tm:retransmission_handler: retransmission_handler : request
resending (t=0x77db3af0, OPTIONS s ... ) 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:set_timer:
relative timeout is 1000000 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]:
DBG:tm:insert_timer_unsafe: [5]: 0x77db3c3c (1841878000000) 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]:
DBG:tm:retransmission_handler: retransmission_handler : done 

and then the "normal" timer:

Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:timer_routine:
timer routine:0,tl=0x77db5740 next=0x77db3c58, timeout=1841815 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:timer_routine:
timer routine:0,tl=0x77db3c58 next=(nil), timeout=1841815 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]:
DBG:tm:final_response_handler: stop retr. and send CANCEL (0x77db3af0) 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]:
DBG:tm:t_should_relay_response: T_code=0, new_code=408 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:t_pick_branch:
picked branch 0, code 408 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:local_reply:
branch=0, save=0, winner=0 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: DBG:tm:local_reply:
local transaction completed 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]:
DBG:tm:run_trans_callbacks: trans=0x77db3af0, callback type 256, id 0
entered 
Jun 10 17:45:56 SIP01 /usr/sbin/openser[31730]: Options-Request finished
with code 408

which is definitely not after 15 seconds...
I would fix it myself, but i don't know where to find nor where to
look....

Any help welcome,
Carsten