[OpenSIPS-Users] Avpops failure route
Andrew Pogrebennyk
andrew.pogrebennyk at portaone.com
Sun Dec 6 19:41:02 CET 2009
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. And if the gateway receives different branch
on transaction to which no final reply has been sent yet - it can merge
the requests. 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.
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.
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.
--
Sincerely,
Andrew Pogrebennyk
More information about the Users
mailing list