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