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 <[email protected] <mailto:[email protected]>> 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:[email protected]:5060
    <http://sip:[email protected]: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:[email protected]:5060
    <http://sip:[email protected]:5060>}
    Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
    DBG:core:get_hdr_field: <To> [49];
    uri=[sip:[email protected]:5060
    <http://sip:[email protected]:5060>]
    Jul 17 10:38:35 siphost /usr/sbin/opensips[27582]:
    DBG:core:get_hdr_field: to body
    [<sip:[email protected]:5060
    <http://sip:[email protected]: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:[email protected]:5060
    <http://sip:[email protected]: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:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    To: <sip:[email protected]:5060
    <http://sip:[email protected]:5060>>.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    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:[email protected]:5060
    <http://sip:[email protected]:5060>>.
    P-Asserted-Identity: "9995551212"
    <sip:[email protected]:5060
    <http://sip:[email protected]: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:[email protected]:5060
    <http://sip:[email protected]:5060>>;tag=aeac620b.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    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:[email protected]:5060
    <http://sip:[email protected]:5060> SIP/2.0.
    Via: SIP/2.0/UDP 10.14.84.203;branch=z9hG4bK050f.4234dfd2.3.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    To: <sip:[email protected]:5060
    <http://sip:[email protected]: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:[email protected]:5060
    <http://sip:[email protected]:5060>>;tag=aeac620b.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    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:[email protected]:5060
    <http://sip:[email protected]:5060> SIP/2.0.
    Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    To: <sip:[email protected]:5060
    <http://sip:[email protected]:5060>>;tag=aeac620b.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    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:[email protected]:5060
    <http://sip:[email protected]:5060>>;tag=aeac620b.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    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:[email protected]:5060
    <http://sip:[email protected]:5060> SIP/2.0.
    Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    To: <sip:[email protected]:5060
    <http://sip:[email protected]:5060>>;tag=aeac620b.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    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:[email protected]:5060
    <http://sip:[email protected]:5060>>;tag=aeac620b.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    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:[email protected]:5060
    <http://sip:[email protected]:5060> SIP/2.0.
    Via: SIP/2.0/UDP 10.10.24.36:5060;branch=z9hG4bK02B027d670e963c415e.
    From:
    <sip:[email protected]:5060;pstn-params=9084818088>;tag=gK0201303f.
    To: <sip:[email protected]:5060
    <http://sip:[email protected]:5060>>;tag=aeac620b.
    Call-ID: [email protected]
    <mailto:[email protected]>.
    CSeq: 25848 ACK.
    Max-Forwards: 70.
    Content-Length: 0.
    .

-- Thanks,
    Tim

    .

-- Thanks,
    Tim



    _______________________________________________
    Users mailing list
    [email protected]  <mailto:[email protected]>
    http://lists.opensips.org/cgi-bin/mailman/listinfo/users




--
Thanks,
Tim

978-267-1001
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users

Reply via email to