Repository navigation
test_asyncio: test_create_server_ssl_over_ssl() failed on ARM64 macOS 3.x #95573
Description
Activity
Findings so far:
- I'm able to reproduce this on my M1 Max laptop running macOS Monterey 12.5 on an installed framework build (i.e.
./configure --enable-framework=) - The test failure is intermittent, related to some resource congestion, easiest way to repro is to run
./python.exe -m test test_asyncio -m test_create_server_ssl_over_ssl -F -j8 - The test failure happens with both
--pydebugand release builds - The test failure happens both on OpenSSL 3.0.0.1.0 as well as on 1.1.1.14.15 (as reported by
ssl._OPENSSL_API_VERSION) - I ran with @tiran's gh-95573: Add debug callback for SSL BIO #95613, debug output from a failure attached on the PR (beware, it's 1.6 MB of text)
- The test is failing for as long as it exists, i.e., since 13c10bf which is definitely related: bpo-44011: New asyncio ssl implementation #31275
Now the open question is: did the new test surface a pre-existing flakiness or was the flakiness introduced by the SSL rewrite in GH-31275?
- I'm able to reproduce this on my M1 Max laptop running macOS Monterey 12.5 on an installed framework build (i.e.
Crash log from 13c10bf:
Thu Aug 4 01:05:08 CEST 2022 Python 3.11.0a5+ 0:00:00 load avg: 7.99 Run tests in parallel using 8 child processes 0:00:01 load avg: 10.71 [ 1/1] test_asyncio failed (1 error) test test_asyncio failed -- Traceback (most recent call last): File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/contextlib.py", line 155, in __exit__ self.gen.throw(typ, value, traceback) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/test/test_asyncio/test_ssl.py", line 155, in _silence_eof_received_warning yield ^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/test/test_asyncio/test_ssl.py", line 1157, in test_create_server_ssl_over_ssl self.loop.run_until_complete(start_server()) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py", line 640, in run_until_complete return future.result() ^^^^^^^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/test/test_asyncio/test_ssl.py", line 1150, in start_server await asyncio.wait_for(asyncio.gather(*tasks), TIMEOUT) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py", line 445, in wait_for return fut.result() ^^^^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/test/test_asyncio/test_ssl.py", line 1128, in test_client await fut ^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/test/test_asyncio/test_ssl.py", line 1102, in prog do(sslobj.write, A_DATA) ^^^^^^^^^^^^^^^^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/test/test_asyncio/test_ssl.py", line 1097, in do sock.send(outgoing.read()) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/Volumes/RAMDisk/installed-13c10bfb77/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/ssl.py", line 1209, in send return self._sslobj.write(data) ^^^^^^^^^^^^^^^^^^^^^^^^ ssl.SSLEOFError: EOF occurred in violation of protocol (_ssl.c:2386) == Tests result: FAILURE == 10 slowest tests: - test_asyncio: 958 ms 1 test failed: test_asyncioProgress! Using a variation of the "easiest way" from @ambv, I am now able to reliably produce the test failure on (some) Intel Macs, Intel Macs on a VM as well as multiple Apple Silicon (M1) Macs using either OpenSSL 1.1 or 3, with or without pydebug, with or without Mac framework build, top of 3.11 source build or with python.org 3.11.0b5 macOS installer, and on multiple macOS versions (in particular, 11.6.8, 12.5, and 13.0 developer beta).
/path/to/python -m test test_asyncio -m test_create_server_ssl_over_ssl -F -j0The key is setting the
-jvalue. In many case,-j0, which computes a default based on the machine configuration is sufficient, but not always. For whatever reason, the failure appears to be much more difficult to reproduce on the Intel Macs I have access to. Rather than using-j0, in some cases, I've had to use a larger value like-j24and even with that it could take 25 or more iterations before a failure on one Intel Mac, whereas on an M1 MacBookPro, the test would fail fairly reliably in one iteration with-j0-> 12 processes.I'm going to step away from this now but ping me if you need help reproducing. I'll also ping @ronaldoussoren here in case this behavior might ring a bell.
I haven't had the time to read though all the conversations about this on Discord, but this reminds me of #26893. I'll see if I can put aside some time tonight for debugging this.
We have decided to revert to unblock the release of 3.11.0rc1
Reacted by Erlend E. Aasland and Christian HeimesIn May 2021, Andrew Svetlov copied the asyncio SSL implementation from uvloop to Python (asyncio). Sadly, Pablo had to revert it (GH-88177) in Python 3.10, due to test_asyncio failures on buildbots.
In Feburary 2022, Kumar Aditya basically copied it again to Python upstream. Sadly, the first release candidate of Python 3.11 is scheduled for tomorrow and there is no asyncio expert available to debug this tricky issue. Moreover, the issue only occurs on macOS which makes is harder to debug (for example, I don't have access to any macOS machine).
By the way, the commit message lacks author information from source repository, and the motivation behind the change is missing. Most of the code was written by Yury and Fantix.
We have decided to revert to unblock the release of 3.11.0rc1
The discussion occurred on Discord #python-dev. For example, Pablo wrote there:
We also have the possibility to revert that change. If the problem is in 3.10 as well that's a pity, but is a safer option given that the RC is tomorrow.
The failing asyncio test_create_server_ssl_over_ssl() test is testing "TLS over TLS".
Reacted by Erlend E. AaslandI found the root reason by temporarily disabling this suppression:
cpython/Lib/test/test_asyncio/test_ssl.py
Lines 1159 to 1160 in 8a0d9a6
Task exception was never retrieved future: <Task finished name='Task-79' coro=<TestSSL.test_create_server_ssl_over_ssl.<locals>.handle_client() done, defined at cpython/Lib/test/test_asyncio/test_ssl.py:1039> exception=OSError(55, 'No buffer space available')> Traceback (most recent call last): File "cpython/Lib/test/test_asyncio/test_ssl.py", line 1042, in handle_client data = await reader.readexactly(len(A_DATA)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "cpython/Lib/asyncio/streams.py", line 728, in readexactly await self._wait_for_data('readexactly') File "cpython/Lib/asyncio/streams.py", line 522, in _wait_for_data await self._waiter File "cpython/Lib/asyncio/selector_events.py", line 1049, in write n = self._sock.send(data) ^^^^^^^^^^^^^^^^^^^^^ OSError: [Errno 55] No buffer space availableI think a reasonable fix is to reduce the test data size:
cpython/Lib/test/test_asyncio/test_ssl.py
Lines 1027 to 1028 in 8a0d9a6
Reducing from 1MB to 64KB seems to work fine on an M1 macOS with
-j64(thanks to @ned-deily and @ambv for reproducing!).Reacted by Erlend E. AaslandI am confused, the original error is not
OSError: [Errno 55] No buffer space availablebut
ssl.SSLEOFError: EOF occurred in violation of protocol (_ssl.c:2386)Could you provide a bit more context on how that error is making the other one appear?
@fantix, thanks for your successful investigation. Exciting find! However, I agree with Pablo that it's not quite clear how silencing a warning might have lead to silencing of the OSError that in turn lead to the SSLEOFError. It's a bit of a head scratcher.
Additionally, speaking of the proposed workaround (I can't make myself call it a fix), don't you think a 1MB blob is realistic enough that it should be supported even in cases of raised concurrency? 64 processes still isn't that much, honestly, but we were able to easily overwhelm the test with just
-j8.Am I right thinking that this suggests that tunneling SSL in SSL with this sslproto implementation isn't feasible for production use? I mean, I've seen JavaScript files over 1MB 😆 Let me know what you think.
Thanks for checking! Those are good questions. Let me try to answer one of them here first:
cpython/Lib/test/test_asyncio/test_ssl.py
Lines 148 to 157 in 6a5104f
I think this
Filteris wrong (originally introduced here, I'll create a fix) - it effectively suppressed all asyncio logging because no logger would have a namehas no effect when using ssl(which should be a part of the message to filter out).In our case here,
StreamReaderProtocolcreates server-side asyncio tasks ofhandle_client()that are not awaited. Their errors went into theasynciologger and got suppressed. When the server-side is failing unexpectedly, the client-sideSSLSocketwould encounter an unexpected disconnection and raisessl.SSLEOFError: EOF occurred in violation of protocol. As we were (by mistake) only showing client-side errors in this case, that became the first thing in sight.For the second question of why the
No buffer space availablewas raised in the first place, I'll need some more time to investigate. Will follow up here soon!Reacted by Shantanu@fantix's discovery led @ronaldoussoren to create a C-only repoducer for the problem, proving it's not an issue with asyncio's new SSL implementation. He filed FB11063974 about this issue in Apple's tracker. I could reproduce the issue using Ronald's code.
Instead of reverting the new asyncio.sslproto, we should instead special-case macOS to decrease the buffer size as @fantix is suggesting. Let's only decrease the buffer for the Mac.
Reacted by Erlend E. Aasland, Fantix King and synodriverThis can now be closed and the 3.11 release is unblocked. Thanks for investigating @tiran and @ned-deily, thanks for identifying the root cause and issuing PRs @fantix, and thanks @ronaldoussoren for ensuring the problem is not Python-specific and following up with Apple.
Reacted by Erlend E. AaslandReacted by Fantix King
test_create_server_ssl_over_ssl() of test_asyncio failed on ARM64 macOS 3.x: https://buildbot.python.org/all/#/builders/725/builds/2392
The same test failed when test_asyncio was re-run.