[SR-Users] ACK to 200 OK discarded by loose_route()
SIP Mailing-list
sip at racitup.com
Tue Apr 10 16:38:33 CEST 2012
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 at 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 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
>
> /* 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 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>
> 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]
> 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
> >]
> 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 at 10.130.11.101>;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890#015#012To:
> <sip:18000005835 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>#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]
> 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
> >]
> 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]
> to(f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4) [
> sip:18000005835 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 SIP/2.0
> Method: ACK
> Request-URI: sip:18000005835 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
> >;tag=774ee38-650b820a-13c4-50022-182890-4de156df-182890
> SIP from address: sip:441865000101 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
> >;tag=f8a6698-0-13c4-50022-16d0d4-103b30a3-16d0d4
> SIP to address: sip:18000005835 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>
> Contact Binding: <sip:441865000101 at 10.130.11.101>
> URI: <sip:441865000101 at 10.130.11.101>
> SIP contact address: sip:441865000101 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;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]
> 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>]
> 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;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>;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;transport=udp SIP/2.0
> Method: ACK
> Request-URI: sip:123 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>;tag=lsboj
> SIP to address: sip:123 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 listsr-users at 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/
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20120410/60950e5e/attachment-0001.htm>
More information about the sr-users
mailing list