GeezerVison is showing github.com — test_asyncio: test_start_tls_server_1() fails randomly · Issue #76639 · python/cpython
test_asyncio: test_start_tls_server_1() fails randomly #76639Description
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/1st1'
closed_at = <Date 2018-05-29.20:02:20.072>
created_at = <Date 2017-12-30.19:20:50.946>
labels = ['3.8', 'type-bug', '3.7', 'expert-asyncio']
title = 'test_asyncio: test_start_tls_server_1() fails randomly'
updated_at = <Date 2018-05-29.20:02:20.071>
user = 'https://github.com/pitrou' bugs.python.org fields:
activity = <Date 2018-05-29.20:02:20.071>
actor = 'vstinner'
assignee = 'yselivanov'
closed = True
closed_date = <Date 2018-05-29.20:02:20.072>
closer = 'vstinner'
components = ['asyncio']
creation = <Date 2017-12-30.19:20:50.946>
creator = 'pitrou'
dependencies = []
files = []
hgrepos = []
issue_num = 32458
keywords = ['patch']
message_count = 34.0
messages = ['309244', '309254', '309255', '309256', '309521', '310405', '313507', '317468', '317638', '317639', '317640', '317643', '317751', '317755', '317758', '317759', '317760', '317761', '317762', '317807', '317808', '317809', '317817', '317833', '317862', '317871', '317872', '317873', '317898', '317907', '317918', '317920', '318055', '318080']
nosy_count = 7.0
nosy_names = ['terry.reedy', 'vstinner', 'christian.heimes', 'ned.deily', 'asvetlov', 'yselivanov', 'miss-islington']
pr_nums = ['5054', '7157', '7166', '7170']
priority = None
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue32458'
versions = ['Python 3.7', 'Python 3.8'] Activitypitrou commented on Dec 30, 2017 It seems test_asyncio fails sporadically on AppVeyor:
https://ci.appveyor.com/project/python/cpython/build/3.7.0a0.10081#L2650
======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLS)
----------------------------------------------------------------------
Traceback (most recent call last):
File "C:\projects\cpython\lib\test\test_asyncio\test_sslproto.py", line 284, in test_start_tls_server_1
asyncio.wait_for(main(), loop=self.loop, timeout=10))
File "C:\projects\cpython\lib\asyncio\base_events.py", line 440, in run_until_complete
return future.result()
File "C:\projects\cpython\lib\asyncio\tasks.py", line 398, in wait_for
raise futures.TimeoutError()
concurrent.futures._base.TimeoutError======================================================================
FAIL: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLS)
----------------------------------------------------------------------
Traceback (most recent call last):
File "C:\projects\cpython\lib\test\test_asyncio\functional.py", line 43, in tearDown
self.fail('unexpected calls to loop.call_exception_handler()')
AssertionError: unexpected calls to loop.call_exception_handler()1st1 commented on Dec 30, 2017 I'm leaving on a two-weeks vacation today. To avoid risking breaking the workflow, I'll mask this tests on AppVeyor. I'll investigate this when I get back. 1st1 commented on Dec 30, 2017 1st1 commented on Dec 30, 2017 Please keep this issue open. terryjreedy commented on Jan 5, 2018 After fresh update and debug rebuild on master(3.7), with Win10 patched last night, I got
======================================================================
FAIL: test_call_later (test.test_asyncio.test_events.ProactorEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "F:\dev\3x\lib\test\test_asyncio\test_events.py", line 290, in test_call_later
self.assertTrue(0.08 <= t1-t0 <= 0.8, t1-t0)
AssertionError: False is not true : 0.07800000000861473I have not seen this before. Four subsequent runs passed. asvetlov commented on Jan 22, 2018 Hmm, the scheduled call was executed sooner than expected.
Actually we had 0.1 sec delay, checked for at least 0.08 but actual call time was 0.078
BTW I recall an issue with Windows when call_later() was executed sooner already. ned-deily commented on Mar 9, 2018 vstinner commented on May 28, 2018 I just reproduced the issue on Linux. Open 3 terminals and run the commands in parallel:
(1) ./python -m test test_asyncio -m test_start_tls_server_1 -F
(2) ./python -m test -j16 -r
(3) ./python -m test -j16 -r
It's a race condition which doesn't depend on the OS, but on the system load. 1st1 commented on May 28, 2018
It's a race condition which doesn't depend on the OS, but on the system load.
Yeah, I agree. The current timeout for the test is 5 seconds and it tries to transfer 2mb of data, which isn't that much actually. I'll bump the timeout and reduce the amount of data transferred in #7130
Thing is, these are the very first *functional* tests for asyncio. Before it was mostly tested with mocks. So we'll need some adjustment period to learn how slow/loaded the CI servers are and what kind of timeouts are safe to use. vstinner commented on May 28, 2018
Yeah, I agree. The current timeout for the test is 5 seconds and it tries to transfer 2mb of data, which isn't that much actually. I'll bump the timeout and reduce the amount of data transferred in #7130
What is the purpose of a timeout of 5 seconds? Some buildbots are really slow.
If the purpose is to detect when the test hangs: use a timeout of 5 minutes, or at least 1 minute (60 seconds). 1st1 commented on May 28, 2018
If the purpose is to detect when the test hangs: use a timeout of 5 minutes, or at least 1 minute (60 seconds).
OK, sounds good, will do that. vstinner commented on May 28, 2018
OK, sounds good, will do that.
Race condition! I created #7157 to increase the timeout from 5 seconds to 60 seconds. 1st1 commented on May 28, 2018 #7130 is in. It includes many tests for TLS tests as well as bugfixes to asyncio code. Hopefully this all will make tests more stable. 1st1 commented on May 28, 2018 vstinner commented on May 28, 2018 While Yury seems unable to reproduce the bug, it's easy for me to reproduce it on Linux. After 2 hours of debugging, I found the root issue: a race condition not in the test, but in asyncio itself! => bpo-33674 "asyncio: race condition in SSLProtocol". miss-islington commented on May 28, 2018 1st1 commented on May 29, 2018 Should we close this issue now? vstinner commented on May 29, 2018 I'm not 100% sure that all issues are fixed, but the tests seem much more reliable yet. I close the issue. If the bug reoccurs, I will reopen the issue or open a new one.
MetadataMetadataDevelopmentNo branches or pull requestsIssue actions
|