[SR-Users] rare impossibility to send requests to TLS connected peer

Vasiliy Ganchev vancecezar at gmail.com
Tue Jan 26 10:11:30 CET 2016


Hi folk!

Have a rare issue with tls connections.

Have a server with 100+ active tls connections, that are connected to
separate TCP proxy, that listen on port 443. 
TCP proxy send sip traffic to Kamailio via localhost:5061. In this way all
connections in Kamailio are considered from Localhost.

Issue scheme:
- UA-A (sip-phone, UDP/TCP/TLS) -> call -> sip server (Kamailio+Asterisk
based) -> UA-B (sip phone, transport=TLS)
- The troubles happened in part of flow to UA-B:
--- kamailio script make lookup(location), find AOR for UA-B (here is OK)
--- after t_relay, kamailio make branch_route logic and try to send INVITE
to tcp socket
--- HERE IS the trouble: connection seems to be opened, but Kamailio cannot
send INVITE there (say:  no open tcp connection found)
--- Kamailio try to open tcp connection from itself, TCP proxy refuse it
--- as a result - Kamailio answer 477 to Asterisk, and finish processing

debug level 3 logs (from the point where Kamailio try to send INVITE in
opened connection)
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:1463]:
_tcpconn_find(): tcpconn_find: 0  port 60286
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [ip_addr.c:243]:
print_ip(): tcpconn_find: ip 127.0.0.1
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:1820]:
tcp_send(): tcp_send: no open tcp connection found, opening new one
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [ip_addr.c:243]:
print_ip(): tcpconn_new: new tcp connection: 127.0.0.1
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:1073]:
tcpconn_new(): tcpconn_new: on port 60286, type 3
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:1626]:
_tcpconn_add_alias_unsafe(): _tcpconn_add_alias_unsafe: alias port 60286 for
hash 2646, id 404319
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:1626]:
_tcpconn_add_alias_unsafe(): _tcpconn_add_alias_unsafe: alias port 60286 for
hash 2728, id 404319
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:1624]:
_tcpconn_add_alias_unsafe(): _tcpconn_add_alias_unsafe: alias already
present
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:1382]:
tcpconn_add(): tcpconn_add: hashes: 2646:2728:0, 863
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tls [tls_server.c:184]:
tls_complete_init(): Using TLS domain TLSc<default>
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tls [tls_domain.c:700]:
sr_ssl_ctx_info_callback(): SSL handshake started
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: ERROR: <core> [tcp_main.c:2742]:
tcpconn_1st_send(): connect 127.0.0.1:60286 failed (RST) Connection refused
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: ERROR: <core> [tcp_main.c:2752]:
tcpconn_1st_send(): 127.0.0.1:60286: connect & send  for 0xb1d3b7e8 failed:
Connection refused (111)
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core> [tcp_main.c:2947]:
tcpconn_chld_put(): tcpconn_chld_put: destroying connection 0xb1d3b7e8
(404319, -1) flags 0060
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: ERROR: tm [../../forward.h:247]:
msg_send(): tcp_send failed
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_fwd.c:1591]:
t_send_branch(): t_send_branch: send to 127.0.0.1:60286 (3) failed
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: WARNING: tm [t_fwd.c:1610]:
t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_funcs.c:358]:
t_relay_to(): ERROR:tm:t_relay_to:  t_forward_nonack returned error
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_funcs.c:375]:
t_relay_to(): -477 error reply generation delayed
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_lookup.c:1526]:
t_unref(): t_unref: delayed error reply generation(-477)
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: <core>
[parser/msg_parser.c:339]: parse_headers(): parse_headers:
flags=ffffffffffffffff
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_reply.c:1670]:
cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_reply.c:728]:
_reply_light(): DEBUG: reply sent out. buf=0xb67c000c: SIP/2.0 477
Unfortun..., shmem=0xb1b676cc: SIP/2.0 477 Unfortun
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_funcs.c:156]:
put_on_wait(): DEBUG: put on WAIT
Jan 25 14:32:43   /usr/sbin/kamailio[4722]: DEBUG: tm [t_reply.c:738]:
_reply_light(): DEBUG: _reply_light: finished


Additionally want to say, that suddenly we don't have clear reproduce, it
happened only on 2 production servers, what are common conditions for issue:
- transport=TLS
- when issued call is done, I checked with netstat, the connection is alive
- the issued device is re-REGISTERed as usual, in kamctl ul show I see
registration before/during/after issued call
- issue appear only when connection through our custom TCP proxy :443 (to
Kamailio it is from 127.0.0.1:5061)
- if connection switched to Kamailio 5061 directly - issue never (till now)
reproduced
- in one of the issued server - I noticed big number of tcp id. Doing kamcmd
core.tcp_list, I saw e.g. id: 567852 (usually id numbers are not more than
1000).
- if kamailio/device reboot - problem disappear

Because of not completely understanding how tcp core is working in kamailio,
ask any suggestion, why such could happen. 
Any idea/hints would be greatly appreciated!

kamailio -v
version: kamailio 4.2.5 (i386/linux)
flags: STATS: Off, EXTRA_DEBUG, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS,
DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC,
F_MALLOC, DBG_F_MALLOC, USE_FUTEX, 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, epoll_lt, epoll_et, sigio_rt, select.
id: unknown
compiled on 16:03:38 Jan 12 2016 with gcc 4.3.2

sorry for the long description
cheers!



--
View this message in context: http://sip-router.1086192.n5.nabble.com/rare-impossibility-to-send-requests-to-TLS-connected-peer-tp144986.html
Sent from the Users mailing list archive at Nabble.com.



More information about the sr-users mailing list