[issue38323] test_asyncio: test_close_kill_running() hangs on AMD64 RHEL7 Refleaks 3.x

[STINNER Victor]

STINNER Victor <vstinner at python.org> added the comment:

I'm able to reproduce the issue locally using the command:

./python -m test test_asyncio --match=test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests.test_close_kill_running -v -F -j20 --timeout=30.0

Example:

...
0:00:47 load avg: 14.35 [287] test_asyncio passed -- running: test_asyncio (31.1 sec)
0:00:47 load avg: 14.35 [288] test_asyncio passed -- running: test_asyncio (31.3 sec)
0:00:47 load avg: 14.35 [289/1] test_asyncio crashed (Exit code 1)
Timeout (0:00:30)!
Thread 0x00007f3bbd098740 (most recent call first):
  File "/home/vstinner/python/master/Lib/selectors.py", line 468 in select
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 1837 in _run_once
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 589 in run_forever
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 621 in run_until_complete
  File "/home/vstinner/python/master/Lib/test/test_asyncio/test_subprocess.py", line 484 in test_close_kill_running
...


I added some debug traces.

Logs when it works:
---
0:01:39 load avg: 21.21 [512] test_asyncio passed -- running: test_asyncio (31.0 sec)
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... MultiLoopChildWatcher: attach_loop <_UnixSelectorEventLoop running=False closed=False debug=False>
MultiLoopChildWatcher: SIGCHLD signal registered
MultiLoopChildWatcher: attach_loop None
MultiLoopChildWatcher: attach_loop None
MultiLoopChildWatcher: SIGCHLD signal registered
ok

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

Ran 1 test in 0.054s

OK
MultiLoopChildWatcher: _do_waitpid 27887
MultiLoopChildWatcher: _do_waitpid (0, 0)
kill 27887 9
MultiLoopChildWatcher: _sig_chld
MultiLoopChildWatcher: _do_waitpid_all
MultiLoopChildWatcher: _do_waitpid 27887
MultiLoopChildWatcher: _do_waitpid (27887, 9)
MultiLoopChildWatcher: _do_waitpid: call (<bound method _UnixSelectorEventLoop._child_watcher_callback of <_UnixSelectorEventLoop running=True closed=False debug=False>>, <_UnixSelectorEventLoop running=True closed=False debug=False>)
---

Logs when it hangs:
---
0:01:40 load avg: 21.21 [514/1] test_asyncio crashed (Exit code 1)
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... MultiLoopChildWatcher: attach_loop <_UnixSelectorEventLoop running=False closed=False debug=False>
MultiLoopChildWatcher: SIGCHLD signal registered
MultiLoopChildWatcher: _do_waitpid 26010
MultiLoopChildWatcher: _do_waitpid (0, 0)
kill 26010 9
Timeout (0:00:30)!
Thread 0x00007f4b73f35740 (most recent call first):
  File "/home/vstinner/python/master/Lib/selectors.py", line 468 in select
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 1837 in _run_once
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 589 in run_forever
  File "/home/vstinner/python/master/Lib/asyncio/base_events.py", line 621 in run_until_complete
  File "/home/vstinner/python/master/Lib/test/test_asyncio/test_subprocess.py", line 484 in test_close_kill_running
...
---

It seems like sometimes, MultiLoopChildWatcher._sig_chld() is not called.

----------

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