[OpenSIPS-Users] Ack Ignored

Bogdan-Andrei Iancu bogdan at opensips.org
Mon Jul 23 10:26:20 CEST 2012 

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
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20120723/5bc0df90/attachment-0001.htm>

More information about the Users mailing list