Hi Daniel,
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.0The 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 NOTICEdebug=3#log_stderror=yes
memdbg=5memlog=5mem_summary=2
log_facility=LOG_LOCAL0
fork=yeschildren=4
/* uncomment the next line to disable TCP (default on) */disable_tcp=yes
/* uncomment the next line to disable the auto discovery of local aliasesbased 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 tobind 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 NATtcp_connection_lifetime=3605
####### Modules Section ########
# set paths to location of modules (to sources or installation folders)#!ifdef WITH_SRCPATHmpath="modules_k:modules"#!elsempath="/usr/lib/kamailio/modules_k/:/usr/lib/kamailio/modules/"#!endif
# For the kamctl interfaceloadmodule "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 ALG10loadmodule "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/messagesloadmodule "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() etcloadmodule "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 notmodparam("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 pingedmodparam("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 requiredmodparam("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 = 4096modparam("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 requestsif(has_totag()) {if (loose_route()) {# t_relay() relays a message statefully; forward() (stateless) easily gets in a muddleif(!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 404t_relay();} else {# ACK without transaction, ignore and discardxlog("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 destinationif(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 itrecord_route();# With t_relay(), the proxy creates its own messages like 100 trying, instead of forwarding the original# forward() is not recommendedt_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 headersonreply_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-16d0d4Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29Apr 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=16Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/parse_via.c:2563]: end of header reached, state=5Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first viaApr 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 = 70Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/msg_parser.c:103]: found end of headerApr 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-182890Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: sanity [mod_sanity.c:251]: sanity checks result: 1Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: siputils [checks.c:107]: totag foundApr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: rr [loose.c:85]: is_preloaded: NoApr 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 5060Apr 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 routerApr 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=1Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failedApr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction foundApr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28277]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelesslyApr 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=1Apr 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-16d0d4Apr 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=29Apr 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 upApr 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=16Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/parse_via.c:2563]: end of header reached, state=5Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first viaApr 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=16Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/parse_via.c:2563]: end of header reached, state=5Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=100Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:528]: parse_headers: this is the second viaApr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: maxfwd [mf_funcs.c:85]: value = 69Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/msg_parser.c:103]: found end of headerApr 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-182890Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: sanity [mod_sanity.c:251]: sanity checks result: 1Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: siputils [checks.c:107]: totag foundApr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: rr [loose.c:108]: No Route headers foundApr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: rr [loose.c:838]: There is no Route HFApr 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=1Apr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failedApr 6 14:10:29 UKCY-VM-LINUX199 /usr/sbin/kamailio[28276]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction foundApr 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 timesApr 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 ProtocolRequest-Line: ACK sip:18000005835@10.130.11.121 SIP/2.0Method: ACKRequest-URI: sip:18000005835@10.130.11.121Request-URI User Part: 18000005835Request-URI Host Part: 10.130.11.121[Resent Packet: False][Request Frame: 7][Response Time (ms): 29]Message HeaderFrom: <sip:441865000101@10.130.11.101>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890SIP from address: sip:441865000101@10.130.11.101SIP from address User Part: 441865000101SIP from address Host Part: 10.130.11.101SIP tag: 774ee38-650b820a-13c4-50022-182890-4de156df-182890To: <sip:18000005835@10.130.11.121>;tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4SIP to address: sip:18000005835@10.130.11.121SIP to address User Part: 18000005835SIP to address Host Part: 10.130.11.121SIP tag: f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4Call-ID: fb041312-da6d-4fb7-bfee-32677fbab37bCSeq: 1 ACKSequence Number: 1Method: ACKVia: SIP/2.0/UDP 10.130.11.101:5060;branch=z9hG4bK-182890-5e5e75ec-235d6d1eTransport: UDPSent-by Address: 10.130.11.101Sent-by port: 5060Branch: z9hG4bK-182890-5e5e75ec-235d6d1eMax-Forwards: 70Contact: <sip:441865000101@10.130.11.101>Contact Binding: <sip:441865000101@10.130.11.101>SIP contact address: sip:441865000101@10.130.11.101Allow-Events: referContent-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=6Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/parse_via.c:1288]: Found param type 232, <branch> = <z9hG4bKPjWvIFG5BzVRtUe1jnpRa1ilioYiezOrTz>; state=16Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/parse_via.c:2563]: end of header reached, state=5Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first viaApr 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=ggpxlApr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29Apr 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: NoApr 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 5060Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [forward.c:448]: check_self: host != meApr 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 5062Apr 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 meApr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: <core> [parser/msg_parser.c:103]: found end of headerApr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr [loose.c:173]: No next Route HF foundApr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: rr [loose.c:728]: No next URI foundApr 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=0xffffffffffffffffApr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm [t_lookup.c:527]: t_lookup_request: start searching: hash=17962, isACK=1Apr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failedApr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction foundApr 6 14:24:30 adventure /usr/sbin/kamailio[8545]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelesslyApr 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=1Apr 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 timesApr 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 ProtocolRequest-Line: ACK sip:123@192.168.0.104;transport=udp SIP/2.0Method: ACKRequest-URI: sip:123@192.168.0.104;transport=udpRequest-URI User Part: 123Request-URI Host Part: 192.168.0.104[Resent Packet: False][Request Frame: 13][Response Time (ms): 6489]Message HeaderVia: SIP/2.0/UDP 192.168.0.3:38653;rport;branch=z9hG4bKPjyL0GhUP12E0Dkn2CQ5BR9aQm67DdxKfETransport: UDPSent-by Address: 192.168.0.3Sent-by port: 38653RPort: rportBranch: z9hG4bKPjyL0GhUP12E0Dkn2CQ5BR9aQm67DdxKfEMax-Forwards: 70From: <sip:racitup@mobile>;tag=6UtDyO9vBPzP46w7K8AGOfL6qQbFciijSIP from address: sip:racitup@mobileSIP from address User Part: racitupSIP from address Host Part: mobileSIP tag: 6UtDyO9vBPzP46w7K8AGOfL6qQbFciijTo: <sip:123@192.168.0.104>;tag=lsbojSIP to address: sip:123@192.168.0.104SIP to address User Part: 123SIP to address Host Part: 192.168.0.104SIP tag: lsbojCall-ID: 1jtxqtjWsDqEL3C2tsrhS3WtRirBFcB7CSeq: 3674 ACKSequence Number: 3674Method: ACKContent-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
-- Daniel-Constantin Mierla Kamailio Advanced Training, April 23-26, 2012, Berlin, Germany http://www.asipto.com/index.php/kamailio-advanced-training/