Hi guys,<div><br></div><div>Hope someone can help me with this.</div><div><br></div><div>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</div>
<div>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)</div><div>
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..."</div>
<div><br></div><div>Any help would be much appreciated!</div><div><br></div><div>TIA,</div><div>Richard</div><div><br></div><div>kamailio.cfg:</div><div>...</div><div><div>#!KAMAILIO</div><div>#</div><div># Kamailio (OpenSER) SIP Server v3.2 - default configuration script</div>
<div># - web: <a href="http://www.kamailio.org">http://www.kamailio.org</a></div><div># - git: <a href="http://sip-router.org">http://sip-router.org</a></div><div>#</div><div># Direct your questions about this file to: <<a href="mailto:sr-users@lists.sip-router.org">sr-users@lists.sip-router.org</a>></div>
<div>#</div><div># Refer to the Core CookBook at <a href="http://www.kamailio.org/dokuwiki/doku.php">http://www.kamailio.org/dokuwiki/doku.php</a></div><div># for an explanation of possible statements, functions and parameters.</div>
<div>#</div><div># </div><div># Several features can be enabled using '#!define WITH_FEATURE' directives:</div><div>#</div><div># RAC: Uses dispatcher algorithm 10 to keep track of load distribution</div><div>#</div>
<div># Use: kamctl start/stop/restart</div><div><br></div><div>####### Global Parameters #########</div><div><br></div><div># Output goes to /var/log/syslog</div><div># 5 gives too much output</div><div># 3 is DEBUG, even this can go crazy</div>
<div># 2 is INFO</div><div># 1 is NOTICE</div><div>debug=3</div><div>#log_stderror=yes</div><div><br></div><div>memdbg=5</div><div>memlog=5</div><div>mem_summary=2</div><div><br></div><div>log_facility=LOG_LOCAL0</div><div>
<br></div><div>fork=yes</div><div>children=4</div><div><br></div><div>/* uncomment the next line to disable TCP (default on) */</div><div>disable_tcp=yes</div><div><br></div><div>/* uncomment the next line to disable the auto discovery of local aliases</div>
<div> based on reverse DNS on IPs (default on) */</div><div>auto_aliases=no</div><div><br></div><div>/* add local domain aliases */</div><div>alias=<a href="http://10.130.11.121:5060">10.130.11.121:5060</a></div><div><br>
</div><div>/* uncomment and configure the following line if you want Kamailio to </div><div> bind on a specific interface/port/proto (default bind on all available) */</div><div>listen=udp:<a href="http://10.130.11.121:5060">10.130.11.121:5060</a></div>
<div><br></div><div>/* port to listen to</div><div> * - can be specified more than once if needed to listen on many ports */</div><div>#port=5062</div><div><br></div><div># life time of TCP connection when there is no traffic</div>
<div># - a bit higher than registration expires to cope with UA behind NAT</div><div>tcp_connection_lifetime=3605</div><div><br></div><div><br></div><div>####### Modules Section ########</div><div><br></div><div># set paths to location of modules (to sources or installation folders)</div>
<div>#!ifdef WITH_SRCPATH</div><div>mpath="modules_k:modules"</div><div>#!else</div><div>mpath="/usr/lib/kamailio/modules_k/:/usr/lib/kamailio/modules/"</div><div>#!endif</div><div><br></div><div># For the kamctl interface</div>
<div>loadmodule "mi_fifo.so"</div><div>#loadmodule "kex.so"</div><div># TM module is required for t_relay()</div><div>loadmodule "tm.so"</div><div>#loadmodule "tmx.so"</div><div>loadmodule "sl.so"</div>
<div># RR module is required for loose_route() and record_route()</div><div>loadmodule "rr.so"</div><div># PV is required for avp's for ALG10</div><div>loadmodule "pv.so"</div><div># Used for mf_process_maxfwd_header()</div>
<div>loadmodule "maxfwd.so"</div><div>#loadmodule "usrloc.so"</div><div>#loadmodule "registrar.so"</div><div># textops is required for is_method()</div><div>loadmodule "textops.so"</div>
<div># For has_totag()</div><div>loadmodule "siputils.so"</div><div># xlog is required for user xlog() formatted messages. Output goes to /var/log/messages</div><div>loadmodule "xlog.so"</div><div># For sanity_check()</div>
<div>loadmodule "sanity.so"</div><div>#loadmodule "ctl.so"</div><div>#loadmodule "cfg_rpc.so"</div><div>#loadmodule "mi_rpc.so"</div><div>#loadmodule "acc.so"</div><div><br>
</div><div><br></div><div><br></div><div># Added by RAC 2012-04-04: required for ds_select_dst() etc</div><div>loadmodule "dispatcher.so"</div><div><br></div><div><br></div><div># ----------------- setting module-specific parameters ---------------</div>
<div><br></div><div># ----- mi_fifo params -----</div><div>modparam("mi_fifo", "fifo_name", "/tmp/kamailio_fifo")</div><div><br></div><div><br></div><div># Added by RAC 2012-04-04</div><div># ----- dispatcher params -----</div>
<div>modparam("dispatcher", "list_file", "/etc/kamailio/dispatcher.list")</div><div>modparam("dispatcher", "force_dst", 0)</div><div>modparam("dispatcher", "use_default", 1)</div>
<div>modparam("dispatcher", "ds_ping_method", "OPTIONS")</div><div># Only set ping reply codes that are acceptable. CE should only reply "200OK" if OK, "486 Busy Here" if not</div>
<div>modparam("dispatcher", "ds_ping_reply_codes", "class=2")</div><div>modparam("dispatcher", "ds_ping_from", "<a href="mailto:sip%3Aproxy@10.130.11.121">sip:proxy@10.130.11.121</a>")</div>
<div>modparam("dispatcher", "ds_ping_interval", 20)</div><div># In this mode only inactive destinations marked as probe-able will be pinged</div><div>modparam("dispatcher", "ds_probing_mode", 2)</div>
<div>modparam("dispatcher", "ds_probing_threshhold", 1)</div><div>modparam("dispatcher", "ds_hash_expire", 3600)</div><div># Flag "2" MUST be set to use the AVPs listed below. If not set these will be <null></div>
<div>modparam("dispatcher", "flags", 2)</div><div>modparam("dispatcher", "dst_avp", "$avp(dsdst)")</div><div>modparam("dispatcher", "grp_avp", "$avp(dsgrp)")</div>
<div>modparam("dispatcher", "cnt_avp", "$avp(dscnt)")</div><div># For algorithm 10, call load distribution duid (in list_file), dstid_avp and ds_hash_size are required</div><div>modparam("dispatcher", "dstid_avp", "$avp(dsdstid)")</div>
<div># Appears to be the size (2^ds_hash_size) of a hashtable for storing the state of individual sessions</div><div># Presumably needs to be bigger than the number of concurrent sessions expected</div><div># 2^12 = 4096</div>
<div>modparam("dispatcher", "ds_hash_size", 12)</div><div><br></div><div>####### Routing Logic ########</div><div><br></div><div># ds_load_update():</div><div># if it is a BYE or CANCEL - remove the load from destination address used to forward the INVITE</div>
<div># if it is a reply to INVITE - set internal state to confirmed for call load structure when reply code is 2xx.</div><div>#</div><div># ds_load_unset(): Remove the call load for the destination that routed the call. </div>
<div><br></div><div><br></div><div><br></div><div># Main SIP request routing logic</div><div># - processing of any incoming SIP request starts with this route</div><div># - note: this is the same as route { ... }</div><div>
request_route {</div><div><br></div><div> if (!mf_process_maxfwd_header("10")) {</div><div> sl_send_reply("483","Too Many Hops");</div><div> exit;</div><div> }</div><div><br>
</div><div> if(!sanity_check("1511", "7")) {</div><div> xlog("Malformed SIP message from $si:$sp\n");</div><div> exit;</div><div> }</div><div><br></div><div> # Added by RAC 2012-04-04</div>
<div> # Do not run ds_load_update() here; the reply to the orginal invite is sufficient to release the load</div><div> # loose_route() performs routing of in-dialog requests</div><div> if(has_totag()) {</div><div>
if (loose_route()) {</div><div> # t_relay() relays a message statefully; forward() (stateless) easily gets in a muddle</div><div> if(!t_relay()) {</div><div> if (method == "ACK") xlog("L_ERR", "cid:$ci [$rm] [200-OK] t_relay failed\n");</div>
<div> else xlog("L_WARN", "cid:$ci Existing Transaction relay failed: [$rm] from($ft) [$fu] to($tt) [$tu]\n");</div><div> sl_reply_error();</div><div> }</div><div>
else xlog("L_INFO", "cid:$ci Existing Transaction: [$rm] from($ft) [$fu] to($tt) [$tu]\n");</div><div> } else if (method == "ACK") {</div><div> if (t_check_trans()) {</div>
<div> # stateful ACK after 487 or 404</div><div> t_relay();</div><div> } else {</div><div> # ACK without transaction, ignore and discard</div><div> xlog("L_WARN", "cid:$ci Dropping ACK: from($ft) [$fu] to($tt) [$tu]\n");</div>
<div> }</div><div> } else {</div><div> sl_send_reply("404","Not here");</div><div> }</div><div> exit;</div><div> } # has_totag()</div><div><br></div><div> # dest set1, ALG10: call load distribution: least number of calls receives the next call</div>
<div> # Keeps a hash table of calls based on Call-ID to track call load per destination</div><div> if(ds_select_dst("1", "10"))</div><div> xlog("L_NOTICE", "cid:$ci Destination Selected: [$rm] from($ft) [$fu] routed to [sip:$tU@$dd:$dp] ($avp(dsdstid))\n");</div>
<div> else {</div><div> xlog("L_ERR", "No destinations available: [$rm] from [$fu]\n");</div><div> sl_send_reply("500","No destinations available");</div><div> <span class="Apple-tab-span" style="white-space:pre"> </span> drop();</div>
<div> exit();</div><div> }</div><div> # record_route() causes ALL messages to go through the proxy including ACKs and BYEs. Results in 16 SIP packets</div><div> # Without record_route(), after 200OK, the ACK and BYE is sent direct. Results in 11 SIP packets</div>
<div> # Must use record_route() with call load distribution, otherwise we will not know when a call is released</div><div> # and cannot account for it</div><div> record_route();</div><div> # With t_relay(), the proxy creates its own messages like 100 trying, instead of forwarding the original</div>
<div> # forward() is not recommended</div><div> t_relay();</div><div><br></div><div>}</div><div><br></div><div>event_route[dispatcher:dst-down] {</div><div> xlog("L_ERR", "Destination down: [$rm] $ru ($du)\n");</div>
<div>}</div><div><br></div><div>event_route[dispatcher:dst-up] {</div><div> xlog("L_NOTICE", "Destination up: [$rm] $ru\n");</div><div>}</div><div><br></div><div># Added by RAC 2012-04-04: Update call loads on replies for ALG10.</div>
<div># Default action is to reply upstream statelessly using Via headers</div><div>onreply_route {</div><div> xlog("L_INFO", "cid:$ci Reply: [$rm] [$rs-$rr] from($ft) [$fu] to($tt) [$tu]\n");</div><div>
if(is_method("INVITE")) {</div><div> if(status=~"2[0-9][0-9]")</div><div> ds_load_update();</div><div> else if(status=~"[3-7][0-9][0-9]")</div><div> ds_load_unset();</div>
<div> }</div><div> else if(is_method("BYE")) {</div><div> ds_load_update();</div><div> }</div><div>}</div></div><div>...</div><div><br></div><div><div>Bad debug trace (CE to IVRSim):</div><div>NOTE: Phone numbers have been changed</div>
<div>...</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:628]: SIP Request:</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:630]: method: <ACK></div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:632]: uri: <<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>></div><div>
Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:634]: version: <SIP/2.0></div><div>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</div>
<div>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</div><div>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=[<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>] </div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body [<<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>>]</div>
<div>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></div><div>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</div>
<div>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</div><div>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</div>
<div>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</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [receive.c:146]: After parse_msg...</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [receive.c:187]: preparing to run routing scripts...</div><div>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!</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 </div><div>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</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header</div><div>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</div>
<div>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</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: sanity [mod_sanity.c:251]: sanity checks result: 1</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: siputils [checks.c:107]: totag found</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: rr [loose.c:85]: is_preloaded: No</div>
<div>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]</div><div>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</div>
<div>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</div><div>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'</div>
<div>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)</div><div>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</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed</div><div>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</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelessly </div><div>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)</div>
<div>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-182890 SIP/2.0#015#012From: <<a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a>>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890#015#012To: <<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>>;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: <<a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a>>#015#012Allow-Events: refer#015#012Content-Length: 0#015#012#015#012.</div>
<div>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</div><div>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)</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:628]: SIP Request:</div><div>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)</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:630]: method: <ACK></div><div>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)</div>
<div>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></div><div>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)</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:634]: version: <SIP/2.0></div><div>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)</div>
<div>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</div><div>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)</div>
<div>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</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [xavp.c:365]: destroying xavp list (nil)</div>
<div>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=[<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>] </div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [receive.c:290]: receive_msg: cleaning up</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body [<<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>>]</div>
<div>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></div><div>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</div>
<div>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</div><div>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</div>
<div>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</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [receive.c:146]: After parse_msg...</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [receive.c:187]: preparing to run routing scripts...</div><div>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!</div>
<div>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</div><div>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</div>
<div>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</div><div>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</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: maxfwd [mf_funcs.c:85]: value = 69 </div><div>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</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header</div><div>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</div>
<div>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</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: sanity [mod_sanity.c:251]: sanity checks result: 1</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: siputils [checks.c:107]: totag found</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: rr [loose.c:108]: No Route headers found</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: rr [loose.c:838]: There is no Route HF</div><div>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)</div>
<div>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</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed</div>
<div>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</div><div>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)</div>
<div>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) [<a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a>] to(f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4) [<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>]</div>
<div>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)</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: last message repeated 5 times</div>
<div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [xavp.c:365]: destroying xavp list (nil)</div><div>Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [receive.c:290]: receive_msg: cleaning up</div>
<div>...</div><div><br></div><div>Bad SIP ACK:</div><div>...</div><div>Session Initiation Protocol</div><div> Request-Line: ACK <a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a> SIP/2.0</div>
<div> Method: ACK</div><div> Request-URI: <a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a></div><div> Request-URI User Part: 18000005835</div><div> Request-URI Host Part: 10.130.11.121</div>
<div> [Resent Packet: False]</div><div> [Request Frame: 7]</div><div> [Response Time (ms): 29]</div><div> Message Header</div><div> From: <<a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a>>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890</div>
<div> SIP from address: <a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a></div><div> SIP from address User Part: 441865000101</div><div> SIP from address Host Part: 10.130.11.101</div>
<div> SIP tag: 774ee38-650b820a-13c4-50022-182890-4de156df-182890</div><div> To: <<a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a>>;tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4</div>
<div> SIP to address: <a href="mailto:sip%3A18000005835@10.130.11.121">sip:18000005835@10.130.11.121</a></div><div> SIP to address User Part: 18000005835</div><div> SIP to address Host Part: 10.130.11.121</div>
<div> SIP tag: f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4</div><div> Call-ID: fb041312-da6d-4fb7-bfee-32677fbab37b</div><div> CSeq: 1 ACK</div><div> Sequence Number: 1</div><div> Method: ACK</div>
<div> Via: SIP/2.0/UDP 10.130.11.101:5060;branch=z9hG4bK-182890-5e5e75ec-235d6d1e</div><div> Transport: UDP</div><div> Sent-by Address: 10.130.11.101</div><div> Sent-by port: 5060</div>
<div> Branch: z9hG4bK-182890-5e5e75ec-235d6d1e</div><div> Max-Forwards: 70</div><div> Route: <sip:10.130.11.121;lr;ftag=774ee38-650b820a-13c4-50022-182890-4de156df-182890></div><div> Contact: <<a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a>></div>
<div> Contact Binding: <<a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a>></div><div> URI: <<a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a>></div>
<div> SIP contact address: <a href="mailto:sip%3A441865000101@10.130.11.101">sip:441865000101@10.130.11.101</a></div><div> Allow-Events: refer</div><div> Content-Length: 0</div><div>...</div>
<div><br></div><div><br></div><div><br></div><div>Good debug trace (Richard laptop, Twinkle local and csipsimple on wifi):</div><div>...</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:628]: SIP Request:</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:630]: method: <ACK></div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:632]: uri: <<a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>;transport=udp></div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:634]: version: <SIP/2.0></div><div>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</div>
<div>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</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/parse_via.c:2563]: end of header reached, state=5</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first via</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [receive.c:146]: After parse_msg...</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [receive.c:187]: preparing to run routing scripts...</div>
<div>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!</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=ggpxl</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [35]; uri=[<a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>] </div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body [<<a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>>]</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <10807> <ACK></div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr [loose.c:85]: is_preloaded: No</div><div>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]</div>
<div>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</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [forward.c:448]: check_self: host != me</div>
<div>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]</div><div>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</div>
<div>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</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr [loose.c:173]: No next Route HF found</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr [loose.c:728]: No next URI found</div><div>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</div>
<div>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</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelessly </div>
<div>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)</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [forward.c:601]: Sending:#012ACK <a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>;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: <<a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>>;tag=ggpxl#015#012Call-ID: zH5ub5H6ooVWQmBzZyswgMSLn7rb2xJl#015#012CSeq: 10807 ACK#015#012Content-Length: 0#015#012#015#012.</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [forward.c:603]: orig. len=418, new_len=411, proto=1</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)</div>
<div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: last message repeated 5 times</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [xavp.c:365]: destroying xavp list (nil)</div><div>Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [receive.c:290]: receive_msg: cleaning up</div>
<div>...</div><div><br></div><div>Good ACK:</div><div>...</div><div>Session Initiation Protocol</div><div> Request-Line: ACK <a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>;transport=udp SIP/2.0</div>
<div> Method: ACK</div><div> Request-URI: <a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>;transport=udp</div><div> Request-URI User Part: 123</div><div> Request-URI Host Part: 192.168.0.104</div>
<div> [Resent Packet: False]</div><div> [Request Frame: 13]</div><div> [Response Time (ms): 6489]</div><div> Message Header</div><div> Via: SIP/2.0/UDP 192.168.0.3:38653;rport;branch=z9hG4bKPjyL0GhUP12E0Dkn2CQ5BR9aQm67DdxKfE</div>
<div> Transport: UDP</div><div> Sent-by Address: 192.168.0.3</div><div> Sent-by port: 38653</div><div> RPort: rport</div><div> Branch: z9hG4bKPjyL0GhUP12E0Dkn2CQ5BR9aQm67DdxKfE</div>
<div> Max-Forwards: 70</div><div> From: <sip:racitup@mobile>;tag=6UtDyO9vBPzP46w7K8AGOfL6qQbFciij</div><div> SIP from address: sip:racitup@mobile</div><div> SIP from address User Part: racitup</div>
<div> SIP from address Host Part: mobile</div><div> SIP tag: 6UtDyO9vBPzP46w7K8AGOfL6qQbFciij</div><div> To: <<a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a>>;tag=lsboj</div>
<div> SIP to address: <a href="mailto:sip%3A123@192.168.0.104">sip:123@192.168.0.104</a></div><div> SIP to address User Part: 123</div><div> SIP to address Host Part: 192.168.0.104</div>
<div> SIP tag: lsboj</div><div> Call-ID: 1jtxqtjWsDqEL3C2tsrhS3WtRirBFcB7</div><div> CSeq: 3674 ACK</div><div> Sequence Number: 3674</div><div> Method: ACK</div><div> Route: <sip:192.168.0.104:5062;lr;ftag=6UtDyO9vBPzP46w7K8AGOfL6qQbFciij></div>
<div> Content-Length: 0</div><div>...</div></div><div><br></div>