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.
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
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: 071ae17301d3eb470f5cdde00cd9b24b@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@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.157sip: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.157sip: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-users@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
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 http://79.170.68.151:5060 -> 79.170.68.157:5060 http://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 mailto:sip%3A59146292331@79.170.68.157;user=phone;noa=international>;tag=ldb0cbn6-CC-23. From: "Javi Gallart"<sip:34917019888@79.170.68.151 mailto:sip%3A34917019888@79.170.68.151;user=phone;noa=national>;tag=45093230-co8241-INS033. Call-ID: 071ae17301d3eb470f5cdde00cd9b24b@ens.com mailto:071ae17301d3eb470f5cdde00cd9b24b@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@gmail.com mailto: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> <mailto: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 <mailto: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> <mailto: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 <mailto: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://twitter.com/#%21/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
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 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: 071ae17301d3eb470f5cdde00cd9b24b@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@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.157sip: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-users@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
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 mailto: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 <http://79.170.68.151:5060> -> 79.170.68.157:5060 <http://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 <mailto:sip%3A59146292331@79.170.68.157>;user=phone;noa=international>;tag=ldb0cbn6-CC-23. From: "Javi Gallart"<sip:34917019888@79.170.68.151 <mailto:sip%3A34917019888@79.170.68.151>;user=phone;noa=national>;tag=45093230-co8241-INS033. Call-ID: 071ae17301d3eb470f5cdde00cd9b24b@ens.com <mailto:071ae17301d3eb470f5cdde00cd9b24b@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@gmail.com <mailto: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> <mailto: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 <mailto: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> <mailto: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 <mailto: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://twitter.com/#%21/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://twitter.com/#%21/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 mailto:dnotivol@gmail.com
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=phonesip: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 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: 071ae17301d3eb470f5cdde00cd9b24b@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@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.157sip: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-users@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@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
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 mailto: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 <mailto: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 <http://79.170.68.151:5060> -> 79.170.68.157:5060 <http://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 <mailto:sip%3A59146292331@79.170.68.157>;user=phone;noa=international>;tag=ldb0cbn6-CC-23. From: "Javi Gallart"<sip:34917019888@79.170.68.151 <mailto:sip%3A34917019888@79.170.68.151>;user=phone;noa=national>;tag=45093230-co8241-INS033. Call-ID: 071ae17301d3eb470f5cdde00cd9b24b@ens.com <mailto:071ae17301d3eb470f5cdde00cd9b24b@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@gmail.com <mailto: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> <mailto: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 <mailto: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> <mailto: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 <mailto: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://twitter.com/#%21/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://twitter.com/#%21/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 <mailto:dnotivol@gmail.com>-- Daniel-Constantin Mierla -http://www.asipto.com http://twitter.com/#!/miconda <http://twitter.com/#%21/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
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=phonesip: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 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: 071ae17301d3eb470f5cdde00cd9b24b@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@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.157sip: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-users@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@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
-- 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 -
David Notivol