asyncio: MultiLoopWatcher has a race condition (test_asyncio: test_close_kill_running() hangs on AMD64 RHEL7 Refleaks 3.x) #82504
Comments
|
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(...) 404 tests OK. 10 slowest tests:
1 test failed: 14 tests skipped: Re-running failed tests in verbose mode Re-running test_asyncio in verbose mode test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok test_close_kill_running (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests) ... ok |
vstinner
added
3.9
|
Fail on x86 Gentoo Refleaks 3.x: (...) == Tests result: FAILURE == 410 tests OK. 10 slowest tests:
1 test failed: 8 tests skipped: |
|
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) |
vstinner
changed the title
|
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: ... I added some debug traces. Logs when it works: ---------------------------------------------------------------------- Ran 1 test in 0.054s OK Logs when it hangs: It seems like sometimes, MultiLoopChildWatcher._sig_chld() is not called. |
vstinner
changed the title
|
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 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: test_close_dont_kill_finished (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... ok |
|
I'd like to spend time by reproducing the issue locally. |
|
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. |
Any update on this issue? It's still failing randomly on buildbots. Example: Another option is to skip the test_close_kill_running() until it's fixed which usually means forget about it until an user gets the bug for real in production. |
|
I marked bpo-38182 as a duplicate of this issue: "test_asyncio: SubprocessMultiLoopWatcherTests.test_stdin_stdout() failed on AMD64 FreeBSD 10-STABLE Non-Debug 3.x". |
|
This issue is still failing frequently on buildbots. What can be done to stop getting test failures on buildbots? |
|
Victor, sorry. If I reduce an amount of code executed in a signal handler by spawning a auxiliary thread, setting threading. Event in sighandler, and doing all dirty work in this secondary thread -- the problem goes away. I've mastered a quick hack to skip the problematic test on a hang, it may unblock other developers. |
|
Issue open since 2019-09-30 and tests still hang randomly. What's the progress on this issue? |
|
I have also explored a few different solutions and was unable to find a fix for this issue. If it's still causing intermittent hangs after Andrew's patch, we may want to consider skipping |
There are more MultiLoopWatcher tests which hang randomly, it's not only test_close_kill_running(). I'm fine with skipping tests until someone can come up with a fix. |
What other MultiLoopWatcher tests are currently having random hangs? From searching "MultiLoopWatcher" on bpo, I'm only finding this issue. For now, I'll just work on a PR to temporarily skip |
Oh, never mind. I see |
|
I looked into this a little after reproducing it locally. What I found is that MultiLoopChildWatcher._sig_chld() *is* called. It's just that it's only called immediately after timeout=5 has elapsed. (The timeout=5 was added by Andrew here: )Consider this line in asyncio.tasks.wait_for(), which is to trigger the timeout: Line 476 in 7f7e706 timeout_handle = loop.call_later(timeout, _release_waiter, waiter)I put some debug statements inside _release_waiter, and I found that _sig_chld() is called after the timeout has elapsed and before _release_waiter starts. So basically, it looks like CPython is holding onto the signal, and waiting for the loop to do something more before running the handler and calling the _sig_chld(). The code base already has logic to skip running signal handlers in various cases, but I don't know whether it relates to this issue: Lines 1410 to 1425 in 7f7e706 It seems like there are a number of issues on the tracker related to signals (some solved and others not, e.g. https://bugs.python.org/issue21895 ). So it looks to me like this could point to a deeper issue between asyncio and CPython's signal handling. |
|
I'm attaching a stand-alone script that can reproduce the issue. It doesn't use unittest or even MultiLoopChildWatcher. It starts an event loop and then repeatedly calls loop.subprocess_exec() with 0.2 seconds in between until the "hang" happens (which shows up as a timeout). I recommend running the script for about 15 seconds, and if it doesn't happen, re-run it again. You might need to run it a half-dozen or dozen times to see the hang, but it can also happen right away. I'm sure the script can be cleaned up and simplified a lot more. This is just a start. I wanted to see how much of the cruft I could strip out quickly. This is what the output looks like after one of the hangs: /.../cpython/Lib/subprocess.py:1048: ResourceWarning: subprocess 3282 is still running You can ignore the ResourceWarnings. You can also see at the end that the _sig_child() handler was called even in the timeout case (right before the loop.call_later(TIMEOUT, ...) callback began). |
|
I'm attaching a slightly simpler version of the script. |
|
I'm adding Nathaniel in case he can recognize this as one of the signal handler cases he's already come across. |
|
I don't have any particular insight into the bug, but I do have an On Sat, May 9, 2020, 05:39 Chris Jerdonek <[email protected]> wrote:
|
I had proposed deprecating it in another bpo issue, but it was brought up that MutliLoopWatcher had only been added recently in 3.8. So, it might be a bit too soon to deprecate it already. Although I suppose that if there are several complex and difficult to resolve issues with the implementation, it may very well be less damaging to deprecate it now rather than after it's gained a decent a decent amount of usage. |
|
I was able to simplify the script a lot more and continue to reproduce the hang. It's attached as test-kill3.py (80 lines). It doesn't use subprocess_exec() or a watcher anymore -- just subprocess.Popen() followed by popen.kill(), and then awaiting on a future. The right amount of time has to elapse between the popen.kill() and the await, so I introduced a random bit of variability in between. The right range / amount of time to put in between probably depends on the machine. (What you want is a narrow range right on the borderline, where sometimes the signal fires right before the await, and sometimes right after.) I also added a printf() statement at the beginning of signalmodule.c's trip_signal(), so I can see in the console whether the signal is firing before or after the await. In the timeout / hang case, the signal will be firing after. The hang is very infrequent with the script, though (less frequent than the original unittest). It can take multiple 1-minute runs. It seems similar issues have happened a number of times in the past around the signal-handling code. See e.g. https://bugs.python.org/issue30038 and changes to the neighboring code since then. |
|
I think I have a possible explanation for this now. In my reproducer script and in the original test, the wakeup file descriptor isn't set. I think this explains why the loop isn't waking up to call SIGCHLD's handler when the signal comes in. The reason the wakeup file descriptor isn't set in the original test is that MultiLoopChildWatcher registers the SIGCHLD handler using signal.signal(): cpython/Lib/asyncio/unix_events.py Lines 1261 to 1267 in 74ea6b5 rather than using loop.add_signal_handler(), which calls signal.set_wakeup_fd(): cpython/Lib/asyncio/unix_events.py Line 95 in 74ea6b5 Is there a reason MultiLoopChildWatcher.attach_loop() isn't calling loop.add_signal_handler()? Since attach_loop() has to be called from the main thread anyways, it seems like it could be okay. I also wonder if the documentation could perhaps be more specific as to the difference between loop.add_signal_handler() and signal.signal(). Currently, it just says callbacks registered with add_signal_handler() are "allowed to interact with the event loop": |
|
I posted a draft PR for this issue: #20142 |
|
FYI your PR 20142 together with my PR #23154 allow me to run the whole test_asyncio test suite on OpenIndiana 5.11: $ ./python -m unittest -v test.test_asyncio
(...)
Ran 2298 tests in 71.668sOK (skipped=52) without your PR at least one of the tests is hanging forever. So, this PR improves Solaris/SunOS/illumos/OpenIndiana side of things as well. |
|
This issue is not solved. I can still reproduce the hang using: ./python -m test test_asyncio -m SubprocessMultiLoopWatcherTests -v -F -j20 --timeout=30.0 Example with test_cancel_make_subprocess_transport_exec: $ ./python -m test test_asyncio -m test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests.test_cancel_make_subprocess_transport_exec -v -F -j20 --timeout=30.0
...
0:00:37 load avg: 10.97 [163] test_asyncio passed -- running: test_asyncio (30.9 sec)
test_cancel_make_subprocess_transport_exec (test.test_asyncio.test_subprocess.SubprocessMultiLoopWatcherTests) ... okRan 1 test in 0.032s OK ---------------------------------------------------------------------- Ran 1 test in 0.036s OK Test complete in less than 1 second, but sometimes it hangs for at least 30 seconds. |
Yes, nothing was changed. After diagnosing this issue and trying some things out in a draft PR, my conclusion is that an asyncio maintainer really needs to weigh in on what to do (especially Andrew who authored the class). The reason is that the hang is closely tied to MultiLoopChildWatcher's documented purpose. The only way I could see to fix MultiLoopChildWatcher would change its documented behavior and make it the same as SafeChildWatcher, which would defeat the purpose of having a separate class: #20142 (comment) |
|
When I reproduce test_cancel_make_subprocess_transport_exec() hang, the problem is that the C signal handler is called with SIGCHLD when the child process completes, but the Python signal handler is not called. Python is "blocked" in a selector (maybe select.select(), it doesn't matter). I guess that the selector is interrupted by a signal (even if asyncio calls signal.setinterrupt(SIGCHLD, False)), but since the signal handler doesn't raise an exception, the syscall is restarted: see the PEP-475. I understood that the asyncio event loop only gets the opportunity to call the Python signal handler if there is a pending asyncio event (call_soon, call_timer, event on a tracked FD, whatever). If the signal arrives when the event loop is idle, the Python signal handler will never be called since the selector is called with timeout=0 (blocking mode). 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(). |
This is the conclusion I came to, too. But changing MultiLoopChildWatcher to use loop.add_signal_handler() would contradict the class's documented purpose and make it the same as SafeChildWatcher. This is why I think a maintainer needs to weigh in. The class's purpose / design might fundamentally not be workable. If it can't be made to work, maybe it should be removed or be documented as susceptible to hangs. |
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:
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:
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.
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: 8747Background: 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:
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' 20Here is the breakdown of what happens:
The issue of interruption can also happen in the case of running a single process. If the _sig_chld interrupts the call to 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 |
|
|
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: