Mailing List Archive

[issue38912] test_asyncio altered the execution environment
STINNER Victor <vstinner@python.org> added the comment:

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

----------
nosy: +vstinner

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
Change by STINNER Victor <vstinner@python.org>:


----------
keywords: +patch
pull_requests: +20861
stage: -> patch review
pull_request: https://github.com/python/cpython/pull/21718

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:


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


----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:

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 ==

----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:

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

----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:

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.

----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:

> 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)

----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:

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.

----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
Change by STINNER Victor <vstinner@python.org>:


----------
pull_requests: +20956
pull_request: https://github.com/python/cpython/pull/21827

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:


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


----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:

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 :-(

----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com
[issue38912] test_asyncio altered the execution environment [ In reply to ]
STINNER Victor <vstinner@python.org> added the comment:

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

----------

_______________________________________
Python tracker <report@bugs.python.org>
<https://bugs.python.org/issue38912>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/list-python-bugs%40lists.gossamer-threads.com