[SR-Users] ACK not relayed

David Notivol dnotivol at gmail.com
Mon Jul 30 11:10:14 CEST 2012


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 at 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
> ACK sip:200.87.137.150:5060;user=phone SIP/2.0.
> Via: SIP/2.0/UDP 79.170.68.151:5060
> ;branch=z9hG4bK334faa4497ll114a52eACK450932302031.
> Max-Forwards: 70.
> Route: <sip:79.170.68.157;lr;ftag=45093230-co8241-INS033>.
> To: <sip:59146292331 at 79.170.68.157
> ;user=phone;noa=international>;tag=ldb0cbn6-CC-23.
> From: "Javi Gallart"<sip:34917019888 at 79.170.68.151
> ;user=phone;noa=national>;tag=45093230-co8241-INS033.
> Call-ID: 071ae17301d3eb470f5cdde00cd9b24b at ens.com.
> CSeq: 824101 ACK.
> User-Agent: ENSR3.0.66.34-IS33-RMRG106382-RG105488-CPO13110.
> Content-Length: 0.
>
>
> 2012/7/30 Daniel-Constantin Mierla <miconda at 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 at 79.170.68.157><sip:59138553189 at 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 at 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 at 79.170.68.157> <sip:59138553189 at 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 listsr-users at lists.sip-router.orghttp://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>
>>
>> --
>> Daniel-Constantin Mierla - http://www.asipto.comhttp://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.comhttp://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 at gmail.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20120730/b5cc833b/attachment-0001.htm>


More information about the sr-users mailing list