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: sr-users@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-182890 SIP/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 ...
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: <sr-users@lists.sip-router.org mailto:sr-users@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 http://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 http://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 mailto:sip%3Aproxy@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 orginalinvite 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 callsreceives 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 mailto:sip%3A18000005835@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 mailto:sip%3A18000005835@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 mailto:sip%3A18000005835@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-182890 SIP/2.0#015#012From: <sip:441865000101@10.130.11.101 mailto:sip%3A441865000101@10.130.11.101>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890#015#012To: <sip:18000005835@10.130.11.121 mailto:sip%3A18000005835@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 mailto:sip%3A441865000101@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 mailto:sip%3A18000005835@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 mailto:sip%3A18000005835@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 <mailto:sip%3A441865000101@10.130.11.101>] to(f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4) [sip:18000005835@10.130.11.121 <mailto:sip%3A18000005835@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 <mailto:sip%3A18000005835@10.130.11.121> SIP/2.0 Method: ACK Request-URI: sip:18000005835@10.130.11.121 <mailto:sip%3A18000005835@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 <mailto:sip%3A441865000101@10.130.11.101>>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890 SIP from address: sip:441865000101@10.130.11.101 <mailto:sip%3A441865000101@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 <mailto:sip%3A18000005835@10.130.11.121>>;tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4 SIP to address: sip:18000005835@10.130.11.121 <mailto:sip%3A18000005835@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 <mailto:sip%3A441865000101@10.130.11.101>> Contact Binding: <sip:441865000101@10.130.11.101 <mailto:sip%3A441865000101@10.130.11.101>> URI: <sip:441865000101@10.130.11.101 <mailto:sip%3A441865000101@10.130.11.101>> SIP contact address: sip:441865000101@10.130.11.101 <mailto:sip%3A441865000101@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 <mailto:sip%3A123@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 <mailto:sip%3A123@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 <mailto:sip%3A123@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 <mailto:sip%3A123@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 <mailto:sip%3A123@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 <mailto:sip%3A123@192.168.0.104>;transport=udp SIP/2.0 Method: ACK Request-URI: sip:123@192.168.0.104 <mailto:sip%3A123@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 <mailto:sip%3A123@192.168.0.104>>;tag=lsboj SIP to address: sip:123@192.168.0.104 <mailto:sip%3A123@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 list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
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 miconda@gmail.com 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: <sr-users@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 issufficient 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 callsreceives 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/
-
Daniel-Constantin Mierla -
SIP Mailing-list