[OpenSIPS-Users] Ack Ignored

Tim Burke timdburke at gmail.com
Tue Jul 17 20:10:22 CEST 2012 

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>
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}
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]
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>]
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 -> 10.14.84.183:5060
INVITE sip:2025551212 at 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>.
Call-ID: 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>.
P-Asserted-Identity: "9995551212" <sip:9995551212 at 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 -> 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>;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.
CSeq: 25848 INVITE.
User-Agent: NVP/4.0.1-CT79038 .
Content-Length: 0.
.

U 10.14.84.203:5060 -> 10.14.84.183:5060
ACK sip:2025551212 at 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.
To: <sip:2025551212 at 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 -> 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>;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.
CSeq: 25848 INVITE.
User-Agent: NVP/4.0.1-CT79038 .
Content-Length: 0.
.

U 10.10.24.36:5060 -> 10.14.84.203:5060
ACK sip:2025551212 at 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>;tag=aeac620b.
Call-ID: 335708310_82542752 at 10.10.24.36.
CSeq: 25848 ACK.
Max-Forwards: 70.
Content-Length: 0.
.

U 10.14.84.203:5060 -> 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>;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.
CSeq: 25848 INVITE.
User-Agent: NVP/4.0.1-CT79038 .
Content-Length: 0.
.

U 10.10.24.36:5060 -> 10.14.84.203:5060
ACK sip:2025551212 at 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>;tag=aeac620b.
Call-ID: 335708310_82542752 at 10.10.24.36.
CSeq: 25848 ACK.
Max-Forwards: 70.
Content-Length: 0.
.

U 10.14.84.203:5060 -> 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>;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.
CSeq: 25848 INVITE.
User-Agent: NVP/4.0.1-CT79038 .
Content-Length: 0.
.

U 10.10.24.36:5060 -> 10.14.84.203:5060
ACK sip:2025551212 at 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>;tag=aeac620b.
Call-ID: 335708310_82542752 at 10.10.24.36.
CSeq: 25848 ACK.
Max-Forwards: 70.
Content-Length: 0.
.

-- 
Thanks,
Tim

.

-- 
Thanks,
Tim
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20120717/4e5b2b9d/attachment-0001.htm>

More information about the Users mailing list