Description

Dispatcher destination attribute "socket", is not always respected.
Syslog throws:

ERROR: <core> [core/socket_info.c:2067]: parse_protohostport(): bad port number in udp:10.2.10.49:5064

Troubleshooting

Reproduction

relevant (I think) kamailio.cfg:

listen=udp:127.0.0.1:5060        
listen=udp:10.2.10.49:5060
listen=udp:10.2.10.49:5064
listen=udp:10.2.10.49:5065
listen=udp:10.2.10.49:5066
auto_bind_ipv6=0
auto_aliases=0

modparam("dispatcher", "list_file", "/opt/kamailio/dispatcher.list")
modparam("dispatcher", "flags", 2)
modparam("dispatcher", "dst_avp", "$avp(ds_dst)")
modparam("dispatcher", "grp_avp", "$avp(ds_grp)")
modparam("dispatcher", "cnt_avp", "$avp(ds_cnt)")
modparam("dispatcher", "dstid_avp", "$avp(ds_dstid)")
modparam("dispatcher", "ds_hash_size", 9)
modparam("dispatcher", "setid_pvname", "$var(ds_setid)")
modparam("dispatcher", "attrs_avp", "$avp(ds_attrs_dst)")
modparam("dispatcher", "attrs_pvname", "$avp(ds_attrs_from)")
modparam("dispatcher", "sock_avp", "$avp(ds_socket)")
modparam("dispatcher", "ds_default_socket", "udp:10.2.10.49:5066")
modparam("dispatcher", "ds_ping_method", "OPTIONS")
modparam("dispatcher", "ds_ping_interval", 10)
modparam("dispatcher", "ds_probing_mode", 3)

dispatcher.list:

3 sip:127.0.0.1:1234;transport=udp 8 0 duid=abc;socket=udp:10.2.10.49:5064;pipe=p10
3 sip:127.0.0.1:1235;transport=udp 8 0 duid=abc;pipe=p10;socket=udp:10.2.10.49:5065
3 sip:127.0.0.1:1236;transport=udp 8 0 duid=abc;pipe=p10

Above kamailio.cfg and dispatcher.list demonstrates issue when probing (OPTIONS poll).
I did not test actual request dispatching yet.

Log Messages

20:26:37 freebsd11 kamailio[31694]: DEBUG: dispatcher [dispatch.c:2660]: ds_ping_set(): probing set #3, URI sip:127.0.0.1:1236;transport=udp
20:26:37 freebsd11 kamailio[31694]: DEBUG: dispatcher [dispatch.c:2674]: ds_ping_set(): >>>--- here2 - using default socket ---<<<
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:988]: request(): request
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:1027]: request(): uac_r->ssock==udp:10.2.10.49:5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2077]: lookup_local_socket(): lookup_local_socket() phostp==udp:10.2.10.49:5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:1978]: parse_protohostport(): parse_protohostport ins==udp:10.2.10.49:5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2082]: lookup_local_socket(): lookup_local_socket() grep_sock_info()
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==9 && [10.2.10.49] == [127.0.0.1]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==10 && [10.2.10.49] == [10.2.10.49]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==10 && [10.2.10.49] == [10.2.10.49]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5064 (advertise 0) matches port 5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==10 && [10.2.10.49] == [10.2.10.49]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5065 (advertise 0) matches port 5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==10 && [10.2.10.49] == [10.2.10.49]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5066 (advertise 0) matches port 5066
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:427]: t_uac_prepare(): next_hop=<sip:127.0.0.1:1236;transport=udp>
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:152]: dlg2hash(): hashid 37205
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:640]: send_prepared_request_impl(): uac: 0x802572e98  branch: 0  to 127.0.0.1:1236
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [./../../core/onsend.h:69]: run_onsend(): required parameters are not available - ignoring
20:26:37 freebsd11 kamailio[31694]: DEBUG: dispatcher [dispatch.c:2660]: ds_ping_set(): probing set #3, URI sip:127.0.0.1:1235;transport=udp
20:26:37 freebsd11 kamailio[31694]: DEBUG: dispatcher [dispatch.c:2670]: ds_ping_set(): >>>--- here1 - using destination specific socket ---<<<
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:988]: request(): request
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:1027]: request(): uac_r->ssock==udp:10.2.10.49:5065
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2077]: lookup_local_socket(): lookup_local_socket() phostp==udp:10.2.10.49:5065
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:1978]: parse_protohostport(): parse_protohostport ins==udp:10.2.10.49:5065
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2082]: lookup_local_socket(): lookup_local_socket() grep_sock_info()
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==9 && [10.2.10.49] == [127.0.0.1]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5065
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==10 && [10.2.10.49] == [10.2.10.49]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5065
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==10 && [10.2.10.49] == [10.2.10.49]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5064 (advertise 0) matches port 5065
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 10==10 && [10.2.10.49] == [10.2.10.49]
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5065 (advertise 0) matches port 5065
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:427]: t_uac_prepare(): next_hop=<sip:127.0.0.1:1235;transport=udp>
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:152]: dlg2hash(): hashid 37202
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:640]: send_prepared_request_impl(): uac: 0x802572148  branch: 0  to 127.0.0.1:1235
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [./../../core/onsend.h:69]: run_onsend(): required parameters are not available - ignoring
20:26:37 freebsd11 kamailio[31694]: DEBUG: dispatcher [dispatch.c:2660]: ds_ping_set(): probing set #3, URI sip:127.0.0.1:1234;transport=udp
20:26:37 freebsd11 kamailio[31694]: DEBUG: dispatcher [dispatch.c:2670]: ds_ping_set(): >>>--- here1 - using destination specific socket ---<<<
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:988]: request(): request
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:1027]: request(): uac_r->ssock==udp:10.2.10.49:5064
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2077]: lookup_local_socket(): lookup_local_socket() phostp==udp:10.2.10.49:5064
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:1978]: parse_protohostport(): parse_protohostport ins==udp:10.2.10.49:5064
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2020]: parse_protohostport(): B *tmp==;
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2024]: parse_protohostport(): Y looks like strtol() ran too far
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2026]: parse_protohostport(): ins->len  : 19
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2027]: parse_protohostport(): ins->s    : 0x80255fe88
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2028]: parse_protohostport(): first     : 0x80255fe8b
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2029]: parse_protohostport(): first+1   : 0x80255fe8c
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2030]: parse_protohostport(): second    : 0x80255fe96
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2031]: parse_protohostport(): second+1  : 0x80255fe97
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2032]: parse_protohostport(): ins s+len : 0x80255fe9b
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2033]: parse_protohostport(): tmp       : 0x80255fe9b
20:26:37 freebsd11 kamailio[31694]: ERROR: <core> [core/socket_info.c:2067]: parse_protohostport(): bad port number in udp:10.2.10.49:5064
20:26:37 freebsd11 kamailio[31694]: DEBUG: <core> [core/socket_info.c:2079]: lookup_local_socket(): lookup_local_socket() return NULL
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:427]: t_uac_prepare(): next_hop=<sip:127.0.0.1:1234;transport=udp>
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:152]: dlg2hash(): hashid 37203
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [uac.c:640]: send_prepared_request_impl(): uac: 0x8025713f8  branch: 0  to 127.0.0.1:1234
20:26:37 freebsd11 kamailio[31694]: DEBUG: tm [./../../core/onsend.h:69]: run_onsend(): required parameters are not available - ignoring

NOTE: above output contains additional debug statements, see below and 77394f0.

SIP Traffic

$ doas tcpdump -i lo0 -s 0 -n port 5060 or port 5064 or port 5065 or port 5066
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo0, link-type NULL (BSD loopback), capture size 262144 bytes
.
.
.
20:26:37.465870 IP 10.2.10.49.5066 > 127.0.0.1.1236: UDP, length 374
20:26:37.465885 IP 10.2.10.49.5065 > 127.0.0.1.1235: UDP, length 374
20:26:37.465894 IP 10.2.10.49.5060 > 127.0.0.1.1234: SIP: OPTIONS sip:127.0.0.1:1234;transport=udp SIP/2.0
20:26:37.968876 IP 10.2.10.49.5066 > 127.0.0.1.1236: UDP, length 374
20:26:37.969043 IP 10.2.10.49.5065 > 127.0.0.1.1235: UDP, length 374
20:26:37.969216 IP 10.2.10.49.5060 > 127.0.0.1.1234: SIP: OPTIONS sip:127.0.0.1:1234;transport=udp SIP/2.0
.
.
.

Summary of sent packets:
src port 5066 == listener socket + dispatcher default socket
src port 5065 == listener socket + explicitly set to destination 127.0.0.1:1235
src port 5060 == listener socket, not mentioned in dispatcher config
Probe packets to destination 127.0.0.1:1234 are sent with src port 5060, expected 5064.

Possible Solutions

Looks like strtol(second+1, &tmp, 10) in core/socket_info.c runs too far because it expects null terminated string but is passed char* of Kamailio str struct instead.
Commit 77394f0 tries to highlights this.

Additional Information

Found initially in stable 5.0.2 with new configuration.
Replicated in master (20a9616).

version: kamailio 5.1.0-dev4 (x86_64/freebsd)
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, select, kqueue.
id: unknown
compiled on 19:21:12 Jun 21 2017 with clang39 3.9

FreeBSD 11

$ uname -a
FreeBSD freebsd11 11.0-RELEASE-p9 FreeBSD 11.0-RELEASE-p9 #0: Tue Apr 11 08:48:40 UTC 2017     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64


You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.