Localy generated transaction with dns failover and socket forcing

[Den4t]

Description

DNS failover do not wok for localy generated transaction when script forcing socket
or sets Via parameters with corex via_add_srvid/via_add_xavp_params, in log appear the errors:

Dec 24 13:30:17 sbc kamailio[9772]: 10(9800) DEBUG: <core> [core/parser/parse_uri.c:1306]: parse_uri(): bad uri,  state 0 parsed: <<F3>gbf> (4) / <<F3>gbf#017^?> (38)
Dec 24 13:30:17 sbc kamailio[9772]: 10(9800) ERROR: tm [ut.h:245]: uri2dst2(): bad_uri: [<F3>gbf#017^?]

Reproduction

Config stripped for localize problem:

#!define IPADDR_THISNODE "192.168.122.130"
#!subst "/IPADDR_THISNODE/192.168.122.130/"

#!define MULTIDOMAIN 0

####### Global Parameters #########

#!define WITH_DEBUG

### LOG Levels: 3=DBG, 2=INFO, 1=NOTICE, 0=WARN, -1=ERR
#!ifdef WITH_DEBUG
debug=4
log_stderror=yes
#!else
debug=2
log_stderror=no
#!endif

memdbg=5
memlog=5

log_facility=LOG_LOCAL0
log_prefix="{$mt $hdr(CSeq) $ci} "

/* number of SIP routing processes */
children=8

server_id = 10
xavp_via_params = "via"

/* 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

/* listen on local and anycast addresses */
listen=udp:IPADDR_THISNODE:5060

#### DNS settings
use_dns_cache = on              # Use KAMAILIO internal DNS cache
use_dns_failover = on           # Depends on KAMAILIO internal DNS cache
#dns_srv_loadbalancing = on      #
#dns_try_naptr = on             #
dns_try_naptr = off             #
dns_retr_time=1                 # Time in seconds before retrying a DNS request
dns_retr_no=1                   # Number of DNS retransmissions before giving up
dns_try_ipv6=yes
dns_use_search_list=no

####### Modules Section ########
/* set paths to location of modules */
loadmodule "jsonrpcs.so"
loadmodule "kex.so"
loadmodule "corex.so"
loadmodule "tm.so"
loadmodule "tmx.so"
loadmodule "sl.so"
loadmodule "rr.so"
loadmodule "pv.so"
loadmodule "maxfwd.so"
loadmodule "siputils.so"
loadmodule "xlog.so"
loadmodule "ctl.so"
loadmodule "cfg_rpc.so"
loadmodule "counters.so"
loadmodule "dispatcher.so"

# ----------------- setting module-specific parameters ---------------

# ----- jsonrpcs params -----
modparam("jsonrpcs", "pretty_format", 1)
/* set the path to RPC fifo control file */
# modparam("jsonrpcs", "fifo_name", "/run/kamailio/kamailio_rpc.fifo")
/* set the path to RPC unix socket control file */
# modparam("jsonrpcs", "dgram_socket", "/run/kamailio/kamailio_rpc.sock")

# ----- tm params -----
# auto-discard branches from previous serial forking leg
modparam("tm", "failure_reply_mode", 3)
# ----- tm params -----
modparam("tm", "fr_timer", 2000)
#modparam("tm", "reparse_on_dns_failover", 0)


# ----- dispatcher params -----
modparam("dispatcher", "list_file", "/etc/kamailio/dispatcher.list")
modparam("dispatcher", "ds_ping_interval", 10)
modparam("dispatcher", "ds_probing_mode", 1)
modparam("dispatcher", "ds_probing_threshold", 2)
modparam("dispatcher", "ds_ping_method", "OPTIONS")
modparam("dispatcher", "outbound_proxy", "sip:proxy")

# ----- corex params -----
modparam("corex", "dns_cache", "type=A;name=proxy;addr=192.168.122.129;ttl=3600000;flags=2")
modparam("corex", "dns_cache", "type=A;name=proxy;addr=192.168.122.131;ttl=3600000;flags=2")

# ----- rr params -----
# set next param to 1 to add value to ;lr param (helps with some UAs)
modparam("rr", "enable_full_lr", 0)
# do not append from tag to the RR (no need for this script)
modparam("rr", "append_fromtag", 0)

onsend_route {
        xinfo(">> onsend_route snd_to=$sndto(ip)\n");
}

event_route [tm:local-request] {
        xlog("L_INFO", ">> Routing locally generated $rm to $ru\n");
        xinfo(">> mbu: $mbu");
        $fs = "udp:IPADDR_THISNODE:5060";
//      This have the same effect as forcing socket
//        via_add_srvid(1);
        t_set_fr(1000,250);
}

disparcher list have only one target:
110 sip:192.168.122.131:5060;transport=udp 0 1

The scenario is simple - dispatcher try to ping target via proxy, config have two "A" records in cache,
all work as expected until tm:local-request route modify Via header by setting $fs or one of the
corex module functions which set flags FL_ADD_SRVID|FL_ADD_XAVP_VIA_PARAMS|FL_USE_XAVP_VIA_FIELDS,
tm in this case (after error as above) decline failover.

Debugging Data

transaction fail log:

Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: dispatcher [dispatch.c:3546]: ds_ping_result_helper(): probe all, mode DS_PROBE_ALL
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: dispatcher [dispatch.c:3589]: ds_ping_set(): probing set #110, URI sip:192.168.122.131:5060;transport=udp
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: dispatcher [dispatch.c:3620]: ds_ping_set(): Default ping_from: sip:dispatcher@localhost
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: dispatcher [dispatch.c:3630]: ds_ping_set(): Default outbound proxy: sip:proxy
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: tm [uac.c:457]: t_uac_prepare(): next_hop=<sip:proxy>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/dns_cache.c:527]: _dns_hash_find(): (_sip._udp.proxy(15), 33), h=170
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/dns_cache.c:3050]: dns_srv_resolve_ip(): ("_sip._udp.proxy", 0, 0), ret=-5, ip=
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/dns_cache.c:527]: _dns_hash_find(): (proxy(5), 1), h=878
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/dns_cache.c:2807]: dns_a_resolve(): (proxy, 0) returning 0
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/dns_cache.c:3176]: dns_srv_sip_resolve(): (proxy, 0, 0), ip, ret=0
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: tm [uac.c:158]: dlg2hash(): hashid 55725
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: tm [uac.c:246]: t_run_local_req(): executing event_route[tm:local-request]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg():  method:  <OPTIONS>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg():  uri:     <sip:192.168.122.131:5060;transport=udp>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg():  version: <SIP/2.0>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKda9d.ac749307000000000000000000000000.0>; state=16
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) INFO: <script>: >> Routing locally generated OPTIONS to sip:192.168.122.131:5060;transport=udp
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/msg_translator.c:1799]: check_boundaries(): no multi-part body
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) INFO: <script>: >> mbu: OPTIONS sip:192.168.122.131:5060;transport=udp SIP/2.0
Dec 24 13:15:37 sbc kamailio[9772]: Via: SIP/2.0/UDP 192.168.122.130;branch=z9hG4bKda9d.ac749307000000000000000000000000.0
Dec 24 13:15:37 sbc kamailio[9772]: To: <sip:192.168.122.131:5060;transport=udp>
Dec 24 13:15:37 sbc kamailio[9772]: From: <sip:dispatcher@localhost>;tag=e92e326f0a937cb326014225217c2c12-5929046b
Dec 24 13:15:37 sbc kamailio[9772]: CSeq: 10 OPTIONS
Dec 24 13:15:37 sbc kamailio[9772]: Call-ID: 62100fd077a3a243-9799@192.168.122.130
Dec 24 13:15:37 sbc kamailio[9772]: Max-Forwards: 70
Dec 24 13:15:37 sbc kamailio[9772]: Content-Length: 0
Dec 24 13:15:37 sbc kamailio[9772]: User-Agent: kamailio (5.5.3 (x86_64/linux))
Dec 24 13:15:37 sbc kamailio[9772]: #015
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: pv [pv_core.c:2703]: pv_set_force_sock(): trying to set send-socket to [udp:192.168.122.130:5060]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 15==15 && [192.168.122.130] == [192.168.122.130]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: tm [uac.c:314]: t_run_local_req(): local Via update - new socket: [192.168.122.130] - msg-flags: 0 9(9799) DEBUG: tm [uac.c:340]: t_run_local_req(): apply new updates with Via to sip msg
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/msg_translator.c:1799]: check_boundaries(): no multi-part body
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg():  method:  <OPTIONS>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg():  uri:     <sip:192.168.122.131:5060;transport=udp>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg():  version: <SIP/2.0>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKda9d.ac749307000000000000000000000000.0>; state=16
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=10
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [42]; uri=[sip:192.168.122.131:5060;transport=udp]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (42)[<sip:192.168.122.131:5060;transport=udp>
Dec 24 13:15:37 sbc kamailio[9772]: ], to tag (0)[]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type 4
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type 5
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <10> <OPTIONS>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID] type 6
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Content-Length] type 12
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [User-Agent] type 28
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg():  method:  <OPTIONS>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg():  uri:     <sip:192.168.122.131:5060;transport=udp>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg():  version: <SIP/2.0>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKda9d.ac749307000000000000000000000000.0>; state=16
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=10
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [42]; uri=[sip:192.168.122.131:5060;transport=udp]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (42)[<sip:192.168.122.131:5060;transport=udp>
Dec 24 13:15:37 sbc kamailio[9772]: ], to tag (0)[]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type 4
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type 5
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <10> <OPTIONS>
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID] type 6
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: tm [uac.c:189]: uac_refresh_hdr_shortcuts(): cseq: [CSeq: 10]
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) DEBUG: tm [uac.c:685]: send_prepared_request_impl(): uac: 0x7f0f6262b9c8  branch: 0  to 192.168.122.131:5060
Dec 24 13:15:37 sbc kamailio[9772]:  9(9799) INFO: <script>: >> onsend_route snd_to=192.168.122.131
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: <core> [core/parser/parse_uri.c:1306]: parse_uri(): bad uri,  state 0 parsed: <<F3>gbf> (4) / <<F3>gbf#017^?> (38)
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) ERROR: tm [ut.h:245]: uri2dst2(): bad_uri: [<F3>gbf#017^?]
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:1363]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=408
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:1592]: t_should_relay_response(): rps completed - uas status: 0 branch: 0
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:2236]: local_reply(): branch=0, save=0, winner=0
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:2275]: local_reply(): local transaction completed 408/0 (totag retr: 0/1024)
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_hooks.c:256]: run_trans_callbacks_internal(): DBG: trans=0x7f0f6262b738, callback type 1024, id 0 entered
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: dispatcher [dispatch.c:3491]: ds_options_callback(): OPTIONS-Request was finished with code 408 (to sip:192.168.122.131:5060;transport=udp, group 110)
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: dispatcher [dispatch.c:2973]: ds_update_state(): update state for sip:192.168.122.131:5060;transport=udp in group 110 to 10
Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: dispatcher [dispatch.c:3049]: ds_update_state(): old state was 9, set new state to 9

I think that error somewhere in memory management when allocating/free structures for Via header modification
which is hard to debug, i have insert several debug output in uac.c in my case the problem fire after a call of function insert_tmcb:

        /* Register the callbacks after everything is successful and nothing can fail.
        Otherwise the callback parameter would be freed twise, once from TMCB_DESTROY,
        and again because of the negative return code. */
        {// extra debug
                struct ua_client *uac=&request->my_T->uac[0];
                LM_DBG(">>>>> Before insert_tmcb\n");
                LM_DBG(">>>>> request uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri));
                uac=&new_cell->uac[0];
                LM_DBG(">>>>> new_cell uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri));
        }
        if(uac_r->cb && insert_tmcb(&(new_cell->tmcb_hl), uac_r->cb_flags,
                                                                *(uac_r->cb), uac_r->cbp, NULL)!=1){
                ret=E_OUT_OF_MEM;
                LM_ERR("short of tmcb shmem\n");
                goto error1;
        }
        {// extra debug
                struct ua_client *uac=&request->my_T->uac[0];
                LM_DBG(">>>>> After insert_tmcb\n");
                LM_DBG(">>>>> request uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri));
                uac=&new_cell->uac[0];
                LM_DBG(">>>>> new_cell uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri));
        }

In log i see:

Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:189]: uac_refresh_hdr_shortcuts(): cseq: [CSeq: 10]
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:591]: t_uac_prepare(): >>>>> Before insert_tmcb
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:592]: t_uac_prepare(): >>>>> request uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: sip:192.168.122.131:5060;transport=udp
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:594]: t_uac_prepare(): >>>>> new_cell uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: sip:192.168.122.131:5060;transport=udp
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:604]: t_uac_prepare(): >>>>> After insert_tmcb
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:605]: t_uac_prepare(): >>>>> request uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: <F3>#007yDr^?
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:607]: t_uac_prepare(): >>>>> new_cell uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: <F3>#007yDr^?
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) DEBUG: tm [uac.c:699]: send_prepared_request_impl(): uac: 0x7f72407959c8  branch: 0  to 192.168.122.131:5060
Dec 24 14:36:39 sbc kamailio[12709]:  9(12732) INFO: <script>: >> onsend_route snd_to=192.168.122.131
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: <core> [core/parser/parse_uri.c:1306]: parse_uri(): bad uri,  state 0 parsed: <<F3>#007yD> (4) / <<F3>#007yDr^?> (38)
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) ERROR: tm [ut.h:245]: uri2dst2(): bad_uri: [<F3>#007yDr^?]
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:1363]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=408
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:1592]: t_should_relay_response(): rps completed - uas status: 0 branch: 0
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:2236]: local_reply(): branch=0, save=0, winner=0
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:2275]: local_reply(): local transaction completed 408/0 (totag retr: 0/1024)
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_hooks.c:256]: run_trans_callbacks_internal(): DBG: trans=0x7f7240795738, callback type 1024, id 0 entered
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:3491]: ds_options_callback(): OPTIONS-Request was finished with code 408 (to sip:192.168.122.131:5060;transport=udp, group 110)
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:2973]: ds_update_state(): update state for sip:192.168.122.131:5060;transport=udp in group 110 to 10
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:3004]: ds_update_state(): destination did not replied 1 times, threshold 2
Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:3049]: ds_update_state(): old state was 0, set new state to 10

insert_tmcb have shm_malloc fincion call in the beninig, after this call the content of uri structure is broken.

Additional Information

• Kamailio Version - output of kamailio -v

version: kamailio 5.5.3 (x86_64/linux) 473cef
flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED
ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.

• Operating System:

Ubuntu 18.04.6 LTS

[Den4t]

Authors, can anyone take this?

Initialy problem appears from anycast configuration, when Via header used to track original node.

[oej]

Failover in SIP needs SRV records. I would not expect DNS round robin to work with failover. Just load balancing. But if the choosen IP fails, that's a failure.

[Den4t]

Hi @oej !

Disagree about "I would not expect DNS round robin to work with failover. Just load balancing.", according to doc:

use_dns_failover = on |off - if on and sending a request fails (due to not
      being allowed from an onsend_route, send failure, blocklisted destination
      or, when using tm, invite timeout), and the destination resolves to
      multiple ip addresses and/or multiple SRV records, the send will be
      re-tried using the next ip/record. In tm's case a new branch will be
      created for each new send attempt.

And if we comment out the strings which modify Via hiader in the scenario above:

//        $fs = "udp:IPADDR_THISNODE:5060";
//      This have the same effect as forcing socket
//        via_add_srvid(1);

We have the following signaling exchange:

If uncomment any of the statement which modify Via then error appear as described in the first post .

[miconda]

Hopefully this if fixed by commit 0ed1282 .

Testing and feedback would be appreciated and in case all is ok, then it will backported.

In case there are still problems, reopen.

[Den4t]

Hi @miconda !

Ths !
Will check at this week.

[Den4t]

Hi @miconda !

I checked this commit, now it works, there are no errors in the log, except for one - there are no extra attributes in the second branch in the Via header,
srvid=10 in my case:

2022/01/26 13:50:57.083262 192.168.122.130:5060 -> 192.168.122.131:5060
OPTIONS sip:192.168.122.131:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.122.130;branch=z9hG4bK1f34.23d14794000000000000000000000000.0;srvid=10
To: <sip:192.168.122.131:5060;transport=udp>
From: <sip:dispatcher@localhost>;tag=e92e326f0a937cb326014225217c2c12-6c22046b
CSeq: 10 OPTIONS
Call-ID: 6bf96ef8338b5e4a-58713@192.168.122.130
Max-Forwards: 70
Content-Length: 0
User-Agent: kamailio (5.6.0-dev3 (x86_64/linux))

2022/01/26 13:50:57.331945 192.168.122.130:5060 -> 192.168.122.129:5060
OPTIONS sip:192.168.122.131:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.122.130;branch=z9hG4bK1f34.23d14794000000000000000000000000.1
To: <sip:192.168.122.131:5060;transport=udp>
From: <sip:dispatcher@localhost>;tag=e92e326f0a937cb326014225217c2c12-6c22046b
CSeq: 10 OPTIONS
Call-ID: 6bf96ef8338b5e4a-58713@192.168.122.130
Max-Forwards: 70
Content-Length: 0
User-Agent: kamailio (5.6.0-dev3 (x86_64/linux))

2022/01/26 13:50:57.334087 192.168.122.129:5060 -> 192.168.122.130:5060
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.122.130;rport=5060;received=192.168.122.130;branch=z9hG4bK1f34.23d14794000000000000000000000000.1
Call-ID: 6bf96ef8338b5e4a-58713@192.168.122.130
From: <sip:dispatcher@localhost>;tag=e92e326f0a937cb326014225217c2c12-6c22046b
To: <sip:192.168.122.131>;tag=z9hG4bK1f34.23d14794000000000000000000000000.1
CSeq: 10 OPTIONS
WWW-Authenticate: Digest realm="asterisk",nonce="1643194257/ff6d7e670c94e952efa5b03ea181f1b3",opaque="30981a5d6736d06f",algorithm=md5,qop="auth"
Server: Asterisk PBX 18.1.1
Content-Length:  0

[Den4t]

Do i need to reopen issue ?