Issue38912
This issue tracker has been migrated to GitHub,
and is currently read-only.
For more information,
see the GitHub FAQs in the Python's Developer Guide.
Created on 2019-11-26 00:50 by pablogsal, last changed 2022-04-11 14:59 by admin. This issue is now closed.
Pull Requests | |||
---|---|---|---|
URL | Status | Linked | Edit |
PR 21718 | merged | vstinner, 2020-08-03 17:10 | |
PR 21827 | merged | vstinner, 2020-08-11 13:47 | |
PR 22691 | merged | JustinTArthur, 2020-10-14 04:21 | |
PR 22799 | merged | miss-islington, 2020-10-20 01:19 | |
PR 22800 | merged | miss-islington, 2020-10-20 01:19 |
Messages (19) | |||
---|---|---|---|
msg357470 - (view) | Author: Pablo Galindo Salgado (pablogsal) * | Date: 2019-11-26 00:50 | |
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 |
|||
msg374743 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-03 17:10 | |
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 |
|||
msg374755 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-03 20:51 | |
New changeset 701b63894fdb75b12865b9be6261ce4913da76f5 by Victor Stinner in branch 'master': bpo-38912: regrtest logs unraisable exception into sys.__stderr__ (GH-21718) https://github.com/python/cpython/commit/701b63894fdb75b12865b9be6261ce4913da76f5 |
|||
msg374758 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-03 21:55 | |
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 == |
|||
msg374759 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-03 22:02 | |
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 |
|||
msg374763 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-03 22:37 | |
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. |
|||
msg374850 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-05 00:14 | |
> 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) |
|||
msg374851 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-05 00:17 | |
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. |
|||
msg375180 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-11 15:03 | |
New changeset a0b57b3317d6653255415af5228c94485aa57a0d by Victor Stinner in branch '3.9': bpo-38912: regrtest logs unraisable exception into sys.__stderr__ (GH-21718) (GH-21827) https://github.com/python/cpython/commit/a0b57b3317d6653255415af5228c94485aa57a0d |
|||
msg375181 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-11 15:04 | |
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 :-( |
|||
msg375182 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-08-11 15:29 | |
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 |
|||
msg378481 - (view) | Author: STINNER Victor (vstinner) * | Date: 2020-10-12 09:02 | |
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>()]>> .... |
|||
msg378602 - (view) | Author: Justin Arthur (JustinTArthur) * | Date: 2020-10-14 04:31 | |
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. |
|||
msg379071 - (view) | Author: Kyle Stanley (aeros) * | Date: 2020-10-20 01:19 | |
New changeset de73d432bb29f6439f2db16cb991e15e09c70c26 by Justin Turner Arthur in branch 'master': bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691) https://github.com/python/cpython/commit/de73d432bb29f6439f2db16cb991e15e09c70c26 |
|||
msg379072 - (view) | Author: Kyle Stanley (aeros) * | Date: 2020-10-20 01:24 | |
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. |
|||
msg379074 - (view) | Author: miss-islington (miss-islington) | Date: 2020-10-20 01:40 | |
New changeset e43bee7e114ec361efde34f4b546f984574e6653 by Miss Skeleton (bot) in branch '3.9': bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691) https://github.com/python/cpython/commit/e43bee7e114ec361efde34f4b546f984574e6653 |
|||
msg379075 - (view) | Author: miss-islington (miss-islington) | Date: 2020-10-20 01:44 | |
New changeset 3faef630a44be2d1ea5516e85e95fef4fd027a95 by Miss Skeleton (bot) in branch '3.8': bpo-38912: fix close before connect callback in test_asyncio SSL tests (GH-22691) https://github.com/python/cpython/commit/3faef630a44be2d1ea5516e85e95fef4fd027a95 |
|||
msg410940 - (view) | Author: Kumar Aditya (kumaraditya) * | Date: 2022-01-19 12:47 | |
See https://github.com/python/cpython/pull/30274 test_asyncio is always failing with env changed. |
|||
msg415295 - (view) | Author: Andrew Svetlov (asvetlov) * | Date: 2022-03-15 20:50 | |
The main branch is clear |
History | |||
---|---|---|---|
Date | User | Action | Args |
2022-04-11 14:59:23 | admin | set | github: 83093 |
2022-03-15 20:50:48 | asvetlov | set | status: open -> closed resolution: fixed messages: + msg415295 stage: patch review -> resolved |
2022-01-19 12:47:49 | kumaraditya | set | status: pending -> open nosy: + kumaraditya messages: + msg410940 |
2021-08-24 08:34:15 | serhiy.storchaka | set | status: open -> pending |
2020-10-20 01:44:09 | miss-islington | set | messages: + msg379075 |
2020-10-20 01:40:09 | miss-islington | set | messages: + msg379074 |
2020-10-20 01:24:59 | aeros | set | messages: + msg379072 |
2020-10-20 01:19:22 | miss-islington | set | pull_requests: + pull_request21757 |
2020-10-20 01:19:15 | miss-islington | set | nosy:
+ miss-islington pull_requests: + pull_request21756 |
2020-10-20 01:19:00 | aeros | set | messages: + msg379071 |
2020-10-14 04:31:47 | JustinTArthur | set | nosy:
vstinner, asvetlov, yselivanov, pablogsal, JustinTArthur, aeros messages: + msg378602 |
2020-10-14 04:21:10 | JustinTArthur | set | nosy:
+ JustinTArthur pull_requests: + pull_request21662 |
2020-10-12 12:05:00 | pablogsal | set | nosy:
+ aeros |
2020-10-12 09:02:15 | vstinner | set | messages: + msg378481 |
2020-08-11 15:29:09 | vstinner | set | messages: + msg375182 |
2020-08-11 15:04:31 | vstinner | set | messages: + msg375181 |
2020-08-11 15:03:41 | vstinner | set | messages: + msg375180 |
2020-08-11 13:47:18 | vstinner | set | pull_requests: + pull_request20956 |
2020-08-05 00:17:51 | vstinner | set | messages: + msg374851 |
2020-08-05 00:14:01 | vstinner | set | messages: + msg374850 |
2020-08-03 22:37:06 | vstinner | set | messages: + msg374763 |
2020-08-03 22:02:23 | vstinner | set | messages: + msg374759 |
2020-08-03 21:55:21 | vstinner | set | messages: + msg374758 |
2020-08-03 20:51:46 | vstinner | set | messages: + msg374755 |
2020-08-03 17:10:18 | vstinner | set | keywords:
+ patch stage: patch review pull_requests: + pull_request20861 |
2020-08-03 17:10:05 | vstinner | set | nosy:
+ vstinner messages: + msg374743 |
2019-11-26 00:50:21 | pablogsal | create |