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

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

feat(env): `NO_UVLOOP` to force disable uvloop

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.)

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')

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.

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

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):
                ...

fix(web): hotfix unclosed `uvloop` SSL transport

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

@rojamit

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)

@Rongronggg9

@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:

server-side: attaching client sockets using loop.connect_accepted_socket with ssl=ssl_context
client-side: connect to server then while True: write data at maximum speed
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

@Rongronggg9

@Rongronggg9 hmm, is uvloop abandoned?...

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.

@Rongronggg9

Sorry for the late reply! With a quick look through the details (thanks @Rongronggg9 for the debugging!), this is probably because the remote peer didn't reply a proper TLS close_notify.

More specifically, transport.close() is similar to socket.close(), they don't imply an immediate shutdown on the low-level resources. Instead, they are supposed to do a graceful shutdown, with all the write buffer flushed and nicely closes the connection - in TLS 1.3 this means each end sends a close_notify message. Which TLS version are you using btw?

So here locates the buggy code:

cdef _do_flush(self, object context=None):
    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)

cdef _do_shutdown(self, object context=None):
    try:
        # we must skip all application data (if any) before unwrap
        self._do_read_into_void(context)  # <--- I am so sad because I am buggy
        try:
            self._sslobj.unwrap()
        except ssl_SSLAgainErrors as exc:
            self._process_outgoing()
        else:
            self._process_outgoing()
            if not self._get_write_buffer_size():
                self._on_shutdown_complete(None)
    except Exception as ex:
        self._on_shutdown_complete(ex)

Being commented out, uvloop shows 100% the same behavior as vanilla asyncio in CPython 3.11 (closing the connection as expected and logging the fatal error):

DEBUG:asyncio:<uvloop.loop.SSLProtocol object at 0x7f9cbfbcf5e0>: Error occurred during shutdown
Traceback (most recent call last):
  File "uvloop/sslproto.pyx", line 624, in uvloop.loop.SSLProtocol._do_shutdown
  File "/usr/lib/python3.11/ssl.py", line 983, in unwrap
    return self._sslobj.shutdown()
           ^^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLError: [SSL: APPLICATION_DATA_AFTER_CLOSE_NOTIFY] application data after close notify (_ssl.c:2672)

You may also inspect the source code of both uvloop and asyncio yourself. Vanilla asyncio in CPython 3.11 indeed does NOT read before unwrap in the shutdown stage.

def _do_flush(self):
    self._do_read()
    self._set_state(SSLProtocolState.SHUTDOWN)
    self._do_shutdown()

def _do_shutdown(self):
    try:
        if not self._eof_received:
            self._sslobj.unwrap()
    except SSLAgainErrors:
        self._process_outgoing()
    except ssl.SSLError as exc:
        self._on_shutdown_complete(exc)
    else:
        self._process_outgoing()
        self._call_eof_received()
        self._on_shutdown_complete(None)

https://github.com/python/cpython/blob/3.11/Lib/asyncio/sslproto.py#L643

this is probably because the remote peer didn't reply a proper TLS close_notify.

After reading more refs, I finally realized that there do be such a probability that the "weird" behavior is caused by misbehaved servers (my case) or clients (#471 (comment)).

Indeed, according to the spec (e.g. https://www.rfc-editor.org/rfc/rfc5246), waiting for close_notify ("two-way shutdown") is considered more secure (to get rid of truncation attacks). However, there are tons of server/client implementations never reply to close_notify, making the "secure" behavior "leak" bandwidth. In all use cases of TLS, HTTPS is absolutely the most widespread, and HTTP/1.0 or newer is not vulnerable to truncation attacks no matter whether the TLS shutdown is one-way or two-way.

So there are three solutions:

just act like how CPython asyncio does, ignore the APPLICATION_DATA_AFTER_CLOSE_NOTIFY error, and no longer wait for close_notify reply from the other side.
keep the current behavior, but add more procedures to determine if the other side will never reply to close_notify, if so, drop the connection early (the current 30s timeout insanely leaks bandwidth).
(?) add an option to switch between the two behavior.

The violation of spec is so widespread that until now no other one realized that it is caused by a violation. My preference is 1.

Thanks for the very detailed reply and sorry for the delay!

I think we should do (1) for TLS 1.2 and lower to "conform with widespread implementation practice", and cut down the SSL_SHUTDOWN_TIMEOUT to maybe 10s to reduce the impact in TLS 1.3.

Python 3.11 behaves differently because #385 wasn't merged in, I'll probably create a PR to do #385 there, together with the proposed fix here.

Close transport after sending close_notify in TLSv1.2

@Dreamsorcerer

cut down the SSL_SHUTDOWN_TIMEOUT to maybe 10s to reduce the impact in TLS 1.3.

At first, I consider it is OK. After doing some tests, I was so sad to find that Cloudflare still violates the spec even in TLS 1.3... It means that the situation of the violation does not become much better in the world of TLS 1.3.

https://speed.cloudflare.com/__down?bytes=500000000

For servers, they maintain a connection pool and recycle connections immediately (which relies on client-side one-way shutdowns), not willing to "waste" any bandwidth to reply to close_notify. For client developers, they don't know much and hardly care about the spec, but worry about bandwidth a lot.

I think we should reconsider Option 3 ("add an option to switch between the two behavior"), both for uvloop and CPython asyncio. If already known that the SSLProtocol is used by HTTP/1.0 or later, libraries on top of uvloop or asyncio can simply force one-way shutdowns, and vice versa.

@Dreamsorcerer @asvetlov @webknjaz Sorry for disturbing you. What do you think about the issue?

@Dreamsorcerer

I think we should reconsider Option 3 ("add an option to switch between the two behavior"), both for uvloop and CPython asyncio. If already known that the SSLProtocol is used by HTTP/1.0 or later, libraries on top of uvloop or asyncio can simply force one-way shutdowns, and vice versa.

@Dreamsorcerer @asvetlov @webknjaz Sorry for disturbing you. What do you think about the issue?

I'm no expert with TLS, so I'm just relying on your investigations. :P

My only question if we add a switch, who changes the switch? If it's the user, when would they know which option to use?

My only question if we add a switch, who changes the switch? If it's the user, when would they know which option to use?

That could be a question to be discussed. What's your preference for that? My preference is that everyone can change it, but HTTP libraries should have two-way shutdowns turned off by default. Option 3 is just my personal advice, not a result of the discussion. You may have other choices :)

Even if both CPython asyncio and uvloop adopted #507, libraries on top of them could still call .abort() to roughly simulate a one-way shutdown.

In fact, I am more concerned about aiohttp maintainers' opinion about the question that "comfort to the spec or save users' bandwidth?" At least for HTTP/1.0 or later, doing a two-way shutdown does not show additional advantages according to my research, but wastes a lot of bandwidth if the other side only supports one-way shutdowns. Most users do not expect such behavior.

Actually I got a new idea. We can implement the SSLTransport.write_eof() method and move the two-way shutdown there, while changing the behavior of SSLTransport.close() to one-way shutdown to meet the general need, as the RFC 8446 does say:

Both parties need not wait to receive a "close_notify" alert before closing their read side of the connection, though doing so would introduce the possibility of truncation.

If the status quo (of CPython, both <= 3.10 and == 3.11) is already taking this risk of truncation, I think it is okay to keep it that way. Users who do care about this risk could just write_eof() and explicitly wait until eof_received(), and then close the transport safely. This also opens doors to implementing "TLS downgrade" - the counter-version of loop.start_tls().

Proposed shutdown flow:

So basically user could now 1) call write_eof() (and expect to receive more TLS data), or 2) return different values in eof_received(). Specifically in (2), if the returned value is a false value, we just close the underlying transport; or else if it's a true value:

We keep the underlying transport open. User could still send TLS data if write_eof() wasn't called, and eventually close the transport when the user chooses to do so.
If the "true value" is an asyncio protocol object, we downgrade the TLS connection to a plaintext connection using the given protocol object, by calling set_protocol() on the underlying transport. The SSLProtocol will be discarded, and the given protocol will receive the underlying transport through connection_made().

@fantix

@fantix Wow, your flow graph is so clear. I second your proposal!

There is a slight question, however. How can a user "return different values in eof_received()"? Shouldn't it be a method of SSLProtocol? Or users are expected to subclass SSLProtocol to change the behavior?

哈哈，哪里哪里🤓谢谢

You may notice 2 eof_received() in the diagram, the green one is the one you mentioned in SSLProtocol, while the red one is a user-provided protocol implementation inheriting directly from asyncio.Protocol, a.k.a. “app protocol”. And that’s the one user would return different values from.

You may notice 2 eof_received() in the diagram, the green one is the one you mentioned in SSLProtocol, while the red one is a user-provided protocol implementation inheriting directly from asyncio.Protocol, a.k.a. “app protocol”. And that’s the one user would return different values from.

Understood. Then I have no more questions and thanks for your explanation :)

feat(env): `NO_UVLOOP` to force disable uvloop

fix(web): hotfix unclosed `uvloop` SSL transport

Navigation Menu

Repository navigation

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

Desciption

To reproduce

Log and screenshot

6 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	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())

	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)

	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)

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

Description

Desciption

To reproduce

Log and screenshot

Activity

Rongronggg9 commented on May 22, 2022

Rongronggg9 commented on May 22, 2022

Rongronggg9 commented on May 22, 2022

Rongronggg9 commented on May 22, 2022

Rongronggg9 commented on May 24, 2022

rojamit commented on May 31, 2022

Rongronggg9 commented on May 31, 2022

rojamit commented on Jun 1, 2022

rojamit commented on Jun 23, 2022

Rongronggg9 commented on Jun 23, 2022

fantix commented on Jun 23, 2022

6 remaining items

Rongronggg9 commented on Sep 15, 2022

Rongronggg9 commented on Sep 16, 2022

fantix commented on Oct 1, 2022

Rongronggg9 commented on Oct 2, 2022

Dreamsorcerer commented on Oct 2, 2022

Rongronggg9 commented on Oct 2, 2022

fantix commented on Oct 2, 2022

fantix commented on Oct 2, 2022

Rongronggg9 commented on Oct 3, 2022

fantix commented on Oct 3, 2022

Rongronggg9 commented on Oct 8, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

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