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.

classification
Title: asyncio: ssl client-server with "slow" read
Type: behavior Stage: resolved
Components: asyncio Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: MultiSosnooley, asvetlov, bdraco, christian.heimes, kumaraditya, thehesiod, yselivanov
Priority: normal Keywords:

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) * (Python committer) 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) * (Python committer) 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) * (Python triager) 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) * (Python committer) Date: 2022-03-08 13:32
Thanks for checking
History
Date User Action Args
2022-04-11 14:59:11adminsetgithub: 80279
2022-03-08 13:32:40asvetlovsetstatus: open -> closed
resolution: fixed
messages: + msg414753

stage: resolved
2022-03-05 06:54:16kumaradityasetnosy: + kumaraditya
messages: + msg414564
2020-06-25 05:34:31christian.heimessetnosy: + christian.heimes
messages: + msg372301
2020-06-25 00:52:45thehesiodsetmessages: + msg372296
2020-06-24 23:28:10thehesiodsetmessages: + msg372293
2020-06-24 23:02:07thehesiodsetmessages: + msg372291
2020-06-24 19:05:57bdracosetnosy: + bdraco
2020-06-24 10:36:51thehesiodsetnosy: + thehesiod
2019-02-26 12:12:32asvetlovsetmessages: + msg336656
2019-02-24 00:22:05MultiSosnooleycreate