Author vstinner
Recipients asvetlov, vstinner, yselivanov
Date 2019-10-22.21:38:49
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1571780329.27.0.401942187775.issue38323@roundup.psfhosted.org>
In-reply-to
Content
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.
History
Date User Action Args
2019-10-22 21:38:49vstinnersetrecipients: + vstinner, asvetlov, yselivanov
2019-10-22 21:38:49vstinnersetmessageid: <1571780329.27.0.401942187775.issue38323@roundup.psfhosted.org>
2019-10-22 21:38:49vstinnerlinkissue38323 messages
2019-10-22 21:38:49vstinnercreate