Issue36098
This issue tracker has been migrated to GitHub,
and is currently read-only.
For more information,
see the GitHub FAQs in the Python's Developer Guide.
Created on 2019-02-24 00:22 by MultiSosnooley, last changed 2022-04-11 14:59 by admin. This issue is now closed.
Messages (8) | |||
---|---|---|---|
msg336420 - (view) | Author: MultiSosnooley (MultiSosnooley) | Date: 2019-02-24 00:22 | |
Recently, some awesome contributors add support for implicit ssl mode for aioftp. But this produced some issues and one of them is not relevant to aioftp, but to asyncio. Here is link https://repl.it/@multisosnooley/asyncio-ssl-connection-with-slow-retreiving to reproduce. This code mimics one test of aioftp: filesystem slower, than socket write. Reduced code to reproduce use sleep for this purpose. So we have proper run without ssl (you can test this by removing ssl argument in server and client instantiation) and «buggy» in case of ssl. After some digging in I realised, that someone calls connection_lost of ssl protocol before we read all data from transport. Data sent by server, but client have (looks like 64k) buffer and since there is no transport read fails. Also, I can say (with help of wireshark) that in case of non-ssl connection, tcp FIN initiated by server (as it should be), but in case of ssl — FIN sent by client. Direct code to reproduce ``` import ssl import asyncio import trustme HOST = "127.0.0.1" PORT = 8021 ca = trustme.CA() server_cert = ca.issue_server_cert(HOST) ssl_server = ssl.create_default_context(ssl.Purpose.CLIENT_AUTH) server_cert.configure_cert(ssl_server) ssl_client = ssl.create_default_context(ssl.Purpose.SERVER_AUTH) ca.configure_trust(ssl_client) async def handler(reader, writer): writer.write(b"0" * 4 * 100 * 1024) await writer.drain() writer.close() await asyncio.sleep(1) print("handler done") async def client(): # reader, writer = await asyncio.open_connection(HOST, PORT) reader, writer = await asyncio.open_connection(HOST, PORT, ssl=ssl_client) count = 0 while True: data = await reader.read(8192) count += len(data) print(f"received {len(data)}, total {count}") if not data: break await asyncio.sleep(0.001) writer.close() loop = asyncio.get_event_loop() # start = asyncio.start_server(handler, HOST, PORT) start = asyncio.start_server(handler, HOST, PORT, ssl=ssl_server) server = loop.run_until_complete(start) loop.run_until_complete(client()) server.close() loop.run_until_complete(server.wait_closed()) ``` Output: ``` received 8192, total 8192 received 8192, total 16384 received 8192, total 24576 received 8192, total 32768 received 8192, total 40960 received 8192, total 49152 received 8192, total 57344 received 8192, total 65536 received 8192, total 73728 received 8192, total 81920 received 8192, total 90112 received 8192, total 98304 received 8192, total 106496 received 8192, total 114688 received 8192, total 122880 received 8192, total 131072 received 8192, total 139264 received 8192, total 147456 received 8192, total 155648 received 8192, total 163840 received 8192, total 172032 received 8192, total 180224 received 8192, total 188416 received 8192, total 196608 received 8192, total 204800 received 8192, total 212992 received 8192, total 221184 received 8192, total 229376 received 8192, total 237568 received 8192, total 245760 received 8192, total 253952 received 8192, total 262144 received 8192, total 270336 received 8192, total 278528 received 8192, total 286720 received 8192, total 294912 received 8192, total 303104 received 8192, total 311296 received 8192, total 319488 received 8192, total 327680 received 8192, total 335872 Traceback (most recent call last): File "slow-data-test.py", line 46, in <module> loop.run_until_complete(client()) File "/home/poh/.pyenv/versions/3.6.7/lib/python3.6/asyncio/base_events.py", line 473, in run_until_complete return future.result() File "slow-data-test.py", line 33, in client data = await reader.read(8192) File "/home/poh/.pyenv/versions/3.6.7/lib/python3.6/asyncio/streams.py", line 640, in read self._maybe_resume_transport() File "/home/poh/.pyenv/versions/3.6.7/lib/python3.6/asyncio/streams.py", line 408, in _maybe_resume_transport self._transport.resume_reading() File "/home/poh/.pyenv/versions/3.6.7/lib/python3.6/asyncio/sslproto.py", line 351, in resume_reading self._ssl_protocol._transport.resume_reading() AttributeError: 'NoneType' object has no attribute 'resume_reading' ``` |
|||
msg336656 - (view) | Author: Andrew Svetlov (asvetlov) * ![]() |
Date: 2019-02-26 12:12 | |
Thanks for the report. We definitely have to fix `AttributeError`. Unfortunately, SSL implementation in asyncio is very tricky. Yuri has an experimental asyncio ssl replacement in his uvloop project rewritten from scratch. There is a plan to port it into asyncio itself. P.S. `await writer.drain()` doesn't send all data to buffer but ensures that the write buffer size is below high watermark limit (https://docs.python.org/3/library/asyncio-protocol.html#asyncio.WriteTransport.set_write_buffer_limits) Actually, it is good. Even after pushing a data into socket buffer you have no knowledge when the data is delivered to peer (or maybe not delivered at all at the moment of socket closing). Moreover, when I experimented with write buffer disabling (transport.set_write_buffer_limits(1)) in aiohttp server benchmarks was executed about 50% slower for simple 'ping' request. |
|||
msg372291 - (view) | Author: Alexander Mohr (thehesiod) * | Date: 2020-06-24 23:02 | |
as an FYI I've reproduced this with the httpx library as well: https://repl.it/repls/PristineBonyBugs#main.py. It reproduces on this site but I've been unable to reproduce it locally. It does always reproduce on our production systems. what's interesting is that it I can't seem to be able to reproduce it with aiohttp either on that site or locally: https://repl.it/@thehesiod/PristineBonyBugs-1#main.py does aiohttp do something to avoid this scenario? |
|||
msg372293 - (view) | Author: Alexander Mohr (thehesiod) * | Date: 2020-06-24 23:28 | |
I've updated https://repl.it/@thehesiod/PristineBonyBugs#main.py to contain both httpx + aiohttp testcases, and now httpx reproduces almost immediately and aiohttp is still ok |
|||
msg372296 - (view) | Author: Alexander Mohr (thehesiod) * | Date: 2020-06-25 00:52 | |
so I did some investigation into the difference between aiohttp + httpx and it appears that for some reason httpx does an extra read after the connection is closed. |
|||
msg372301 - (view) | Author: Christian Heimes (christian.heimes) * ![]() |
Date: 2020-06-25 05:34 | |
The additional read may read the TLS shutdown alert from the wire. The TLS record layer can send additional messages besides application layer data, e.g. for post handshake authentication, sessions, rekeying, and to indicate that one side is shutting down the current TLS connection. To investigate you can either use the undocumented SSLContext._msg_callback debug hook or Wireshark with SSLKEYLOGFILE env var (available since 3.8). |
|||
msg414564 - (view) | Author: Kumar Aditya (kumaraditya) * ![]() |
Date: 2022-03-05 06:54 | |
This has been fixed with bpo-44011 on main branch. Output on main branch: -------------------------------------------------------------------------- /workspaces/cpython/main.py:42: DeprecationWarning: There is no current event loop loop = asyncio.get_event_loop() received 8192, total 8192 received 8192, total 16384 received 8192, total 24576 received 8192, total 32768 received 8192, total 40960 received 8192, total 49152 received 8192, total 57344 received 8192, total 65536 received 8192, total 73728 received 8192, total 81920 received 8192, total 90112 received 8192, total 98304 received 8192, total 106496 received 8192, total 114688 received 8192, total 122880 received 8192, total 131072 received 8192, total 139264 received 8192, total 147456 received 8192, total 155648 received 8192, total 163840 received 8192, total 172032 received 8192, total 180224 received 8192, total 188416 received 8192, total 196608 received 8192, total 204800 received 8192, total 212992 received 8192, total 221184 received 8192, total 229376 received 8192, total 237568 received 8192, total 245760 received 8192, total 253952 received 8192, total 262144 received 8192, total 270336 received 8192, total 278528 received 8192, total 286720 received 8192, total 294912 received 8192, total 303104 received 8192, total 311296 received 8192, total 319488 received 8192, total 327680 received 8192, total 335872 received 8192, total 344064 received 8192, total 352256 received 8192, total 360448 received 8192, total 368640 received 8192, total 376832 received 8192, total 385024 received 8192, total 393216 received 8192, total 401408 received 8192, total 409600 received 0, total 409600 ------------------------------------------------------------------------ This can be closed now @asvetlov. |
|||
msg414753 - (view) | Author: Andrew Svetlov (asvetlov) * ![]() |
Date: 2022-03-08 13:32 | |
Thanks for checking |
History | |||
---|---|---|---|
Date | User | Action | Args |
2022-04-11 14:59:11 | admin | set | github: 80279 |
2022-03-08 13:32:40 | asvetlov | set | status: open -> closed resolution: fixed messages: + msg414753 stage: resolved |
2022-03-05 06:54:16 | kumaraditya | set | nosy:
+ kumaraditya messages: + msg414564 |
2020-06-25 05:34:31 | christian.heimes | set | nosy:
+ christian.heimes messages: + msg372301 |
2020-06-25 00:52:45 | thehesiod | set | messages: + msg372296 |
2020-06-24 23:28:10 | thehesiod | set | messages: + msg372293 |
2020-06-24 23:02:07 | thehesiod | set | messages: + msg372291 |
2020-06-24 19:05:57 | bdraco | set | nosy:
+ bdraco |
2020-06-24 10:36:51 | thehesiod | set | nosy:
+ thehesiod |
2019-02-26 12:12:32 | asvetlov | set | messages: + msg336656 |
2019-02-24 00:22:05 | MultiSosnooley | create |