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><sip:59146938249@79.170.68.157:5060;user=phone>
Regards,
David.
2012/7/30 Daniel-Constantin Mierla <mico...@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 <mico...@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@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.
>> Call-ID: 071ae17301d3eb470f5cdde00cd9b...@ens.com.
>> CSeq: 824101 ACK.
>> User-Agent: ENSR3.0.66.34-IS33-RMRG106382-RG105488-CPO13110.
>> Content-Length: 0.
>>
>>
>> 2012/7/30 Daniel-Constantin Mierla <mico...@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><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> <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
>>> listsr-us...@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
> dnoti...@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
>
>
_______________________________________________
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
