[OpenSIPS-Users] treply in failure route causes retransmissions
Bogdan-Andrei Iancu
bogdan at voice-system.ro
Tue Apr 13 19:12:30 CEST 2010
Hi Brett,
could you post the logs (even privately) of the entire call ?
Regards,
Bogdan
Brett Nemeroff wrote:
> Bogdan,
> I didn't see anything odd about the ACK.. The RURI in it matched the
> original RURI from the INVITE...
>
> U 5.6.7.8:5060 -> 10.249.126.19:5060
> INVITE sip:74211234 at sip.mydomain.com SIP/2.0.
> Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK70c91e1d;rport.
> From: "15125551212" <sip:15125551212 at 5.6.7.8>;tag=as2c0ca056.
> To: <sip:74211234 at sip.mydomain.com>.
> Contact: <sip:15125551212 at 5.6.7.8>.
> Call-ID: 3e03fbce60ffb90b35030aeb73eb88a5 at 5.6.7.8.
> CSeq: 102 INVITE.
> User-Agent: Asterisk PBX.
> Max-Forwards: 70.
> Remote-Party-ID: "15125551212" <sip:15125551212 at 5.6.7.8>;privacy=off;screen=no.
> Date: Tue, 13 Apr 2010 13:08:25 GMT.
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO.
> Supported: replaces.
> Content-Type: application/sdp.
> Content-Length: 236.
>
>
> U 10.249.126.19:5060 -> 5.6.7.8:5060
> SIP/2.0 503 Cannot route.
> Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK70c91e1d;rport=5060.
> From: "15125551212" <sip:15125551212 at 5.6.7.8>;tag=as2c0ca056.
> To: <sip:74211234 at sip.mydomain.com>;tag=155c340f586c28d0300cf5a6ccf90d99-c2f7.
> Call-ID: 3e03fbce60ffb90b35030aeb73eb88a5 at 5.6.7.8.
> CSeq: 102 INVITE.
> Server: OpenSIPS (1.6.2-notls (i386/linux)).
> Content-Length: 0.
> .
>
>
> U 5.6.7.8:5060 -> 10.249.126.19:5060
> ACK sip:74211234 at sip.mydomain.com SIP/2.0.
> Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK70c91e1d;rport.
> From: "15125551212" <sip:15125551212 at 5.6.7.8>;tag=as2c0ca056.
> To: <sip:74211234 at sip.mydomain.com>;tag=155c340f586c28d0300cf5a6ccf90d99-c2f7.
> Contact: <sip:15125551212 at 5.6.7.8>.
> Call-ID: 3e03fbce60ffb90b35030aeb73eb88a5 at 5.6.7.8.
> CSeq: 102 ACK.
> User-Agent: Asterisk PBX.
> Max-Forwards: 70.
> Remote-Party-ID: "15125551212" <sip:15125551212 at 5.6.7.8>;privacy=off;screen=no.
> Content-Length: 0.
>
> ..
>
>
> >From what I understand from the syslog, it appears that the ACK does
> match a transaction. but it still performs the retrans.. I hope this
> is the right segment to be useful...
> ...
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:tm:t_lookup_request: start searching: hash=18475, isACK=1
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:tm:matching_3261: RFC3261 transaction matched, tid=579b7283
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:tm:t_lookup_request: REF_UNSAFE: after is 2
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:tm:t_lookup_request: transaction found (T=0xb60be734)
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:tm:cleanup_uac_timers: RETR/FR timers reset
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:tm:insert_timer_unsafe: [2]: 0xb60be77c (31591)
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:tm:t_unref: UNREF_UNSAFE: after is 1
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:core:destroy_avp_list: destroying list (nil)
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]:
> DBG:core:receive_msg: cleaning up
> Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8178]:
> DBG:tm:_reply_light: finished
> …
> Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:utimer_routine: timer routine:4,tl=0xb60be880 next=0xb60be7fc,
> timeout=31572400000
> Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:utimer_routine: timer routine:4,tl=0xb60be7fc next=(nil),
> timeout=31572400000
> Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:retransmission_handler: retransmission_handler : reply
> resending (t=0xb60be734, SIP/2.0 5 ... )
> Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:t_retransmit_reply: buf=0x78e040: SIP/2.0 5...,
> shmem=0xb60bc67c: SIP/2.0 5
> Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:set_timer: relative timeout is 1000000
> Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:insert_timer_unsafe: [5]: 0xb60be7fc (31573400000)
> Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:retransmission_handler: retransmission_handler : done
> Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:utimer_routine: timer routine:5,tl=0xb60be7fc next=(nil),
> timeout=31573400000
> Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:retransmission_handler: retransmission_handler : reply
> resending (t=0xb60be734, SIP/2.0 5 ... )
> Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:t_retransmit_reply: buf=0x78e040: SIP/2.0 5...,
> shmem=0xb60bc67c: SIP/2.0 5
> Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:set_timer: relative timeout is 2000000
> Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:insert_timer_unsafe: [6]: 0xb60be7fc (31575400000)
> Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:retransmission_handler: retransmission_handler : done
> Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:utimer_routine: timer routine:6,tl=0xb60be7fc next=(nil),
> timeout=31575400000
> Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:retransmission_handler: retransmission_handler : reply
> resending (t=0xb60be734, SIP/2.0 5 ... )
> Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:t_retransmit_reply: buf=0x78e040: SIP/2.0 5...,
> shmem=0xb60bc67c: SIP/2.0 5
> Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:set_timer: relative timeout is 4000000
> Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:insert_timer_unsafe: [7]: 0xb60be7fc (31579400000)
> Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:retransmission_handler: retransmission_handler : done
> Apr 13 13:17:00 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:timer_routine: timer routine:0,tl=0xb60be818 next=(nil),
> timeout=31576
> Apr 13 13:17:01 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]:
> DBG:tm:timer_routine: timer routine:1,tl=0xb60be89c next=(nil),
> timeout=31577
>
> Thanks for your help!
> -Brett
>
>
> On Tue, Apr 13, 2010 at 5:24 AM, Bogdan-Andrei Iancu
> <bogdan at voice-system.ro> wrote:
>
>> Hi Brett,
>>
>> in the failing case, maybe the received ACK does not match the
>> transaction, so opensips keeps retransmitting - could you post the
>> received INVITE, the sent 503 and the received ACK ?
>>
>> Regards,
>> Bogdan
>>
>> Brett Nemeroff wrote:
>>
>>> Hello all,
>>> I'm pretty sure I'm missing something obvious here..
>>>
>>> After hitting a failure route, I'm seeing retransmissions with a
>>> t_reply. If I clear out the failure_route, opensips generates a 500,
>>> which is sent out and it's happy with. Almost like the 500 (which is
>>> internally generated) is sent statelessly, from a failure route?
>>> Opensips sits on a server with a private IP and is NATed. I've set the
>>> outside IP address in the advertised_address config param.
>>>
>>>
>>> failure_route[1] {
>>> xlog("L_INFO","In failure route");
>>> }
>>>
>>>
>>> (opensips at 10.249.126.19)
>>> 0.052840 10.249.126.19 -> 1.2.3.4 SIP/SDP Request: INVITE
>>> sip:74211234 at 1.2.3.4, with session description
>>> 0.061683 1.2.3.4 -> 10.249.126.19 SIP Status: 100 Trying
>>> 0.062550 1.2.3.4 -> 10.249.126.19 SIP Status: 503 Service Unavailable
>>> 0.062637 10.249.126.19 -> 1.2.3.4 SIP Request: ACK sip:74211234 at 1.2.3.4
>>> 0.062724 10.249.126.19 -> 5.6.7.8 SIP Status: 500 Service Unavailable
>>> 0.100239 5.6.7.8 -> 10.249.126.19 SIP Request: ACK sip:1234 at sip.mydomain.com
>>> (No retransmissions.. everyone happy)
>>>
>>>
>>> ---------------
>>>
>>> Now if I put a t_reply in there..
>>> failure_route[1] {
>>> xlog("L_INFO","In failure route");
>>> t_reply("503","Cannot route");
>>> exit;
>>> }
>>>
>>>
>>> 0.042059 10.249.126.19 -> 1.2.3.4 SIP/SDP Request: INVITE
>>> sip:74211234 at 1.2.3.4, with session description
>>> 0.051466 1.2.3.4 -> 10.249.126.19 SIP Status: 100 Trying
>>> 0.051919 1.2.3.4 -> 10.249.126.19 SIP Status: 503 Service Unavailable
>>> 0.052222 10.249.126.19 -> 1.2.3.4 SIP Request: ACK sip:742112324 at 1.2.3.4
>>> 0.052436 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route
>>> 0.089601 5.6.7.8 -> 10.249.126.19 SIP Request: ACK sip:1234 at sip.mydomain.com
>>> 1.030506 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route
>>> 2.030507 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route
>>> 4.030615 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route
>>> (not happy)
>>>
>>>
>>> Any ideas??
>>> Thanks!
>>> -Brett
>>>
>>>
More information about the Users
mailing list