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

[Henning Westerholt]

On Wednesday 11 June 2008, Carsten Bock wrote:
> [..]
> And according to the logs and to the source, this does happen correctly
> (if i understand the TM-Timers correctly):

Hi Carsten,

> This is the debug-output when i execute t_request:
> [..]
> 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)
                                               ^^^^^^^

this looks strange. On trunk (for the normal tm timer) i get this:

Jun 11 17:21:46 ca ../openser[777]: DBG:tm:set_timer: relative timeout is 
500000
Jun 11 17:21:46 ca ../openser[777]: DBG:tm:insert_timer_unsafe: [4]: 
0xb5c6c42c (500000)
Jun 11 17:21:46 ca ../openser[777]: DBG:tm:set_timer: relative timeout is 15
Jun 11 17:21:46 ca ../openser[777]: DBG:tm:insert_timer_unsafe: [0]: 
0xb5c6c448 (15)
            ^^

> [..]
> 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 11 17:21:57 ca ../openser[785]: DBG:tm:insert_timer_unsafe: [7]: 
0xb5c6c42c (15500000)
Jun 11 17:21:57 ca ../openser[785]: DBG:tm:retransmission_handler: 
retransmission_handler : done
Jun 11 17:22:01 ca ../openser[785]: DBG:tm:timer_routine: timer 
routine:0,tl=0xb5c6c448 next=(nil), timeout=15
                                            ^^
Jun 11 17:22:01 ca ../openser[785]: DBG:tm:final_response_handler: stop retr. 
and send CANCEL (0xb5c6c2e0)
Jun 11 17:22:01 ca ../openser[785]: DBG:tm:t_should_relay_response: 
T_code=100, new_code=408
Jun 11 17:22:01 ca ../openser[785]: DBG:tm:t_pick_branch: picked branch 0, 
code 408

It seems that the timer is created with value around 1.8 seconds from your 
module code, and the core handle accordingly.

Cheers,

Henning