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.