asyncio.StreamReader.read hangs for reused socket file descriptors when asyncio.StreamWriter.close() is not called

[ntc2]

BPO	44805
Nosy	@ntc2, @asvetlov, @1st1
Files	server.py: Example server code client.py: Example client code

^{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 = None
created_at = <Date 2021-08-02.07:45:23.250>
labels = ['type-bug', '3.9', 'expert-asyncio']
title = 'asyncio.StreamReader.read hangs for reused socket file descriptors when asyncio.StreamWriter.close() is not called'
updated_at = <Date 2021-10-24.08:09:32.313>
user = 'https://github.com/ntc2'

bugs.python.org fields:

activity = <Date 2021-10-24.08:09:32.313>
actor = 'ntc2'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['asyncio']
creation = <Date 2021-08-02.07:45:23.250>
creator = 'ntc2'
dependencies = []
files = ['50198', '50199']
hgrepos = []
issue_num = 44805
keywords = []
message_count = 3.0
messages = ['398731', '398734', '404916']
nosy_count = 3.0
nosy_names = ['ntc2', 'asvetlov', 'yselivanov']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue44805'
versions = ['Python 3.9']

[ntc2]

Problem
=======

When using asyncio streams via

(r,w) = asyncio.open_connection(sock=socket)

with a already connected socket socket, if you call socket.close()
but not w.close() when you're done, then when the OS later reuses
the file descriptor of socket for a new socket, and that new socket
is used with

(r,w) = asyncio.open_connection(sock=socket)

again, the r.read(...) for the new r can hang indefinitely, even
when data is available on the underlying socket. When the hang
happens, closing the socket on the writer side doesn't help, and the
socket gets stuck forever in the CLOSE_WAIT state on the reader
side. Using strace shows that the reader side is stuck in
epoll_wait(...).

Client and server programs that reproduce the bug
=================================================

Run the server in one shell and then run the client in the other
shell. They each take one argument, that controls how they close their
sockets/streams when they're done.

Usage: python3 client.py CLOSE_MODE
Usage: python3 server.py CLOSE_MODE

Where CLOSE_MODE can be

• "": don't close the socket in any way
• "S": close open_connection socket using socket.socket.close()
• "A": close open_connection socket using asyncio.StreamWriter.close()
• "SA": close open_connection socket both ways

These are also attached, but here's the source.

The client.py:

import asyncio, socket, sys

async def client(src_ip, close_mode):
    s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
    src_ip_port = (src_ip, 0)
    s.bind(src_ip_port)
    dst_ip_port = ('127.0.0.2', 12345)
    s.connect(dst_ip_port)
    print(f'Connected from {src_ip}')
    print(s)
    try:
        (r,w) = await asyncio.open_connection(sock=s)
        print('<- ', end='', flush=True)
        in_line = await r.read(100)
        print(in_line)
        out_line = b'client'
        print('-> ', end='', flush=True)
        w.write(out_line)
        await w.drain()
        print(out_line)
    finally:
        if 'S' in close_mode:
            s.close()
        if 'A' in close_mode:
            w.close()
            await w.wait_closed()
        print('Closed socket')
        print()

async def main(close_mode):
    await client('127.0.0.3', close_mode)
    await client('127.0.0.4', close_mode)
close_mode = sys.argv[1]
asyncio.run(main(close_mode))

The server.py:

import asyncio, socket, sys

async def server(close_mode):
    s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
    ip = '127.0.0.2'
    port = 12345
    print(f'Listening on {ip}:{port}')
    print(s)
    try:
        s.bind((ip, port))
        s.listen()
        while True:
            (a, (a_ip, a_port)) = s.accept()
            print(f'Client connected from {a_ip}:{a_port}')
            print(a)
            try:
                (r,w) = await asyncio.open_connection(sock=a)
                print('-> ', end='', flush=True)
                out_line = b'server'
                w.write(out_line)
                await w.drain()
                print(out_line)
                print('<- ', end='', flush=True)
                in_line = await r.read(100)
                print(in_line)
            finally:
                if 'S' in close_mode:
                    a.close()
                if 'A' in close_mode:
                    w.close()
                    await w.wait_closed()
                print('Closed client socket')
                print()
    finally:
        s.close()
        print('Closed server socket')

close_mode = sys.argv[1]
asyncio.run(server(close_mode))

Example session: server.py S and client.py A
================================================

Note that file descriptor 7 is reused on the server side, before the
server hangs on r.read.

Run the server in one shell:

    $ python3 server.py S
    Listening on 127.0.0.2:12345
    <socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('0.0.0.0', 0)>
    Client connected from 127.0.0.3:34135
    <socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.2', 12345), raddr=('127.0.0.3', 34135)>
    -> b'server'
    <- b'client'
    Closed client socket
    
    Client connected from 127.0.0.4:46639
    <socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.2', 12345), raddr=('127.0.0.4', 46639)>
    -> b'server'
    <-

The server is hanging on r.read above.

Run the client in another shell, after starting the server:

    $ python3 client.py A
    Connected from 127.0.0.3
    <socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.3', 34135), raddr=('127.0.0.2', 12345)>
    <- b'server'
    -> b'client'
    Closed socket

Connected from 127.0.0.4
<socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.4', 46639), raddr=('127.0.0.2', 12345)>
<- b'server'
-> b'client'
Closed socket

    $ lsof -ni @127.0.0.2
    COMMAND   PID     USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME
    python3 26692 conathan    6u  IPv4 9992763      0t0  TCP 127.0.0.2:12345 (LISTEN)
    python3 26692 conathan    7u  IPv4 9991149      0t0  TCP 127.0.0.2:12345->127.0.0.4:46639 (CLOSE_WAIT)

Example session: server.py '' and client.py A
================================================

Note that file descriptors are not reused on the server side now, and
nothing hangs.

Server:

    $ python3 server.py ''
    Listening on 127.0.0.2:12345
    <socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('0.0.0.0', 0)>
    Client connected from 127.0.0.3:37833
    <socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.2', 12345), raddr=('127.0.0.3', 37833)>
    -> b'server'
    <- b'client'
    Closed client socket

Client connected from 127.0.0.4:39463
<socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.2', 12345), raddr=('127.0.0.4', 39463)>
-> b'server'
<- b'client'
Closed client socket

Client:

    $ python3 client.py A
    Connected from 127.0.0.3
    <socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.3', 37833), raddr=('127.0.0.2', 12345)>
    <- b'server'
    -> b'client'
    Closed socket

Connected from 127.0.0.4
<socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.4', 39463), raddr=('127.0.0.2', 12345)>
<- b'server'
-> b'client'
Closed socket

Behavior for different combinations of closure modes
====================================================

Perhaps this is overkill, but here's what happens for all 15 possible
combinations of how the client and server close their connections.

For example, "Client=S, Server=S" below means we run $ python3 client.py S and $ python3 server.py S. Sometimes multiple
combinations have the same behavior, so they're grouped together
below.

Client=S, Server='';
Client=S, Server=S;
Client=S, Server=A;
Client=S, Server=SA

---

Client hangs on r.read on second connection, and killing the server
on the other end has no effect, with the socket stuck in CLOSE_WAIT on
the client side forever.

Client='', Server=S;
Client=A, Server=S
------------------

Server hangs on r.read on second connection, and client exits
normally, with the socket stuck in CLOSE_WAIT on the server side
forever.

Client=SA, Server=S

---

Everything works the first time, but if you run the client in a loop,
e.g. with

    $ while true; do python3 client.py SA; done

then the server will eventually hang on r.read after ~3 client
sessions.

Client='', Server='';
Client='', Server=A;
Client=A, Server='';
Client=SA, Server=''
-------------------

Everything works! But here we see that the client and/or server
(whichever side is using '' for mode) is not reusing the socket file
descriptors right away (have to wait for GC). This is evidence that
the problem is due to stale state in asyncio tied to the reused file
descriptors.

Client=A, Server=A;
Client=A, Server=SA;
Client=SA, Server=A;
Client=SA, Server=SA

---

Everything works, but this is not surprising because both sides closed
the StreamWriter with w.close().

Possibly related bugs
=====================

https://bugs.python.org/issue43253: Windows only, calling
socket.socket.close() on a socket used with
asyncio.open_connection(sock=socket).

https://bugs.python.org/issue41317: reused file descriptors across
different connections.

https://bugs.python.org/issue34795,
https://bugs.python.org/issue30064: closing a socket used with
asyncio.

https://bugs.python.org/issue35065: reading from a closed stream can
hang. Could be related if the problem is due to aliased streams from
reused file descriptors.

https://bugs.python.org/issue43183: sockets used with asyncio getting
stuck in WAIT_CLOSED.

System info
===========

$ python3 --version
Python 3.9.6

$ lsb_release -a
LSB Version:    core-9.20170808ubuntu1-noarch:printing-9.20170808ubuntu1-noarch:security-9.20170808ubuntu1-noarch
Distributor ID: Ubuntu
Description:    Ubuntu 18.04.5 LTS
Release:        18.04
Codename:       bionic

[ntc2]

Oh, and I can't count: there are 16 = 4x4 possible combinations of socket closure modes for the client and server. The one I missed was Client='', Server=SA, where everything works because the client doesn't reuse file descriptors and the server closes its sockets correctly.

[ntc2]

Just wanted to clarify: my previous "where everything works" comment is not saying this bug doesn't exist, I just mean I missed one case in my analysis of the bug. The bug is very much there, and easy to reproduce using the example programs I attached.

Bump!

[kumaraditya303]

@ntc2 Is this still an issue? This issue description is very large and is hard to understand what the problem is.

[gvanrossum]

Since the OP has invested much effort in the analysis, maybe they can submit a PR using a fix? We're still short of asyncio experts and it's a lot easier to review a PR than it is to come up with a fix for a complex bug like this.

Also, the first step should be if this is still a problem with 3.11 (or the main branch).

[ntc2]

Yes, this is still an issue, I just tested against 6cbbc26. For example, the python3 server.py A and python3 client.py S combination fails as originally described.

Sorry that the issue description is so large, I may have gotten carried away describing the test cases. But the high level description of the issue is not complex. I'll repeat it again here, trying to be more clear. Let me know if it still doesn't make sense.

Problem

The asyncio streams API provides open_connection, which lets you create a reader-writer stream pair (r,w) from an already connected socket socket, like this:

(r,w) = asyncio.open_connection(sock=socket)

There are two different close functions you can call when you're done with the stream -- w.close() and socket.close() -- and your program can hang if you use socket.close() but not w.close(). In particular, the hang happens when the OS reuses the underlying file descriptor of socket in a new socket socket2, you create a new stream with (r2,w2) = asyncio.open_connection(sock=socket2), and you then call r2.read(...). When the hang happens, the socket socket2 is stuck in the CLOSE_WAIT state.

Example Programs Illustrating the Bug

There are simple example programs attached to the original bug report. You can reproduce the problem by running python3 server.py A in one shell followed by python3 client.py S in another shell.

I don't know anything about how asyncio is implemented internally, so I have no idea how to fix this issue, but hopefully the simple example programs and ease of reproducing the bug will make it obvious to someone familiar with the asyncio internals. If no one who understands the asyncio implementation is available I can take a stab at it myself.

[gvanrossum]

The cause is a bug in the user code, right? Because you should be calling w.close(). I assume you had some much larger body of code where it wasn't obvious to see that this was happening and you spent a significant amount of time debugging this.

The cause of the hang seems to be that, since w.close() isn't called, the socket's fd is never removed from the selector. When the reuse happens, the new socket's fd (which is the same as the old fd) is added to the selector by calling loop._add_writer(), which, for better or for worse, has logic to recognize that it's actually updating an existing fd and just changes the selector registration for the fd (which it thinks is the same fd).

Note: I haven't attempted to run the example code, so I may be off about this. It's possible that the selector is confused about the reader end of the socket instead of the writer, or that what's confused is the transport.

In any case I'm not sure I want to look more into this unless you feel this is a legitimate usage pattern and the problem is a bug in asyncio.

One thing we could do (assuming we agree it's a user bug) would be to make it easier to detect the problem, e.g. when opening a new connection it might check with the selector if the fd still appears to be in use and then raise an exception instead of proceeding. t's possible that this is as simple as calling the selector's get_key() method (it's supposed to raise KeyError if the fd isn't registered), though IIRC transports occasionally register and unregister their fd so it may not be a foolproof method.

[ntc2]

Yes, this is a minimal example illustrating a real bug I ran into porting part of a large program to use asyncio, in order to make some long running networking code timeout-able. I think it's fair to characterize this as a bug in my code, but at minimum the asyncio documentation should probably say not to call socket.close() after calling asyncio.open_connection(sock=socket), and even better if the asyncio library could do something better than hang when this happens.

As to whether my usage pattern was legitimate, I think what happened was that I had some code like this, that didn't use async at all:

socket = create_and_connect_socket()
try:
    long_running_network_stuff(socket)
finally:
    socket.close()

Then I refactored long_running_network_stuff to use asyncio.open_connection internally, so that it could timeout. So the problem is that the refactoring is wrong, and the socket.close() needs to become StreamWriter.close(). But I think it was a reasonable mistake to make, and hard to debug, since the program hangs later when the underlying socket fd is reused, not where the socket.close() call happens.

[gvanrossum]

Yeah, we should at least make sure the docs clarify this. I haven't thought about it too much yet, but when you pass a socket into open_connection() is that a transfer of ownership? It seems logical that if you call open_connection() you should also close the connection at some point (maybe using try/finally too). But does closing the connection actually close the socket for you? Either way, closing an already closed socket is a no-op, so you could keep the following try/except but add another inside the long-running stuff that closes the higher-level connection. (UPDATE: Yes, these are definitely ownership transfers.)

[gvanrossum]

Please have a look at GH-88968 to review the doc changes I am proposing.

[gvanrossum]

I am looking into providing better diagnostics. Since you mentioned hanging in r.read() I looked at it, and the control flow goes to StreamReader._maybe_resume_transport(), then to _SelectorSocketTransport.resume_reading(), then to _SelectorTransport._add_reader(), and finally to BaseSelectorEventLoop._add_reader(). Note the leading underscore in _add_reader(). If we had called add_reader() (no leading underscore), we would have hit this little helper method in BaseSelectorEventLoop:

    def add_reader(self, fd, callback, *args):
        """Add a reader callback."""
        self._ensure_fd_no_transport(fd)
        self._add_reader(fd, callback, *args)

And guess what! The _ensure_fd_no_transport() call performs the check that would have caught your mistake. (I think, I didn't test this yet.) But because we wanted to save a few microseconds we bypassed this check by calling _add_reader() directly. :-(

Next I'm going to run your test scenario and check whether my theory is right.

[gvanrossum]

Yup, it seems to go so. If I change _SelectorTransport._add_reader() to call self._loop.add_reader() (no leading _) then upon reuse the server script gives

Traceback (most recent call last):
  File "/Users/guido/cpython/Lib/asyncio/events.py", line 83, in _run
    self._context.run(self._callback, *self._args)
  File "/Users/guido/cpython/Lib/asyncio/selector_events.py", line 885, in _add_reader
    self._loop.add_reader(fd, callback, *args)
  File "/Users/guido/cpython/Lib/asyncio/selector_events.py", line 339, in add_reader
    self._ensure_fd_no_transport(fd)
  File "/Users/guido/cpython/Lib/asyncio/selector_events.py", line 257, in _ensure_fd_no_transport
    raise RuntimeError(
RuntimeError: File descriptor 7 is used by transport <_SelectorSocketTransport fd=7 read=idle write=<idle, bufsize=0>>

Unfortunately there seems to be something in the client where _add_reader() is called and then add_reader() is also called. I am losing the trail here, but it looks like the fix isn't as simple as I had hoped.

[gvanrossum]

Hm, it looks like that method (added in GH-72555) is for a slightly different cross-check. I have to ponder this some more.

UPDATE: More discussion in this old PR and this old issue.

[gvanrossum]

It's perhaps possible to call self._ensure_fd_no_transport(sock) in create_connection(), except the latter lives in BaseEventLoop, while _ensure_fd_no_transport() is defined in a subclass thereof, BaseSelectorEventLoop. We can probably make this work by overriding create_connection() in the latter. Or maybe the check can be moved to _create_connection_transport().

[ntc2]

I looked at your doc changes in #97936. In conjunction with a defensive "fail fast" fix, like making sure that _ensure_fd_no_transport(sock) is always called as part of asyncio.open_connection(sock=socket), the doc changes seem sufficient. But if for some reason it's not possible to ensure that _ensure_fd_no_transport is always called, and so the possibility of the more subtle failure mode remains (hanging later when the socket fd is reused), then I think the warning in the docs should be more harsh and explicitly tell the user that calling socket.close() after the ownership transfer may lead to subtle bugs in their program.

Anyway, thanks for debugging this! Making sure that _ensure_fd_no_transport is always called as part of open_connection seems like a great solution from the user friendliness point of view, and would have saved me hours of debugging when I ran into this problem.

[gvanrossum]

I consider this good enough.