test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots

[pablogsal]

BPO	35031
Nosy	@terryjreedy, @vstinner, @tiran, @ned-deily, @asvetlov, @1st1, @pablogsal, @miss-islington, @openandclose
PRs	bpo-35031: Fix test_start_tls_server_1 on FreeBSD buildbots #10011 [3.7] bpo-35031: Fix test_start_tls_server_1 on FreeBSD buildbots (GH-10011) #10496 bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() #14148 [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-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS #14188 [3.8] bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188) #14191 [3.7] bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188) #14192

^{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-14.21:07:17.113>
created_at = <Date 2018-10-20.14:06:47.648>
labels = ['3.7', '3.8', 'type-bug', 'tests', 'expert-asyncio']
title = 'test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots'
updated_at = <Date 2019-10-14.21:07:17.112>
user = 'https://github.com/pablogsal'

bugs.python.org fields:

activity = <Date 2019-10-14.21:07:17.112>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-10-14.21:07:17.113>
closer = 'vstinner'
components = ['Tests', 'asyncio']
creation = <Date 2018-10-20.14:06:47.648>
creator = 'pablogsal'
dependencies = []
files = []
hgrepos = []
issue_num = 35031
keywords = ['patch']
message_count = 24.0
messages = ['328138', '328143', '328145', '328148', '328157', '328163', '328833', '328835', '328837', '328839', '328871', '329785', '332756', '332764', '332803', '337234', '345831', '345832', '345837', '345839', '345961', '345967', '345973', '354654']
nosy_count = 9.0
nosy_names = ['terry.reedy', 'vstinner', 'christian.heimes', 'ned.deily', 'asvetlov', 'yselivanov', 'pablogsal', 'miss-islington', 'op368']
pr_nums = ['10011', '10496', '14148', '14150', '14151', '14188', '14191', '14192']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue35031'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[pablogsal]

https://buildbot.python.org/all/#/builders/168/builds/91
https://buildbot.python.org/all/#/builders/172/builds/41
https://buildbot.python.org/all/#/builders/173/builds/51

CURRENT-amd64% ./python -m test test_asyncio -m test_start_tls_server_1
Run tests sequentially
0:00:00 load avg: 3.36 [1/1] test_asyncio

Stderr:
/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py:497: DeprecationWarning: The loop argument is deprecated and scheduled for removal in Python 3.10.
  await asyncio.wait_for(
/usr/home/pablo/cpython/Lib/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x802db68f0>
  warnings.warn(f"unclosed transport {self!r}", ResourceWarning,
Unhandled error in exception handler
context: {'message': 'Future exception was never retrieved', 'exception': ConnectionResetError(54, 'Connection reset by peer'), 'future': <Future finished exception=ConnectionResetError(54, 'Connection reset by peer')>}
Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/test/libregrtest/runtest.py", line 179, in runtest_inner
    test_runner()
  File "/usr/home/pablo/cpython/Lib/test/libregrtest/runtest.py", line 175, in test_runner
    support.run_unittest(tests)
  File "/usr/home/pablo/cpython/Lib/test/support/__init__.py", line 2001, in run_unittest
    _run_suite(suite)
  File "/usr/home/pablo/cpython/Lib/test/support/__init__.py", line 1920, in _run_suite
    raise TestFailed(err)
test.support.TestFailed: Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 504, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/usr/home/pablo/cpython/Lib/asyncio/base_events.py", line 582, in run_until_complete
    return future.result()
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 497, in run_main
    await asyncio.wait_for(
  File "/usr/home/pablo/cpython/Lib/asyncio/tasks.py", line 457, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

Stderr:
/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py:497: DeprecationWarning: The loop argument is deprecated and scheduled for removal in Python 3.10.
await asyncio.wait_for(
/usr/home/pablo/cpython/Lib/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x802db68f0>
warnings.warn(f"unclosed transport {self!r}", ResourceWarning,

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/asyncio/base_events.py", line 1647, in call_exception_handler
    self._exception_handler(self, context)
  File "/usr/home/pablo/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'
/usr/home/pablo/cpython/Lib/test/support/__init__.py:1550: ResourceWarning: unclosed <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 25746)>
  gc.collect()
test test_asyncio failed -- Traceback (most recent call last):
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 504, in test_start_tls_server_1
    self.loop.run_until_complete(run_main())
  File "/usr/home/pablo/cpython/Lib/asyncio/base_events.py", line 582, in run_until_complete
    return future.result()
  File "/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py", line 497, in run_main
    await asyncio.wait_for(
  File "/usr/home/pablo/cpython/Lib/asyncio/tasks.py", line 457, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

Stderr:
/usr/home/pablo/cpython/Lib/test/test_asyncio/test_sslproto.py:497: DeprecationWarning: The loop argument is deprecated and scheduled for removal in Python 3.10.
await asyncio.wait_for(
/usr/home/pablo/cpython/Lib/asyncio/sslproto.py:321: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x802db68f0>
warnings.warn(f"unclosed transport {self!r}", ResourceWarning,

test_asyncio failed in 1 min 749 ms

== Tests result: FAILURE ==

1 test failed:
test_asyncio

Total duration: 1 min 800 ms
Tests result: FAILURE

[pablogsal]

Bisecting points to commit dbf1022 as the dirst bad commit:

dbf1022 is the first bad commit
commit dbf1022
Author: Yury Selivanov <yury@magic.io>
Date: Mon May 28 14:31:28 2018 -0400

bpo-33654: Support BufferedProtocol in set_protocol() and start_tls() (GH-7130)

In this commit:

* Support BufferedProtocol in set_protocol() and start_tls()
* Fix proactor to cancel readers reliably
* Update tests to be compatible with OpenSSL 1.1.1
* Clarify BufferedProtocol docs
* Bump TLS tests timeouts to 60 seconds; eliminate possible race from start_serving
* Rewrite test_start_tls_server_1

[pablogsal]

I think something is going on with the buildbot itself or the test has some race condition because that commit has been built before multiple times with no error. I am investigating in the buildbot itself.

[pablogsal]

Building and testing the parent of dbf1022 always succeeds.

[pablogsal]

It seems that the problem is that the ServerProto of test_start_tls_server_1 never receives a call to eof_received(). Weirdly enough it seems that if the HELLO_MSG is large enough (1024 * 1024), then the test always succeed. If we deactivate tls in the test, the test succeeds with any message lenght.

[pablogsal]

Re-adding client_context.options |= ssl.OP_NO_TLSv1_3 makes the test pass again.

[vstinner]

Any progress on this issue? It's still failing:
https://buildbot.python.org/all/#/builders/168/builds/143

[pablogsal]

Someone needs to review PR10011

[vstinner]

note: Roundup sent me comments as email notifications in the backward order, that's funny to see Pablo's answer before my question :-)