TCP handle leakage for "stale" connections

[shsmith]

I have noticed that over time the number of IP handles reported by lsof continues to grow and far exceeds the number of connections reported by the sessions RPC.

One IP in particular appears over 1000 times, even though there is no active session for the IP.

Here are the logs from 2 days ago when this IP briefly connected:

INFO:ElectrumX:[21536] SSL 41.144.95.105:52782, 666 total
INFO:ServerManager:closing stale connections [19859, 21536, 20904, 21120, 6123, 21278, 21097, 21124, 21481]

This IP does not appear at all after that.

Possibly related: the "subs" value in the getinfo RPC is much higher than the sum of subs for the sessions RPC. I suspect these are related to the stuck TCP handles.

Live Munin charts: http://vps.hsmiths.com:49001/munin/electrumx-day.html

A snapshot from near block 446220:

full lsof output: http://vps.hsmiths.com:49001/lsof.txt
getinfo output: http://vps.hsmiths.com:49001/getinfo
sessions output: http://vps.hsmiths.com:49001/sessions

[kyuupichan]

I just noticed this having gotten back from a 10 day break. My subs are over-counted, and my groups list way more sessions than exist.

[kyuupichan]

As this was a bug, I've done a backport to 0.9.23. I don't anticipate backporting anything else to 0.9.x.

[shsmith]

I think the leak is still happening.
http://h.hsmiths.com:49001/munin/localdomain/localhost.localdomain/electrumx_lsof-day.png

Using this script I can see that there are currently over 500 IPv4 connections that do not show up in the 'sessions' rpc:

# report lsof for electrumx, omitting known sessions (looking for leakage)

#get electrumx pid
pid=`electrumx_rpc.py getinfo | grep pid | grep -o '[0-9]*'`

#get list of session IP:PORT and convert newline to " -e "
iplist=`electrumx_rpc.py sessions | grep -v Peer | sed -E "s/\s+/ /g" | cut -d" " -f 12 | tr '\n' ' ' | sed 's/ / -e /g'`

#get open IPv handles, omit session addresses and listening ports
lsof -n -p $pid | grep IPv | grep -v -e $iplist LISTEN

This is from the raspberry pi, which I restarted this morning.
http://h.hsmiths.com:49004/munin/localdomain/localhost.localdomain/electrumx_lsof-day.png

You can see that for the first hour or so the open IPv count tracked sessions, but after that IPv got ahead of sessions. Looks like some sessions are ending but not actually closing the socket.

[shsmith]

I searched my logs for the leaked addresses reported by the script and found very few hits.
I suspect these are not electrum connections, but something else scanning the port and getting stuck.

As a test, I did a simple telnet to port 50002 on one server and telnet just sat there with a blank screen. ElectrumX did not log this as a session.
I waited over 10 minutes and the telnet session was still open and waiting for input.

Maybe we need some sort of an initial handshake timeout.
If a connection is accepted but no valid SSL handshake and/or no RPC commands are received in x seconds, the socket should be closed.

[kyuupichan]

I cannot see any way asyncio allows one to control this. A TCP connection goes through immediately to connection_made (and therefore is logged) on creation, but because SSL is wrapped, it doesn't call connection_made until the handshake is complete. The Protocol class is constructed when the initial socket connection is made, but there are no details available of that socket to my application until the handshake completes. If it doesn't, it seems to just sit there forever.

[shsmith]

I wonder if something like this would work:
socket.setdefaulttimeout(env.session_timeout)

[kyuupichan]

The problem I have is I don't have a socket.

…

On Thu, 12 Jan 2017, 08:20 shsmith, ***@***.***> wrote: I wonder if something like this would work: socket.setdefaulttimeout(env.session_timeout) — You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub <#94 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADKliN2KR3IeLNDDspqeIN9cl5I948-nks5rRWPGgaJpZM4LY2Vm> .

[shsmith]

I thought it was a static method in the socket class and applied to all newly created sockets.

[shsmith]

https://docs.python.org/3/library/socket.html?highlight=socket#socket.setdefaulttimeout

[shsmith]

shsmith@c84f68c didn't help because asyncio is using nonblocking sockets.

I suspect the stuck sockets are looping here:
https://github.com/python/asyncio/blob/374930d766c347f126c88d61a75c17a7dd3a2450/asyncio/sslproto.py#L201

This code block does not have any kind of timeout, but one could be added to make use of self._handshake_start_time.