test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots #79212

pablogsal · 2018-10-20T14:06:48Z

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 · 2018-10-20T14:06:47Z

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 · 2018-10-20T15:07:33Z

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 · 2018-10-20T15:17:55Z

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 · 2018-10-20T15:24:30Z

Building and testing the parent of dbf1022 always succeeds.

pablogsal · 2018-10-20T16:20:48Z

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 · 2018-10-20T16:57:05Z

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

vstinner · 2018-10-29T14:31:44Z

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

pablogsal · 2018-10-29T14:39:31Z

Someone needs to review PR10011

vstinner · 2018-10-29T15:28:51Z

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

pablogsal · 2018-10-29T15:47:02Z

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

Maybe I just answered faster than the speed of light ;)

pablogsal · 2018-10-29T20:47:47Z

New changeset f6a47f3 by Pablo Galindo in branch 'master':
bpo-35031: Fix test_start_tls_server_1 on FreeBSD buildbots (GH-10011)
f6a47f3

miss-islington · 2018-11-13T01:24:44Z

New changeset 3f9fe53 by Miss Islington (bot) in branch '3.7':
bpo-35031: Fix test_start_tls_server_1 on FreeBSD buildbots (GH-10011)
3f9fe53

terryjreedy · 2018-12-30T19:30:07Z

should this be closed?

pablogsal · 2018-12-30T21:48:12Z

I think is missing a manual backport to 3.6, but now that we are in security fixes only I am not sure of what to do.

ned-deily · 2018-12-31T05:22:58Z

If the failure has regularly shown up on 3.6 FreeBSD buildbots in the past, I would accept a backport of the test change to 3.6.

openandclose · 2019-03-05T18:02:47Z

Am I wrong with something?
But test_start_tls_server_1 in newly made cpython fails on my plain intel linux personal PC.

If I comment out the FreeBSD conditional (to apply ssl.OP_NO_TLSv1_3),
the test passes.

If I change HELLO_MSG to 1*1024*1024 (msg328157),
the test passes.

I reported the details in https://bugs.python.org/issue35998#msg336986 and the following.

vstinner · 2019-06-17T09:12:07Z

Commit f6a47f3 introduced a workaround on Windows and FreeBSD. It was removed by commit f0749da in bpo-35998... but then Windows restarted to fail:
https://bugs.python.org/issue35998#msg345644

So I wrote PR 14148 to reintroduce the workaround until someone finds time to have a look.

Note: this issue is open since October 2018.

vstinner · 2019-06-17T09:47:55Z

New changeset c034b78 by Victor Stinner in branch 'master':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
c034b78

miss-islington · 2019-06-17T10:06:57Z

New changeset a5ddbfb by Miss Islington (bot) in branch '3.8':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
a5ddbfb

miss-islington · 2019-06-17T10:10:53Z

New changeset 0040903 by Miss Islington (bot) in branch '3.7':
bpo-35031, test_asycio: disable TLS 1.3 in test_start_tls_server_1() (GH-14148)
0040903

ned-deily · 2019-06-18T08:37:39Z

New changeset a514f78 by Ned Deily in branch 'master':
bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188)
a514f78

miss-islington · 2019-06-18T08:56:57Z

New changeset f49c85d by Miss Islington (bot) in branch '3.8':
bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188)
f49c85d

ned-deily · 2019-06-18T09:45:14Z

New changeset c101d1a by Ned Deily (Miss Islington (bot)) in branch '3.7':
bpo-35031: also disable TLS 1.3 for test_start_tls_server_1 on macOS (GH-14188) (GH-14192)
c101d1a

vstinner · 2019-10-14T21:07:17Z

It seems like the issue has been fixed.

See also bpo-35998 for a similar issue on other platforms.

pablogsal added 3.7 (EOL) end of life 3.8 only security fixes tests Tests in the Lib/test dir topic-asyncio type-bug An unexpected behavior, bug, or error labels Oct 20, 2018

pablogsal changed the title ~~test_asyncio test_start_tls_server_1 fails in~~ test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots Oct 20, 2018

vstinner closed this as completed Oct 14, 2019

ezio-melotti transferred this issue from another repository Apr 10, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots #79212

test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots #79212

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

vstinner commented Oct 29, 2018

pablogsal commented Oct 29, 2018

vstinner commented Oct 29, 2018

pablogsal commented Oct 29, 2018

pablogsal commented Oct 29, 2018

miss-islington commented Nov 13, 2018

terryjreedy commented Dec 30, 2018

pablogsal commented Dec 30, 2018

ned-deily commented Dec 31, 2018

openandclose mannequin commented Mar 5, 2019

vstinner commented Jun 17, 2019

vstinner commented Jun 17, 2019

miss-islington commented Jun 17, 2019

miss-islington commented Jun 17, 2019

ned-deily commented Jun 18, 2019

miss-islington commented Jun 18, 2019

ned-deily commented Jun 18, 2019

vstinner commented Oct 14, 2019

test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots #79212

test_asyncio test_start_tls_server_1 fails in AMD64 FreeBSD CURRENT buildbots #79212

Comments

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

pablogsal commented Oct 20, 2018

vstinner commented Oct 29, 2018

pablogsal commented Oct 29, 2018

vstinner commented Oct 29, 2018

pablogsal commented Oct 29, 2018

pablogsal commented Oct 29, 2018

miss-islington commented Nov 13, 2018

terryjreedy commented Dec 30, 2018

pablogsal commented Dec 30, 2018

ned-deily commented Dec 31, 2018

openandclose mannequin commented Mar 5, 2019

vstinner commented Jun 17, 2019

vstinner commented Jun 17, 2019

miss-islington commented Jun 17, 2019

miss-islington commented Jun 17, 2019

ned-deily commented Jun 18, 2019

miss-islington commented Jun 18, 2019

ned-deily commented Jun 18, 2019

vstinner commented Oct 14, 2019