Repository navigation
test_asyncio: test_start_tls_server_1() fails randomly on the Cirrus CI FreeBSD job #109051
Description
0:14:00 load avg: 2.96 Run tests in parallel using 4 child processes (timeout: 10 min, worker timeout: 15 min)
0:14:01 load avg: 2.96 [1/1/1] test.test_asyncio.test_sslproto failed (1 failure)
Re-running test.test_asyncio.test_sslproto in verbose mode (matching: test_start_tls_client_reg_proto_1, test_start_tls_client_reg_proto_1, test_start_tls_server_1)
test_start_tls_client_reg_proto_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests.test_start_tls_client_reg_proto_1) ... skipped 'Windows only'
test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests.test_start_tls_server_1) ... skipped 'Windows only'
test_start_tls_client_reg_proto_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests.test_start_tls_client_reg_proto_1) ... ok
test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests.test_start_tls_server_1) ... protocol.resume_writing() failed
protocol: <asyncio.sslproto.SSLProtocol object at 0x8417074e0>
transport: <_SelectorSocketTransport fd=8 read=polling write=<polling, bufsize=0>>
Traceback (most recent call last):
File "/tmp/cirrus-ci-build/Lib/asyncio/transports.py", line 300, in _maybe_resume_protocol
self._protocol.resume_writing()
File "/tmp/cirrus-ci-build/Lib/asyncio/sslproto.py", line 905, in resume_writing
assert self._ssl_writing_paused
^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError
Unexpected calls to loop.call_exception_handler():
[{'exception': AssertionError(),
'message': 'protocol.resume_writing() failed',
'protocol': <asyncio.sslproto.SSLProtocol object at 0x8417074e0>,
'transport': <_SelectorSocketTransport closed fd=8>}]
FAIL
======================================================================
FAIL: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests.test_start_tls_server_1)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/tmp/cirrus-ci-build/Lib/test/test_asyncio/functional.py", line 39, in tearDown
self.fail('unexpected calls to loop.call_exception_handler()')
AssertionError: unexpected calls to loop.call_exception_handler()
----------------------------------------------------------------------
Ran 4 tests in 0.599s
FAILED (failures=1, skipped=2)
test test.test_asyncio.test_sslproto failed
1 test failed again:
test.test_asyncio.test_sslproto
== Tests result: FAILURE then FAILURE ==
FreeBSD job: https://cirrus-ci.com/task/5957332299939840
Activity
vstinner commentedon Sep 7, 2023
@emaste @sorcio @zware: I'm unable to reproduce this issue on my FreeBSD VM. Are you able to reproduce it?
vstinner commentedon Sep 7, 2023
See also issue #108973: "test_asyncio: test_subprocess_consistent_callbacks() fails randomly".
sorcio commentedon Sep 7, 2023
Running only the specific test in a --forever loop, no failure after 4k runs. Did you see the test fail on multiple jobs?
sorcio commentedon Sep 7, 2023
Error is a race condition. If HELLO_MSG is not sent by the time start_tls is called, the socket transport writer may try to resume the ssl protocol object assuming it was the protocol that was paused.
I don't understand all this code, but it looks like
_FlowControlMixinkeeps some state about the protocol (_protocol_paused) but is not aware that the protocol object can be replaced.sorcio commentedon Sep 7, 2023
Can be reproduced reliably by setting PAYLOAD_SIZE to a larger value, e.g.
1024 * 500sorcio commentedon Sep 7, 2023
I took some notes about details and possible solutions:
pause_writing()/resume_writing()are called in pairs, and only once per event. Some protocols rely on this promise for correctness.transport.set_protocol()can take any protocol. lt doesn't have a way to know whether the protocol is waiting for a resume, so the transport cannot sync its own internal bookkeeping, and cannot guarantee 1.To avoid this, it could be explicitly required that
set_protocol()is only called with a protocol known to be in the same "paused" state as the current one. Or, just to be make it easier, setting a new protocol could be forbidden between a pause and a resume, and the new protocol should not be waiting a resume. This requirement would cascade onstart_tls(): just don't call it if you are paused1. De facto, this is already required, and it only needs to be made official. I'd bet most protocol implementations are already built this way because they stumbled on this issue at some point. Tests would have to be adapted to follow the same pattern.Alternatively (or in addition to the above),
start_tls()could be changed so to inform the ssl wrapper about the "paused" state (currently SSLProtocol assumes the application protocol is unpaused, but it could take that information in the constructor). It doesn't have a general way to know this information, of course, but transports in the stdlib can expose it in a backwards-compatible way. Third parties implementors already rely on undocumented details (the_start_tls_compatibleflag), so they can adapt if needed.Another option is to ignore the design/documentation issue and just focus on the error. That is, to make SSLProtocol robust to an unpaired resume_writing() call after initialization. Or to change the tests so that they don't start_tls while paused. Not ideal but maybe appealing for a 3.11 fix if needed.
I don't think the requirement can be loosened, i.e. for
set_protocol()to accept any protocol regardless of paused state, without changing the user-facing API to expose such state information.Footnotes
A little care needs to be taken because start_tls yields before it gives the new transport to the application, but I believe the current implementation is fine. Unless a pathological transport preserved a reference to the protocol and decides to call its pause_writing asynchronously, which it's not supposed to do, I don't see a way to violate the precondition. ↩
sorcio commentedon Sep 11, 2023
Ok, I got curious about the origin of this bug and realized that it was introduced when cpython migrated the sslproto code from uvloop. So I found that uvloop also has the bug.
Leaving the design issue aside, why was that assertion even there? It's because the ssl wrapper is in between the original transport and the original protocol, and it adds its own flow control mechanism and its own write buffer.
Different idea (draft). Can we remove the flow control code and the extra buffer? If we do that, we can leave the pause/resume writing business to the underlying transport and the application protocol. The wrapper doesn't have to sync paused-writing state, so this bug disappears.
This changes semantics a bit, because now the application code understands the buffer limits in terms of "application bytes", while the transport sees "ssl bytes". I don't know if this is a problem, but also, I don't believe the current implementation is the correct solution. This is the way it worked in Python 3.10 (before porting the uvloop code) and the change wasn't even mentioned in the release notes.
sorcio commentedon Sep 19, 2023
I opened a PR with the last suggestion, both to test and to discuss the solution.
The change is not insignificant, so I can also propose a smaller one for 3.11/3.12 with less impact on the overall logic.
pythongh-109051: fix start_tls() on paused-for-writing transport
pythongh-109051: fix start_tls() on paused-for-writing transport
sorcio commentedon Sep 20, 2023
Ok, as promised, a less invasive PR that I think can be easily backported up to 3.11 #109603
No changes in logic, just support the case that was not supported.
It also makes a best-effort attempt to preserve compatibility with third-party transports that don't implement
_FlowControlMixin. They are not supported but it's not completely unlikely that existing code uses custom Transport classes, e.g. wrappers.vstinner commentedon Sep 6, 2024
Cirrus CI has been removed. I close the issue. The discussion can continue in #109603 if needed.
vstinner commentedon Apr 30, 2026
test_asyncio pass on FreeBSD buildbots, and Cirrus CI is shutting down.
Fix CI: news entry, lint fixes, and test updates (pythongh-109051)
Fix CI: news entry, lint fixes, and test updates (pythongh-109051)