Re: [SR-Users] ACK to 200 OK discarded by loose_route()

10 Apr 2012

Hi Daniel,

Thanks for looking into that for me and yes I see the problem now. We'll
have to get our software fixed to support loose routing.
Is there a way to do this without using loose routing, for example building
two completely separate SIP dialogs with the proxy in the middle?

Cheers,
Richard

On 9 April 2012 11:17, Daniel-Constantin Mierla &lt;miconda(a)gmail.com&gt; wrote:

...
   Hello,

 the r-uri in the bad ACK is pointing to the proxy, as I understood from
 the headers. It should point to callee IP address.

 Look at he 200ok for INVITE to see the Contact address -- some device
 involved in the call does not implement properly loose routing or the
 contact address is improperly updated somewhere.

 Cheers,
 Daniel

 On 4/6/12 5:16 PM, SIP Mailing-list wrote:

 Hi guys,

  Hope someone can help me with this.

  The background: I'm just trying to implement a simple load balancer with
 one source and multiple destinations using the call load balancer (ALG10)
 in dispatcher. kamailio version 3.2.0
 The symptoms: I have a simple script working in one test environment
 (csipsimple -> kamailaio -> Twinkle) but can't get it to work in another
 (Dialogic HMP 3.0 -> kamailio -> Dialogic HMP 3.0)
  The details: I've done a debug trace (below) in both environments and
 can't see the problem. For some reason the ACK is destroyed before it is
 forwarded even though the log says "[forward.c:601]: Sending:#012ACK..."

  Any help would be much appreciated!

  TIA,
 Richard

  kamailio.cfg:
 ...
  #!KAMAILIO
 #
 # Kamailio (OpenSER) SIP Server v3.2 - default configuration script
 #     - web: http://www.kamailio.org
 #     - git: http://sip-router.org
 #
 # Direct your questions about this file to: &lt;sr-users(a)lists.sip-router.org
   #
 # Refer to the Core CookBook at http://www.kamailio.org/dokuwiki/doku.php
 # for an explanation of possible statements, functions and parameters.
 #
 #
 # Several features can be enabled using '#!define WITH_FEATURE' directives:
 #
 # RAC: Uses dispatcher algorithm 10 to keep track of load distribution
 #
 # Use: kamctl start/stop/restart

  ####### Global Parameters #########

  # Output goes to /var/log/syslog
 # 5 gives too much output
 # 3 is DEBUG, even this can go crazy
 # 2 is INFO
 # 1 is NOTICE
 debug=3
 #log_stderror=yes

  memdbg=5
 memlog=5
 mem_summary=2

  log_facility=LOG_LOCAL0

  fork=yes
 children=4

  /* uncomment the next line to disable TCP (default on) */
 disable_tcp=yes

  /* uncomment the next line to disable the auto discovery of local aliases
    based on reverse DNS on IPs (default on) */
 auto_aliases=no

  /* add local domain aliases */
 alias=10.130.11.121:5060

  /* uncomment and configure the following line if you want Kamailio to
    bind on a specific interface/port/proto (default bind on all available)
 */
 listen=udp:10.130.11.121:5060

  /* port to listen to
  * - can be specified more than once if needed to listen on many ports */
 #port=5062

  # life time of TCP connection when there is no traffic
 # - a bit higher than registration expires to cope with UA behind NAT
 tcp_connection_lifetime=3605

  ####### Modules Section ########

  # set paths to location of modules (to sources or installation folders)
 #!ifdef WITH_SRCPATH
 mpath="modules_k:modules"
 #!else
 mpath="/usr/lib/kamailio/modules_k/:/usr/lib/kamailio/modules/"
 #!endif

  # For the kamctl interface
 loadmodule "mi_fifo.so"
 #loadmodule "kex.so"
 # TM module is required for t_relay()
 loadmodule "tm.so"
 #loadmodule "tmx.so"
 loadmodule "sl.so"
 # RR module is required for loose_route() and record_route()
 loadmodule "rr.so"
 # PV is required for avp's for ALG10
 loadmodule "pv.so"
 # Used for mf_process_maxfwd_header()
 loadmodule "maxfwd.so"
 #loadmodule "usrloc.so"
 #loadmodule "registrar.so"
 # textops is required for is_method()
 loadmodule "textops.so"
 # For has_totag()
 loadmodule "siputils.so"
 # xlog is required for user xlog() formatted messages. Output goes to
 /var/log/messages
 loadmodule "xlog.so"
 # For sanity_check()
 loadmodule "sanity.so"
 #loadmodule "ctl.so"
 #loadmodule "cfg_rpc.so"
 #loadmodule "mi_rpc.so"
 #loadmodule "acc.so"

  # Added by RAC 2012-04-04: required for ds_select_dst() etc
 loadmodule "dispatcher.so"

  # ----------------- setting module-specific parameters ---------------

  # ----- mi_fifo params -----
 modparam("mi_fifo", "fifo_name", "/tmp/kamailio_fifo")

  # Added by RAC 2012-04-04
 # ----- dispatcher params -----
 modparam("dispatcher", "list_file",   
"/etc/kamailio/dispatcher.list")
 modparam("dispatcher", "force_dst", 0)
 modparam("dispatcher", "use_default", 1)
 modparam("dispatcher", "ds_ping_method", "OPTIONS")
 # Only set ping reply codes that are acceptable. CE should only reply
 "200OK" if OK, "486 Busy Here" if not
 modparam("dispatcher", "ds_ping_reply_codes", "class=2")
 modparam("dispatcher", "ds_ping_from",
"sip:proxy@10.130.11.121")
 modparam("dispatcher", "ds_ping_interval", 20)
 # In this mode only inactive destinations marked as probe-able will be
 pinged
 modparam("dispatcher", "ds_probing_mode", 2)
 modparam("dispatcher", "ds_probing_threshhold", 1)
 modparam("dispatcher", "ds_hash_expire", 3600)
 # Flag "2" MUST be set to use the AVPs listed below. If not set these will
 be <null>
 modparam("dispatcher", "flags",     2)
 modparam("dispatcher", "dst_avp",    "$avp(dsdst)")
 modparam("dispatcher", "grp_avp",    "$avp(dsgrp)")
 modparam("dispatcher", "cnt_avp",    "$avp(dscnt)")
 # For algorithm 10, call load distribution duid (in list_file), dstid_avp
 and ds_hash_size are required
 modparam("dispatcher", "dstid_avp",    "$avp(dsdstid)")
 # Appears to be the size (2^ds_hash_size) of a hashtable for storing the
 state of individual sessions
 # Presumably needs to be bigger than the number of concurrent sessions
 expected
 # 2^12 = 4096
 modparam("dispatcher", "ds_hash_size", 12)

  ####### Routing Logic ########

  # ds_load_update():
 #  if it is a BYE or CANCEL - remove the load from destination address
 used to forward the INVITE
 #  if it is a reply to INVITE - set internal state to confirmed for call
 load structure when reply code is 2xx.
 #
 # ds_load_unset(): Remove the call load for the destination that routed
 the call.

  # Main SIP request routing logic
 # - processing of any incoming SIP request starts with this route
 # - note: this is the same as route { ... }
  request_route {

      if (!mf_process_maxfwd_header("10")) {
         sl_send_reply("483","Too Many Hops");
         exit;
     }

      if(!sanity_check("1511", "7")) {
         xlog("Malformed SIP message from $si:$sp\n");
         exit;
     }

      # Added by RAC 2012-04-04
     # Do not run ds_load_update() here; the reply to the orginal invite is
 sufficient to release the load
     # loose_route() performs routing of in-dialog requests
     if(has_totag()) {
          if (loose_route()) {
             # t_relay() relays a message statefully; forward() (stateless)
 easily gets in a muddle
             if(!t_relay()) {
                 if (method == "ACK") xlog("L_ERR", "cid:$ci
[$rm]
 [200-OK] t_relay failed\n");
                 else xlog("L_WARN", "cid:$ci Existing Transaction relay
 failed: [$rm] from($ft) [$fu] to($tt) [$tu]\n");
                 sl_reply_error();
             }
              else xlog("L_INFO", "cid:$ci Existing Transaction: [$rm]
 from($ft) [$fu] to($tt) [$tu]\n");
         } else if (method == "ACK") {
             if (t_check_trans()) {
                 # stateful ACK after 487 or 404
                 t_relay();
             } else {
                 # ACK without transaction, ignore and discard
                 xlog("L_WARN", "cid:$ci Dropping ACK: from($ft) [$fu]
 to($tt) [$tu]\n");
             }
         } else {
             sl_send_reply("404","Not here");
         }
         exit;
     } # has_totag()

      # dest set1, ALG10: call load distribution: least number of calls
 receives the next call
     # Keeps a hash table of calls based on Call-ID to track call load per
 destination
     if(ds_select_dst("1", "10"))
         xlog("L_NOTICE", "cid:$ci Destination Selected: [$rm] from($ft)
 [$fu] routed to [sip:$tU@$dd:$dp] ($avp(dsdstid))\n");
     else {
         xlog("L_ERR", "No destinations available: [$rm] from
[$fu]\n");
         sl_send_reply("500","No destinations available");
      drop();
         exit();
     }
     # record_route() causes ALL messages to go through the proxy including
 ACKs and BYEs. Results in 16 SIP packets
     # Without record_route(), after 200OK, the ACK and BYE is sent direct.
 Results in 11 SIP packets
     # Must use record_route() with call load distribution, otherwise we
 will not know when a call is released
     #  and cannot account for it
     record_route();
     # With t_relay(), the proxy creates its own messages like 100 trying,
 instead of forwarding the original
     # forward() is not recommended
     t_relay();

  }

  event_route[dispatcher:dst-down] {
     xlog("L_ERR", "Destination down: [$rm] $ru ($du)\n");
 }

  event_route[dispatcher:dst-up] {
     xlog("L_NOTICE", "Destination up: [$rm] $ru\n");
 }

  # Added by RAC 2012-04-04: Update call loads on replies for ALG10.
 # Default action is to reply upstream statelessly using Via headers
 onreply_route {
     xlog("L_INFO", "cid:$ci Reply: [$rm] [$rs-$rr] from($ft) [$fu]
 to($tt) [$tu]\n");
      if(is_method("INVITE")) {
         if(status=~"2[0-9][0-9]")
             ds_load_update();
         else if(status=~"[3-7][0-9][0-9]")
             ds_load_unset();
     }
     else if(is_method("BYE")) {
         ds_load_update();
     }
 }
  ...

  Bad debug trace (CE to IVRSim):
 NOTE: Phone numbers have been changed
 ...
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:628]: SIP Request:
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:630]:  method:  <ACK>
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:632]:  uri:     <sip:18000005835@10.130.11.121>
  Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:634]:  version: <SIP/2.0>
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/parse_to.c:174]: DEBUG: add_param:
 tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/parse_to.c:803]: end of header reached, state=29
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [81]; uri=[
 sip:18000005835@10.130.11.121]
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:189]: DEBUG: to body [<sip:18000005835@10.130.11.121
 ]  Apr  6 14:10:29 UKCY-VM-LINUX199
/usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <1> <ACK>
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/parse_via.c:1288]: Found param type 232, <branch> =
 <z9hG4bK-182890-5e5e75ec-235d6d1e>; state=16
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/parse_via.c:2563]: end of header reached, state=5
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:515]: parse_headers: Via found, flags=2
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:517]: parse_headers: this is the first via
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [receive.c:146]: After parse_msg...
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [receive.c:187]: preparing to run routing scripts...
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: sl
 [sl_funcs.c:307]: DEBUG : sl_filter_ACK: to late to be a local ACK!
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: maxfwd
 [mf_funcs.c:85]: value = 70
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/msg_parser.c:103]: found end of header
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/parse_to.c:174]: DEBUG: add_param:
 tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [parser/parse_to.c:803]: end of header reached, state=29
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: sanity
 [mod_sanity.c:251]: sanity checks result: 1
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG:
 siputils [checks.c:107]: totag found
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: rr
 [loose.c:85]: is_preloaded: No
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [socket_info.c:502]: grep_sock_info - checking if host==us: 13==13 &&
  [10.130.11.121] == [10.130.11.121]
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [socket_info.c:505]: grep_sock_info - checking if port 5060 matches port
 5060
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: rr
 [loose.c:594]: Next hop: '
 sip:10.130.11.121;lr;ftag=774ee38-650b820a-13c4-50022-182890-4de156df-182890'
 is loose router
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: rr
 [loose.c:644]: The last route URI: '
 sip:10.130.11.121;lr;ftag=774ee38-650b820a-13c4-50022-182890-4de156df-182890
 '
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm
 [t_lookup.c:1379]: DEBUG: t_newtran: msg id=6 , global msg id=5 , T on
 entrance=(nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm
 [t_lookup.c:527]: t_lookup_request: start searching: hash=37904, isACK=1
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm
 [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm
 [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm
 [t_funcs.c:315]: SER: forwarding ACK  statelessly
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [msg_translator.c:204]: check_via_address(10.130.11.101, 10.130.11.101, 0)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [forward.c:601]: Sending:#012ACK

sip:10.130.11.121;lr;ftag=774ee38-650b820a-13c4-50022-182890-4de156df-182890SIP/2.0#015#012From:
<

sip:441865000101@10.130.11.101>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890#015#012To:

<sip:18000005835@10.130.11.121>;tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4#015#012Call-ID:
 fb041312-da6d-4fb7-bfee-32677fbab37b#015#012CSeq: 1 ACK#015#012Via:
 SIP/2.0/UDP 10.130.11.121;branch=z9hG4bKcydzigwkX#015#012Via: SIP/2.0/UDP
 10.130.11.101:5060;branch=z9hG4bK-182890-5e5e75ec-235d6d1e#015#012Max-Forwards:
 69#015#012Contact: <sip:441865000101@10.130.11.101>#015#012Allow-Events:
 refer#015#012Content-Length: 0#015#012#015#012.
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [forward.c:603]: orig. len=550, new_len=566, proto=1
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:628]: SIP Request:
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:630]:  method:  <ACK>
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:632]:  uri:
 <sip:10.130.11.121;lr;ftag=774ee38-650b820a-13c4-50022-182890-4de156df-182890>
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:634]:  version: <SIP/2.0>
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_to.c:174]: DEBUG: add_param:
 tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_to.c:803]: end of header reached, state=29
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [xavp.c:365]: destroying xavp list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [81]; uri=[
 sip:18000005835@10.130.11.121]
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core>
 [receive.c:290]: receive_msg: cleaning up
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:189]: DEBUG: to body [<sip:18000005835@10.130.11.121
 ]  Apr  6 14:10:29 UKCY-VM-LINUX199
/usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <1> <ACK>
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_via.c:1288]: Found param type 232, <branch> =
 <z9hG4bKcydzigwkX>; state=16
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_via.c:2563]: end of header reached, state=5
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:515]: parse_headers: Via found, flags=2
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:517]: parse_headers: this is the first via
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [receive.c:146]: After parse_msg...
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [receive.c:187]: preparing to run routing scripts...
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: sl
 [sl_funcs.c:307]: DEBUG : sl_filter_ACK: to late to be a local ACK!
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_via.c:1288]: Found param type 232, <branch> =
 <z9hG4bK-182890-5e5e75ec-235d6d1e>; state=16
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_via.c:2563]: end of header reached, state=5
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:515]: parse_headers: Via found, flags=100
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:528]: parse_headers: this is the second via
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: maxfwd
 [mf_funcs.c:85]: value = 69
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/msg_parser.c:103]: found end of header
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_to.c:174]: DEBUG: add_param:
 tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [parser/parse_to.c:803]: end of header reached, state=29
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: sanity
 [mod_sanity.c:251]: sanity checks result: 1
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG:
 siputils [checks.c:107]: totag found
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: rr
 [loose.c:108]: No Route headers found
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: rr
 [loose.c:838]: There is no Route HF
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm
 [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=5 T start=(nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm
 [t_lookup.c:527]: t_lookup_request: start searching: hash=37904, isACK=1
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm
 [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm
 [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm
 [t_lookup.c:1148]: DEBUG: t_check_msg: msg id=6 global id=6 T end=(nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: WARNING:
 <script>: cid:fb041312-da6d-4fb7-bfee-32677fbab37b Dropping ACK:
 from(774ee38-650b820a-13c4-50022-182890-4de156df-182890) [
 sip:441865000101@10.130.11.101]
 to(f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4) [
 sip:18000005835@10.130.11.121]
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: last message
 repeated 5 times
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [xavp.c:365]: destroying xavp list (nil)
 Apr  6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core>
 [receive.c:290]: receive_msg: cleaning up
 ...

  Bad SIP ACK:
 ...
 Session Initiation Protocol
     Request-Line: ACK sip:18000005835@10.130.11.121 SIP/2.0
         Method: ACK
         Request-URI: sip:18000005835@10.130.11.121
             Request-URI User Part: 18000005835
             Request-URI Host Part: 10.130.11.121
         [Resent Packet: False]
         [Request Frame: 7]
         [Response Time (ms): 29]
     Message Header
         From: <sip:441865000101@10.130.11.101

;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890              SIP from
address: sip:441865000101@10.130.11.101
                 SIP from address User Part: 441865000101
                 SIP from address Host Part: 10.130.11.101
             SIP tag: 774ee38-650b820a-13c4-50022-182890-4de156df-182890
         To: <sip:18000005835@10.130.11.121
 ;tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4
             SIP to address: sip:18000005835@10.130.11.121
                 SIP to address User Part: 18000005835
                 SIP to address Host Part: 10.130.11.121
             SIP tag: f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4
         Call-ID: fb041312-da6d-4fb7-bfee-32677fbab37b
         CSeq: 1 ACK
             Sequence Number: 1
             Method: ACK
         Via: SIP/2.0/UDP 10.130.11.101:5060
 ;branch=z9hG4bK-182890-5e5e75ec-235d6d1e
             Transport: UDP
             Sent-by Address: 10.130.11.101
             Sent-by port: 5060
             Branch: z9hG4bK-182890-5e5e75ec-235d6d1e
         Max-Forwards: 70
         Route:
 <sip:10.130.11.121;lr;ftag=774ee38-650b820a-13c4-50022-182890-4de156df-182890>
         Contact: <sip:441865000101@10.130.11.101>
             Contact Binding: <sip:441865000101@10.130.11.101>
                 URI: <sip:441865000101@10.130.11.101>
                     SIP contact address: sip:441865000101@10.130.11.101
         Allow-Events: refer
         Content-Length: 0
 ...

  Good debug trace (Richard laptop, Twinkle local and csipsimple on wifi):
 ...
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:628]: SIP Request:
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:630]:  method:  <ACK>
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:632]:  uri:     <sip:123@192.168.0.104;transport=udp>
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:634]:  version: <SIP/2.0>
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/parse_via.c:1288]: Found param type 235, <rport> = <n/a>; state=6
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/parse_via.c:1288]: Found param type 232, <branch> =
 <z9hG4bKPjWvIFG5BzVRtUe1jnpRa1ilioYiezOrTz>; state=16
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/parse_via.c:2563]: end of header reached, state=5
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:515]: parse_headers: Via found, flags=2
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:517]: parse_headers: this is the first via
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [receive.c:146]: After parse_msg...
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [receive.c:187]: preparing to run routing scripts...
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: sl
 [sl_funcs.c:307]: DEBUG : sl_filter_ACK: to late to be a local ACK!
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/parse_to.c:174]: DEBUG: add_param: tag=ggpxl
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/parse_to.c:803]: end of header reached, state=29
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [35]; uri=[
 sip:123@192.168.0.104]
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:189]: DEBUG: to body [<sip:123@192.168.0.104>]
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <10807> <ACK>
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr
 [loose.c:85]: is_preloaded: No
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [socket_info.c:502]: grep_sock_info - checking if host==us: 13==13 &&
  [192.168.0.104] == [192.168.0.104]
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [socket_info.c:505]: grep_sock_info - checking if port 5062 matches port
 5060
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [forward.c:448]: check_self: host != me
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [socket_info.c:502]: grep_sock_info - checking if host==us: 13==13 &&
  [192.168.0.104] == [192.168.0.104]
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [socket_info.c:505]: grep_sock_info - checking if port 5062 matches port
 5062
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr
 [loose.c:709]: Topmost route URI: '
 sip:192.168.0.104:5062;lr;ftag=gYRr.jGE57ZMeLuxYrVmKDuHlnX964Fa' is me
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [parser/msg_parser.c:103]: found end of header
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr
 [loose.c:173]: No next Route HF found
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr
 [loose.c:728]: No next URI found
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm
 [t_lookup.c:1379]: DEBUG: t_newtran: msg id=2 , global msg id=1 , T on
 entrance=0xffffffffffffffff
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm
 [t_lookup.c:527]: t_lookup_request: start searching: hash=17962, isACK=1
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm
 [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm
 [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm
 [t_funcs.c:315]: SER: forwarding ACK  statelessly
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [msg_translator.c:204]: check_via_address(192.168.0.3, 192.168.0.3, 0)
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [forward.c:601]: Sending:#012ACK sip:123@192.168.0.104;transport=udp
 SIP/2.0#015#012Via: SIP/2.0/UDP 192.168.0.104:5062;branch=z9hG4bKcydzigwkX#015#012Via:
 SIP/2.0/UDP
192.168.0.3:51351;rport=51351;branch=z9hG4bKPjWvIFG5BzVRtUe1jnpRa1ilioYiezOrTz#015#012Max-Forwards:
 70#015#012From:
<sip:racitup@mobile>;tag=gYRr.jGE57ZMeLuxYrVmKDuHlnX964Fa#015#012To:
 <sip:123@192.168.0.104>;tag=ggpxl#015#012Call-ID:
 zH5ub5H6ooVWQmBzZyswgMSLn7rb2xJl#015#012CSeq: 10807
 ACK#015#012Content-Length:  0#015#012#015#012.
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [forward.c:603]: orig. len=418, new_len=411, proto=1
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: last message repeated
 5 times
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [xavp.c:365]: destroying xavp list (nil)
 Apr  6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core>
 [receive.c:290]: receive_msg: cleaning up
 ...

  Good ACK:
 ...
 Session Initiation Protocol
     Request-Line: ACK sip:123@192.168.0.104;transport=udp SIP/2.0
         Method: ACK
         Request-URI: sip:123@192.168.0.104;transport=udp
             Request-URI User Part: 123
             Request-URI Host Part: 192.168.0.104
         [Resent Packet: False]
         [Request Frame: 13]
         [Response Time (ms): 6489]
     Message Header
         Via: SIP/2.0/UDP 192.168.0.3:38653
 ;rport;branch=z9hG4bKPjyL0GhUP12E0Dkn2CQ5BR9aQm67DdxKfE
             Transport: UDP
             Sent-by Address: 192.168.0.3
             Sent-by port: 38653
             RPort: rport
             Branch: z9hG4bKPjyL0GhUP12E0Dkn2CQ5BR9aQm67DdxKfE
         Max-Forwards: 70
         From: <sip:racitup@mobile>;tag=6UtDyO9vBPzP46w7K8AGOfL6qQbFciij
             SIP from address: sip:racitup@mobile
                 SIP from address User Part: racitup
                 SIP from address Host Part: mobile
             SIP tag: 6UtDyO9vBPzP46w7K8AGOfL6qQbFciij
         To: <sip:123@192.168.0.104>;tag=lsboj
             SIP to address: sip:123@192.168.0.104
                 SIP to address User Part: 123
                 SIP to address Host Part: 192.168.0.104
             SIP tag: lsboj
         Call-ID: 1jtxqtjWsDqEL3C2tsrhS3WtRirBFcB7
         CSeq: 3674 ACK
             Sequence Number: 3674
             Method: ACK
         Route:
 <sip:192.168.0.104:5062;lr;ftag=6UtDyO9vBPzP46w7K8AGOfL6qQbFciij>
         Content-Length:  0
 ...

 _______________________________________________
 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
 Kamailio Advanced Training, April 23-26, 2012, Berlin,
Germanyhttp://www.asipto.com/index.php/kamailio-advanced-training/

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

2005

2004

2003

2002

Re: [SR-Users] ACK to 200 OK discarded by loose_route()