`_SSLProtocolTransport.close()` cannot close the connection until timeout or EOF

[Rongronggg9]

• uvloop version: 0.16.0
• Python version: CPython 3.9.12
• Platform: Debian GNU/Linux bookworm/sid x86_64
• Can you reproduce the bug with PYTHONASYNCIODEBUG in env?: yes
• Does uvloop behave differently from vanilla asyncio? How?: yes, the bug is only reproducible with uvloop

Desciption

If uvloop is enabled, as long as EOF is not reached, even if the response, connection, and session are all closed, the server from which aiohttp requested resources, will still keep sending packets to the aiohttp-client for some time. However, the bug is only reproducible with uvloop enabled.

To reproduce

aiohttp[speedups]==3.8.1
uvloop==0.16.0

import asyncio
import aiohttp
import uvloop
import logging

logging.basicConfig(level=logging.DEBUG)


async def fetch(url):
    async with aiohttp.ClientSession() as session:
        async with session.get(url) as response:
            logging.debug(response)
            logging.debug(response.content)


async def reproduce(wait):
    await fetch('https://sgp-ping.vultr.com/vultr.com.1000MB.bin')
    await asyncio.sleep(wait)  # now you will see that the file is still being downloaded


def main(enable_uvloop):
    if enable_uvloop:
        logging.info('********** Using uvloop **********')
        uvloop.install()  # the bug is only reproducible with uvloop
    else:
        logging.info('********** Using asyncio **********')
    loop = asyncio.new_event_loop()
    loop.set_debug(True)  # or set env PYTHONASYNCIODEBUG=1, not necessary to reproduce the bug
    asyncio.set_event_loop(loop)
    loop.run_until_complete(reproduce(15 if enable_uvloop else 5))
    loop.close()


if __name__ == '__main__':
    main(enable_uvloop=False)
    main(enable_uvloop=True)
    input('Press Enter to exit')

Log and screenshot

INFO:root:********** Using asyncio **********
DEBUG:asyncio:Using selector: EpollSelector
DEBUG:asyncio:Get address info sgp-ping.vultr.com:443, type=<SocketKind.SOCK_STREAM: 1>, flags=<AddressInfo.AI_ADDRCONFIG: 32>
INFO:asyncio:Getting address info sgp-ping.vultr.com:443, type=<SocketKind.SOCK_STREAM: 1>, flags=<AddressInfo.AI_ADDRCONFIG: 32> took 209.423ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('45.32.100.168', 443))]
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x7fc80064dfa0> starts SSL handshake
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x7fc80064dfa0>: SSL handshake took 225.2 ms
DEBUG:asyncio:<asyncio.TransportSocket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 51708), raddr=('45.32.100.168', 443)> connected to 45.32.100.168:443: (<asyncio.sslproto._SSLProtocolTransport object at 0x7fc7ff9b5a00>, <aiohttp.client_proto.ResponseHandler object at 0x7fc800205b20>)
DEBUG:root:<ClientResponse(https://sgp-ping.vultr.com/vultr.com.1000MB.bin) [200 OK]>
<CIMultiDictProxy('Server': 'nginx', 'Date': 'Sat, 21 May 2022 00:29:55 GMT', 'Content-Type': 'application/octet-stream', 'Content-Length': '1048576000', 'Last-Modified': 'Mon, 20 Sep 2021 19:54:01 GMT', 'Connection': 'keep-alive', 'Etag': '"6148e6d9-3e800000"', 'Expires': 'Sun, 22 May 2022 00:29:55 GMT', 'Cache-Control': 'max-age=86400', 'X-Frame-Options': 'DENY', 'X-Content-Type-Options': 'nosniff', 'Access-Control-Allow-Origin': '*', 'Accept-Ranges': 'bytes')>

DEBUG:root:<StreamReader 15968 bytes>
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x7fc80064dfa0>: SSL error in data received
Traceback (most recent call last):
  File "/usr/lib/python3.9/asyncio/sslproto.py", line 534, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.9/asyncio/sslproto.py", line 206, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/lib/python3.9/ssl.py", line 948, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: APPLICATION_DATA_AFTER_CLOSE_NOTIFY] application data after close notify (_ssl.c:2756)
DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False debug=True>
INFO:root:********** Using uvloop **********
DEBUG:asyncio:<uvloop.loop.SSLProtocol object at 0x7fc8040f8b40> starts SSL handshake
DEBUG:asyncio:<uvloop.loop.SSLProtocol object at 0x7fc8040f8b40>: SSL handshake took 227.0 ms
DEBUG:root:<ClientResponse(https://sgp-ping.vultr.com/vultr.com.1000MB.bin) [200 OK]>
<CIMultiDictProxy('Server': 'nginx', 'Date': 'Sat, 21 May 2022 00:30:01 GMT', 'Content-Type': 'application/octet-stream', 'Content-Length': '1048576000', 'Last-Modified': 'Mon, 20 Sep 2021 19:54:01 GMT', 'Connection': 'keep-alive', 'Etag': '"6148e6d9-3e800000"', 'Expires': 'Sun, 22 May 2022 00:30:01 GMT', 'Cache-Control': 'max-age=86400', 'X-Frame-Options': 'DENY', 'X-Content-Type-Options': 'nosniff', 'Access-Control-Allow-Origin': '*', 'Accept-Ranges': 'bytes')>

DEBUG:root:<StreamReader 15968 bytes>
Press Enter to exit	

The bug has also been reported to aiohttp: aio-libs/aiohttp#6762

[Rongronggg9]

Some statistics in my production environment. (In my use case only the response headers and/or the beginning 4KB of the response body is needed.)

[Rongronggg9]

I'd done some deep-dive and found that the bug is a TLS/SSL-relevant bug. Non-TLS connections can be closed even if uvloop is enabled.

-    await fetch('https://sgp-ping.vultr.com/vultr.com.1000MB.bin')
+    await fetch('http://sgp-ping.vultr.com/vultr.com.1000MB.bin')

[Rongronggg9]

I also analyzed the web traffic with Wireshark. With asyncio, RST is immediately sent once the connection was closed; but with uvloop, closing the connection won't change anything as if is it not closed, RST is only sent after the event loop is closed.

[Rongronggg9]

Another deep-dive:

async def fetch(url):
    async with aiohttp.ClientSession() as session:
        async with session.get(url) as response:
            logging.debug(response)
            logging.debug(response.content)
+            await asyncio.sleep(5)  # at this point, only a little part of the response is read, then pends
+            return  # after the connection is "closed", uvloop will resume reading the response

[Rongronggg9]

A deeper dive shows the direct cause of the bug.

async def reproduce(wait):
    await fetch('https://sgp-ping.vultr.com/vultr.com.1000MB.bin')
-    await asyncio.sleep(wait)  # now you will see that the file is still being downloaded
+    await asyncio.sleep(35)  # the download will last for exactly 30s, then abort

---

aiohttp closing its high-level connection causes uvloop to call _SSLProtocolTransport.close().

uvloop/uvloop/sslproto.pyx

Lines 42 to 51 in 3e71ddc

	def close(self):
	"""Close the transport.
	Buffered data will be flushed asynchronously. No more data
	will be received. After all buffered data is flushed, the
	protocol's connection_lost() method will (eventually) called
	with None as its argument.
	"""
	self._closed = True
	self._ssl_protocol._start_shutdown(self.context.copy())

uvloop/uvloop/sslproto.pyx

Lines 559 to 574 in 3e71ddc

	cdef _start_shutdown(self, object context=None):
	if self._state in (FLUSHING, SHUTDOWN, UNWRAPPED):
	return
	# we don't need the context for _abort or the timeout, because
	# TCP transport._force_close() should be able to call
	# connection_lost() in the right context
	if self._app_transport is not None:
	self._app_transport._closed = True
	if self._state == DO_HANDSHAKE:
	self._abort(None)
	else:
	self._set_state(FLUSHING)
	self._shutdown_timeout_handle = \
	self._loop.call_later(self._ssl_shutdown_timeout,
	lambda: self._check_shutdown_timeout())
	self._do_flush(context)

We can easily verify that the low-level connection is closed 30 seconds after aiohttp have "closed" its high-level connection (as long as the response body is big enough). This complies with SSL_SHUTDOWN_TIMEOUT. That is to say, it is SSLProtocol._ssl_shutdown_timeout() that eventually closes the connection.

uvloop/uvloop/includes/consts.pxi

Line 24 in 3e71ddc

DEF SSL_SHUTDOWN_TIMEOUT = 30.0

Now that SSLProtocol._ssl_shutdown_timeout() is called, the conclusion is evident that SSLProtocol._do_flush() causes the reading to be resumed but meanwhile is stuck in something until EOF or timeout is reached, causing the reading sustained.

uvloop/uvloop/sslproto.pyx

Lines 600 to 618 in 3e71ddc

	cdef _do_flush(self, object context=None):
	"""Flush the write backlog, discarding new data received.
	We don't send close_notify in FLUSHING because we still want to send
	the remaining data over SSL, even if we received a close_notify. Also,
	no application-level resume_writing() or pause_writing() will be called
	in FLUSHING, as we could fully manage the flow control internally.
	"""
	try:
	self._do_read_into_void(context)
	self._do_write()
	self._process_outgoing()
	self._control_ssl_reading()
	except Exception as ex:
	self._on_shutdown_complete(ex)
	else:
	if not self._get_write_buffer_size():
	self._set_state(SHUTDOWN)
	self._do_shutdown(context)

---

Here's a simple hotfix to stop uvloop from reading the response happily and not willing to close the connection.

class AiohttpUvloopTransportHotfix(contextlib.AbstractAsyncContextManager):
    def __init__(self, response: aiohttp.ClientResponse):
        self.response = response

    async def __aexit__(self, exc_type, exc_val, exc_tb):
        if UVLOOP_ENABLED:
            self.response.connection.transport.abort()

async def fetch(url):
    async with aiohttp.ClientSession() as session:
        async with session.get(url) as response:
            async with AiohttpUvloopTransportHotfix(response):
                ...

[rojamit]

i have the same problem with httpS server using uvloop, but with asyncio it works as expected.
After close() call i cant see new data_received calls associated with "closed" connection, but incoming traffic persists for about 10 seconds after transport.close(). switching to abort() didnt help

[Rongronggg9]

Hi, @rojamit. I don't really so much familiar with aio servers. Could you please figure out some code to reproduce that?
(I wonder, since it is a TLS/SSL issue, why aio servers are affected? Typically speaking a server itself should not deal with TLS/SSL itself as it is the business of reverse proxies, e.g. Nginx)

[rojamit]

@Rongronggg9 right, its a https reverse proxy implemented with asyncio and httptools. problem occurs only with uvloop, and looks like 1:1 as yours, but on the server-side

about code:

1. server-side: attaching client sockets using loop.connect_accepted_socket with ssl=ssl_context
2. client-side: connect to server then while True: write data at maximum speed
3. server-side: transport.close()

and... traffic still persist for about 10-30 seconds AFTER close()

without uvloop - no problems like this

notice: no new data_received calls after close() occurs, but traffic and CPU load

[rojamit]

@Rongronggg9 hmm, is uvloop abandoned?...

[Rongronggg9]

Hopefully not. Historically speaking, some of the recent versions were released right after a long-time radio silence. If someone figures out a PR to fix this, it could make the process faster. I am not really familiar with C-binding libraries so I can do little.