test_ssl: test_wrong_cert_tls13() and test_pha_required_nocert() fail randomly on Windows

[pablogsal]

BPO	43921
Nosy	@tiran, @zooba, @pablogsal, @miss-islington
PRs	python/cpython#25561 python/cpython#25574 python/cpython#26489 python/cpython#26494 python/cpython#26501 python/cpython#26502 python/cpython#26518 python/cpython#26520

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields: ```python assignee = 'https://github.com/tiran' closed_at = None created_at = labels = ['expert-SSL', 'type-bug', 'tests', '3.10'] title = 'test_ssl: test_wrong_cert_tls13() and test_pha_required_nocert() fail randomly on Windows' updated_at = user = 'https://github.com/pablogsal' ``` bugs.python.org fields: ```python activity = actor = 'vstinner' assignee = 'christian.heimes' closed = False closed_date = None closer = None components = ['Tests', 'SSL'] creation = creator = 'pablogsal' dependencies = [] files = [] hgrepos = [] issue_num = 43921 keywords = ['patch'] message_count = 28.0 messages = ['391677', '391717', '391725', '391775', '394317', '394318', '394320', '394340', '394343', '394346', '394397', '394398', '394399', '394400', '394407', '394408', '394916', '394924', '394944', '394955', '394967', '394968', '395011', '395043', '395044', '395045', '395072', '395078'] nosy_count = 4.0 nosy_names = ['christian.heimes', 'steve.dower', 'pablogsal', 'miss-islington'] pr_nums = ['25561', '25574', '26489', '26494', '26501', '26502', '26518', '26520'] priority = None resolution = None stage = 'needs patch' status = 'open' superseder = None type = 'behavior' url = 'https://bugs.python.org/issue43921' versions = ['Python 3.10'] ```

[pablogsal]

https://buildbot.python.org/all/#/builders/405/builds/9

Extract from the logs:

The Buildbot has detected a new failure on builder AMD64 Windows8.1 Non-Debug 3.x while building python/cpython. Full details are available at: https://buildbot.python.org/all/#builders/405/builds/9

Buildbot URL: https://buildbot.python.org/all/

Worker for this Build: ware-win81-release

Build Reason: \<unknown> Blamelist: E-Paine \63801254+E-Paine@users.noreply.github.com\, Raymond Hettinger \rhettinger@users.noreply.github.com\, Simon Charette \charette.s@gmail.com\, Steve Dower \steve.dower@python.org\

BUILD FAILED: failed test (failure)

Summary of the results of the build (if available): \===================================================

== Tests result: FAILURE then FAILURE ==

395 tests OK.

10 slowest tests:

• test_multiprocessing_spawn: 2 min 43 sec
• test_concurrent_futures: 2 min 25 sec
• test_io: 1 min 43 sec
• test_largefile: 1 min 41 sec
• test_peg_generator: 1 min 39 sec
• test_mmap: 1 min 19 sec
• test_asyncio: 58.8 sec
• test_regrtest: 45.3 sec
• test_unparse: 44.1 sec
• test_tokenize: 41.1 sec

1 test failed: test_ssl

30 tests skipped: test_curses test_dbm_gnu test_dbm_ndbm test_devpoll test_epoll test_fcntl test_fork1 test_gdb test_grp test_ioctl test_kqueue test_multiprocessing_fork test_multiprocessing_forkserver test_nis test_openpty test_ossaudiodev test_pipes test_poll test_posix test_pty test_pwd test_readline test_resource test_spwd test_syslog test_threadsignals test_wait3 test_wait4 test_xxtestfuzz test_zipfile64

1 re-run test: test_ssl

Total duration: 9 min 15 sec

Captured traceback \==================

Traceback (most recent call last):
   File "D:\buildarea\3.x.ware-win81-release.nondebug\build\lib\test\test_ssl.py", line 2333, in wrap_conn
    self.sslconn = self.server.context.wrap_socket(
   File "D:\buildarea\3.x.ware-win81-release.nondebug\build\lib\ssl.py", line 518, in wrap_socket
    return self.sslsocket_class._create(
   File "D:\buildarea\3.x.ware-win81-release.nondebug\build\lib\ssl.py", line 1070, in _create
    self.do_handshake()
   File "D:\buildarea\3.x.ware-win81-release.nondebug\build\lib\ssl.py", line 1339, in do_handshake
    self._sslobj.do_handshake()
 ssl.SSLCertVerificationError: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed: self signed certificate (_ssl.c:969)

Traceback (most recent call last):
  File "D:\buildarea\3.x.ware-win81-release.nondebug\build\lib\test\test_ssl.py", line 255, in wrapper
    return func(*args, **kw)
  File "D:\buildarea\3.x.ware-win81-release.nondebug\build\lib\test\test_ssl.py", line 3171, in test_wrong_cert_tls13
    self.fail("Use of invalid cert should have failed!")
AssertionError: Use of invalid cert should have failed!

Test report \===========

Failed tests:

• test_ssl

Failed subtests:

• test_wrong_cert_tls13 - test.test_ssl.ThreadedTests

Sincerely, -The Buildbot

[tiran]

New changeset e047239eafefe8b19725efffe7756443495cf78b by Christian Heimes in branch 'master': bpo-43921: ignore failing test_wrong_cert_tls13 on Windows (GH-25561) https://github.com/python/cpython/commit/e047239eafefe8b19725efffe7756443495cf78b

[tiran]

Another TLS 1.3 client cert auth test is flaky, too.

https://buildbot.python.org/all/#/builders/577/builds/14/steps/4/logs/stdio

\====================================================================== FAIL: test_pha_required_nocert (test.test_ssl.TestPostHandshakeAuth) ----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\buildarea\pull_request.bolen-windows10\build\lib\test\test_ssl.py", line 4412, in test_pha_required_nocert
    s.recv(1024)
AssertionError: SSLError not raised

[tiran]

New changeset ce9a0643496ba802ea97a3da20eace3a1117ea48 by Christian Heimes in branch 'master': bpo-43921: also accept EOF in post-handshake auth test (GH-25574) https://github.com/python/cpython/commit/ce9a0643496ba802ea97a3da20eace3a1117ea48

[pablogsal]

Unfortunately this is still failing sporadically. Last failure 5 days ago:

https://buildbot.python.org/all/#/builders/405/builds/153

[pablogsal]

The issue is marked as referred blocker, it won't block this beta release, but it will block the next, so we should decide how to proceed by then

[tiran]

I neither have a macOS nor a Windows machine to reproduce and debug the issue. Since I'm cannot reproduce the problem on Linux, I'm unable to debug and fix it.

[pablogsal]

Ok, but bear in mind that this will block the next beta and you are the expert in this area.

[pablogsal]

Also, this started to happen after the changes in PEP-644, and seems that reverting all changes related to the pep fixes the issue (at least I cannot reproduce it anymore after manually reverting the changes).

[pablogsal]

Also, I think the solution in:

https://github.com/python/cpython/pull/25561

(skipping the test) is not acceptable for the next beta.

Christian, I know that this is complicated for you yo reproduce and that this is a hard issue to debug, but this seems linked to the changes in PEP-644 and the reality is that a release manager I don't know the cause of these new failures and the facts are that this is not happening in 3.9 or before.

If we don't fix this for the next beta, I will be forced to revert PEP-644 until we have a permanent fix.

[zooba]

I can't reproduce these on my own (Windows) machine either.

Looking at the output, I think the tests are just going to be inherently flakey. It's not testing the specific scenario directly enough, and relying heavily on implicit synchronization.

We probably just need a different approach to testing these. I think at the very least starting the server on the main test thread and using a helper to send the request is going to be easier to keep things in sync.

But that's not going to be done in time to unblock. Skipping the test seems like an okay compromise.

[vstinner]

Looking at the output, I think the tests are just going to be inherently flakey. It's not testing the specific scenario directly enough, and relying heavily on implicit synchronization.

My notes to debug race conditions: https://pythondev.readthedocs.io/unstable_tests.html#debug-race-conditions

In general, you should run the same test in a loop in many processes in parallel *and* stress the machine with a random workload.

My favorite recipe:

• Terminal 1: python -m test -F -j20 \<... options for the test ...>
• Terminal 2: python -m test -j0 -r -F

Sadly, there is no silver bullet for -j20: sometimes, the machine must be "more idle" to trigger the bug (ex: -j5), sometimes the machine must almost die, be more stressed (-j100).

Happy hacking!

[pablogsal]

Looking at the output, I think the tests are just going to be inherently flakey. It's not testing the specific scenario directly enough, and relying heavily on implicit synchronization.

But 3.9 and 3.8 are not failing on test_ssl, so do something has clearly changed. Are the failing tests new?

[pablogsal]

Also, this seems to be reproducible in MacOS at least:

https://bugs.python.org/issue44229

[zooba]

But 3.9 and 3.8 are not failing on test_ssl, so do something has clearly changed. Are the failing tests new?

They're flakey in the sense that they're not failing reliably, when they clearly should be :)

If something changed about how any part of the response is written into the buffer, it could change when the OS decides to dispatch it and unblock the receiving thread, which is going to affect the state observed by the test at the time it observes it (and as we already know, there are inherent race conditions that sometimes recognise the close of the connection before it's finished reading). These are difficult tests to write, because there are so many weird interactions like this.

In terms of this actual change, my best guess is that one of the removed checks actually mattered on Windows, probably because of a different compile flag. We just use the defaults as generated by their Perl scripts, and I'd hope that there'd be compile errors if anything too blatant was changed (I don't see anything obvious looking through 39258d3595300bc7b952854c915f63ae2d4b9c3e). But short of that, I don't see anything deterministic changed here.

[pablogsal]

Thanks for the explanation!

They're flakey in the sense that they're not failing reliably, when they clearly should be :)

Yeah, I do agree with you in this, but I am still not happy that they *realiably* pass in 3.9 and 3.8 in two different OS where now they fail: Windows and MacOS

But short of that, I don't see anything deterministic changed here.

Well, but the test *deterministically* fail in 3.10 and main and don't fail in 3.9 or 3.8. And it also happens in MacOS.

I really don't want to be annoying here, I really don't. But please, understand my position as RM when I say that I feel uncomfortable with this situation as the test pass without any problem or complication in previous releases and now they don't and there has been a huge change in OpenSSL in the middle.

Also, the asyncio tests for SSL now hang a lot in the refleak buildbots. For example:

https://buildbot.python.org/all/#/builders/673/builds/20

I feel uncomfortable with a solution that basically is "skip the tests", when the test before used to pass deterministically and without problems. I am not an expert in the SSL area by far, so I don't know exactly what is the risk here.

I really apologize if I am insisting on this, but I think is important.

[vstinner]

On the main branch, I can reproduce test_pha_required_nocert() failure:

vstinner@DESKTOP-DK7VBIL C:\vstinner\python\main>python -m test test_ssl -u all -v -F -j5 -m test_pha_required_nocert

test_pha_required_nocert (test.test_ssl.TestPostHandshakeAuth) ...  server:  new connection from ('127.0.0.1', 57456)
 client cert is None
 client did not provide a cert
 server: connection cipher is now ('TLS_AES_256_GCM_SHA384', 'TLSv1.3', 256)
TLS: (<ssl.SSLSocket fd=644, family=AF_INET, type=SOCK_STREAM, proto=0, laddr=('127.0.0.1', 57455), raddr=('127.0.0.1', 57456)>, 'write', TLSVersion.TLSv1_3, _TLSContentType.ALERT, _TLSAlertType.CERTIFICA
TE_REQUIRED, b'\x02t')
Test server failure:
Traceback (most recent call last):
   File "C:\vstinner\python\main\lib\test\test_ssl.py", line 2444, in run
    msg = self.read()
   File "C:\vstinner\python\main\lib\test\test_ssl.py", line 2421, in read
    return self.sslconn.read()
   File "C:\vstinner\python\main\lib\ssl.py", line 1131, in read
    return self._sslobj.read(len)
 ssl.SSLError: [SSL: PEER_DID_NOT_RETURN_A_CERTIFICATE] peer did not return a certificate (_ssl.c:2522)
FAIL

====================================================================== FAIL: test_pha_required_nocert (test.test_ssl.TestPostHandshakeAuth) ----------------------------------------------------------------------

Traceback (most recent call last):
  File "C:\vstinner\python\main\lib\test\test_ssl.py", line 4458, in test_pha_required_nocert
    with self.assertRaisesRegex(
AssertionError: SSLError not raised

[vstinner]

FAIL: test_pha_required_nocert (test.test_ssl.TestPostHandshakeAuth)

When this bug occurs, s.recv(1024) returns an empty byte string (b'').

I wrote PR 26489 to handle this case.

[vstinner]

New changeset 320eaa7f42b413cd5e5436ec92d4dc5ba150395f by Victor Stinner in branch 'main': bpo-43921: Fix test_ssl.test_pha_required_nocert() (GH-26489) https://github.com/python/cpython/commit/320eaa7f42b413cd5e5436ec92d4dc5ba150395f

[miss-islington]

New changeset e5e93e6145090a636e67766a53b758d7ac78e3ad by Miss Islington (bot) in branch '3.10': bpo-43921: Fix test_ssl.test_pha_required_nocert() (GH-26489) https://github.com/python/cpython/commit/e5e93e6145090a636e67766a53b758d7ac78e3ad

[vstinner]

See my comparison of read() and write() errors on Linux vs Windows: https://github.com/python/cpython/pull/26501#issuecomment-853489167

I wrote PR 26502 to fix test_wrong_cert_tls13() on Windows (currently, the test is skipped).

On Linux, read() always raises an exception when the connection is reset.

On Windows, read() sometimes fails with SSL_ERROR_SYSCALL+WSAECONNRESET, and in this case the internal C function raises a SSLEOFError. But the outer Python wrapper method converts SSLEOFError to an empty string because the SSL socket is created with suppress_ragged_eofs=True by default.

I don't know why on Linux read() only fails with SSL_ERROR_SSL with ERR_peek_last_error()=0x14094418, whereas it's not the case on Windows. It may be an implementation detail, different between Windows socket and Linux socket.

[vstinner]

In Python 3.9, test_pha_required_nocert() looks more strict, it requires read() to fail with the 'tlsv13 alert certificate required' error message:

    # receive alert
    with self.assertRaisesRegex(
            ssl.SSLError,
            'tlsv13 alert certificate required'):
        s.recv(1024)

In the main branch, it tolerates "EOF occurred" error:

# test sometimes fails with EOF error. Test passes as long as
# server aborts connection with an error.
with self.assertRaisesRegex(
    ssl.SSLError,
    '(certificate required|EOF occurred)'
):
    # receive CertificateRequest
    data = s.recv(1024)
    self.assertEqual(data, b'OK\n')

        # send empty Certificate + Finish
        s.write(b'HASCERT')

        # receive alert
        s.recv(1024)

[vstinner]

New changeset ea0210fa8ccca769896847f25fc6fadfe9a717bc by Victor Stinner in branch 'main': bpo-43921: Fix test_ssl.test_wrong_cert_tls13() on Windows (GH-26502) https://github.com/python/cpython/commit/ea0210fa8ccca769896847f25fc6fadfe9a717bc

[vstinner]

New changeset 5c2191df9a21a3b3d49dd0711b8d2b92591ce82b by Victor Stinner in branch 'main': bpo-43921: Cleanup test_ssl.test_wrong_cert_tls13() (GH-26520) https://github.com/python/cpython/commit/5c2191df9a21a3b3d49dd0711b8d2b92591ce82b

[vstinner]

New changeset d2ab15f5376aa06ed120164f1b84bb40adbdd068 by Miss Islington (bot) in branch '3.10': bpo-43921: Fix test_ssl.test_wrong_cert_tls13() on Windows (GH-26502) (GH-26518) https://github.com/python/cpython/commit/d2ab15f5376aa06ed120164f1b84bb40adbdd068

[vstinner]

Ok, test_wrong_cert_tls13() and test_pha_required_nocert() of test_ssl should now be more reliable on Windows. I consider that the initial issue is now fixed and I close the issue.

[tiran]

Reopening

• python/cpython#70689 is missing backport to 3.9. I also don't consider the changeset a proper fix. It's a patch that makes the test pass when something goes wrong. We have not yet figured out why something goes wrong on Windows sometimes.

• python/cpython#70707 is missing backports to 3.9 and 3.10

[vstinner]

Christian: I mostly care about buildbots. I cannot reproduce the issue in 3.9. If it's not broken, I don't want to touch the code :-)

For python/cpython#70707, I explained that I don't want to backport it (it's only in main). Moreover, you asked for automated backports, but it failed. If you consider that it should be backported, please go ahead :-) https://github.com/python/cpython/pull/26520#issuecomment-854148173

"GH-26502 is missing backport to 3.9. I also don't consider the changeset a proper fix. It's a patch that makes the test pass when something goes wrong. We have not yet figured out why something goes wrong on Windows sometimes."

I am not convinced that getting an SSLEOFError on Windows is a bug. I cannot explain it why 3.10 and main branches behave differently, but I'm not interested to investigate.