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

Tue Jan 26 12:40:34 CET 2016

Hello,

can you make a diagram of how the tcp proxy is involved in the sip
traffic routing? From where it receives the traffic and where it sends
it? Does it open connections towards kamailio?

Kamailio is using source IP and port at the moment of opening the tcp
connection to identify the tcp connections to be used based on target
sip URI.

Cheers,
Daniel

On 26/01/16 10:11, Vasiliy Ganchev wrote:
> 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.
>
> _______________________________________________
> 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
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Book: SIP Routing With Kamailio - http://www.asipto.com
http://miconda.eu