[SR-Users] ACK not relayed

David Notivol dnotivol at gmail.com
Mon Jul 30 15:55:42 CEST 2012


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 at 79.170.68.157:5060;user=phone><sip:59146938249 at 79.170.68.157:5060;user=phone>


Regards,
David.

2012/7/30 Daniel-Constantin Mierla <miconda at 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 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
>
>
> --
> 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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20120730/a353441e/attachment-0001.htm>


More information about the sr-users mailing list