[OpenSIPS-Users] Ack Ignored
Bogdan-Andrei Iancu
bogdan at opensips.org
Wed Jul 25 06:51:20 CEST 2012
Hi Tim,
That ACK is an hop-by-hop ACK (ACK to a negative reply) and it should be
absorbed (with timer cancellation) by TM module when hitting any TM
function (t_newtran, t_check_trans, t_relay, etc). Usually you do this
in the main route (the request route) (has nothing to do with the
failure route) - check the default cfg script to see how those ACKs are
handled : follow the path in the script : has_totag() => no
loose_route() => ACK => t_check_trans()
Regards,
Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
http://www.opensips-solutions.com
On 07/24/2012 09:30 PM, Tim Burke wrote:
> Thanks Bogdan,
> I'll grab some logs but in the meantime I was able to have opensips
> detect the ACK by adding a call to t_relay() at the bottom of my
> route() function. From that it seems like I have to send the ACK to
> the tm module so that tm can clear the timers where it's waiting for
> ACK in response to 500 being sent.
>
> I understand the conversion of the 503 to 500 but I didn't understand
> why osips doesn't process the ACK in order to clear the "waiting for
> ACK" timers.
>
> On Mon, Jul 23, 2012 at 4:26 AM, Bogdan-Andrei Iancu
> <bogdan at opensips.org <mailto:bogdan at opensips.org>> wrote:
>
> Hi Tim,
>
> Could you send my (off list) the logs (in debug 4) covering the
> entire call (invite to last 500 retransmission) ?
>
> Regarding the 500 - by default, in failure route, the received
> reply is forwarded to caller - in your case, the received 503 is
> fwded as 500 back (there is a translation from 503 to 500,
> according to RFC)
>
> Regards,
>
> Bogdan-Andrei Iancu
> OpenSIPS Founder and Developer
> http://www.opensips-solutions.com
>
>
> On 07/17/2012 09:10 PM, Tim Burke wrote:
>> Sorry about the large posting but I wanted to included as many
>> details a possible. I'm trying to figure out why opensips seems
>> to be ignoring ACK received from far end when a 500 is sent.
>>
>> This code in play is in my failure_route where I'm reacting to
>> 503 received from my internal media gateway. It seems like osips
>> is sending a 500 on my behalf even if I just exit the
>> failure_route. The far end relies to the 500 with an ACK but
>> osips seems to now like it and repeats the process for a total of
>> 3 500 messages sent out. I'm on osips 1.6.2 and have the
>> following in the log. I'm not sure of the significance of: "Jul
>> 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:sl:sl_filter_ACK: to late to be a local ACK!"
>>
>> sip proxy: 10.14.84.203
>> MG: 10.14.84.183
>> External system: 10.10.24.36
>>
>> I'm wondering:
>> * Can/should I prevent osips from sending the 500 on my behalf?
>> * Why are the ACKs ignored by osips?
>>
>> failure_route[11] {
>>
>> if (t_was_cancelled()) {
>> exit;
>> }
>>
>> if ( ($T_reply_code=="604") || ($T_reply_code=="404") ||
>> ($T_reply_code=="486") ) {
>> xlog("L_WARN", "Received $T_reply_code from
>> NVP:$avp(i:271) for callid [$ci] - DID is most likely not
>> configured");
>> route(5);
>> }
>>
>> xlog("L_WARN","Route failed - $avp(i:271) $avp(i:272)
>> $avp(i:273)");
>> xlog("Details - (mf [$mF] ruri [$ru] callid [$ci])");
>>
>> # ds_next_dst - will do the routing.
>> if (ds_next_dst()){
>> xlog("L_INFO","First Route Failed : Routing to
>> $avp(i:271) $avp(i:272) $avp(i:273)");
>> xlog("Details - (mf [$mF] ruri [$ru] callid [$ci])");
>> xlog("L_INFO"," ");
>>
>> # relay the call to the new destination
>> t_on_failure("11");
>> t_relay();
>> }
>> else {
>> xlog("L_CRIT","ds_dispatcher Sorry none of our
>> gateways are available to take your call.");
>> exit;
>> }
>> }
>>
>>
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:t_retransmit_reply: buf=0x2af449a51620: SIP/2.0 5...,
>> shmem=0x2af44b3a0fa8: SIP/2.0 5
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:set_timer: relative timeout is 2000000
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:insert_timer_unsafe: [6]: 0x2af44b39a2f8 (14600000)
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:retransmission_handler: retransmission_handler : done
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_msg: SIP Request:
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_msg: method: <ACK>
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_msg: uri: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_msg: version: <SIP/2.0>
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_headers: flags=2
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_via_param: found param type 232, <branch> =
>> <z9hG4bK02B027d670e963c415e>; state=16
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_via: end of header reached, state=5
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_headers: via found, flags=2
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_headers: this is the first via
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:receive_msg: After parse_msg...
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:receive_msg: preparing to run routing scripts...
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:sl:sl_filter_ACK: to late to be a local ACK!
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:comp_scriptvar: str 20 : true
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_headers: flags=100
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_to_param: tag=aeac620b
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_to: end of header reached, state=29
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:parse_to: display={},
>> ruri={sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>}
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:get_hdr_field: <To> [49];
>> uri=[sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>]
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:get_hdr_field: to body
>> [<sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>]
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:get_hdr_field: cseq <CSeq>: <25848> <ACK>
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:maxfwd:is_maxfwd_present: value = 70
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:destroy_avp_list: destroying list 0x2af44b39a010
>> Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
>> DBG:core:receive_msg: cleaning up
>> Jul 17 10:38:36 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:timer_routine: timer routine:0,tl=0x2af44b39a5d8
>> next=0x2af44b39a7b0, timeout=13
>> Jul 17 10:38:36 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:timer_routine: timer routine:0,tl=0x2af44b39a7b0
>> next=0x2af44b39a988, timeout=13
>> Jul 17 10:38:36 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:timer_routine: timer routine:0,tl=0x2af44b39a988
>> next=0x2af44b39a328, timeout=13
>> Jul 17 10:38:36 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:timer_routine: timer routine:0,tl=0x2af44b39a328
>> next=(nil), timeout=13
>> Jul 17 10:38:36 siphost /usr/sbin/opensips[27595]:
>> DBG:tm:insert_timer_unsafe: [2]: 0x2af44b39a230 (18)
>>
>>
>> U 10.14.84.203:5060 <http://10.14.84.203:5060> ->
>> 10.14.84.183:5060 <http://10.14.84.183:5060>
>> INVITE sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060> SIP/2.0.
>> Via: SIP/2.0/UDP 10.14.84.203;branch=z9hG4bK050f.4234dfd2.3.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 INVITE.
>> Max-Forwards: 13.
>> Allow: INVITE, ACK, CANCEL, BYE, REGISTER, REFER, INFO,
>> SUBSCRIBE, NOTIFY, PRACK, UPDATE, OPTIONS, MESSAGE, PUBLISH.
>> Accept: application/sdp, application/isup, application/dtmf,
>> application/dtmf-relay, multipart/mixed.
>> Contact: <sip:9995551212 at 10.10.24.36:5060
>> <http://sip:9995551212@10.10.24.36:5060>>.
>> P-Asserted-Identity: "9995551212"
>> <sip:9995551212 at 10.10.24.36:5060
>> <http://sip:9995551212@10.10.24.36:5060>>, "9995551212"
>> <tel:9995551212>.
>> Supported: timer, 100rel.
>> Session-Expires: 1800.
>> Min-SE: 90.
>> Content-Disposition: session; handling=required.
>> Content-Type: application/sdp.
>> Content-Length: 314.
>> .
>> v=0.
>> o=Sonus_UAC 11709 17649 IN IP4 10.10.24.36.
>> s=SIP Media Capabilities.
>> c=IN IP4 216.115.26.209.
>> t=0 0.
>> m=audio 11676 RTP/AVP 0 18 2 100.
>> a=rtpmap:0 PCMU/8000.
>> a=rtpmap:18 G729/8000.
>> a=fmtp:18 annexb=no.
>> a=rtpmap:2 G726-32/8000.
>> a=rtpmap:100 telephone-event/8000.
>> a=fmtp:100 0-15.
>> a=sendrecv.
>> a=maxptime:20.
>>
>>
>> U 10.14.84.183:5060 <http://10.14.84.183:5060> ->
>> 10.14.84.203:5060 <http://10.14.84.203:5060>
>> SIP/2.0 503 Service Unavailable.
>> Via: SIP/2.0/UDP 10.14.84.203;branch=z9hG4bK050f.4234dfd2.3.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 INVITE.
>> User-Agent: NVP/4.0.1-CT79038 .
>> Content-Length: 0.
>> .
>>
>> U 10.14.84.203:5060 <http://10.14.84.203:5060> ->
>> 10.14.84.183:5060 <http://10.14.84.183:5060>
>> ACK sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060> SIP/2.0.
>> Via: SIP/2.0/UDP 10.14.84.203;branch=z9hG4bK050f.4234dfd2.3.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> CSeq: 25848 ACK.
>> Max-Forwards: 70.
>> User-Agent: OpenSIPS (1.6.2-notls (x86_64/linux)).
>> Content-Length: 0.
>> .
>>
>> U 10.14.84.203:5060 <http://10.14.84.203:5060> -> external:5060
>> SIP/2.0 500 Service Unavailable.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 INVITE.
>> User-Agent: NVP/4.0.1-CT79038 .
>> Content-Length: 0.
>> .
>>
>> U 10.10.24.36:5060 <http://10.10.24.36:5060> -> 10.14.84.203:5060
>> <http://10.14.84.203:5060>
>> ACK sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060> SIP/2.0.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 ACK.
>> Max-Forwards: 70.
>> Content-Length: 0.
>> .
>>
>> U 10.14.84.203:5060 <http://10.14.84.203:5060> ->
>> 10.10.24.36:5060 <http://10.10.24.36:5060>
>> SIP/2.0 500 Service Unavailable.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 INVITE.
>> User-Agent: NVP/4.0.1-CT79038 .
>> Content-Length: 0.
>> .
>>
>> U 10.10.24.36:5060 <http://10.10.24.36:5060> -> 10.14.84.203:5060
>> <http://10.14.84.203:5060>
>> ACK sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060> SIP/2.0.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 ACK.
>> Max-Forwards: 70.
>> Content-Length: 0.
>> .
>>
>> U 10.14.84.203:5060 <http://10.14.84.203:5060> ->
>> 10.10.24.36:5060 <http://10.10.24.36:5060>
>> SIP/2.0 500 Service Unavailable.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 INVITE.
>> User-Agent: NVP/4.0.1-CT79038 .
>> Content-Length: 0.
>> .
>>
>> U 10.10.24.36:5060 <http://10.10.24.36:5060> -> 10.14.84.203:5060
>> <http://10.14.84.203:5060>
>> ACK sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060> SIP/2.0.
>> Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
>> From:
>> <sip:9995551212 at 10.10.24.36:5060;pstn-params=9084818088>;tag=gK0201303f.
>> To: <sip:2025551212 at 10.14.84.203:5060
>> <http://sip:2025551212@10.14.84.203:5060>>;tag=aeac620b.
>> Call-ID: 335708310_82542752 at 10.10.24.36
>> <mailto:335708310_82542752 at 10.10.24.36>.
>> CSeq: 25848 ACK.
>> Max-Forwards: 70.
>> Content-Length: 0.
>> .
>>
>> --
>> Thanks,
>> Tim
>>
>> .
>>
>> --
>> Thanks,
>> Tim
>>
>>
>>
>> _______________________________________________
>> Users mailing list
>> Users at lists.opensips.org <mailto:Users at lists.opensips.org>
>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
>
>
> --
> Thanks,
> Tim
>
> 978-267-1001
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20120725/07748861/attachment-0001.htm>
More information about the Users
mailing list