[OpenSIPS-Users] Avpops failure route
Bogdan-Andrei Iancu
bogdan at voice-system.ro
Tue Dec 8 22:40:42 CET 2009
Hi Andrew,
Andrew Pogrebennyk wrote:
> Bogdan-Andrei Iancu wrote:
>>> http://www.mail-archive.com/users@lists.opensips.org/msg07999.html
>>> but Bogdan didn't reply yet.
>>>
>> Sorry - missed that one :D....
>> It is interesting what you are saying, but I wouldn't say it is a bug
>> in OpenSIPS, but rather a bug in the GW - even if the first and the
>> second INVITE belong to the same call, they are different branches
>> (different VIA headers) and any SIP entity must accept (in
>> parallel,as individual attempts) multiple branches of the same call.
>
> Bogdan,
> You are correct. But the thing is that when fr_inv_timer hits,
> OpenSIPS (prematurely) sends INVITE on the next branch and only after
> that CANCELs the previous one.
Correct, and this is perfectly correct from SIP point of view. While
there are ongoing branches, a proxy can fire more new branches, even to
existing destinations.
> And if the gateway receives different branch on transaction to which
> no final reply has been sent yet - it can merge the requests.
May be merged if the destination is the same - to be honest I have to check.
> Let me know if you need the traces, but I've found this behavior to be
> consistent in the versions 1.3.2 - 1.5.3.
This behaviour is from the oldest version of SER :).
Even if you change (which makes no sense anyhow) the order (CANCEL and
later INVITE), there is no guarantee (at UDP level) that the order will
be preserved at transport level.
>
> Another thing I've found is that OpenSIPS resets the fr_timer in
> retransmission_handler() if no provisional response to INVITE has been
> received, or retransmission_handler() seems to affect the fr_timer
> somehow.
>
> Here we see that it forwards the INVITE and sets FR_TIMER as per script:
>
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]: Request leaving
> server, D-URI='<null>' - M=INVITE RURI=sip:400[...skipped...]
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:core:check_via_address: params a.b.c.d, a.b.c.d, 0
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: relative timeout is 500000
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=500000, final
> value=72500000
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:insert_timer_unsafe: [4]: 0x28701a18 (72500000)
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:_set_fr_retr: FR_TIMER = 20
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: relative timeout is 20
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=20, final value=92
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:insert_timer_unsafe: [0]: 0x28701a34 (92)
> ...
>
> Here it hits the retransmission_handler() - and this "relative timeout
> is 1000000" messages appears:
>
> Dec 6 22:22:12 sip2 /usr/local/sbin/opensips[16127]:
> DBG:core:receive_msg: cleaning up
> Dec 6 22:22:13 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:utimer_routine: timer routine:4,tl=0x28701a18 next=0x28701980,
> timeout=72500000
> Dec 6 22:22:13 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:retransmission_handler: retransmission_handler : request
> resending (t=0x287017b8, INVITE si ... )
> Dec 6 22:22:13 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: relative timeout is 1000000
> Dec 6 22:22:13 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=1000000, final
> value=73500000
> Dec 6 22:22:13 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:insert_timer_unsafe: [5]: 0x28701a18 (73500000)
> Dec 6 22:22:13 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:retransmission_handler: retransmission_handler : done
> Dec 6 22:22:13 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:utimer_routine: timer routine:4,tl=0x28701980 next=0x0,
> timeout=72500000
>
> I think this timeout somehow interferes with fr_timer because when
> fr_timer hits in 20 seconds, OpenSIPS _silently_ fails over to the
> next forwarding destination without sending CANCEL to _this_ branch.
> This occurs only when no provisional response has been got so I tend
> to think this is somehow related to the timeout thing.
This is correct - according to tRFC3261, if the reply was received from
a branch, there is no need to send CANCEL to it (if proxy wants to close
the branch).
Regards,
Bogdan
>
> I have added extra debug print to insert_timer_unsafe() like:
> LM_DBG("calling insert_timer_unsafe: timeout=%lld, final
> value=%lld\n",timeout,timeout + get_ticks());
>
> so you could see the sequence of timer updates:
>
> Dec 6 22:22:14 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=2000000, final
> value=75500000
> Dec 6 22:22:16 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=4000000, final
> value=79500000
> Dec 6 22:22:20 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=4000000, final
> value=83500000
> Dec 6 22:22:24 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=4000000, final
> value=87500000
> Dec 6 22:22:28 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=4000000, final
> value=91500000
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=4000000, final
> value=95500000
>
> Then OpenSIPS fails over to the next forwarding destination on locally
> generated 408 - but note there is no real "sending cancel..." message
> from cancel_branch() between
> "relay_reply: branch=1, save=1, relay=-1" and
> "final_response_handler: done":
>
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:timer_routine: timer routine:0,tl=0x28701a34 next=0x2870199c,
> timeout=92
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:final_response_handler: stop retr. and send CANCEL (0x287017b8)
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:t_should_relay_response: T_code=183, new_code=408
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:t_pick_branch: picked branch 1, code 408
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:is_3263_failure: dns-failover test: branch=1, last_recv=408,
> flags=1
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:t_should_relay_response: trying DNS-based failover
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:t_check_status: checked status is <408>
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:avpops:ops_pushto_avp: 1 avps were processed
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]: DBG:tm:t_check:
> start=0x287017b8
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]: DBG:tm:t_check:
> transaction already found!
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:pv_get_tm_reply_code: reply code is <408>
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]: forwarded on 408
> to: sip:400[...skipped...]@a.b.c.d
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]: 1 avps were
> removed
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:core:pv_get_dsturi: no destination URI
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]: Request leaving
> server, D-URI='<null>' - M=INVITE RURI=sip:400[...skipped...]
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:core:check_via_address: params a.b.c.d, a.b.c.d, 0
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: relative timeout is 500000
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=500000, final
> value=92500000
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:insert_timer_unsafe: [4]: 0x28701b2c (92500000)
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:_set_fr_retr: FR_TIMER = 20
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: relative timeout is 20
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:set_timer: calling insert_timer_unsafe: timeout=20, final
> value=112
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:insert_timer_unsafe: [0]: 0x28701b48 (112)
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:relay_reply: branch=1, save=1, relay=-1
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:final_response_handler: done
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16128]:
> DBG:tm:timer_routine: timer routine:0,tl=0x2870199c next=0x0, timeout=92
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16127]:
> DBG:core:parse_msg: SIP Reply (status):
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16127]:
> DBG:core:parse_msg: version: <SIP/2.0>
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16127]:
> DBG:core:parse_msg: status: <100>
> Dec 6 22:22:32 sip2 /usr/local/sbin/opensips[16127]:
> DBG:core:parse_msg: reason: <Trying>
>
> Thank you.
>
--
Bogdan-Andrei Iancu
www.voice-system.ro
More information about the Users
mailing list