Leaking TCP Connections with SIPS

I’m having a problem with TCP connections: Asterisk does not close them and hits the open files limit after running for some time.

[May 30 20:46:38] ERROR[17130] chan_sip.c: Could not create sip alert pipe in tcptls thread, error Too many open files

My setup is as follows:
Asterisk 1.6.2.4 on public IP address
Phones: Snom 300 behind NAT, using SIPS
The phones re-register regularly and create a hanging TCP connection everytime they do.

Output in /var/log/asterisk:

[Jun  2 16:22:21] VERBOSE[19312] chan_sip.c:     -- Registered SIP '614' at 93.211.178.141 port 61434
[Jun  2 16:57:22] VERBOSE[19596] chan_sip.c:     -- Registered SIP '614' at 93.211.178.141 port 62196
[Jun  2 17:32:23] VERBOSE[19883] chan_sip.c:     -- Registered SIP '614' at 93.211.178.141 port 62340

Output of netstat:

tcp        0      0 <*-public-ip>:5061      93.211.178.141:61044    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:61193    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:61341    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:61434    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:61491    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:62196    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:62340    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:63940    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:64796    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:64852    ESTABLISHED
tcp        0      0 <*-public-ip>:5061      93.211.178.141:64997    ESTABLISHED

It seems that for every open TCP connection I get one line of output from “core show threads”:

0xb694db90 handle_tcptls_connection started at [  270] tcptls.c ast_tcptls_server_root()

From my sip.conf:

maxexpiry=3600
minexpiry=60
defaultexpiry=120
session-timers=originate
;session-timers=refuse
session-expires=1800
session-minse=90

I tried to set some timeouts to get rid of these TCP connections but neither “session-timers=originate” nor “session-timers=refuse” changes the situation. I didn’t find other configuration options possibly related to my problem.

Does anybody know how to solve this? Or is this a bug in Asterisk?

Re-run with sip set debug on, as per the bug reporting guidelines on issues.asterisk.org/, then raise an issue there. Preferably try the latest 1.6.2.x release, first.

Additional information before I try the latest 1.6.2.x release:

The problem is not that bad anymore with the following settings:

[general]
maxexpiry=3600
minexpiry=60
defaultexpiry=120
qualifyfreq=30
session-timers=originate
session-expires=1800
session-minse=90

[phone-template](!)
qualify=5000

Asterisk is currently running for almost 3 weeks and the number of open tcp connections is “only” 34. The actual number of phones connected is 6. So the number of leaked TCP connections is far less than before. On the other hand the log is now spammed with the following messages for every connection which is closed properly:

[Jun 21 18:35:52] VERBOSE[17371] chan_sip.c:     -- Registered SIP '656' at 87.179.210.215 port 2112
[Jun 21 18:35:53] NOTICE[17371] chan_sip.c: Peer '656' is now Reachable. (114ms / 5000ms)
[Jun 21 22:39:39] NOTICE[20672] chan_sip.c: Peer '656' is now UNREACHABLE!  Last qualify: 109
[Jun 21 22:55:37] WARNING[17371] chan_sip.c: Failure to write to tcp/tls socket
[Jun 21 22:55:57] WARNING[20672] chan_sip.c: sip_xmit of 0x87c6338 (len 640) to 87.179.210.215:2112 returned -2: Success
[Jun 21 22:56:17] WARNING[20672] chan_sip.c: sip_xmit of 0x87e04a0 (len 640) to 87.179.210.215:2112 returned -2: Success
[Jun 21 22:56:37] WARNING[20672] chan_sip.c: sip_xmit of 0x87e04a0 (len 640) to 87.179.210.215:2112 returned -2: Success
[Jun 21 22:56:57] WARNING[20672] chan_sip.c: sip_xmit of 0x87c6338 (len 640) to 87.179.210.215:2112 returned -2: Success
## message repeats every 20 seconds for some time (in this particular case it was for 40 minutes)

A leaking TCP connection does not produce these messages.

The problem seems to be solved with 1.6.2.9: My Asterisk server is now running for 3 days and no TCP connection was leaked so far.

However the log is still full of the following warnings:

If this is expected behavior the log level shouldn’t be warning in my opinion.

I found a similar (the same?) message in a 2 year old entry in the issue tracker: https://issues.asterisk.org/view.php?id=11972
The reporter “pj” said: "Shouldn’t be this warnings moved to debug log level?"
But “jamesgolovich” (manager) said: “I don’t think the log message should be changed to DEBUG, I think it should stay where its at with level WARNING. One thing I do think I need to do is change the code to set errno to something like EHOSTUNREACH. […]”

Are these messages worth a new entry in the issue tracker or should I just live with them?

Hi everybody, this is my first post in this forum…

Can not confirm, that the problem is resolved.

Using 1.6.2.11, i just encountered the very same issue. After about 3 days of running fine, I get the “Could not create sip alert pipe in tcptls thread, error Too many open files” message and nothing works anymore (Clients may not even register with asterisk anymore). After stopping and restarting asterisk, everything works fine again (for how long? …).
I have only 1 client with static internal IP (using UDP), and 2 mobile clients with variable IP addresses (using TCP), so a rather small set up only.

Would be great, if someone could have a look at the TCP connections once again.

I also cannot confirm that the problem is resolved. My earlier guess was wrong.

After a running time of almost 8 weeks now I see 3 leaked tcp connections. During the whole time an average of 4-5 phones where constantly connected.

I’m now running with sip debug as suggested.

Interesting. I’m still running 1.6.2.9 and I’ve enabled sip debug 3 weeks ago. But so far not a single connection was leaked…

David was on it, appears to be a bug, did you guys verify this? It sounds like it may have been coded out on a later 1.6. version.

-Jake
www.voipcitadel.com

Hi!

I run Asterisk 1.6.2.7 and have the same problem that TCP-Connections get leaked.

I have one SIP-Device (Android running CSipSimple). Every time CSipSimple creates a new TCP-Connection, the old connection does not get dropped.

In normal case, there have to be a TCP-Connection-Timeout. The device was registred via 192.168.0.201. The device is currently not withhin the network, but the TCP-Connection is setted up.

asterisk*CLI> sip show tcp Host Port Transport Type 192.168.0.201 54095 TCP Server 192.168.0.201 58252 TCP Server 192.168.0.201 54611 TCP Server 192.168.0.201 40311 TCP Server 192.168.0.201 57166 TCP Server

asterisk # lsof -p 11681 -n asterisk 11681 root 18u IPv4 10557571 0t0 TCP 192.168.0.254:5060->192.168.0.201:58252 (ESTABLISHED) asterisk 11681 root 21u IPv4 10546486 0t0 TCP 192.168.0.254:5060->192.168.0.201:54095 (ESTABLISHED) asterisk 11681 root 24u IPv4 10567195 0t0 TCP 192.168.0.254:5060->192.168.0.201:54611 (ESTABLISHED) asterisk 11681 root 27u IPv4 10572627 0t0 TCP 192.168.0.254:5060->192.168.0.201:40311 (ESTABLISHED) asterisk 11681 root 36u IPv4 10587356 0t0 TCP 192.168.0.254:5060->192.168.0.201:57166 (ESTABLISHED)

asterisk # netstat -anop | grep 'asterisk' tcp 0 0 192.168.0.254:5060 0.0.0.0:* LISTEN 11681/asterisk off (0.00/0/0) tcp 0 0 192.168.0.254:5060 192.168.0.201:58252 ESTABLISHED 11681/asterisk off (0.00/0/0) tcp 0 0 192.168.0.254:5060 192.168.0.201:57166 ESTABLISHED 11681/asterisk off (0.00/0/0) tcp 0 0 192.168.0.254:5060 192.168.0.201:54095 ESTABLISHED 11681/asterisk off (0.00/0/0) tcp 0 0 192.168.0.254:5060 192.168.0.201:54611 ESTABLISHED 11681/asterisk off (0.00/0/0) tcp 0 0 192.168.0.254:5060 192.168.0.201:40311 ESTABLISHED 11681/asterisk off (0.00/0/0) udp 0 0 192.168.0.254:5060 0.0.0.0:* 11681/asterisk off (0.00/0/0) udp 0 0 192.168.0.254:4569 0.0.0.0:* 11681/asterisk off (0.00/0/0) udp 0 0 0.0.0.0:5000 0.0.0.0:* 11681/asterisk off (0.00/0/0) udp 0 0 0.0.0.0:4520 0.0.0.0:* 11681/asterisk off (0.00/0/0) unix 2 [ ACC ] STREAM LISTENING 10545782 11681/asterisk /var/run/asterisk/asterisk.ctl

That ist very strange… The Port is not open anymore. The Device is gone but the TCP-Connection exists.

The whole of 1.6 ceased mainstream maintenance about 18 months ago. The last version of 1.6.2 was 1.6.2.24. You need to upgrade, preferably to version 11, but at least to 1.6.2.24.

Howdy,

True, and 1.6.x is totally dead, so even if this was presented against 1.6.x, no fixes would occur upstream.