[SR-Users] Howto timeout INVITEs over TCP to something < 30s?

[Daniel Tryba]

On Mon, Aug 22, 2016 at 12:30:18PM +0200, Daniel Tryba wrote:
> > OK. I will have to look at the source code?
> >
> > Btw, did you try with longer timeout? Still the same? If you change the
> > modparam for the timeout, is it used? These will help to narrow down of
> > t_set_fr() has no effect here, but only the modparam...
>
> 31s or 40s are indeed 31 or 40 seconds timeouts with the default
> ft_timer of 30000. Setting fr_timer to 20000 and a t_set_fr<20000 over
> tcp is maxed to 20000.

I have been trying to figure this out, but I'm not getting anywhere.

Incoming INVITE. Do some lookup magic, t_set_fr(10000).
Relay the INVITE, t_newtran is called. Debug output of first block below
is al in the same second.

DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg id=32 , global msg id=32 , T on entrance=(nil)
DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request: start searching: hash=9972, isACK=0
DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261 transaction matching failed
DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 1, id 0 entered
DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 1, id 0 entered
DEBUG: tm [t_funcs.c:321]: t_relay_to(): SER: new INVITE
DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=32 global id=32 T start=0x7f3288e078a0
DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=32 global id=32 T start=0x7f3288e078a0
DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=32 global id=32 T start=0x7f3288e078a0
DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=32 global id=32 T start=0x7f3288e078a0
DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f3288e078a0)!
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 2, id 0 entered
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 2, id 0 entered
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 2, id 0 entered
DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7f3288e078a0
DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f3288e078a0)!
DEBUG: tm [t_lookup.c:975]: t_reply_matching(): reply in callbacks already done (T=0x7f3288e078a0)!
DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7f3288e078a0
DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T start=0x7f3288e078a0
DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f3288e078a0)!
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 2, id 0 entered
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 2, id 0 entered
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 2, id 0 entered
DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T end=0x7f3288e078a0
DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f3288e078a0)!
DEBUG: tm [t_lookup.c:975]: t_reply_matching(): reply in callbacks already done (T=0x7f3288e078a0)!
DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T end=0x7f3288e078a0
DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T start=0x7f3288e078a0
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 32, id 0 entered
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 1048576, id 0 entered
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 512, id 0 entered


20s later the interal 408 is triggered:


DEBUG: tm [timer.c:534]: retr_buf_handler(): tm: timer retr_buf_handler @633715161 (0x7f3288e07b48 -> 0x7f3288e07b28 -> 0x7f3288e078a0)
DEBUG: tm [t_reply.c:1233]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=408
DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f3288e078a0, callback type 128, id 0 entered

And callforward route is triggered from here.