test_asyncio altered the execution environment #83093
Comments
|
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 1 test altered the execution environment: |
pablogsal
added
3.8
|
Recent exmaple on AMD64 Windows10 3.x: 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) |
|
More info with my latest change. AMD64 Windows10 3.x: 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 pipeIt 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 ---------------------------------------------------------------------- Ran 1 test in 0.015s OK 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 # 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 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 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:
|
|
Another error? aarch64 RHEL8 LTO + PGO 3.x: 1 test altered the execution environment: 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. |
|
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 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====================================================================== 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: 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:
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. |
|
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. |
|
See #30274 test_asyncio is always failing with env changed. |
|
The main branch is clear |
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: