test_asyncio altered the execution environment

@vstinner

BPO	38912
Nosy	@vstinner, @asvetlov, @1st1, @pablogsal, @miss-islington, @JustinTArthur, @aeros, @kumaraditya303
PRs	bpo-38912: regrtest logs unraisable exception into sys.__stderr__ #21718 [3.9] bpo-38912: regrtest logs unraisable exception into sys.__stderr__ (GH-21718) #21827 bpo-38912: fix close before connect callback on SSL tests #22691 [3.9] bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691) #22799 [3.8] bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691) #22800

^{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 2022-03-15.20:50:48.930>
created_at = <Date 2019-11-26.00:50:21.199>
labels = ['3.8', 'tests', 'expert-asyncio']
title = 'test_asyncio altered the execution environment'
updated_at = <Date 2022-03-15.20:50:48.930>
user = 'https://github.com/pablogsal'

bugs.python.org fields:

activity = <Date 2022-03-15.20:50:48.930>
actor = 'asvetlov'
assignee = 'none'
closed = True
closed_date = <Date 2022-03-15.20:50:48.930>
closer = 'asvetlov'
components = ['Tests', 'asyncio']
creation = <Date 2019-11-26.00:50:21.199>
creator = 'pablogsal'
dependencies = []
files = []
hgrepos = []
issue_num = 38912
keywords = ['patch']
message_count = 19.0
messages = ['357470', '374743', '374755', '374758', '374759', '374763', '374850', '374851', '375180', '375181', '375182', '378481', '378602', '379071', '379072', '379074', '379075', '410940', '415295']
nosy_count = 8.0
nosy_names = ['vstinner', 'asvetlov', 'yselivanov', 'pablogsal', 'miss-islington', 'JustinTArthur', 'aeros', 'kumaraditya']
pr_nums = ['21718', '21827', '22691', '22799', '22800']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue38912'
versions = ['Python 3.8']

https://buildbot.python.org/all/#/builders/260/builds/60/steps/5/logs/stdio

0:05:06 load avg: 6.65 [131/423] test_contextlib_async passed -- running: test_signal (1 min 53 sec), test_concurrent_futures (4 min 11 sec), test_zipfile (47.5 sec), test_statistics (48.6 sec), test_multiprocessing_forkserver (2 min 58 sec), test_multiprocessing_spawn (4 min 54 sec)
beginning 6 repetitions
123456
Task was destroyed but it is pending!
task: <Task pending name='Task-9' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-11' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-16' coro=<<async_generator_athrow without __name__>()>>
.Task was destroyed but it is pending!
task: <Task pending name='Task-68' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-70' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-75' coro=<<async_generator_athrow without __name__>()>>
.Task was destroyed but it is pending!
task: <Task pending name='Task-127' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-129' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-134' coro=<<async_generator_athrow without __name__>()>>
.Task was destroyed but it is pending!
task: <Task pending name='Task-186' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-188' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-193' coro=<<async_generator_athrow without __name__>()>>
.Task was destroyed but it is pending!
task: <Task pending name='Task-245' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-247' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-252' coro=<<async_generator_athrow without __name__>()>>
.Task was destroyed but it is pending!
task: <Task pending name='Task-304' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-306' coro=<<async_generator_athrow without __name__>()>>
Task was destroyed but it is pending!
task: <Task pending name='Task-311' coro=<<async_generator_athrow without __name__>()>>
.
0:05:06 load avg: 6.65 [132/423] test_ssl passed -- running: test_signal (1 min 53 sec), test_concurrent_futures (4 min 11 sec), test_zipfile (47.6 sec), test_statistics (48.7 sec), test_multiprocessing_forkserver (2 min 58 sec), test_multiprocessing_spawn (4 min 54 sec)
beginning 6 repetitions
123456
/home/buildbot/buildarea/3.8.cstratak-fedora-stable-x86_64.refleak/build/Lib/test/support/init.py:3323: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 45335), raddr=('127.0.0.1', 54018)>
del self.thread
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Resource 'ipv6.google.com' is not available
./home/buildbot/buildarea/3.8.cstratak-fedora-stable-x86_64.refleak/build/Lib/test/support/init.py:3323: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 39709), raddr=('127.0.0.1', 55950)>
del self.thread
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Resource 'ipv6.google.com' is not available
./home/buildbot/buildarea/3.8.cstratak-fedora-stable-x86_64.refleak/build/Lib/test/support/init.py:3323: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 39169), raddr=('127.0.0.1', 34992)>
del self.thread
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Resource 'ipv6.google.com' is not available
./home/buildbot/buildarea/3.8.cstratak-fedora-stable-x86_64.refleak/build/Lib/test/support/init.py:3323: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 53179), raddr=('127.0.0.1', 33400)>
del self.thread
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Resource 'ipv6.google.com' is not available
./home/buildbot/buildarea/3.8.cstratak-fedora-stable-x86_64.refleak/build/Lib/test/support/init.py:3323: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 36717), raddr=('127.0.0.1', 49724)>
del self.thread
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Resource 'ipv6.google.com' is not available
./home/buildbot/buildarea/3.8.cstratak-fedora-stable-x86_64.refleak/build/Lib/test/support/init.py:3323: ResourceWarning: unclosed <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 40913), raddr=('127.0.0.1', 45944)>
del self.thread
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Resource 'ipv6.google.com' is not available
.

beginning 6 repetitions
123456
Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)
Dangling thread: <_MainThread(MainThread, started 140669094238016)>
Dangling thread: <Thread(waitpid-0, started daemon 140668768876288)>
Unknown child process pid 3450080, will report returncode 255
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 3450080 is closed
....Unknown child process pid 3467752, will report returncode 255
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 3467752 is closed
.Unknown child process pid 3468093, will report returncode 255
.

1 test altered the execution environment:
test_asyncio

Recent exmaple on AMD64 Windows10 3.x:
https://buildbot.python.org/all/#/builders/129/builds/1498

0:14:19 load avg: 0.10 [418/423/1] test_asyncio failed (env changed) (1 min 10 sec) -- running: test_mmap (4 min 47 sec), test_io (3 min 41 sec)
Warning -- Unraisable exception
Warning -- Unraisable exception

New changeset 701b638 by Victor Stinner in branch 'master':
bpo-38912: regrtest logs unraisable exception into sys.__stderr__ (GH-21718)
701b638

More info with my latest change.

AMD64 Windows10 3.x:
https://buildbot.python.org/all/#/builders/129/builds/1500

0:10:26 load avg: 3.17 [354/423/2] test_asyncio failed (env changed) (1 min 23 sec) -- running: test_capi (1 min 3 sec)

Warning -- Unraisable exception
Exception ignored in: <function _ProactorBasePipeTransport.__del__ at 0x000001E0C873CCD0>
Traceback (most recent call last):
  File "D:\buildarea\3.x.bolen-windows10\build\lib\asyncio\proactor_events.py", line 115, in __del__
    _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
  File "D:\buildarea\3.x.bolen-windows10\build\lib\asyncio\proactor_events.py", line 79, in __repr__
    info.append(f'fd={self._sock.fileno()}')
  File "D:\buildarea\3.x.bolen-windows10\build\lib\asyncio\windows_utils.py", line 102, in fileno
    raise ValueError("I/O operation on closed pipe")
ValueError: I/O operation on closed pipe

It seems like the issue comes from SubprocessProactorTests. Using python -m test.bisect_cmd, I isolated one test which causes the issue:

+ C:\vstinner\python\master\PCbuild\amd64\python_d.exe -m test --matchfile C:\Users\vstinner\AppData\Local\Temp\tmpoe9_zui_ --fail-env-changed test_asyncio -v
== CPython 3.10.0a0 (heads/master:701b63894f, Aug 3 2020, 23:38:07) [MSC v.1916 64 bit (AMD64)]
== Windows-10-10.0.18362-SP0 little-endian
== cwd: C:\vstinner\python\master\build\test_python_7732æ
== CPU count: 2
== encodings: locale=cp1252, FS=utf-8
0:00:00 Run tests sequentially
0:00:00 [1/1] test_asyncio
test_cancel_post_init (test.test_asyncio.test_subprocess.SubprocessProactorTests) ... ok

----------------------------------------------------------------------

Ran 1 test in 0.015s

OK
C:\vstinner\python\master\lib\asyncio\windows_utils.py:112: ResourceWarning: unclosed <PipeHandle handle=292>
_warn(f"unclosed {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
C:\vstinner\python\master\lib\asyncio\windows_utils.py:112: ResourceWarning: unclosed <PipeHandle handle=792>
_warn(f"unclosed {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback

Warning -- Unraisable exception
Exception ignored in: <function _ProactorBasePipeTransport.__del__ at 0x0000015D1FCA2AF0>
Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 115, in __del__
    _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 79, in __repr__
    info.append(f'fd={self._sock.fileno()}')
  File "C:\vstinner\python\master\lib\asyncio\windows_utils.py", line 102, in fileno
    raise ValueError("I/O operation on closed pipe")
ValueError: I/O operation on closed pipe

Warning -- Unraisable exception
Exception ignored in: <function _ProactorBasePipeTransport.__del__ at 0x0000015D1FCA2AF0>
Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 115, in __del__
    _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 79, in __repr__
    info.append(f'fd={self._sock.fileno()}')
  File "C:\vstinner\python\master\lib\asyncio\windows_utils.py", line 102, in fileno
    raise ValueError("I/O operation on closed pipe")
ValueError: I/O operation on closed pipe
test_asyncio failed (env changed)

== Tests result: ENV CHANGED ==

When I commented code to hide logs in the tests, I saw another bug.

Local patch:

diff --git a/Lib/test/test_asyncio/test_subprocess.py b/Lib/test/test_asyncio/test_subprocess.py
index 177a02cdcc..3095b1d987 100644
--- a/Lib/test/test_asyncio/test_subprocess.py
+++ b/Lib/test/test_asyncio/test_subprocess.py
@@ -456,7 +456,8 @@ class SubprocessMixin:

         # ignore the log:
         # "Exception during subprocess creation, kill the subprocess"
-        with test_utils.disable_logger():
+        #with test_utils.disable_logger():
+        if 1:
             self.loop.run_until_complete(cancel_make_transport())
             test_utils.run_briefly(self.loop)

Output:

0:00:05 [ 14] test_asyncio
test_cancel_post_init (test.test_asyncio.test_subprocess.SubprocessProactorTests) ...

Exception in call
back _ProactorReadPipeTransport._loop_reading(<Future finished result=b''>)
handle: <Handle _ProactorReadPipeTransport._loop_reading(<Future finished result=b''>)>
Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 293, in _loop_reading
    data = self._data[:length]
TypeError: slice indices must be integers or None or have an __index__ method

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\asyncio\events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 325, in _loop_reading
    if length > -1:
TypeError: '>' not supported between instances of 'bytes' and 'int'


Exception in callback _ProactorReadPipeTransport._loop_reading(<Future finished result=b''>)
handle: <Handle _ProactorReadPipeTransport._loop_reading(<Future finished result=b''>)>
Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 293, in _loop_reading
    data = self._data[:length]
TypeError: slice indices must be integers or None or have an __index__ method

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\asyncio\events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 325, in _loop_reading
    if length > -1:
TypeError: '>' not supported between instances of 'bytes' and 'int'
ok

File "C:\vstinner\python\master\lib\asyncio\proactor_events.py", line 293, in _loop_reading
data = self._data[:length]
TypeError: slice indices must be integers or None or have an __index__ method

I created bpo-41467: asyncio: recv_into() must not return b'' if the socket/pipe is closed.

I created bpo-41467: asyncio: recv_into() must not return b'' if the socket/pipe is closed.

This was a real asyncio bug, specific to Windows, and it's now fixed.

But the initial bug report was on Unix (Linux?) and is different:

Warning -- threading_cleanup() failed to cleanup 1 threads (count: 1, dangling: 2)

Another error?

aarch64 RHEL8 LTO + PGO 3.x:
https://buildbot.python.org/all/#/builders/618/builds/835

1 test altered the execution environment:
test_asyncio

0:01:55 load avg: 7.00 [329/423/1] test_asyncio failed (env changed) (1 min 25 sec) -- running: test_peg_generator (1 min)
Warning -- Unraisable exception
Exception ignored in: <function _SSLProtocolTransport.__del__ at 0xffffbd0d68b0>
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/sslproto.py", line 321, in __del__
    self.close()
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/sslproto.py", line 316, in close
    self._ssl_protocol._start_shutdown()
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/sslproto.py", line 590, in _start_shutdown
    self._abort()
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/sslproto.py", line 731, in _abort
    self._transport.abort()
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/selector_events.py", line 678, in abort
    self._force_close(None)
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/selector_events.py", line 729, in _force_close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/base_events.py", line 746, in call_soon
    self._check_closed()
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL8-aarch64.lto-pgo/build/Lib/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
(...)

The error occurred in _SSLProtocolTransport.__del__() on self.close(). The previous line is:

_warn(f"unclosed transport {self!r}", ResourceWarning, source=self)

But I cannot see the warning in tests. Maybe the bug occurred in a test which hides logs.

New changeset a0b57b3 by Victor Stinner in branch '3.9':
bpo-38912: regrtest logs unraisable exception into sys.__stderr__ (GH-21718) (GH-21827)
a0b57b3

On the AArch64 RHEL8 buildbot, I managed to reproduce a ENV_CHANGED issue with only these two test_asyncio tests:

test.test_asyncio.test_events.SelectEventLoopTests.test_create_server_ssl_verify_failed
test.test_asyncio.test_events.SelectEventLoopTests.test_create_server_ssl_verified

I'm running a bisect for like 2 hours... The bug is really hard to trigger :-(

test.test_asyncio.test_events.SelectEventLoopTests.test_create_server_ssl_verified fails randomly and emits an "unraisable exception".

Logs:

+ /home/vstinner/python/master/python -m test --matchfile /tmp/tmpz2f1v5aq test_asyncio --fail-env-changed -v
== CPython 3.10.0a0 (heads/master:0ee0b2938c, Aug 11 2020, 15:50:20) [GCC 8.3.1 20191121 (Red Hat 8.3.1-5)]
== Linux-4.18.0-193.14.3.el8_2.aarch64-aarch64-with-glibc2.28 little-endian
== cwd: /home/vstinner/python/master/build/test_python_585912æ
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
0:00:00 load avg: 7.50 Run tests sequentially
0:00:00 load avg: 7.50 [1/1] test_asyncio
test_create_server_ssl_verified (test.test_asyncio.test_events.SelectEventLoopTests) ... /home/vstinner/python/master/Lib/test/support/__init__.py:597: ResourceWarning: unclosed <socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 43285), raddr=('127.0.0.1', 408
58)>
  gc.collect()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Task was destroyed but it is pending!
task: <Task pending name='Task-4' coro=<BaseSelectorEventLoop._accept_connection2() running at /home/vstinner/python/master/Lib/asyncio/selector_events.py:216> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffa04b9350>()]>>                                                                           
/home/vstinner/python/master/Lib/asyncio/sslproto.py:320: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0xffffa01d48a0>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Warning -- Unraisable exception
Exception ignored in: <function _SSLProtocolTransport.__del__ at 0xffffa09f0910>
Traceback (most recent call last):
  File "/home/vstinner/python/master/Lib/asyncio/sslproto.py", line 321, in __del__
    self.close()
  File "/home/vstinner/python/master/Lib/asyncio/sslproto.py", line 316, in close
    self._ssl_protocol._start_shutdown()
  File "/home/vstinner/python/master/Lib/asyncio/sslproto.py", line 590, in _start_shutdown
    self._abort()
  File "/home/vstinner/python/master/Lib/asyncio/sslproto.py", line 731, in _abort
    self._transport.abort()
  File "/home/vstinner/python/master/Lib/asyncio/selector_events.py", line 678, in abort
    self._force_close(None)
  File "/home/vstinner/python/master/Lib/asyncio/selector_events.py", line 729, in _force_close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 746, in call_soon
    self._check_closed()
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
/home/vstinner/python/master/Lib/asyncio/selector_events.py:702: ResourceWarning: unclosed transport <_SelectorSocketTransport closing fd=7>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
ERROR
/home/vstinner/python/master/Lib/unittest/case.py:620: ResourceWarning: unclosed <socket.socket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 43285)>                                                                                                                        
  outcome.errors.clear()
ResourceWarning: Enable tracemalloc to get the object allocation traceback

======================================================================
ERROR: test_create_server_ssl_verified (test.test_asyncio.test_events.SelectEventLoopTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/vstinner/python/master/Lib/test/test_asyncio/test_events.py", line 1110, in test_create_server_ssl_verified
    proto.transport.close()
AttributeError: 'NoneType' object has no attribute 'close'

Ran 1 test in 0.218s

FAILED (errors=1)
/home/vstinner/python/master/Lib/asyncio/sslproto.py:320: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0xffffa01baec0>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xffffa001b1e0>
transport: <_SelectorSocketTransport closing fd=6>
Traceback (most recent call last):
  File "/home/vstinner/python/master/Lib/test/libregrtest/runtest.py", line 236, in _runtest_inner2
    test_runner()
  File "/home/vstinner/python/master/Lib/test/libregrtest/runtest.py", line 211, in _test_module
    support.run_unittest(tests)
  File "/home/vstinner/python/master/Lib/test/support/__init__.py", line 1082, in run_unittest
    _run_suite(suite)
  File "/home/vstinner/python/master/Lib/test/support/__init__.py", line 974, in _run_suite
    raise TestFailed(err)
test.support.TestFailed: Traceback (most recent call last):
  File "/home/vstinner/python/master/Lib/test/test_asyncio/test_events.py", line 1110, in test_create_server_ssl_verified
    proto.transport.close()
AttributeError: 'NoneType' object has no attribute 'close'


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/vstinner/python/master/Lib/asyncio/selector_events.py", line 916, in write
    n = self._sock.send(data)
ConnectionResetError: [Errno 104] Connection reset by peer

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/vstinner/python/master/Lib/asyncio/sslproto.py", line 684, in _process_write_backlog
    self._transport.write(chunk)
  File "/home/vstinner/python/master/Lib/asyncio/selector_events.py", line 922, in write
    self._fatal_error(exc, 'Fatal write error on socket transport')
  File "/home/vstinner/python/master/Lib/asyncio/selector_events.py", line 717, in _fatal_error
    self._force_close(exc)
  File "/home/vstinner/python/master/Lib/asyncio/selector_events.py", line 729, in _force_close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 746, in call_soon
    self._check_closed()
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
/home/vstinner/python/master/Lib/asyncio/selector_events.py:702: ResourceWarning: unclosed transport <_SelectorSocketTransport closing fd=6>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
test test_asyncio failed
test_asyncio failed

Another failure on aarch64 RHEL7 Refleaks 3.9:
https://buildbot.python.org/all/#builders/122/builds/62

0:53:43 load avg: 0.97 [424/425/1] test_asyncio failed (env changed) (53 min 34 sec) -- running: test_pydoc (29 min 2 sec)
beginning 6 repetitions
123456
../home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/sslproto.py:320: ResourceWarning: unclosed transport <asyncio.sslproto._SSLProtocolTransport object at 0xffff77a58d00>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Warning -- Unraisable exception
Exception ignored in: <function _SSLProtocolTransport.__del__ at 0xffff802d6a50>
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/sslproto.py", line 321, in __del__
    self.close()
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/sslproto.py", line 316, in close
    self._ssl_protocol._start_shutdown()
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/sslproto.py", line 590, in _start_shutdown
    self._abort()
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/sslproto.py", line 731, in _abort
    self._transport.abort()
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/selector_events.py", line 680, in abort
    self._force_close(None)
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/selector_events.py", line 731, in _force_close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/base_events.py", line 746, in call_soon
    self._check_closed()
  File "/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
/home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/selector_events.py:704: ResourceWarning: unclosed transport <_SelectorSocketTransport closing fd=8>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Task was destroyed but it is pending!
task: <Task pending name='Task-8474' coro=<BaseSelectorEventLoop._accept_connection2() running at /home/buildbot/buildarea/3.9.cstratak-RHEL7-aarch64.refleak/build/Lib/asyncio/selector_events.py:218> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffff77a7d8d0>()]>>
....

The "'NoneType' object has no attribute 'close'" error is likely caused by a race against the loop calling the test protocol object's connection_made callback. I was able to reproduce this case occasionally on macOS and it's likely platform-agnostic. Given server/connection cleanup isn't context-managed or finally-driven on the affected tests, raising the NoneType error will skip cleanup and we see additional exceptions from unclosed networking components being garbage collected.

Tests using this test protocol pattern were either waiting for the callback already or were waiting on network i/o that happens long after connection establishment with the exception of:

test_create_server_ssl_verified
test_create_unix_server_ssl_verified

PR 22691 ensures those two tests wait for the connect callbacks as well.

This may not address the env changed error from recent msg378481, as the initial error is not necessarily disclosed in that log.

New changeset de73d43 by Justin Turner Arthur in branch 'master':
bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691)
de73d43

I've applied Justin's patch, and opened PRs for backporting to 3.9 and 3.8 (currently waiting on CI).

Based on my local testing and buildbot fleet results, it definitely reduces the rate at which the failure occurs, but does not 100% resolve the ENV CHANGED failure (from the transport being closed). As a result, I'll leave the issue open for further investigation.

New changeset e43bee7 by Miss Skeleton (bot) in branch '3.9':
bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691)
e43bee7

New changeset 3faef63 by Miss Skeleton (bot) in branch '3.8':
bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691)
3faef63

See #30274 test_asyncio is always failing with env changed.

The main branch is clear

Navigation Menu

Repository navigation

test_asyncio altered the execution environment #83093

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

test_asyncio altered the execution environment #83093

Description

Activity

pablogsal commented on Nov 26, 2019

vstinner commented on Aug 3, 2020

vstinner commented on Aug 3, 2020

vstinner commented on Aug 3, 2020

vstinner commented on Aug 3, 2020

vstinner commented on Aug 3, 2020

vstinner commented on Aug 5, 2020

vstinner commented on Aug 5, 2020

vstinner commented on Aug 11, 2020

vstinner commented on Aug 11, 2020

vstinner commented on Aug 11, 2020

vstinner commented on Oct 12, 2020

JustinTArthur commented on Oct 14, 2020

aeros commented on Oct 20, 2020

aeros commented on Oct 20, 2020

miss-islington commented on Oct 20, 2020

miss-islington commented on Oct 20, 2020

kumaraditya303 commented on Jan 19, 2022

asvetlov commented on Mar 15, 2022

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions