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-... Sent from the Users mailing list archive at Nabble.com.
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-... Sent from the Users mailing list archive at Nabble.com.
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
Hi Daniel, thanks for quick reply!
e.g. 10.100.1.24 - sip phone 10.100.1.85 - server
- sip phone is configured to register to 10.100.1.85:443 - tcp proxy listen on 443 - when SIP request comes, tcp proxy open connect to Kamailio 127.0.0.1:5061, and send request there - tcp proxy does not modify sip traffic - there is pure tcp proxy, it stores pairs outer_ip:port <=> 127.0.0.1:port (make bind of 2 TCP connects)
the kamctl ul show example for such AOR:
AOR:: 251 Contact:: sip:251@10.100.1.24:4165;transport=TLS Q= ...... Received:: sip:127.0.0.1:39370;transport=tls ...... Socket:: tls:127.0.0.1:5061 is this explanation clear enough, or need to add smth?
Cheers!
-- View this message in context: http://sip-router.1086192.n5.nabble.com/rare-impossibility-to-send-requests-... Sent from the Users mailing list archive at Nabble.com.
Hello,
so practically all registration appear to come from 127.0.0.1:xyz, where xyz is some port value.
My guess is that the connection to the tcp proxy is cut and the kamailio tries to open one.
Is the tcp proxy routing traffic to other apps? Why not using another Kamailio that does bridging from port 443 to internal kamailio? Should be simple outbound proxy config, using Path for registrations.
Cheers, Daniel
On 26/01/16 13:14, Vasiliy Ganchev wrote:
Hi Daniel, thanks for quick reply!
e.g. 10.100.1.24 - sip phone 10.100.1.85 - server
- sip phone is configured to register to 10.100.1.85:443
- tcp proxy listen on 443
- when SIP request comes, tcp proxy open connect to Kamailio 127.0.0.1:5061,
and send request there
- tcp proxy does not modify sip traffic
- there is pure tcp proxy, it stores pairs outer_ip:port <=> 127.0.0.1:port
(make bind of 2 TCP connects)
the kamctl ul show example for such AOR:
AOR:: 251 Contact:: sip:251@10.100.1.24:4165;transport=TLS Q= ...... Received:: sip:127.0.0.1:39370;transport=tls ...... Socket:: tls:127.0.0.1:5061 is this explanation clear enough, or need to add smth?
Cheers!
-- View this message in context: http://sip-router.1086192.n5.nabble.com/rare-impossibility-to-send-requests-... Sent from the Users mailing list archive at Nabble.com.
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
Daniel-Constantin Mierla-6 wrote
Hello,
so practically all registration appear to come from 127.0.0.1:xyz, where xyz is some port value.
for devices connected to 443, yes it is (kamailio listen 5060/5061, and devices can connect also directly)
My guess is that the connection to the tcp proxy is cut and the kamailio tries to open one.
Did you mean that kamailio could cut it? netstat show both (phone<=>tcpproxy, tcpproxy <=> kamailio) connections are opened. Analysing tcpdump trace - I saw only attempt to open new connection from Kamailio to tcpproxy (this was when kamailio logged "/ no open tcp connection found, opening new one/".
Any other guess what can be the reason of possible connection cut?
Why kamailio could firstly log this: /_tcpconn_find(): tcpconn_find: 0 port 60286 / and after: /tcp_send(): tcp_send: no open tcp connection found/ (I mean why it could be firstly found, and after this it appear no open tcp connection)
Is the tcp proxy routing traffic to other apps? Why not using another Kamailio that does bridging from port 443 to internal kamailio? Should be simple outbound proxy config, using Path for registrations.
Cheers, Daniel
yes, tcp proxy also routes traffic to other apps (used e.g. when client have only 443 opened to the server). Using another kamailio instance - this is the architecture change, and not what we would like to do (current scheme is working on production servers for a long time)
Many thanks for the answers and ideas!
Cheers!
-- View this message in context: http://sip-router.1086192.n5.nabble.com/rare-impossibility-to-send-requests-... Sent from the Users mailing list archive at Nabble.com.
Hi Daniel!
Currently I have complete scheme of the issue (and at last time to describe it here):
Issue logic (all mentioned functions from tcp_main.c):
SIP phone (A-B) connected via TLS, on port 443 to tcp proxy: 192.168.1.24:3487 <--> 192.168.1.85:443 (connect A) 127.0.0.1:64935 <---> 127.0.0.1:5061 (connect B) Kamailio when receives connect, store in function "_tcpconn_add_alias_unsafe" 3 records (A-B), with following keys: hash1.1: (peer_ip, peer_port, 0 ,0) hash1.2: (peer_ip, peer_port, local_addr, 0) hash1.3: (peer_ip, peer_port, local_addr, local_port)
In some moment of time, later, there is another connect (other phone), connected via TCP, on port 80 to tcp proxy: 10.100.253.14:42761 <--> 192.168.1.85:80 (connect C) 127.0.0.1:64935 <--> 127.0.0.1:5060 (connect D) for this connection, Kamailio also creates TCP aliases records (C-D), 2 out of 3 are the same as in (A-B) (peer_ip, peer_port, local_addr are the same for 2 connections) hash1.1: == hash2.1 hash1.2: == hash2.2 and only one key for alias record is different: hash1.3: != hash2.1:
When phone C-D disconnects, kamailio removes 2 records from aliases table (for A-B, now only hash1.3 left).
After this some SIP request has to be sent to phone A-B, Kamailio when make search using function "_tcpconn_find" use as a key (peer_ip, peer_port, local_addr, 0) (Here I wonder, why not (peer_ip, peer_port, local_addr, local_port) used, but making test series, local_port is always 0 ("tcp_addr_hash" called in "_tcpconn_find") And there is no corresponding alias record (it was removed before).
I agree, the case is exotic, but it is reproducible in some deployment with kamailio behind "big NAT" (with port reuse as well) and 2 connections from outer world to ports 5060/5061
Digging sources I have not found easy way, how to fix such issue, cos it looks like need global changes... (for us, we avoided problem by switching off port reuse in TCP proxy)
If I explained something not clear enough, please point out.
Thanks in advance for responses and trying to find out what is wrong!
Cheers
-- View this message in context: http://sip-router.1086192.n5.nabble.com/rare-impossibility-to-send-requests-... Sent from the Users mailing list archive at Nabble.com.
-
Daniel-Constantin Mierla -
Vasiliy Ganchev