asyncio: MultiLoopWatcher has a race condition (test_asyncio: test_close_kill_running() hangs on AMD64 RHEL7 Refleaks 3.x)

@vstinner

BPO	38323
Nosy	@vstinner, @njsmith, @asvetlov, @cjerdonek, @1st1, @jstasiak, @pablogsal, @miss-islington, @aeros, @Fidget-Spinner, @shreyanavigyan
PRs	bpo-38323: Suppress the hang #18457 bpo-38323: Temporarily skip close_kill_running() for MultiLoopWatcher in test_asyncio #20013 [WIP] bpo-38323: Fix MultiLoopChildWatcher hangs #20142 bpo-38323: Add guard clauses in MultiLoopChildWatcher. #22756 [3.9] bpo-38323: Add guard clauses in MultiLoopChildWatcher. (GH-22756) #23806 [3.8] bpo-38323: Add guard clauses in MultiLoopChildWatcher. (GH-22756) #23807 bpo-38323, asyncio: Fix MultiLoopChildWatcher race condition #26536 bpo-38323: Remove test_cancel_make_subprocess_transport_exec as it has a rance condicion #26541 bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite #26542 [3.9] bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite (GH-26542) #26543 [3.10] bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite (GH-26542) #26544 bpo-38323: Change MultiLoopChildWatcher to install handlers for all the event loops #26574 bpo-44368: Improve syntax errors with invalid as pattern targets #26632 [3.8] bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite (GH-26542) #26670
Files	test-kill.py test-kill2.py test-kill3.py

^{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:

assignee = None
closed_at = None
created_at = <Date 2019-09-30.12:57:35.040>
labels = ['type-bug', 'tests', '3.9', 'expert-asyncio']
title = 'asyncio: MultiLoopWatcher has a race condition (test_asyncio: test_close_kill_running() hangs on AMD64 RHEL7 Refleaks 3.x)'
updated_at = <Date 2021-11-05.17:45:33.738>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2021-11-05.17:45:33.738>
actor = 'byllyfish'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Tests', 'asyncio']
creation = <Date 2019-09-30.12:57:35.040>
creator = 'vstinner'
dependencies = []
files = ['49144', '49145', '49150']
hgrepos = []
issue_num = 38323
keywords = ['patch']
message_count = 49.0
messages = ['353568', '354079', '355150', '355157', '355159', '355362', '355363', '359909', '359910', '359928', '360975', '361576', '361691', '361801', '368061', '368183', '368280', '368467', '368468', '368501', '368511', '368514', '368516', '368532', '368544', '368549', '368561', '368563', '368564', '368699', '368725', '369086', '380420', '383194', '383197', '383199', '395090', '395113', '395119', '395126', '395138', '395139', '395142', '395143', '395376', '395693', '395718', '396684', '405813']
nosy_count = 12.0
nosy_names = ['vstinner', 'njs', 'asvetlov', 'chris.jerdonek', 'yselivanov', 'jstasiak', 'pablogsal', 'miss-islington', 'aeros', 'kj', 'shreyanavigyan', 'byllyfish']
pr_nums = ['18457', '20013', '20142', '22756', '23806', '23807', '26536', '26541', '26542', '26543', '26544', '26574', '26632', '26670']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue38323'
versions = ['Python 3.9']

test_asyncio fails once on AMD64 RHEL7 Refleaks 3.x, and then test_close_kill_running() was killed after 3h 15 min. I guess that it hangs, but I'm not 100% sure. When test_asyncio was re-run, it seems like test_asyncio was run 3x successful but it hanged at the 4rd run. Refleaks runs each test 6 times.

https://buildbot.python.org/all/#/builders/264/builds/10

0:17:04 load avg: 3.01 [416/419/1] test_asyncio failed (12 min 21 sec) -- running: test_multiprocessing_fork (6 min 34 sec), test_concurrent_futures (10 min 52 sec), test_multiprocessing_spawn (13 min 53 sec)
beginning 6 repetitions
123456
.Unknown child process pid 25032, will report returncode 255
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 25032 is closed
.Unknown child process pid 19349, will report returncode 255
Child watcher got an unexpected pid: 19349
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL7-x86_64.refleak/build/Lib/asyncio/unix_events.py", line 1213, in _do_waitpid
    loop, callback, args = self._callbacks.pop(pid)
KeyError: 19349
test test_asyncio failed -- Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.x.cstratak-RHEL7-x86_64.refleak/build/Lib/test/test_asyncio/test_subprocess.py", line 156, in test_shell
    self.assertEqual(exitcode, 7)
AssertionError: 255 != 7

(...)
0:21:59 load avg: 0.52 [419/419/1] test_concurrent_futures passed (15 min 46 sec)
(...)
== Tests result: FAILURE ==

404 tests OK.

10 slowest tests:

test_concurrent_futures: 15 min 46 sec
test_multiprocessing_spawn: 14 min 7 sec
test_asyncio: 12 min 21 sec
test_multiprocessing_forkserver: 8 min 59 sec
test_multiprocessing_fork: 7 min 13 sec
test_io: 3 min 47 sec
test_subprocess: 3 min 30 sec
test_pickle: 2 min 51 sec
test_capi: 2 min 47 sec
test_zipfile: 2 min 41 sec

1 test failed:
test_asyncio

14 tests skipped:
test_devpoll test_gdb test_ioctl test_kqueue test_msilib
test_ossaudiodev test_startfile test_tix test_tk test_ttk_guionly
test_winconsoleio test_winreg test_winsound test_zipfile64

Re-running failed tests in verbose mode

Re-running test_asyncio in verbose mode
beginning 6 repetitions
123456
(...)

test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
...
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok
...
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessSafeWatcherTests) ... ok
...
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests) ... ok
...

test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
...
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok
...
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessSafeWatcherTests) ... ok
...
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests) ... ok
...
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_communicate (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_communicate_ignore_broken_pipe (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_create_subprocess_exec_text_mode_fails (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_create_subprocess_exec_with_path (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_create_subprocess_shell_text_mode_fails (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_devnull_error (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_devnull_input (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_devnull_output (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_empty_input (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_exec_loop_deprecated (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_kill (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_pause_reading (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_popen_error (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_popen_error_with_stdin_pipe (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_process_create_warning (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_read_stdout_after_process_exit (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_send_signal (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_shell (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_shell_loop_deprecated (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_start_new_session (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_stdin_broken_pipe (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_stdin_not_inheritable (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_stdin_stdout (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_subprocess_protocol_create_warning (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_terminate (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok
test_cancel_make_subprocess_transport_exec (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok
test_cancel_post_init (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok
test_cancel_process_wait (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok
test_close_dont_kill_finished (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok
...Timeout (3:15:00)!
Thread 0x00007f666a7a1740 (most recent call first):
File "/home/buildbot/buildarea/3.x.cstratak-RHEL7-x86_64.refleak/build/Lib/selectors.py", line 468 in select
File "/home/buildbot/buildarea/3.x.cstratak-RHEL7-x86_64.refleak/build/Lib/asyncio/base_events.py", line 1837 in _run_once
File "/home/buildbot/buildarea/3.x.cstratak-RHEL7-x86_64.refleak/build/Lib/asyncio/base_events.py", line 589 in run_forever
File "/home/buildbot/buildarea/3.x.cstratak-RHEL7-x86_64.refleak/build/Lib/asyncio/base_events.py", line 621 in run_until_complete
File "/home/buildbot/buildarea/3.x.cstratak-RHEL7-x86_64.refleak/build/Lib/test/test_asyncio/test_subprocess.py", line 484 in test_close_kill_running

Fail on x86 Gentoo Refleaks 3.x:
https://buildbot.python.org/all/#/builders/1/builds/737

(...)
Loop <UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 8654 is closed
.Timeout (3:15:00)!
Thread 0xb7b92700 (most recent call first):
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/selectors.py", line 468 in select
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 1837 in _run_once
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 589 in run_forever
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 621 in run_until_complete
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/test_asyncio/test_subprocess.py", line 484 in test_close_kill_running
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 616 in _callTestMethod
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 659 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 719 in __call_
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/support/testresult.py", line 162 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/support/init.py", line 2032 in _run_suite
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/support/init.py", line 2128 in run_unittest
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 209 in _test_module
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/refleak.py", line 87 in dash_R
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 232 in _runtest_inner2
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 270 in _runtest_inner
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 153 in _runtest
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 193 in runtest
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest_mp.py", line 67 in run_tests_worker
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 654 in _main
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 634 in main
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 712 in main
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/regrtest.py", line 43 in _main
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/regrtest.py", line 47 in <module>
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 85 in _run_code
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 192 in _run_module_as_main

== Tests result: FAILURE ==

410 tests OK.

10 slowest tests:

test_concurrent_futures: 23 min 2 sec
test_multiprocessing_spawn: 22 min 6 sec
test_multiprocessing_forkserver: 15 min 51 sec
test_multiprocessing_fork: 10 min 15 sec
test_regrtest: 10 min 10 sec
test_gdb: 8 min 26 sec
test_lib2to3: 7 min 31 sec
test_pickle: 7 min
test_io: 6 min 50 sec
test_subprocess: 6 min 37 sec

1 test failed:
test_asyncio

8 tests skipped:
test_devpoll test_kqueue test_msilib test_startfile
test_winconsoleio test_winreg test_winsound test_zipfile64
4:25:59 load avg: 1.55
4:25:59 load avg: 1.55 Re-running failed tests in verbose mode
4:25:59 load avg: 1.55 Re-running test_asyncio in verbose mode
(...)
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... Timeout (3:15:00)!
Thread 0xb7c51700 (most recent call first):
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/selectors.py", line 468 in select
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 1837 in _run_once
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 589 in run_forever
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 621 in run_until_complete
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/test_asyncio/test_subprocess.py", line 484 in test_close_kill_running
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 616 in _callTestMethod
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 659 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 719 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84 in __call__
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/unittest/runner.py", line 176 in run
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/support/init.py", line 2032 in _run_suite
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/support/init.py", line 2128 in run_unittest
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 209 in _test_module
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/refleak.py", line 87 in dash_R
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 232 in _runtest_inner2
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 270 in _runtest_inner
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 153 in _runtest
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 193 in runtest
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 318 in rerun_failed_tests
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 691 in _main
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 634 in main
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 712 in main
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/main.py", line 2 in <module>
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 85 in _run_code
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 192 in _run_module_as_main
make: *** [Makefile:1163: buildbottest] Error 1

Also on x86 Gentoo Refleaks 3.x:

https://buildbot.python.org/all/#/builders/1/builds/754

6:11:43 load avg: 1.44 [419/419/2] test_asyncio crashed (Exit code 1)
beginning 6 repetitions
123456
Timeout (3:15:00)!
Thread 0xb7c4d700 (most recent call first):
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/selectors.py", line 468 in select
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 1837 in _run_once
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 589 in run_forever
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/asyncio/base_events.py", line 621 in run_until_complete
File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/test_asyncio/test_subprocess.py", line 484 in test_close_kill_running

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.

It seems like MultiLoopChildWatcher doesn't respect the PEP-475: siginterrupt(False) must not be used. But the following change isn't enough to fix this issue (test_close_kill_running hang).

diff --git a/Lib/asyncio/unix_events.py b/Lib/asyncio/unix_events.py
index d8f653045a..887f837bad 100644
--- a/Lib/asyncio/unix_events.py
+++ b/Lib/asyncio/unix_events.py
@@ -1192,9 +1192,6 @@ class MultiLoopChildWatcher(AbstractChildWatcher):
                                "restore to default handler on watcher close.")
                 self._saved_sighandler = signal.SIG_DFL
 
-            # Set SA_RESTART to limit EINTR occurrences.
-            signal.siginterrupt(signal.SIGCHLD, False)
-
     def _do_waitpid_all(self):
         for pid in list(self._callbacks):
             self._do_waitpid(pid)

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

I was unable to reproduce this locally on OS: Arch Linux 5.3.7 x86_64 and CPU: Intel i5-4460 from the latest commit (heads/master:96b06aefe2) within a reasonable number of tests (~10000). I also tried differing number of jobs, up to 100. What OS were you able to reproduce it locally on using that configuration?

This is of course still an issue since it's still occurring on multiple buildbots intermittently and Victor was able to reproduce it locally, but I was not able to do so on my local setup. This will be significantly harder to debug without a reliable means of reproducing the failure.

I did my tests on Fedora 30 on my laptop which has 4 cores (8 logical CPUs).

The test still hangs randomly. Can it be disabled or fixed?

s390x Debian 3.x:
https://buildbot.python.org/all/#builders/105/builds/167

test_close_dont_kill_finished (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok
Timeout (0:15:00)!
Thread 0x000003ffaa9f8700 (most recent call first):
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/selectors.py", line 468 in select
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/asyncio/base_events.py", line 1852 in _run_once
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/asyncio/base_events.py", line 596 in run_forever
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/asyncio/base_events.py", line 629 in run_until_complete
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/test_asyncio/test_subprocess.py", line 485 in test_close_kill_running
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/case.py", line 616 in _callTestMethod
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/case.py", line 659 in run
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/case.py", line 719 in __call__
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 122 in run
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 84 in __call__
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 122 in run
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 84 in __call__
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 122 in run
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 84 in __call__
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 122 in run
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 84 in __call__
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 122 in run
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/suite.py", line 84 in __call__
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/unittest/runner.py", line 176 in run
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/support/init.py", line 2079 in _run_suite
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/support/init.py", line 2201 in run_unittest
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/runtest.py", line 209 in _test_module
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/runtest.py", line 234 in _runtest_inner2
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/runtest.py", line 270 in _runtest_inner
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/runtest.py", line 153 in _runtest
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/runtest.py", line 193 in runtest
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/main.py", line 318 in rerun_failed_tests
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/main.py", line 691 in _main
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/main.py", line 634 in main
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/libregrtest/main.py", line 712 in main
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/test/main.py", line 2 in <module>
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/runpy.py", line 86 in _run_code
File "/home/dje/cpython-buildarea/3.x.edelsohn-debian-z/build/Lib/runpy.py", line 193 in _run_module_as_main
test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... Makefile:1164: recipe for target 'buildbottest' failed
make: *** [buildbottest] Error 1

I'd like to spend time by reproducing the issue locally.
Please give me a few days.

FYI, I'm able to reproduce the hang by running "python -m test -F test_asyncio -m test_close_kill_running".

Working on the fix.

I'm landing #26542 as a temporary solution meanwhile we decide what to do with PR 26536.

New changeset f171877 by Pablo Galindo in branch 'main':
bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite (GH-26542)
f171877

New changeset b3c50b2 by Miss Islington (bot) in branch '3.9':
bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite (GH-26542)
b3c50b2

New changeset 0d441d2 by Miss Islington (bot) in branch '3.10':
bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite (GH-26542) (GH-26544)
0d441d2

MultiLoopChildWatcher must ensures that the event loop is awaken when it receives a signal by using signal.setwakeup(). This is done by _UnixSelectorEventLoop.add_signal_handler(). Maybe MultiLoopChildWatcher could reuse this function, rather than calling directly signal.signal().

I think this is a good idea. MultiLoopChildWatcher could use setwakeupfd with some no-op callback just to wakeup the loop.

New changeset af5fb67 by Miss Islington (bot) in branch '3.8':
bpo-38323: Skip SubprocessMultiLoopWatcherTest as they can hang the test suite (GH-26542) (GH-26670)
af5fb67

I think this is a good idea. MultiLoopChildWatcher could use setwakeupfd with some no-op callback just to wakeup the loop.

A no-op doesn't solve the issue. It doesn't wake up the event loop. There are only two options to wake up the event loop:

Raise an exception in the Python signal handler
Generate any event which stops the event loop polling. In practice, it means to write into the event loop self pipe.

This issue is similar to call_soon() which doesn't wake up the event loop if called from a different thread: you must call call_soon_threadsafe() which... writes into the self pipe. The self pipe again!

--

MultiLoopChildWatcher cannot use setwakeupfd if it's also used by an event loop to register a signal handler (like CTRL+C). Python currently supports a single signal wakeup FD.

The event loop *must* set the wakeup FD to its own self pipe. Otherwise, the asynchronous Python signal handler register by add_signal_handler() is not called. Extract of the Unix add_signal_handler():

            # Register a dummy signal handler to ask Python to write the signal
            # number in the wakeup file descriptor. _process_self_data() will
            # read signal numbers from this file descriptor to handle signals.
            signal.signal(sig, _sighandler_noop)

Currently, MultiLoopChildWatcher is not related to any event loop, it cannot access such "self pipe".

If MultiLoopChildWatcher is modified to be attached to an event loop... does it contract the whole purpose of MultiLoopChildWatcher?

MultiLoopChildWatcher still has a race condition. I see different options:

Deprecate/Remove MultiLoopChildWatcher
Find a magic fix for MultiLoopChildWatcher. It sounds complicated since it's *designed* to not be related to any event loop. See my failed attempt: PR 26536.
Document the limitation and adapt the unit test to work around the issue.

If an event loop frequently gets events, the worst case is that a child process complete will be notified later, but at least the event is handled. If the event loop is idle, the completion is never notified.

A workaround is to schedule an asynchronous task which runs frequently, like once per minute. It doesn't even have to do anything. It can be a no-op task.

I'm not really excited by documenting the limitation and suggest a hack to work around the limitation. MultiLoopChildWatcher could belong to a PyPI module.

But for the base asyncio from the stdlib, I would prefer to not ship any known race conditions :-( So I'm more in favor of deprecate/remove.

asyncio.MultiLoopChildWatcher has two problems that create a race condition.

The SIGCHLD signal handler does not guard against interruption/re-entry.
The SIGCHLD signal handler can interrupt add_child_handler's self._do_waitpid(pid).

Symptoms:

Log messages that look like this:

1634935451.761 WARNING Unknown child process pid 8747, will report returncode 255
...
1634935451.762 WARNING Child watcher got an unexpected pid: 8747
Traceback (most recent call last):
  File "/Users/runner/hostedtoolcache/Python/3.9.7/x64/lib/python3.9/asyncio/unix_events.py", line 1306, in _do_waitpid
    loop, callback, args = self._callbacks.pop(pid)
KeyError: 8747

Background:

I've been working on a library to make calling asyncio subprocesses more convenient. As part of my testing, I've been stress testing asyncio using different child watcher policies. My CI build runs more than 200 tests each on macOS, Linux and FreeBSD. I've noticed a small percentage of sporadic failures using MultiLoopChildWatcher.

My understanding of Python signal functions is that:

Upon receipt of a signal, the native "C" signal handler sets a flag that indicates the signal arrived.
The main thread checks the signal flags after each bytecode instruction. If a signal flag is set, Python saves the call stack, runs the signal handler on the main thread immediately, then pops the stack when it returns (assuming no exception raised by signal handler).
If you are in the middle of a signal handler running on the main thread and Python detects another signal flag, your signal handler can be interrupted.
Stacked signal handlers run in LIFO order. The last one that enters will run to completion without interruption.

Explanation:

I wrapped MultiLoopChildWatcher's sig_chld function in a decorator that logs when it is entered and exited. This clearly shows that _sig_chld is being re-entered. In the following log snippet, I'm running two commands in a pipeline "tr | cat".

1634935451.743 DEBUG process '/usr/bin/tr' created: pid 8747
...
1634935451.746 DEBUG process '/bin/cat' created: pid 8748
...
1634935451.761 DEBUG enter '_sig_chld' 20
1634935451.761 DEBUG enter '_sig_chld' 20
1634935451.761 WARNING Unknown child process pid 8747, will report returncode 255
1634935451.762 DEBUG process 8748 exited with returncode 0
1634935451.762 DEBUG exit '_sig_chld' 20
1634935451.762 WARNING Child watcher got an unexpected pid: 8747
Traceback (most recent call last):
  File "/Users/runner/hostedtoolcache/Python/3.9.7/x64/lib/python3.9/asyncio/unix_events.py", line 1306, in _do_waitpid
    loop, callback, args = self._callbacks.pop(pid)
KeyError: 8747
1634935451.763 WARNING Unknown child process pid 8748, will report returncode 255
1634935451.763 WARNING Child watcher got an unexpected pid: 8748
Traceback (most recent call last):
  File "/Users/runner/hostedtoolcache/Python/3.9.7/x64/lib/python3.9/asyncio/unix_events.py", line 1306, in _do_waitpid
    loop, callback, args = self._callbacks.pop(pid)
KeyError: 8748
1634935451.763 DEBUG exit '_sig_chld' 20

Here is the breakdown of what happens:

Pid 8747 exits and we enter _sig_chld Support "bpo-" in Misc/NEWS #1.
sig_chld Support "bpo-" in Misc/NEWS #1 calls os.waitpid which gives (pid, status) = (8747, 0).
Before sig_chld Support "bpo-" in Misc/NEWS #1 has a chance to call self._callbacks.pop(pid), it is interrupted.
sig_chld Rename README to README.rst and enhance formatting #2 calls os.waitpid for pid 8747. We get a ChildProcessError and then "Unknown child process pid 8747, will report returncode 255"
sig_chld Rename README to README.rst and enhance formatting #2 invokes the callback for pid 8747 saying the returncode=255.
sig_chld Rename README to README.rst and enhance formatting #2 continues to completion. It reaps pid 8748 normally.
sig_chld Support "bpo-" in Misc/NEWS #1 picks up where it left off. We get an error when we try to pop the callback for 8747.
sig_chld Support "bpo-" in Misc/NEWS #1 calls os.waitpid for pid 8748. This gives us failure messages because it was done by sig_chld Rename README to README.rst and enhance formatting #2.

The issue of interruption can also happen in the case of running a single process. If the _sig_chld interrupts the call to self._do_waitpid(pid) in add_child_watcher, a similar interleaving can occur.

Work-Around:

In my tests, I patched MultiLoopChildWatcher and so far, it appears to be more reliable. In add_child_handler, I call raise_signal(SIGCHLD) so that all the work is done in the signal handler.

class PatchedMultiLoopChildWatcher(asyncio.MultiLoopChildWatcher):
    "Test race condition fixes in MultiLoopChildWatcher."

    def add_child_handler(self, pid, callback, *args):
        loop = asyncio.get_running_loop()
        self._callbacks[pid] = (loop, callback, args)

        # Prevent a race condition in case signal was delivered before
        # callback added.
        signal.raise_signal(signal.SIGCHLD)

    @_serialize
    def _sig_chld(self, signum, frame):
        super()._sig_chld(signum, frame)

_serialize is a decorator that looks like this:

def _serialize(func):
    """Decorator to serialize a non-reentrant signal function.
    If one client is already in the critical section, set a flag to run the
    section one more time. Testing purposes only.
    """

    lock = threading.Lock()  # Used as atomic test-and-set.
    retry = False

    @functools.wraps(func)
    def _decorator(*args, **kwargs):
        nonlocal retry

        while True:
            if lock.acquire(blocking=False):  # pylint: disable=consider-using-with
                try:
                    retry = False
                    func(*args, **kwargs)
                finally:
                    lock.release()
                if retry:
                    continue
            else:
                # A signal handler that interrupts an existing handler will
                # run to completion (LIFO).
                retry = True
            break

    return _decorator

MultiLoopWatcher is deprecated now so closing as "won't fix".

Navigation Menu

Repository navigation

asyncio: MultiLoopWatcher has a race condition (test_asyncio: test_close_kill_running() hangs on AMD64 RHEL7 Refleaks 3.x) #82504

31 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

asyncio: MultiLoopWatcher has a race condition (test_asyncio: test_close_kill_running() hangs on AMD64 RHEL7 Refleaks 3.x) #82504

Description

Activity

vstinner commented on Sep 30, 2019

vstinner commented on Oct 7, 2019

vstinner commented on Oct 22, 2019

vstinner commented on Oct 22, 2019

vstinner commented on Oct 22, 2019

aeros commented on Oct 25, 2019

vstinner commented on Oct 25, 2019

vstinner commented on Jan 13, 2020

asvetlov commented on Jan 13, 2020

asvetlov commented on Jan 13, 2020

31 remaining items

pablogsal commented on Jun 4, 2021

pablogsal commented on Jun 4, 2021

miss-islington commented on Jun 5, 2021

pablogsal commented on Jun 5, 2021

1st1 commented on Jun 9, 2021

pablogsal commented on Jun 12, 2021

vstinner commented on Jun 12, 2021

vstinner commented on Jun 29, 2021

byllyfish commented on Nov 5, 2021

kumaraditya303 commented on Oct 9, 2022

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions