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

[Carsten Bock]

Hi Henning, hi all,

this is odd. The timer is inserted from set_timer (modules/tm/timer.c)
like this:

insert_timer_unsafe( list, new_tl, 
timeout +
((timer_id2type[list_id]==UTIME_TYPE)?get_uticks():get_ticks()));

get_ticks() / get_uticks() from "../../timer.h" is called (both in 1.3
branch and in trunk). From that point of view, i think the "1841815"
value makes sense, since the server has been running for quite a while.
Or am i wrong here?
The curious thing here is, that the value of "1841815" is not created
from my module-code, but from the TM-API (t_request).
The "t_request"-call is created from a separate timer-process created by
my module (register_timer_process()); the timer triggered here is from
the "regular" timer-process (register_timer()).
Could this lead into trouble?

Thanks for your help,
Carsten


-------- Weitergeleitete Nachricht --------
Von: Henning Westerholt <henning.westerholt at 1und1.de>
An: devel at lists.openser.org
Kopie: Carsten Bock <lists at bock.info>
Betreff: Re: [OpenSER-Devel] TM: API: t_request: Timeouts too short?!?
Datum: Wed, 11 Jun 2008 17:42:51 +0200

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