[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