test_asyncio: test_start_tls_server_1() TimeoutError on Fedora 29

[matrixise]

BPO	35998
Nosy	@doko42, @ncoghlan, @vstinner, @tiran, @ned-deily, @asvetlov, @ambv, @1st1, @koobs, @matrixise, @stratakis, @pablogsal, @miss-islington, @tirkarthi, @openandclose
PRs	bpo-35998: Avoid TimeoutError in test_asyncio: test_start_tls_server_1() #14080 [3.8] bpo-35998: Avoid TimeoutError in test_asyncio: test_start_tls_server_1() (GH-14080) #14084 [3.7] bpo-35998: Avoid TimeoutError in test_asyncio: test_start_tls_server_1() (GH-14080) #14086 [3.8] bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148) #14150 [3.7] bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148) #14151 bpo-35998: Fix test_asyncio.test_start_tls_server_1() #16815 [3.8] bpo-35998: Fix test_asyncio.test_start_tls_server_1() (GH-16815) #16817 [3.7] bpo-35998: Fix test_asyncio.test_start_tls_server_1() (GH-16815) #16818
Files	stdout.txt stderr.txt stderr-op368.txt: test_start_tls_server_1 only

^{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 = None
closed_at = <Date 2019-10-16.09:59:14.787>
created_at = <Date 2019-02-15.10:12:18.033>
labels = ['deferred-blocker', '3.8', '3.9', '3.7', 'tests', 'expert-asyncio']
title = 'test_asyncio: test_start_tls_server_1() TimeoutError on Fedora 29'
updated_at = <Date 2019-10-16.09:59:14.773>
user = 'https://github.com/matrixise'

bugs.python.org fields:

activity = <Date 2019-10-16.09:59:14.773>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-10-16.09:59:14.787>
closer = 'vstinner'
components = ['Tests', 'asyncio']
creation = <Date 2019-02-15.10:12:18.033>
creator = 'matrixise'
dependencies = []
files = ['48143', '48144', '48185']
hgrepos = []
issue_num = 35998
keywords = ['patch', '3.7regression']
message_count = 44.0
messages = ['335596', '335597', '335626', '335629', '335635', '336986', '336991', '337125', '337147', '337239', '337563', '337974', '338129', '338368', '338749', '345597', '345598', '345605', '345607', '345608', '345623', '345640', '345644', '345645', '345683', '345807', '345830', '345833', '345838', '345840', '350294', '350341', '354653', '354655', '354656', '354727', '354758', '354759', '354760', '354761', '354762', '354784', '354793', '354794']
nosy_count = 15.0
nosy_names = ['doko', 'ncoghlan', 'vstinner', 'christian.heimes', 'ned.deily', 'asvetlov', 'lukasz.langa', 'yselivanov', 'koobs', 'matrixise', 'cstratak', 'pablogsal', 'miss-islington', 'xtreak', 'op368']
pr_nums = ['14080', '14084', '14086', '14150', '14151', '16815', '16817', '16818']
priority = 'deferred blocker'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue35998'
versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

[matrixise]

======================================================================
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: 3e028b2

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

[matrixise]

here is the stderr.txt

[tirkarthi]

Not sure if it's related but there was a similar report on failure in freebsd bots with tls1.3 : bpo-35031 . 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

[stratakis]

Fedora 29 has openssl 1.1.1 which seems to be related.

[tirkarthi]

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

[openandclose]

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.
f777fa5 (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

[openandclose]

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.

[vstinner]

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 529525f
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>

[openandclose]

uploading stderr-op368.txt.
(basically the same as Stéphane and Karthikeyan.)

[matrixise]

./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: d8b3a98

[openandclose]

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