Asyncio server enters an invalid state after a request with SO_LINGER

[drtyrsa]

BPO	33263
Nosy	@giampaolo, @asvetlov, @1st1, @drtyrsa
PRs	bpo-33263: Fix FD leak in _SelectorSocketTransport #6450 [3.7] bpo-33263: Fix FD leak in _SelectorSocketTransport (GH-6450) #7022 [3.6] bpo-33263: Fix FD leak in _SelectorSocketTransport (GH-6450) #7025

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2018-05-21.10:24:08.693>
created_at = <Date 2018-04-11.17:13:48.506>
labels = ['3.8', 'type-bug', '3.7', 'expert-asyncio']
title = 'Asyncio server enters an invalid state after a request with SO_LINGER'
updated_at = <Date 2018-05-21.10:24:08.692>
user = 'https://github.com/drtyrsa'

bugs.python.org fields:

activity = <Date 2018-05-21.10:24:08.692>
actor = 'asvetlov'
assignee = 'none'
closed = True
closed_date = <Date 2018-05-21.10:24:08.693>
closer = 'asvetlov'
components = ['asyncio']
creation = <Date 2018-04-11.17:13:48.506>
creator = 'drtyrsa'
dependencies = []
files = []
hgrepos = []
issue_num = 33263
keywords = ['patch']
message_count = 4.0
messages = ['315196', '317217', '317220', '317227']
nosy_count = 4.0
nosy_names = ['giampaolo.rodola', 'asvetlov', 'yselivanov', 'drtyrsa']
pr_nums = ['6450', '7022', '7025']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue33263'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[drtyrsa]

Long story short, if you have a TCP asyncio-server (implementing asyncio.Protocol) that sends something to socket in connection_made callback, it will leak fds and won't be able to handle some consequent requests, if you will send to it RST right after TCP-handshake.

In my case, these requests are sent by keepalived demon (it makes TCP-checks that way), but they can be easily hand-crafted.

Example server:

import asyncio

class EchoServerClientProtocol(asyncio.Protocol):
    def connection_made(self, transport):
        self.transport = transport
        self.transport.write(b'Say something')

    def data_received(self, data):
        self.transport.write(data)
        self.transport.close()

loop = asyncio.get_event_loop()
coro = loop.create_server(EchoServerClientProtocol, '127.0.0.1', 8888)
server = loop.run_until_complete(coro)
loop.run_forever()

Example client:

import socket
import struct
import time

# first request
sock = socket.socket()
l_onoff = 1
l_linger = 0
sock.setsockopt(socket.SOL_SOCKET, socket.SO_LINGER, struct.pack('ii', l_onoff, l_linger))
sock.connect(('127.0.0.1', 8022))
sock.close()

time.sleep(1)

# second request
sock = socket.socket()
sock.connect(('127.0.0.1', 8888))
print('Got', sock.recv(1024))
sock.sendall(b'Hi there')
print('Got', sock.recv(1024))  # <-- Will hang here
sock.close()

Why is this happening?

1. First request
   1.1. _SelectorSocketTransport.__init__ schedules connection_made and loop.add_reader.
   1.2. connection_made tries to send data to the socket, it fails, _SelectorTransport._fatal_error is called, then _SelectorTransport._force_close is called.
   1.3. _SelectorTransport._force_close removes the reader from the loop (there is none, it's ok), and schedules closing the socket in _SelectorTransport._call_connection_lost.
   1.4. loop.add_reader is called (scheduled on step 1), it calls epoll_ctl, no error is returned because the socket isn't closed yet.
   1.5. the socket is closed by _SelectorTransport._call_connection_lost (scheduled on step 3). The corresponding entry in _SelectorMapping remains and isn't cleaned up.

2. Second request
   2.1. FD from the first request is reused by the OS
   2.2. BaseSelectorEventLoop._add_reader sees that the FD is already in BaseSelectorEventLoop._selector, so it calls _selector.modify
   2.3 _BaseSelectorImpl.modify sees that the events mask is the same, so it uses a shortcut, changing only the callback, but without calling epoll_ctl. The socket won't be polled.

I think the source of the error is in step 1.4, we shouldn't add the reader if we are already closing the transport. I've made a simple PR fixing this, but maybe there are other options here.

[asvetlov]

New changeset a84d0b3 by Andrew Svetlov (Vlad Starostin) in branch 'master':
bpo-33263: Fix FD leak in _SelectorSocketTransport (GH-6450)
a84d0b3

[asvetlov]

New changeset b8b8000 by Andrew Svetlov (Miss Islington (bot)) in branch '3.7':
bpo-33263: Fix FD leak in _SelectorSocketTransport (GH-6450) (bpo-7022)
b8b8000

[asvetlov]

New changeset 7208bfb by Andrew Svetlov in branch '3.6':
[3.6] bpo-33263: Fix FD leak in _SelectorSocketTransport (GH-6450) (bpo-7025)
7208bfb