26 Jan
2016
26 Jan
'16
2:11 p.m.
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.
26 Jan
26 Jan
4:40 p.m.
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(a)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
5:14 p.m.
New subject: rare impossibility to send requests to TLS connected peer
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.
27 Jan
27 Jan
12:01 a.m.
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(a)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
12:12 p.m.
New subject: rare impossibility to send requests to TLS connected peer
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.
9 Mar
9 Mar
9:08 p.m.
New subject: rare impossibility to send requests to TLS connected peer
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.
2973
days inactive
3016
days old
5 comments
2 participants
participants (2)
-
Daniel-Constantin Mierla -
Vasiliy Ganchev