classification
Title: test_asyncio: TLS tests fail on "x86 Windows7" buildbot
Type: Stage: resolved
Components: asyncio, Tests, Windows Versions: Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, paul.moore, steve.dower, terry.reedy, tim.golden, vstinner, yselivanov, zach.ware
Priority: normal Keywords:

Created on 2018-01-24 09:49 by vstinner, last changed 2018-01-29 12:23 by asvetlov. This issue is now closed.

Messages (11)
msg310576 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-24 09:49
test_asyncio started to fail after the implementation of STARTTLS in asyncio, bpo-23749: commit f111b3dcb414093a4efb9d74b69925e535ddc470.

http://buildbot.python.org/all/#/builders/58/builds/502

Extract of test.pythoninfo:
----
ssl.HAS_SNI: True
ssl.OPENSSL_VERSION: OpenSSL 1.1.0f  25 May 2017
ssl.OPENSSL_VERSION_INFO: (1, 1, 0, 6, 15)
ssl.OP_ALL: -0x7fffffac
ssl.OP_NO_TLSv1_1: 0x10000000

sys.version: 3.7.0a4+ (heads/master:018e1b7, Jan 24 2018, 02:53:43) [MSC v.1900 32 bit (Intel)]
sys.version_info: sys.version_info(major=3, minor=7, micro=0, releaselevel='alpha', serial=4)
sys.windowsversion: sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1')
sys.winver: 3.7-32
---

Extract of compile step:
---
Fetching external libraries...
(...)
openssl-bin-1.1.0f already exists, skipping.
---

Test failures:

======================================================================
ERROR: test_start_tls_client_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 225, in test_start_tls_client_1
    asyncio.wait_for(client(srv.addr), loop=self.loop, timeout=10))
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\base_events.py", line 436, in run_until_complete
    return future.result()
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\tasks.py", line 406, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 285, in test_start_tls_server_1
    asyncio.wait_for(main(), loop=self.loop, timeout=10))
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\base_events.py", line 436, in run_until_complete
    return future.result()
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\tasks.py", line 406, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

======================================================================
ERROR: test_start_tls_client_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_asyncio\test_sslproto.py", line 225, in test_start_tls_client_1
    asyncio.wait_for(client(srv.addr), loop=self.loop, timeout=10))
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\base_events.py", line 436, in run_until_complete
    return future.result()
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\asyncio\tasks.py", line 406, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

======================================================================
FAIL: test_start_tls_server_1 (test.test_asyncio.test_sslproto.ProactorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_asyncio\functional.py", line 42, in tearDown
    self.fail('unexpected calls to loop.call_exception_handler()')
AssertionError: unexpected calls to loop.call_exception_handler()

----------------------------------------------------------------------
Ran 1651 tests in 117.209s

FAILED (failures=1, errors=3, skipped=56)
msg310603 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-01-24 15:40
I now have a Win7 VM, I'll take a look at this later.
msg310680 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-25 15:40
Build 537 of x86 Tiger 3.x failed, whereas the previous build was a success. Hum, maybe these asyncio failures are "just" race conditions, trigger if the system load is too high? I recall that the Windows 7 buildbot is usually slow/busy.

http://buildbot.python.org/all/#/builders/30/builds/537

======================================================================
ERROR: test_start_tls_client_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_sslproto.py", line 225, in test_start_tls_client_1
    asyncio.wait_for(client(srv.addr), loop=self.loop, timeout=10))
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/asyncio/base_events.py", line 436, in run_until_complete
    return future.result()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/asyncio/tasks.py", line 406, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
======================================================================
ERROR: test_start_tls_server_1 (test.test_asyncio.test_sslproto.SelectorStartTLSTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_sslproto.py", line 285, in test_start_tls_server_1
    asyncio.wait_for(main(), loop=self.loop, timeout=10))
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/asyncio/base_events.py", line 436, in run_until_complete
    return future.result()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/asyncio/tasks.py", line 406, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
msg310841 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-01-27 05:18
I ran f:\dev\3x>python -m test -j5 test_asyncio test_asyncio test_asyncio test_asyncio test_asyncio on fresh Win10 build and got 
...
0:01:02 [5/5] test_asyncio passed (62 sec)
F:\dev\3x\lib\asyncio\selector_events.py:648: ResourceWarning: unclosed transport <_SelectorSocketTransport fd=620>
  source=self)
F:\dev\3x\lib\asyncio\selector_events.py:648: ResourceWarning: unclosed transport <_SelectorSocketTransport fd=896>
  source=self)
F:\dev\3x\lib\asyncio\sslproto.py:318: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0x05841EE0>
  source=self)
All 5 tests OK.
(1 test also gave resource warnings.)
msg311101 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:00
Different failure on x86 Tiger 3.x:

http://buildbot.python.org/all/#/builders/30/builds/562

======================================================================
ERROR: test_sendfile_ssl (test.test_asyncio.test_events.KqueueEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2243, in test_sendfile_ssl
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_close_peer_after_receiving (test.test_asyncio.test_events.KqueueEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2325, in test_sendfile_ssl_close_peer_after_receiving
    close_after=len(self.DATA))
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_partial (test.test_asyncio.test_events.KqueueEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2302, in test_sendfile_ssl_partial
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_pre_and_post_data (test.test_asyncio.test_events.KqueueEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2277, in test_sendfile_ssl_pre_and_post_data
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl (test.test_asyncio.test_events.PollEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2243, in test_sendfile_ssl
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_close_peer_after_receiving (test.test_asyncio.test_events.PollEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2325, in test_sendfile_ssl_close_peer_after_receiving
    close_after=len(self.DATA))
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_partial (test.test_asyncio.test_events.PollEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2302, in test_sendfile_ssl_partial
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_pre_and_post_data (test.test_asyncio.test_events.PollEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2277, in test_sendfile_ssl_pre_and_post_data
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl (test.test_asyncio.test_events.SelectEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2243, in test_sendfile_ssl
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_close_peer_after_receiving (test.test_asyncio.test_events.SelectEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2325, in test_sendfile_ssl_close_peer_after_receiving
    close_after=len(self.DATA))
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_partial (test.test_asyncio.test_events.SelectEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2302, in test_sendfile_ssl_partial
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'

======================================================================
ERROR: test_sendfile_ssl_pre_and_post_data (test.test_asyncio.test_events.SelectEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2277, in test_sendfile_ssl_pre_and_post_data
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/db3l/buildarea/3.x.bolen-tiger/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'
msg311103 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:07
Similar errors on more recent macOS version, x86-64 El Capitan 3.x:

http://buildbot.python.org/all/#/builders/93/builds/234

One example:

======================================================================
ERROR: test_sendfile_ssl_partial (test.test_asyncio.test_events.SelectEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.billenstein-elcapitan/build/Lib/test/test_asyncio/test_events.py", line 2302, in test_sendfile_ssl_partial
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/Users/buildbot/buildarea/3.x.billenstein-elcapitan/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/Users/buildbot/buildarea/3.x.billenstein-elcapitan/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'
msg311104 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:08
And x86 Ubuntu Shared 3.x:

http://buildbot.python.org/all/#/builders/88/builds/603

Example:

======================================================================
ERROR: test_sendfile_ssl_partial (test.test_asyncio.test_events.SelectEventLoopTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/buildbot/buildarea/3.x.bolen-ubuntu/build/Lib/test/test_asyncio/test_events.py", line 2302, in test_sendfile_ssl_partial
    srv_proto, cli_proto = self.prepare(is_ssl=True)
  File "/srv/buildbot/buildarea/3.x.bolen-ubuntu/build/Lib/test/test_asyncio/test_events.py", line 2136, in prepare
    srv_ctx = test_utils.simple_server_sslcontext()
  File "/srv/buildbot/buildarea/3.x.bolen-ubuntu/build/Lib/test/test_asyncio/utils.py", line 73, in simple_server_sslcontext
    server_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
AttributeError: 'NoneType' object has no attribute 'SSLContext'
msg311106 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:10
Oh wait, sendfile test errors come from bpo-32622, loop.sendfile().
msg311107 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2018-01-29 12:16
Should be fixed by https://github.com/python/cpython/commit/0f54e00e963
msg311109 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:20
Oh sorry, I was reading old issues. I checked the latest status of buildbot workers for which I reported failures:

* x86 Ubuntu Shared 3.x: FIXED
* x86-64 El Capitan 3.x: FIXED
* x86 Windows7 3.x: FIXED
* x86 Tiger 3.x: compilation doesn't work anymore, see https://bugs.python.org/issue20104#msg311100

Ok, it seems like all issues now have been fixed.

On bpo-20104 will be fixed, if test_asyncio still fails on x86 Tiger 3.x, I will open a more specific issue.

I close this issue.
msg311111 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2018-01-29 12:23
Thanks, Victor!
History
Date User Action Args
2018-01-29 12:23:04asvetlovsetmessages: + msg311111
2018-01-29 12:20:39vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg311109

stage: resolved
2018-01-29 12:16:09asvetlovsetmessages: + msg311107
2018-01-29 12:10:12vstinnersetmessages: + msg311106
2018-01-29 12:08:31vstinnersetmessages: + msg311104
2018-01-29 12:07:13vstinnersetmessages: + msg311103
2018-01-29 12:00:25vstinnersetmessages: + msg311101
2018-01-27 05:18:36terry.reedysetnosy: + terry.reedy
messages: + msg310841
2018-01-25 15:40:15vstinnersetmessages: + msg310680
2018-01-24 15:40:26yselivanovsetmessages: + msg310603
2018-01-24 09:49:28vstinnercreate