Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
pablogsal opened this issue Apr 23, 2021 · 28 comments
Assignees
Labels
3.10 only security fixes tests Tests in the Lib/test dir topic-SSL type-bug An unexpected behavior, bug, or error

Comments

@pablogsal
Copy link
Member

BPO 43921
Nosy @tiran, @zooba, @pablogsal, @miss-islington
PRs
  • bpo-43921: ignore failing test_wrong_cert_tls13 on Windows (GH-25561) #25561
  • bpo-43921: also accept EOF in post-handshake auth test (GH-25574) #25574
  • bpo-43921: Fix test_ssl.test_pha_required_nocert() #26489
  • [3.10] bpo-43921: Fix test_ssl.test_pha_required_nocert() (GH-26489) #26494
  • bpo-43921: Debug test_ssl failures on Windows #26501
  • bpo-43921: Fix test_ssl.test_wrong_cert_tls13() on Windows #26502
  • [3.10] bpo-43921: Fix test_ssl.test_wrong_cert_tls13() on Windows (GH-26502) #26518
  • bpo-43921: Cleanup test_ssl.test_wrong_cert_tls13() #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:

    assignee = 'https://github.com/tiran'
    closed_at = None
    created_at = <Date 2021-04-23.10:56:18.501>
    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 = <Date 2021-06-04.12:30:13.828>
    user = 'https://github.com/pablogsal'

    bugs.python.org fields:

    activity = <Date 2021-06-04.12:30:13.828>
    actor = 'vstinner'
    assignee = 'christian.heimes'
    closed = False
    closed_date = None
    closer = None
    components = ['Tests', 'SSL']
    creation = <Date 2021-04-23.10:56:18.501>
    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
    Copy link
    Member Author

    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

    @pablogsal pablogsal added the 3.10 only security fixes label Apr 23, 2021
    @pablogsal pablogsal added the 3.10 only security fixes label Apr 23, 2021
    @tiran
    Copy link
    Member

    tiran commented Apr 23, 2021

    New changeset e047239 by Christian Heimes in branch 'master':
    bpo-43921: ignore failing test_wrong_cert_tls13 on Windows (GH-25561)
    e047239

    @tiran
    Copy link
    Member

    tiran commented Apr 23, 2021

    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
    Copy link
    Member

    tiran commented Apr 24, 2021

    New changeset ce9a064 by Christian Heimes in branch 'master':
    bpo-43921: also accept EOF in post-handshake auth test (GH-25574)
    ce9a064

    @pablogsal
    Copy link
    Member Author

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

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

    @pablogsal
    Copy link
    Member Author

    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
    Copy link
    Member

    tiran commented May 25, 2021

    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
    Copy link
    Member Author

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

    @pablogsal
    Copy link
    Member Author

    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
    Copy link
    Member Author

    Also, I think the solution in:

    #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
    Copy link
    Member

    zooba commented May 25, 2021

    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
    Copy link
    Member

    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
    Copy link
    Member Author

    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
    Copy link
    Member Author

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

    https://bugs.python.org/issue44229

    @zooba
    Copy link
    Member

    zooba commented May 25, 2021

    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 39258d3). But short of that, I don't see anything deterministic changed here.

    @pablogsal
    Copy link
    Member Author

    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
    Copy link
    Member

    vstinner commented Jun 2, 2021

    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
    Copy link
    Member

    vstinner commented Jun 2, 2021

    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
    Copy link
    Member

    vstinner commented Jun 2, 2021

    New changeset 320eaa7 by Victor Stinner in branch 'main':
    bpo-43921: Fix test_ssl.test_pha_required_nocert() (GH-26489)
    320eaa7

    @miss-islington
    Copy link
    Contributor

    New changeset e5e93e6 by Miss Islington (bot) in branch '3.10':
    bpo-43921: Fix test_ssl.test_pha_required_nocert() (GH-26489)
    e5e93e6

    @vstinner
    Copy link
    Member

    vstinner commented Jun 3, 2021

    See my comparison of read() and write() errors on Linux vs Windows:
    #26501 (comment)

    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 vstinner changed the title test_ssl fails on Windows buildbots test_ssl: test_wrong_cert_tls13() and test_pha_required_nocert() fail randomly on Windows Jun 3, 2021
    @vstinner vstinner changed the title test_ssl fails on Windows buildbots test_ssl: test_wrong_cert_tls13() and test_pha_required_nocert() fail randomly on Windows Jun 3, 2021
    @vstinner
    Copy link
    Member

    vstinner commented Jun 3, 2021

    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
    Copy link
    Member

    vstinner commented Jun 3, 2021

    New changeset ea0210f by Victor Stinner in branch 'main':
    bpo-43921: Fix test_ssl.test_wrong_cert_tls13() on Windows (GH-26502)
    ea0210f

    @vstinner
    Copy link
    Member

    vstinner commented Jun 3, 2021

    New changeset 5c2191d by Victor Stinner in branch 'main':
    bpo-43921: Cleanup test_ssl.test_wrong_cert_tls13() (GH-26520)
    5c2191d

    @vstinner
    Copy link
    Member

    vstinner commented Jun 3, 2021

    New changeset d2ab15f by Miss Islington (bot) in branch '3.10':
    bpo-43921: Fix test_ssl.test_wrong_cert_tls13() on Windows (GH-26502) (GH-26518)
    d2ab15f

    @vstinner
    Copy link
    Member

    vstinner commented Jun 3, 2021

    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.

    @vstinner vstinner added tests Tests in the Lib/test dir topic-SSL labels Jun 3, 2021
    @vstinner vstinner closed this as completed Jun 3, 2021
    @vstinner vstinner added tests Tests in the Lib/test dir topic-SSL labels Jun 3, 2021
    @vstinner vstinner closed this as completed Jun 3, 2021
    @tiran
    Copy link
    Member

    tiran commented Jun 4, 2021

    Reopening

    @tiran tiran reopened this Jun 4, 2021
    @tiran tiran added the type-bug An unexpected behavior, bug, or error label Jun 4, 2021
    @tiran tiran reopened this Jun 4, 2021
    @tiran tiran added the type-bug An unexpected behavior, bug, or error label Jun 4, 2021
    @vstinner
    Copy link
    Member

    vstinner commented Jun 4, 2021

    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 #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 :-)
    #26520 (comment)

    "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.

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.10 only security fixes tests Tests in the Lib/test dir topic-SSL type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    5 participants