classification
Title: test_asyncio: test_start_tls_server_1() TimeoutError on Fedora 29
Type: Stage: resolved
Components: asyncio, Tests Versions: Python 3.9, Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, christian.heimes, cstratak, doko, koobs, lukasz.langa, matrixise, miss-islington, ncoghlan, ned.deily, op368, pablogsal, vstinner, xtreak, yselivanov
Priority: deferred blocker Keywords: 3.7regression, patch

Created on 2019-02-15 10:12 by matrixise, last changed 2019-10-16 09:59 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
stdout.txt matrixise, 2019-02-15 10:12
stderr.txt matrixise, 2019-02-15 10:12
stderr-op368.txt op368, 2019-03-04 20:18 test_start_tls_server_1 only
Pull Requests
URL Status Linked Edit
PR 14080 merged asvetlov, 2019-06-14 14:14
PR 14084 merged miss-islington, 2019-06-14 15:26
PR 14086 merged vstinner, 2019-06-14 15:42
PR 14150 merged miss-islington, 2019-06-17 09:48
PR 14151 merged miss-islington, 2019-06-17 09:48
PR 16815 merged vstinner, 2019-10-15 23:37
PR 16817 merged miss-islington, 2019-10-16 08:18
PR 16818 merged vstinner, 2019-10-16 08:25
Messages (44)
msg335596 - (view) Author: Stéphane Wirtel (matrixise) * (Python committer) Date: 2019-02-15 10:12
======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/stephane/src/github.com/python/cpython-original/Lib/test/test_asyncio/test_sslproto.py", line 510, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/home/stephane/src/github.com/python/cpython-original/Lib/asyncio/base_events.py", line 589, in run_until_complete
    return future.result()
  File "/home/stephane/src/github.com/python/cpython-original/Lib/test/test_asyncio/test_sslproto.py", line 503, in run_main
    await asyncio.wait_for(
  File "/home/stephane/src/github.com/python/cpython-original/Lib/asyncio/tasks.py", line 461, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

my current revision: 3e028b2d40370dc986b6f3146a7ae927bc119f97

system: fedora 29
compiled with gcc

gcc (GCC) 8.2.1 20181215 (Red Hat 8.2.1-6)

No issue on Travis, but this test fails on my computer and I cleaned my repo with git clean -dfqx
msg335597 - (view) Author: Stéphane Wirtel (matrixise) * (Python committer) Date: 2019-02-15 10:12
here is the stderr.txt
msg335626 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2019-02-15 17:38
Not sure if it's related but there was a similar report on failure in freebsd bots with tls1.3 : issue35031 . Can you please add SSL info with ./python -m test.pythoninfo | grep ssl ?

Test runs fine on my ubuntu 16.04 machine with below info

$ ./python -m test.pythoninfo | grep ssl
ssl.HAS_SNI: True
ssl.OPENSSL_VERSION: OpenSSL 1.0.2g  1 Mar 2016
ssl.OPENSSL_VERSION_INFO: (1, 0, 2, 7, 15)
ssl.OP_ALL: 0x800003ff
ssl.OP_NO_TLSv1_1: 0x10000000
msg335629 - (view) Author: Charalampos Stratakis (cstratak) * Date: 2019-02-15 17:56
Fedora 29 has openssl 1.1.1 which seems to be related.
msg335635 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2019-02-15 18:49
I can confirm that this fails on a fresh fedora 29 VM as of commit 355f16f. The changes in PR 10011 make this test pass.

SSL version and OS details

$ cat /etc/fedora-release
Fedora release 29 (Twenty Nine)
$ uname -a
Linux fedora-s-1vcpu-1gb-blr1-01 4.20.7-200.fc29.x86_64 #1 SMP Wed Feb 6 19:16:42 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
$ ./python -m test.pythoninfo | grep ssl
ssl.HAS_SNI: True
ssl.OPENSSL_VERSION: OpenSSL 1.1.1a FIPS  20 Nov 2018
ssl.OPENSSL_VERSION_INFO: (1, 1, 1, 1, 15)
ssl.OP_ALL: 0x80000054
ssl.OP_NO_TLSv1_1: 0x10000000

# Test failure with tracemalloc

$ ./python -X tracemalloc -m unittest -v test.test_asyncio.test_sslproto.SelectorStartTLSTests
test_buf_feed_data (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_create_connection_ssl_failed_certificate (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_create_connection_ssl_slow_handshake (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_handshake_timeout (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_client_buf_proto_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_client_corrupted_ssl (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_client_reg_proto_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... /root/cpython/Lib/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x7f2087642170>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
Object allocated at (most recent call last):
  File "/root/cpython/Lib/asyncio/sslproto.py", lineno 446
    self._app_transport = _SSLProtocolTransport(self._loop, self)
ERROR
test_start_tls_slow_client_cancel (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... Unhandled error in exception handler
context: {'message': 'Future exception was never retrieved', 'exception': ConnectionResetError(104, 'Connection reset by peer'), 'future': <Future finished exception=ConnectionResetError(104, 'Connection reset by peer')>}
Traceback (most recent call last):
  File "/root/cpython/Lib/asyncio/base_events.py", line 1653, in call_exception_handler
    self._exception_handler(self, context)
  File "/root/cpython/Lib/test/test_asyncio/functional.py", line 22, in loop_exception_handler
    self.loop.default_exception_handler(context)
AttributeError: 'NoneType' object has no attribute 'default_exception_handler'
/root/cpython/Lib/asyncio/base_events.py:675: ResourceWarning: unclosed <socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 34497)>
  timer = events.TimerHandle(when, callback, args, self, context)
Object allocated at (most recent call last):
  File "/root/cpython/Lib/asyncio/base_events.py", lineno 1360
    sock = socket.socket(af, socktype, proto)
ok
test_start_tls_wrong_args (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok

======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/cpython/Lib/test/test_asyncio/test_sslproto.py", line 510, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/root/cpython/Lib/asyncio/base_events.py", line 589, in run_until_complete
    return future.result()
  File "/root/cpython/Lib/test/test_asyncio/test_sslproto.py", line 503, in run_main
    await asyncio.wait_for(
  File "/root/cpython/Lib/asyncio/tasks.py", line 461, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

----------------------------------------------------------------------
Ran 10 tests in 63.797s

FAILED (errors=1)

# With PR 10011 applied to Fedora

$ ./python -X tracemalloc -m unittest -v test.test_asyncio.test_sslproto.SelectorStartTLSTests
test_buf_feed_data (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_create_connection_ssl_failed_certificate (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_create_connection_ssl_slow_handshake (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_handshake_timeout (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_client_buf_proto_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_client_corrupted_ssl (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_client_reg_proto_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_slow_client_cancel (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok
test_start_tls_wrong_args (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... ok

----------------------------------------------------------------------
Ran 10 tests in 3.734s

OK
msg336986 - (view) Author: Open Close (op368) * Date: 2019-03-02 04:19
I have the same TimeoutError on Arch linux PC (openssl 1.1.1a).

It is random, but for now running test continuously at most 5 times successfully brings about the fail.

So I think msg335635 needs re-checking.
He saids PR 10011 makes this test pass in fedora 29 VM,
but thinking about that it only adds an conditional to FreeBSD, it is not likely.

    if sys.platform.startswith('freebsd'):
        client_context.options |= ssl.OP_NO_TLSv1_3

And indded, if commenting out the conditional line,
the test actually passes.
So I also think the commit needs re-considering.
f777fa5f2bd16ac8d60416eaa64eb9d2cf84ffac (Opt out of TLS 1.3 only on FreeBSD) 

---

$ uname -a
Linux **** 4.20.4-arch1-1-ARCH #1 SMP PREEMPT Wed Jan 23 00:12:22 UTC 2019 x86_64 GNU/Linux
(native, not venv nor vm)

$ ./python -m test.pythoninfo | grep ssl
ssl.HAS_SNI: True
ssl.OPENSSL_VERSION: OpenSSL 1.1.1a  20 Nov 2018
ssl.OPENSSL_VERSION_INFO: (1, 1, 1, 1, 15)
ssl.OP_ALL: 0x80000054
ssl.OP_NO_TLSv1_1: 0x10000000

$ ./python -X tracemalloc -m unittest -v test.test_asyncio.test_sslproto.SelectorStartTLSTests.test_start_tls_server_1
...
======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/philo/me/git/cpython/Lib/test/test_asyncio/test_sslproto.py", line 510, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/home/philo/me/git/cpython/Lib/asyncio/base_events.py", line 589, in run_until_complete
    return future.result()
  File "/home/philo/me/git/cpython/Lib/test/test_asyncio/test_sslproto.py", line 503, in run_main
    await asyncio.wait_for(
  File "/home/philo/me/git/cpython/Lib/asyncio/tasks.py", line 461, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

----------------------------------------------------------------------
Ran 1 test in 60.076s
msg336991 - (view) Author: Open Close (op368) * Date: 2019-03-02 05:22
It may be openssl 1.1.1a specific.
I don't understand most of what they say,
but the changelog (to 1.1.1b) 'looks' suspicious.
https://www.openssl.org/news/changelog.html#x1

...Actually Archlinux updated openssl to 1.1.1b about 4 days ago,
so I can 'test' 1.1.1b.
But which means I may not be able to reproduce the fail after that.
msg337125 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-03-04 15:00
Interesting code in test_ssl.py:

            except (ConnectionResetError, BrokenPipeError) as e:
                # We treat ConnectionResetError as though it were an
                # SSLError - OpenSSL on Ubuntu abruptly closes the
                # connection when asked to use an unsupported protocol.
                #
                # BrokenPipeError is raised in TLS 1.3 mode, when OpenSSL
                # tries to send session tickets after handshake.
                # https://github.com/openssl/openssl/issues/6342
                self.server.conn_errors.append(str(e))
                if self.server.chatty:
                    handle_error("\n server:  bad connection attempt from " + repr(self.addr) + ":\n")
                self.running = False
                self.close()
                return False

and

                except ConnectionResetError:
                    # XXX: OpenSSL 1.1.1 sometimes raises ConnectionResetError
                    # when connection is not shut down gracefully.
                    if self.server.chatty and support.verbose:
                        sys.stdout.write(
                            " Connection reset by peer: {}\n".format(
                                self.addr)
                        )
                    self.close()
                    self.running = False


Interesting commit:

commit 529525fb5a8fd9b96ab4021311a598c77588b918
Author: Christian Heimes <christian@python.org>
Date:   Wed May 23 22:24:45 2018 +0200

    bpo-33618: Enable TLS 1.3 in tests (GH-7079)
    
    TLS 1.3 behaves slightly different than TLS 1.2. Session tickets and TLS
    client cert auth are now handled after the initialy handshake. Tests now
    either send/recv data to trigger session and client certs. Or tests
    ignore ConnectionResetError / BrokenPipeError on the server side to
    handle clients that force-close the socket fd.
    
    To test TLS 1.3, OpenSSL 1.1.1-pre7-dev (git master + OpenSSL PR
    https://github.com/openssl/openssl/pull/6340) is required.
    
    Signed-off-by: Christian Heimes <christian@python.org>
msg337147 - (view) Author: Open Close (op368) * Date: 2019-03-04 20:18
uploading stderr-op368.txt.
(basically the same as Stéphane and Karthikeyan.)
msg337239 - (view) Author: Stéphane Wirtel (matrixise) * (Python committer) Date: 2019-03-05 21:36
./python -m test -W -u network -j0 -r -F test_asyncio

ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/stephane/src/github.com/python/cpython/Lib/test/test_asyncio/test_sslproto.py", line 510, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/home/stephane/src/github.com/python/cpython/Lib/asyncio/base_events.py", line 589, in run_until_complete
    return future.result()
  File "/home/stephane/src/github.com/python/cpython/Lib/test/test_asyncio/test_sslproto.py", line 503, in run_main
    await asyncio.wait_for(
  File "/home/stephane/src/github.com/python/cpython/Lib/asyncio/tasks.py", line 461, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

----------------------------------------------------------------------

Ran 2044 tests in 113.604s

openssl 1.1.1b

revision: d8b3a98c9098c66a714fd5593e1928af0ffbc631
msg337563 - (view) Author: Open Close (op368) * Date: 2019-03-09 08:51
I updated my PC (OpenSSL 1.1.1b).
the same TimeoutError as before.

$ ./python -m test.pythoninfo | grep ssl
ssl.HAS_SNI: True
ssl.OPENSSL_VERSION: OpenSSL 1.1.1b  26 Feb 2019
ssl.OPENSSL_VERSION_INFO: (1, 1, 1, 2, 15)
ssl.OP_ALL: 0x80000054
ssl.OP_NO_TLSv1_1: 0x10000000
msg337974 - (view) Author: Matthias Klose (doko) * (Python committer) Date: 2019-03-15 08:38
seen in Ubuntu 19.04 as well. Started after the openssl update form 1.1.1 to 1.1.1b.
msg338129 - (view) Author: Matthias Klose (doko) * (Python committer) Date: 2019-03-17 13:44
setting to release-blocker for evaluation. the freebsd solution seems to be wrong, just avoiding the error.  Is the test correct, or do we have an issue that TLSv1.3 isn't properly handled?
msg338368 - (view) Author: Charalampos Stratakis (cstratak) * Date: 2019-03-19 15:50
On my system with openssl 1.1.1b, by reducing the PAYLOAD_SIZE the test passes successfully.

It starts failing when it's bigger than 1024 * 95
msg338749 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-03-24 20:08
I am changing the priority of this to "deferred blocker" as our current strategy outlined in Issue34631 is to target full support of OpenSSL 1.1.1 in 3.7.4 and prior to 3.8.0b1.
msg345597 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-14 15:26
New changeset f0749da9a535375f05a2015e8960e8ae54877349 by Victor Stinner (Andrew Svetlov) in branch 'master':
bpo-35998: Avoid TimeoutError in test_asyncio: test_start_tls_server_1() (GH-14080)
https://github.com/python/cpython/commit/f0749da9a535375f05a2015e8960e8ae54877349
msg345598 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-14 15:46
Finally fixed
msg345605 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-14 16:05
> Finally fixed

Thank you very much! I looked at this issue 2 or 3 times but I failed to fix it. This bug was super annoying: it failed multiple times per week on Fedora buildbots.
msg345607 - (view) Author: miss-islington (miss-islington) Date: 2019-06-14 16:12
New changeset 0c2eb6d21013d77e1160250d3cf69ca80215d064 by Miss Islington (bot) in branch '3.8':
bpo-35998: Avoid TimeoutError in test_asyncio: test_start_tls_server_1() (GH-14080)
https://github.com/python/cpython/commit/0c2eb6d21013d77e1160250d3cf69ca80215d064
msg345608 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-14 16:26
New changeset 33feb2e1a391cde91aefcb8d9cf5144b5fbc5d87 by Victor Stinner in branch '3.7':
bpo-35998: Avoid TimeoutError in test_asyncio: test_start_tls_server_1() (GH-14080) (GH-14086)
https://github.com/python/cpython/commit/33feb2e1a391cde91aefcb8d9cf5144b5fbc5d87
msg345623 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-14 17:52
Thanks for the review, Victor!
I have had to fix it much earlier :(
msg345640 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-14 21:51
> I have had to fix it much earlier :(

That's fine. If this bug was more annoying, I would have it fixed myself
earlier. But I had other more critical bugs to fix before that one. The
important part is that it is fixed now.
msg345644 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-14 22:14
Sadly, the fix is not perfect, the test failed on the very "x86 Windows7 3.x" buildbot:
https://buildbot.python.org/all/#/builders/58/builds/2627

ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 578, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\base_events.py", line 606, in run_until_complete
    raise RuntimeError('Event loop stopped before Future completed.')
RuntimeError: Event loop stopped before Future completed.
msg345645 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-14 22:16
x86 Windows7 3.7:
https://buildbot.python.org/all/#/builders/111/builds/1123

test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... Exception in thread test-client:
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\functional.py", line 198, in run
    self._prog(TestSocketWrapper(self._sock))
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 565, in <lambda>
    with self.tcp_client(lambda sock: client(sock, addr),
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 510, in client
    answer = sock.recv_all(len(ANSWER))
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\functional.py", line 138, in recv_all
    data = self.recv(n - len(buf))
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\ssl.py", line 1045, in recv
    return self.read(buflen)
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\ssl.py", line 920, in read
    return self._sslobj.read(len)
ssl.SSLError: [SSL: WRONG_VERSION_NUMBER] wrong version number (_ssl.c:2488)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\threading.py", line 926, in _bootstrap_inner
    self.run()
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\functional.py", line 200, in run
    self._test._abort_socket_test(ex)
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\test\test_asyncio\functional.py", line 122, in _abort_socket_test
    self.fail(ex)
  File "D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\unittest\case.py", line 693, in fail
    raise self.failureException(msg)
AssertionError: [SSL: WRONG_VERSION_NUMBER] wrong version number (_ssl.c:2488)

D:\cygwin\home\db3l\buildarea\3.7.bolen-windows7\build\lib\threading.py:960: ResourceWarning: unclosed <ssl.SSLSocket fd=772, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 64078), raddr=('127.0.0.1', 64077)>
  del exc_type, exc_value, exc_tb
ResourceWarning: Enable tracemalloc to get the object allocation traceback
ERROR
msg345683 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-15 15:02
Ooops. Looks like a real problem, not test-only :(
msg345807 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-06-17 07:45
What to do here?  This was originally filed as a "release blocker" and I allowed 3.7.3 to go out without a resolution for it since we had agreed to @christian.heimes proposal to defer full support of OpenSSL 1.1.1 until 3.7.4.  Now we are approaching code cutoff for 3.7.4.
msg345830 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-17 08:58
No idea what to do.
SSL support is obviously broken.
Current code is too complex to maintain.

Yuri has a full reimplementation of ssl_proto.py in uvloop.
It *seem* to work and can be backported.

I'm sick now, can be ready to work back in a day or two.
msg345833 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-17 09:47
New changeset c034b7824f5a7c50f2946ab3931633200e31d903 by Victor Stinner in branch 'master':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
https://github.com/python/cpython/commit/c034b7824f5a7c50f2946ab3931633200e31d903
msg345838 - (view) Author: miss-islington (miss-islington) Date: 2019-06-17 10:06
New changeset a5ddbfbf50715e3d4b90ad367ed6827c6cbcc52f by Miss Islington (bot) in branch '3.8':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
https://github.com/python/cpython/commit/a5ddbfbf50715e3d4b90ad367ed6827c6cbcc52f
msg345840 - (view) Author: miss-islington (miss-islington) Date: 2019-06-17 10:10
New changeset 0040903bbae043225499babae23649d896ea2eec by Miss Islington (bot) in branch '3.7':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
https://github.com/python/cpython/commit/0040903bbae043225499babae23649d896ea2eec
msg350294 - (view) Author: Łukasz Langa (lukasz.langa) * (Python committer) Date: 2019-08-23 14:10
Should this be closed?
msg350341 - (view) Author: Open Close (op368) * Date: 2019-08-24 01:03
For me, since GH-14080, It's been fixed. (arch linux)
msg354653 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-14 21:06
I closed bpo-37431 as a duplicate of this issue.
msg354655 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-14 21:13
I didn't check if it's the same issue than previous failures, but test_start_tls_server_1() just failed on x86 Gentoo Installed with X 3.8 buildbot:

pythoninfo:

ssl.HAS_SNI: True
ssl.OPENSSL_VERSION: OpenSSL 1.1.1d  10 Sep 2019
ssl.OPENSSL_VERSION_INFO: (1, 1, 1, 4, 15)
ssl.OP_ALL: -0x7fffffac
ssl.OP_NO_TLSv1_1: 0x10000000
ssl.SSLContext.maximum_version: TLSVersion.MAXIMUM_SUPPORTED
ssl.SSLContext.minimum_version: TLSVersion.MINIMUM_SUPPORTED
ssl.SSLContext.options: Options.OP_NO_SSLv3|OP_CIPHER_SERVER_PREFERENCE|OP_ENABLE_MIDDLEBOX_COMPAT|OP_NO_COMPRESSION|OP_ALL
ssl.SSLContext.protocol: _SSLMethod.PROTOCOL_TLS
ssl.SSLContext.verify_mode: VerifyMode.CERT_NONE
ssl.default_https_context.maximum_version: TLSVersion.MAXIMUM_SUPPORTED
ssl.default_https_context.minimum_version: TLSVersion.MINIMUM_SUPPORTED
ssl.default_https_context.options: Options.OP_NO_SSLv3|OP_CIPHER_SERVER_PREFERENCE|OP_ENABLE_MIDDLEBOX_COMPAT|OP_NO_COMPRESSION|OP_ALL
ssl.default_https_context.protocol: _SSLMethod.PROTOCOL_TLS
ssl.default_https_context.verify_mode: VerifyMode.CERT_REQUIRED
ssl.stdlib_context.maximum_version: TLSVersion.MAXIMUM_SUPPORTED
ssl.stdlib_context.minimum_version: TLSVersion.MINIMUM_SUPPORTED
ssl.stdlib_context.options: Options.OP_NO_SSLv3|OP_CIPHER_SERVER_PREFERENCE|OP_ENABLE_MIDDLEBOX_COMPAT|OP_NO_COMPRESSION|OP_ALL
ssl.stdlib_context.protocol: _SSLMethod.PROTOCOL_TLS
ssl.stdlib_context.verify_mode: VerifyMode.CERT_NONE


https://buildbot.python.org/all/#/builders/230/builds/435

test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests) ... Exception in thread test-client:
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/functional.py", line 190, in run
    self._prog(TestSocketWrapper(self._sock))
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/test_sslproto.py", line 575, in <lambda>
    with self.tcp_client(lambda sock: client(sock, addr),
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/test_sslproto.py", line 520, in client
    answer = sock.recv_all(len(ANSWER))
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/functional.py", line 130, in recv_all
    data = self.recv(n - len(buf))
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/ssl.py", line 1226, in recv
    return self.read(buflen)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/ssl.py", line 1101, in read
    return self._sslobj.read(len)
ssl.SSLError: [SSL: WRONG_VERSION_NUMBER] wrong version number (_ssl.c:2560)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/functional.py", line 192, in run
    self._test._abort_socket_test(ex)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/functional.py", line 114, in _abort_socket_test
    self.fail(ex)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/unittest/case.py", line 753, in fail
    raise self.failureException(msg)
AssertionError: [SSL: WRONG_VERSION_NUMBER] wrong version number (_ssl.c:2560)
/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/threading.py:934: ResourceWarning: unclosed <ssl.SSLSocket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 59752), raddr=('127.0.0.1', 45469)>
  self._invoke_excepthook(self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
ERROR


Unhandled error in exception handler
context: {'message': 'Task was destroyed but it is pending!', 'task': <Task pending name='Task-1699' coro=<BaseStartTLS.test_start_tls_server_1.<locals>.main() running at /buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/test_sslproto.py:555> wait_for=<Future finished result=None> cb=[_release_waiter(<Future pendi...xb6a27118>()]>)() at /buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/tasks.py:429]>}
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/base_events.py", line 1729, in call_exception_handler
    self._exception_handler(self, context)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/functional.py", line 22, in loop_exception_handler
    self.loop.default_exception_handler(context)
AttributeError: 'NoneType' object has no attribute 'default_exception_handler'
/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/test_streams.py:40: ResourceWarning: unclosed <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 45469)>
  gc.collect()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/selector_events.py:684: ResourceWarning: unclosed transport <_SelectorSocketTransport fd=8>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0xb5c82b38>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Unhandled error in exception handler
context: {'message': 'Fatal error on SSL transport', 'exception': RuntimeError('Event loop is closed'), 'transport': <_SelectorSocketTransport closing fd=8>, 'protocol': <asyncio.sslproto.SSLProtocol object at 0xb6a27448>}
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/selector_events.py", line 898, in write
    n = self._sock.send(data)
OSError: [Errno 9] Bad file descriptor

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/sslproto.py", line 685, in _process_write_backlog
    self._transport.write(chunk)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/selector_events.py", line 904, in write
    self._fatal_error(exc, 'Fatal write error on socket transport')
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/selector_events.py", line 699, in _fatal_error
    self._force_close(exc)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/selector_events.py", line 711, in _force_close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/base_events.py", line 711, in call_soon
    self._check_closed()
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/base_events.py", line 504, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/base_events.py", line 1729, in call_exception_handler
    self._exception_handler(self, context)
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/functional.py", line 22, in loop_exception_handler
    self.loop.default_exception_handler(context)
AttributeError: 'NoneType' object has no attribute 'default_exception_handler'
/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/test_streams.py:40: ResourceWarning: unclosed <socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 45469)>
  gc.collect()
ResourceWarning: Enable tracemalloc to get the object allocation traceback

ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/test/test_asyncio/test_sslproto.py", line 585, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/buildbot/buildarea/cpython/3.8.ware-gentoo-x86.installed/build/target/lib/python3.8/asyncio/base_events.py", line 606, in run_until_complete
    raise RuntimeError('Event loop stopped before Future completed.')
RuntimeError: Event loop stopped before Future completed.
msg354656 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-14 21:15
Similar failure on x86 Gentoo Non-Debug with X 3.x:
https://buildbot.python.org/all/#/builders/99/builds/3472

ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
msg354727 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-15 13:34
Zachary Ware commented the new failures on the x86 Gentoo worker:

"My worker was updated to OpenSSL v1.1.1d with sslv3 disabled today, which seems like a likely source of these failures."
msg354758 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-15 23:41
I can reproduce the bug on my laptop with the command:

./python -u -m test test_asyncio -m test.test_asyncio.test_sslproto.SelectorStartTLSTests.test_start_tls_server_1 -F -j100

It's a race condition in the test itself, not in asyncio. PR 16815 fix it.

I also got access to Zachary Ware's Gentoo buildbot worker where I can also easily reproduce the bug using "... -F -j2".
msg354759 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-15 23:49
> I also got access to Zachary Ware's Gentoo buildbot worker where I can also easily reproduce the bug using "... -F -j2".

FYI disabling TLSv1.3 works around the issue on this worker. (It doesn't fix the bug, only hides it.)
msg354760 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-16 00:02
FYI "test_start_tls_server_1()" is failing since at least 2017-12-30:
https://bugs.python.org/issue32458#msg309244

I hope that my latest fix will be the last to finally make the test stable.

But I always write that, and the bug always strike me in my back. So I'm now hopeless :-)
msg354761 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-16 00:36
New changeset fab4ef2df0857ab0c97f3058ac5ec3280c4eb891 by Victor Stinner in branch 'master':
bpo-35998: Fix test_asyncio.test_start_tls_server_1() (GH-16815)
https://github.com/python/cpython/commit/fab4ef2df0857ab0c97f3058ac5ec3280c4eb891
msg354762 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-16 00:47
This change needs to be backported to 3.7 and 3.8, but I prefer to wait to see if buildbots like this new change, before doing the backport.
msg354784 - (view) Author: miss-islington (miss-islington) Date: 2019-10-16 08:37
New changeset afbcd9f26d1bf5390f56f18c9afbf753e48f230d by Miss Islington (bot) in branch '3.8':
bpo-35998: Fix test_asyncio.test_start_tls_server_1() (GH-16815)
https://github.com/python/cpython/commit/afbcd9f26d1bf5390f56f18c9afbf753e48f230d
msg354793 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-16 09:44
New changeset 1bceb0e58905fd6d241d7d566e19ca78558973dd by Victor Stinner in branch '3.7':
bpo-35998: Fix test_asyncio.test_start_tls_server_1() (GH-16815) (GH-16818)
https://github.com/python/cpython/commit/1bceb0e58905fd6d241d7d566e19ca78558973dd
msg354794 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-16 09:59
Buildbots are green on the 3.x branch. I backported my fix to 3.7 and 3.8.

I close the issue. I hope that I will not have to reopen it again.
History
Date User Action Args
2019-10-16 09:59:14vstinnersetstatus: open -> closed
versions: + Python 3.9
messages: + msg354794

resolution: fixed
stage: patch review -> resolved
2019-10-16 09:44:41vstinnersetmessages: + msg354793
2019-10-16 08:37:01miss-islingtonsetmessages: + msg354784
2019-10-16 08:25:52vstinnersetpull_requests: + pull_request16370
2019-10-16 08:18:07miss-islingtonsetpull_requests: + pull_request16369
2019-10-16 00:47:01vstinnersetmessages: + msg354762
2019-10-16 00:36:47vstinnersetmessages: + msg354761
2019-10-16 00:02:26vstinnersetmessages: + msg354760
2019-10-15 23:49:25vstinnersetmessages: + msg354759
2019-10-15 23:41:07vstinnersetmessages: + msg354758
2019-10-15 23:37:08vstinnersetpull_requests: + pull_request16366
2019-10-15 13:34:27vstinnersetmessages: + msg354727
2019-10-14 21:15:16vstinnersetmessages: + msg354656
2019-10-14 21:13:23vstinnersetmessages: + msg354655
2019-10-14 21:06:28vstinnersetmessages: + msg354653
2019-10-14 21:06:26vstinnerlinkissue37431 superseder
2019-08-24 01:03:39op368setmessages: + msg350341
2019-08-23 14:10:27lukasz.langasetmessages: + msg350294
2019-06-17 10:10:52miss-islingtonsetmessages: + msg345840
2019-06-17 10:06:56miss-islingtonsetmessages: + msg345838
2019-06-17 09:48:24miss-islingtonsetpull_requests: + pull_request13994
2019-06-17 09:48:16miss-islingtonsetstage: resolved -> patch review
pull_requests: + pull_request13992
2019-06-17 09:47:55vstinnersetmessages: + msg345833
2019-06-17 08:58:12asvetlovsetmessages: + msg345830
2019-06-17 07:45:16ned.deilysetmessages: + msg345807
2019-06-15 15:02:45asvetlovsetmessages: + msg345683
2019-06-14 22:16:45vstinnersetmessages: + msg345645
2019-06-14 22:14:29vstinnersetstatus: closed -> open
resolution: fixed -> (no value)
messages: + msg345644
2019-06-14 21:51:07vstinnersetmessages: + msg345640
2019-06-14 17:52:28asvetlovsetmessages: + msg345623
2019-06-14 16:26:43vstinnersetmessages: + msg345608
2019-06-14 16:12:55miss-islingtonsetnosy: + miss-islington
messages: + msg345607
2019-06-14 16:05:04vstinnersetmessages: + msg345605
2019-06-14 15:46:07asvetlovsetstatus: open -> closed
resolution: fixed
messages: + msg345598

stage: patch review -> resolved
2019-06-14 15:42:12vstinnersetpull_requests: + pull_request13942
2019-06-14 15:26:49miss-islingtonsetpull_requests: + pull_request13941
2019-06-14 15:26:45vstinnersetmessages: + msg345597
2019-06-14 14:14:30asvetlovsetkeywords: + patch
stage: patch review
pull_requests: + pull_request13939
2019-06-14 14:04:48asvetlovlinkissue37081 superseder
2019-04-21 13:25:23ncoghlansetnosy: + ncoghlan
2019-03-24 20:08:44ned.deilysetpriority: release blocker -> deferred blocker
nosy: + christian.heimes
messages: + msg338749

2019-03-19 15:50:00cstrataksetmessages: + msg338368
2019-03-17 13:44:29dokosetpriority: normal -> release blocker
versions: + Python 3.7
nosy: + ned.deily, lukasz.langa

messages: + msg338129

keywords: + 3.7regression
2019-03-15 08:38:12dokosetnosy: + doko
messages: + msg337974
2019-03-09 08:51:56op368setmessages: + msg337563
2019-03-05 21:36:23matrixisesetmessages: + msg337239
2019-03-04 20:18:11op368setfiles: + stderr-op368.txt

messages: + msg337147
2019-03-04 15:00:05vstinnersetmessages: + msg337125
2019-03-02 05:22:13op368setmessages: + msg336991
2019-03-02 04:21:30koobssetnosy: + koobs
2019-03-02 04:19:58op368setnosy: + op368
messages: + msg336986
2019-02-15 18:49:11xtreaksetnosy: + pablogsal
messages: + msg335635
2019-02-15 17:56:16cstrataksetnosy: + cstratak
messages: + msg335629
2019-02-15 17:53:42vstinnersettitle: ./python -m test test_asyncio fails -> test_asyncio: test_start_tls_server_1() TimeoutError on Fedora 29
2019-02-15 17:38:23xtreaksetnosy: + xtreak
messages: + msg335626
2019-02-15 17:25:40vstinnersetnosy: + asvetlov, yselivanov
components: + Tests, asyncio
2019-02-15 17:25:35vstinnersetnosy: + vstinner
2019-02-15 10:12:33matrixisesetfiles: + stderr.txt

messages: + msg335597
2019-02-15 10:12:18matrixisecreate