test_asyncio: test_start_tls_server_1() fails randomly

[pitrou]

BPO	32458
Nosy	@terryjreedy, @vstinner, @tiran, @ned-deily, @asvetlov, @1st1, @miss-islington
PRs	bpo-32458: Temporarily mask start-tls proactor test on Windows #5054 bpo-32458: Increase TLS timeout in test_asyncio #7157 bpo-32458: Further tune start_tls tests #7166 [3.7] bpo-32458: Further tune start_tls tests (GH-7166) #7170

^{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']

[pitrou]

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]

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]

New changeset 0c36bed by Yury Selivanov in branch 'master':
bpo-32458: Temporarily mask start-tls proactor test on Windows (bpo-5054)
0c36bed

[1st1]

Please keep this issue open.

[terryjreedy]

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.07800000000861473

I have not seen this before. Four subsequent runs passed.

[asvetlov]

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]

Note, I think this failure is still happening occasionally on the windows7 buildbot; for example:

http://buildbot.python.org/all/#/builders/111/builds/68/steps/3/logs/stdio
http://buildbot.python.org/all/#/builders/111/builds/85/steps/3/logs/stdio