[New-bugs-announce] [issue47106] test_asyncio: test_shutdown_cleanly() failed with timeout (10 seconds) on slow x86 Gentoo Non-Debug with X 3.x

[STINNER Victor]

New submission from STINNER Victor <vstinner at python.org>:

test_shutdown_cleanly() of test_asyncio failed on x86 Gentoo Non-Debug with X 3.x with a timeout of 10 seconds:
https://buildbot.python.org/all/#/builders/58/builds/1958

asyncio uses a default timeout of 60 seconds for a TLS handshake, but the test takes makes 6x shorter: use a timeout of 10 seconds, I'm not sure why.

To support slow buildbots, I would suggest to use *longer* timeout than the default, not *shorter* timeouts.

test_ssl uses various values for the TLS timeout:

* 1.0 second
* 10.0 seconds
* 40.0 seconds
* 60.0 seconds

Would it be possible to make these values more consistent?

You may want to use on of test.support timeout which has a value depending on regrtest --timeout parameter: on slow buildbots, these values are larger.

* LOOPBACK_TIMEOUT
* SHORT_TIMEOUT
* LONG_TIMEOUT
* INTERNET_TIMEOUT
* Documentation: https://docs.python.org/dev/library/test.html#test.support.LOOPBACK_TIMEOUT

I would recommend using SHORT_TIMEOUT.

x86 Gentoo Non-Debug with X 3.x uses "--timeout=2100" option:

"0:00:00 load avg: 2.89 Run tests in parallel using 2 child processes (timeout: 35 min, worker timeout: 40 min)"


Logs:

0:35:34 load avg: 3.13 Re-running test_asyncio in verbose mode (matching: test_shutdown_cleanly)
test_shutdown_cleanly (test.test_asyncio.test_ssl.TestSSL) ... Warning -- Uncaught thread exception: AssertionError
Exception in thread test-server:
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1706, in _run
    self._handle_client(conn)
    ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1717, in _handle_client
    self._prog(TestSocketWrapper(sock))
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1183, in server
    sock.unwrap()
    ^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/ssl.py", line 1321, in unwrap
    s = self._sslobj.shutdown()
        ^^^^^^^^^^^^^^^^^^^^^^^
TimeoutError: The read operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/threading.py", line 1031, in _bootstrap_inner
    self.run()
    ^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1675, in run
    self._run()
    ^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1714, in _run
    self._test._abort_socket_test(ex)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 163, in _abort_socket_test
    self.fail(ex)
    ^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/unittest/case.py", line 671, in fail
    raise self.failureException(msg)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: The read operation timed out
ERROR

Stderr:
/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/threading.py:1033: ResourceWarning: unclosed <ssl.SSLSocket fd=9, family=2, type=1, proto=0, laddr=('127.0.0.1', 51261), raddr=('127.0.0.1', 50574)>
  self._invoke_excepthook(self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/asyncio/selector_events.py:834: ResourceWarning: unclosed transport <_SelectorSocketTransport fd=27>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback

======================================================================
ERROR: test_shutdown_cleanly (test.test_asyncio.test_ssl.TestSSL)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 155, in _silence_eof_received_warning
    yield
    ^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1228, in test_shutdown_cleanly
    run(client)
    ^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1222, in run
    self.loop.run_until_complete(
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/asyncio/base_events.py", line 650, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1213, in _gather
    return await asyncio.gather(*tasks)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/test/test_asyncio/test_ssl.py", line 1191, in client
    reader, writer = await asyncio.open_connection(
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/asyncio/streams.py", line 47, in open_connection
    transport, _ = await loop.create_connection(
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/asyncio/base_events.py", line 1098, in create_connection
    transport, protocol = await self._create_connection_transport(
                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/asyncio/base_events.py", line 1131, in _create_connection_transport
    await waiter
    ^^^^^^^^^^^^
ConnectionAbortedError: SSL handshake is taking longer than 10.0 seconds: aborting the connection

Stderr:
/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.nondebug/build/Lib/threading.py:1033: ResourceWarning: unclosed <ssl.SSLSocket fd=9, family=2, type=1, proto=0, laddr=('127.0.0.1', 51261), raddr=('127.0.0.1', 50574)>
  self._invoke_excepthook(self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback

----------------------------------------------------------------------
Ran 1 test in 16.068s

FAILED (errors=1)
test test_asyncio failed
1 test failed again:
    test_asyncio

----------
components: Tests
messages: 415926
nosy: vstinner
priority: normal
severity: normal
status: open
title: test_asyncio: test_shutdown_cleanly() failed with timeout (10 seconds) on slow x86 Gentoo Non-Debug with X 3.x
versions: Python 3.11

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue47106>
_______________________________________