test_asyncio: test_start_tls_server_1() fails randomly on the Cirrus CI FreeBSD job

[vstinner]

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

Linked PRs

• gh-109051: asyncio: remove outgoing buffer from sslproto #109571
• gh-109051: fix start_tls() on paused-for-writing transport #109603

[vstinner]

@emaste @sorcio @zware: I'm unable to reproduce this issue on my FreeBSD VM. Are you able to reproduce it?

[vstinner]

See also issue #108973: "test_asyncio: test_subprocess_consistent_callbacks() fails randomly".

[sorcio]

Running only the specific test in a --forever loop, no failure after 4k runs. Did you see the test fail on multiple jobs?

[sorcio]

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 _FlowControlMixin keeps some state about the protocol (_protocol_paused) but is not aware that the protocol object can be replaced.

[sorcio]

Can be reproduced reliably by setting PAYLOAD_SIZE to a larger value, e.g. 1024 * 500

[sorcio]

I took some notes about details and possible solutions:

1. There is a documented promise that pause_writing() / resume_writing() are called in pairs, and only once per event. Some protocols rely on this promise for correctness.
2. This requires transports (including middleware kind of transports like the sslproto one) to do some internal bookkeeping, in order to avoid calling the pause/resume callbacks more than once without a paired call.
3. 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 on start_tls(): just don't call it if you are paused¹. 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_compatible flag), 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

1. 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]

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]

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.