[SR-Users] ACK to 200 OK discarded by loose_route()
Daniel-Constantin Mierla
miconda at gmail.com
Mon Apr 9 12:17:51 CEST 2012
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 at lists.sip-router.org <mailto:sr-users at 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 at 10.130.11.121
> <mailto:sip%3Aproxy at 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 at 10.130.11.121
> <mailto:sip%3A18000005835 at 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 at 10.130.11.121
> <mailto:sip%3A18000005835 at 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 at 10.130.11.121 <mailto:sip%3A18000005835 at 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 at 10.130.11.101
> <mailto:sip%3A441865000101 at 10.130.11.101>>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890#015#012To:
> <sip:18000005835 at 10.130.11.121
> <mailto:sip%3A18000005835 at 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 at 10.130.11.101
> <mailto:sip%3A441865000101 at 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 at 10.130.11.121
> <mailto:sip%3A18000005835 at 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 at 10.130.11.121 <mailto:sip%3A18000005835 at 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 at 10.130.11.101
> <mailto:sip%3A441865000101 at 10.130.11.101>]
> to(f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4)
> [sip:18000005835 at 10.130.11.121 <mailto:sip%3A18000005835 at 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 at 10.130.11.121
> <mailto:sip%3A18000005835 at 10.130.11.121> SIP/2.0
> Method: ACK
> Request-URI: sip:18000005835 at 10.130.11.121
> <mailto:sip%3A18000005835 at 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 at 10.130.11.101
> <mailto:sip%3A441865000101 at 10.130.11.101>>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890
> SIP from address: sip:441865000101 at 10.130.11.101
> <mailto:sip%3A441865000101 at 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 at 10.130.11.121
> <mailto:sip%3A18000005835 at 10.130.11.121>>;tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4
> SIP to address: sip:18000005835 at 10.130.11.121
> <mailto:sip%3A18000005835 at 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 at 10.130.11.101
> <mailto:sip%3A441865000101 at 10.130.11.101>>
> Contact Binding: <sip:441865000101 at 10.130.11.101
> <mailto:sip%3A441865000101 at 10.130.11.101>>
> URI: <sip:441865000101 at 10.130.11.101
> <mailto:sip%3A441865000101 at 10.130.11.101>>
> SIP contact address:
> sip:441865000101 at 10.130.11.101 <mailto:sip%3A441865000101 at 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 at 192.168.0.104
> <mailto:sip%3A123 at 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 at 192.168.0.104 <mailto:sip%3A123 at 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 at 192.168.0.104
> <mailto:sip%3A123 at 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 at 192.168.0.104
> <mailto:sip%3A123 at 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 at mobile>;tag=gYRr.jGE57ZMeLuxYrVmKDuHlnX964Fa#015#012To:
> <sip:123 at 192.168.0.104
> <mailto:sip%3A123 at 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 at 192.168.0.104
> <mailto:sip%3A123 at 192.168.0.104>;transport=udp SIP/2.0
> Method: ACK
> Request-URI: sip:123 at 192.168.0.104
> <mailto:sip%3A123 at 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 at mobile>;tag=6UtDyO9vBPzP46w7K8AGOfL6qQbFciij
> SIP from address: sip:racitup at mobile
> SIP from address User Part: racitup
> SIP from address Host Part: mobile
> SIP tag: 6UtDyO9vBPzP46w7K8AGOfL6qQbFciij
> To: <sip:123 at 192.168.0.104
> <mailto:sip%3A123 at 192.168.0.104>>;tag=lsboj
> SIP to address: sip:123 at 192.168.0.104
> <mailto:sip%3A123 at 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 at 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/
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20120409/b04d8682/attachment-0001.htm>
More information about the sr-users
mailing list