If an enduser INVITEted over TCP t_set_fr(t) with t < 30s have no effect, the INVITE will always timeout after 30s. What is controlling this 30s? The only default at 30s is the fr_timer, which should have no part in the timeout between an 1xx and a final answer for an INVITE.
On 18/08/16 10:40, Daniel Tryba wrote:
If an enduser INVITEted over TCP t_set_fr(t) with t < 30s have no effect, the INVITE will always timeout after 30s. What is controlling this 30s? The only default at 30s is the fr_timer, which should have no part in the timeout between an 1xx and a final answer for an INVITE.
Is this about ringing timout or the connection to user is no longer available?
Cheers, Daniel
On Fri, Aug 19, 2016 at 09:37:15AM +0200, Daniel-Constantin Mierla wrote:
If an enduser INVITEted over TCP t_set_fr(t) with t < 30s have no effect, the INVITE will always timeout after 30s. What is controlling this 30s? The only default at 30s is the fr_timer, which should have no part in the timeout between an 1xx and a final answer for an INVITE.
Is this about ringing timout or the connection to user is no longer available?
Ringing timeout, the task is to forward the call to an other destination (or voicemail).
On 19/08/16 13:07, Daniel Tryba wrote:
On Fri, Aug 19, 2016 at 09:37:15AM +0200, Daniel-Constantin Mierla wrote:
If an enduser INVITEted over TCP t_set_fr(t) with t < 30s have no effect, the INVITE will always timeout after 30s. What is controlling this 30s? The only default at 30s is the fr_timer, which should have no part in the timeout between an 1xx and a final answer for an INVITE.
Is this about ringing timout or the connection to user is no longer available?
Ringing timeout, the task is to forward the call to an other destination (or voicemail).
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...
Cheers, Daniel
On Mon, Aug 22, 2016 at 09:27:25AM +0200, Daniel-Constantin Mierla wrote:
Ringing timeout, the task is to forward the call to an other destination (or voicemail).
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.
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.
-
Daniel Tryba -
Daniel-Constantin Mierla