Hello,

We found out the problem, it was out fault. The ACK was dropped because the was a previous (and incorrect) evaluation of $rU. Being $null for these calls, the ACK wasn't relayed. We already fixed it; thanks for the assistance. 

Regards,
David.

2012/7/30 Daniel-Constantin Mierla <miconda@gmail.com>
Hello,

add $si, $ru and $ci in the xlog(...) from the config to compare with ngrep trace, maybe there are different ACKs.

Cheers,
Daniel


On 7/30/12 3:55 PM, David Notivol wrote:
Hello,

It looks like the r-uri in the trace is different from the one kamailio considers. From the ACK message captured with ngrep:
ACK sip:200.87.137.150:5060;user=phone SIP/2.0

But form the logs:
Jul 30 09:15:00 theseus-test /usr/local/kamailio/sbin/kamailio[1577]: DEBUG: <core> [parser/msg_parser.c:630]:  method:  <ACK>
Jul 30 09:15:00 theseus-test /usr/local/kamailio/sbin/kamailio[1577]: DEBUG: <core> [parser/msg_parser.c:632]:  uri: <sip:59146938249@79.170.68.157:5060;user=phone>


Regards,
David.

2012/7/30 Daniel-Constantin Mierla <miconda@gmail.com>
Hello,

the log message shows that the transaction is not found. Is the ACK coming late after 200ok ? There is a tm module parameter that you can adjust to prolong the time a transaction is kept after completion, if that is the case.

Also, be sure the INVITE is sent using tm functions, not stateless via core function.

Then, instead of dropping, you can just try forwarding it if the uri si not myself, like adding:

if(uri!=myself) t_relay();

before the exit.

Cheers,
Daniel


On 7/30/12 11:10 AM, David Notivol wrote:
This is the code that's being executed:

route[WITHINDLG] {
    if (has_totag()) {
        # sequential request withing a dialog should
        # take the path determined by record-routing
        xlog("ESTAMOS EN WITHIN\n");
        if (loose_route()){
            xlog("LOOSE ROUTE DETECTED\n");
            if (is_method("ACK")) {
                xlog("ES UN ACK\n");
            }
            route(BYE);
            route(RELAY);
        } else {
            xlog("NO LOOSE ROUTE\n");
            if ( is_method("ACK") ) {
                if ( t_check_trans() ) {
                    xlog("NO LOOSE AND TRANSACTION FOUND\n");
                    # no loose-route, but stateful ACK;
                    # must be an ACK after a 487
                    # or e.g. 404 from upstream server
                    t_relay();
                    exit;
                } else {
                    xlog("NO LOOSE AND TRANSACTION NOT FOUND\n");
                    # ACK without matching transaction ... ignore and discard
                    exit;
                }
            }
            sl_send_reply("404","Not here");
        }
        exit;
    }
}


And the call log with cfgtrace. It seems to be clear that the transaction is not matched, but we can't see why.

Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=335 a=26 n=xlog
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: <script>: ESTAMOS EN WITHIN
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=360 a=17 n=if
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=336 a=25 n=loose_route
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: rr [loose.c:108]: No Route headers found
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: rr [loose.c:838]: There is no Route HF
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=344 a=26 n=xlog
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: <script>: NO LOOSE ROUTE
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=359 a=17 n=if
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=345 a=26 n=is_method
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=357 a=17 n=if
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=346 a=25 n=t_check_trans
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=12 global id=10 T start=(nil)
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: tm [t_lookup.c:527]: t_lookup_request: start searching: hash=58737, isACK=1
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: tm [t_lookup.c:1148]: DEBUG: t_check_msg: msg id=12 global id=12 T end=(nil)
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=354 a=26 n=xlog
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: <script>: NO LOOSE AND TRANSACTION NOT FOUND
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: ERROR: *** cfgtrace: c=[/usr/local/kamailio/etc/kamailio/kamailio.cfg] l=356 a=3 n=exit
Jul 30 04:58:08 theseus-test /usr/local/kamailio/sbin/kamailio[577]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)

2012/7/30 Daniel-Constantin Mierla <miconda@gmail.com>
Hello,

if your config is based on the default one, there is a check for associated INVITE transaction and if that does not exist, then the ACK is droppend.

You can use debugger module with cfgtrace set on in order to see what actions in the config file are executed. That will help to see if it gets to t_check_trans() and then exit.

Cheers,
Daniel


On 7/30/12 10:35 AM, David Notivol wrote:
Hi Daniel,

This is the ACK message:

U 2012/07/30 04:23:31.604721 79.170.68.151:5060 -> 79.170.68.157:5060
Via: SIP/2.0/UDP 79.170.68.151:5060;branch=z9hG4bK334faa4497ll114a52eACK450932302031.
Max-Forwards: 70.
To: <sip:59146292331@79.170.68.157;user=phone;noa=international>;tag=ldb0cbn6-CC-23.
From: "Javi Gallart"<sip:34917019888@79.170.68.151;user=phone;noa=national>;tag=45093230-co8241-INS033.
CSeq: 824101 ACK.
User-Agent: ENSR3.0.66.34-IS33-RMRG106382-RG105488-CPO13110.
Content-Length: 0.


2012/7/30 Daniel-Constantin Mierla <miconda@gmail.com>
Hello,

can you add a log message to print the source ip, call id and r-uri?

It may happen that the ACK is looping back if r-uri is pointing to itself.

Also, try to get the ngrep on all devices, like:

ngrep -d any -qt -W byline port 5060

Pasting the ACK request here will help to see if something is wrong with it.

Cheers,
Daniel


On 7/30/12 8:53 AM, David Notivol wrote:
In a UAC-Kamailio-UAS scenario, we've found a case where the ACK coming from uac is not relayed by our proxy to the uas. This is the log for the ACK message:
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:624]: SIP Request:
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:626]:  method:  <ACK>
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:628]:  uri: <sip:59138553189@79.170.68.157>
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:630]:  version: <SIP/2.0>
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/parse_via.c:1286]: Found param type 235, <rport> = <n/a>; state=6
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bKKc4gKXyemS9HD>; state=16
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=2
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: this is the first via
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [receive.c:149]: After parse_msg...
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [receive.c:190]: preparing to run routing scripts...
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: sl [sl_funcs.c:396]: DEBUG : sl_filter_ACK: to late to be a local ACK!
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: maxfwd [mf_funcs.c:85]: value = 65
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=6ne1x6d6-CC-23
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [52]; uri=[sip:59138553189@79.170.68.157]
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [<sip:59138553189@79.170.68.157>]
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <31362871> <ACK>
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:202]: DEBUG: get_hdr_body : content_length=0
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/msg_parser.c:104]: found end of header
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=0cS8trtaF196F
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: sanity [mod_sanity.c:255]: sanity checks result: 1
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: siputils [checks.c:106]: totag found
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: ERROR: <script>: ESTAMOS EN WITHIN
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: rr [loose.c:108]: No Route headers found
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: DEBUG: rr [loose.c:829]: There is no Route HF
     Jul 27 10:04:59 theseus-test /usr/local/kamailio/sbin/kamailio[17358]: ERROR: <script>: NO LOOSE ROUTE 

However, in a pcap trace I clearly see the Route header:
This is the Record-Route in the 200 message
     Record-Route: <sip:79.170.68.157;lr;ftag=330cdf48-co1022-INS033>
And this is the Route header in the ACk:
     Route: <sip:79.170.68.157;lr;ftag=330cdf48-co1022-INS033>

I haven't been able to figure out what's going on. We have plenty of traffic working in that proxy. What am I missing?

Thanks in advance
David. 


_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users@lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users


-- 
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio Advanced Training, Seattle, USA, Sep 23-26, 2012 - http://asipto.com/u/katu
Kamailio Practical Workshop, Netherlands, Sep 10-12, 2012 - http://asipto.com/u/kpw



-- 
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio Advanced Training, Seattle, USA, Sep 23-26, 2012 - http://asipto.com/u/katu
Kamailio Practical Workshop, Netherlands, Sep 10-12, 2012 - http://asipto.com/u/kpw



--
Saludos,
David Notivol
dnotivol@gmail.com


-- 
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio Advanced Training, Seattle, USA, Sep 23-26, 2012 - http://asipto.com/u/katu
Kamailio Practical Workshop, Netherlands, Sep 10-12, 2012 - http://asipto.com/u/kpw


-- 
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio Advanced Training, Seattle, USA, Sep 23-26, 2012 - http://asipto.com/u/katu
Kamailio Practical Workshop, Netherlands, Sep 10-12, 2012 - http://asipto.com/u/kpw