IPC stability bugs

Bug 62

Spawn test fails on slow CI runners that miss a one-second exit deadline

Status
Fixed
Symptom
Timeout; worst effect seen: test failure only
Where seen
Libmultiprocess tests (mptest)
Trigger
Starting a child process (fork and exec)
First reported
2026-04-01 (first report)
Fixed
2026-04-03
Fix
mp#266
Shipped to Bitcoin Core
bitcoin#34977

Summary

The mptest case "SpawnProcess does not run callback in child" failed once in Bitcoin Core CI because it gave the spawned child process only one second to exit, which a loaded CI runner did not meet. The defect was in test code and did not affect users: SpawnProcess itself behaved correctly. Fixed by raising the deadline to 30 seconds in mp#266, shipped to Bitcoin Core in the subtree update bitcoin#34977.

What happened

Root cause

The test, added in mp#237 when SpawnProcess was made safe to call after fork() in a multithreaded process, forks a child through SpawnProcess, closes the socket, and polls waitpid(WNOHANG) for the child to exit. test/mp/test/spawn_tests.cpp gave the child a fixed std::chrono::milliseconds{1000}, after which it killed the child with SIGKILL and failed the status check.

The child only execs true, after the parent's fd_to_args callback has waited about 50 ms for the test's releaser thread. On a busy runner that can take longer than a second to be scheduled and finish. The failing case took 1051610 us, which is the 50 ms delay plus the 1000 ms deadline, consistent with a child that was late rather than hung.

The code

The test "SpawnProcess does not run callback in child" in test/mp/test/spawn_tests.cpp, as of cc0b23fc323c^. The fd_to_args callback blocks in the parent until a releaser thread frees target_mutex about 50 ms later; the child then execs true, and the test waits a fixed second for it to exit:

int pid{-1};
const int fd{mp::SpawnProcess(pid, [&](int child_fd) -> std::vector<std::string> {
    // ...
    std::lock_guard<std::mutex> g(target_mutex);
    return {"true", std::to_string(child_fd)};
})};
::close(fd);

int status{0};
// Give the child up to 1 second to exit. If it does not, terminate it and
// reap it to avoid leaving a zombie behind.
const bool exited{WaitPidWithTimeout(pid, std::chrono::milliseconds{1000}, status)};
if (!exited) {
    ::kill(pid, SIGKILL);
    ::waitpid(pid, &status, /*options=*/0);
}
// ...
KJ_EXPECT(exited, "Timeout waiting for child process to exit");
KJ_EXPECT(WIFEXITED(status) && WEXITSTATUS(status) == 0);

On a loaded runner the forked child can take more than a second to be scheduled, exec true and exit. The test then kills it and both expectations fail, although SpawnProcess behaved correctly: the failing run took 1051610 us, the 50 ms delay plus the 1000 ms deadline.

The fix raises the deadline to 30 seconds (cc0b23fc323c; comment change omitted):

@@ -20,6 +20,8 @@
+constexpr auto FAILURE_TIMEOUT = std::chrono::seconds{30};
+
@@ -94,9 +96,9 @@ KJ_TEST("SpawnProcess does not run callback in child")
-    const bool exited{WaitPidWithTimeout(pid, std::chrono::milliseconds{1000}, status)};
+    const bool exited{WaitPidWithTimeout(pid, FAILURE_TIMEOUT, status)};

A healthy child still exits within milliseconds, so the test passes as soon as it does, and 30 seconds is enough headroom for a slow runner while a real deadlock in the child still fails the test.

Fix

cc0b23fc323c replaces the literal with a FAILURE_TIMEOUT constant of 30 seconds (spawn_tests.cpp only, +4/-2). No library code changed.

Timeline

Lessons

What would have prevented this bug, found it sooner, or made it easier to debug. The patterns page groups these lessons across all bugs.

Pattern Test timing, and tests that cannot fail: A test that assumes timing

  • Prevented by a review checklist item, a design rule
  • Earliest detector code review (existed then)
  • Diagnosis easy
  • Fix design easy
  • Debugging aids CI artifacts
  • Rust no

Would Rust have prevented it? No. A test deadline chosen too short is a test-design choice the language cannot see. More on Rust

Could it have been prevented?

Yes. The test checks that a forked child does not hang, so it needs some deadline, but the one-second literal in 5205a87cd90e was sized as an expectation ("a healthy child exits in milliseconds") rather than as a failure ceiling. The distinction is the rule: a timeout that only a broken run pays should be generous, because a healthy run returns as soon as the event happens and never waits it out, while a broken run costs 30 s instead of 1 s once, which nobody minds. The same file's other waits in mptest already used long ceilings, and bitcoin#34727 had scaled the IPC functional tests' waits for exactly this reason two months earlier, which Sjors cited when fixing this one. A review item "is every literal duration in a test a ceiling, and is it sized for the slowest CI runner?" would have caught the line when the test was written.

Could it have been found sooner?

By review, since the number is in the source; no runtime check finds a too-short deadline until a runner is slow enough to miss it. The libmultiprocess repository's own CI never did in eleven weeks; Bitcoin Core's, which runs mptest on more platforms and busier machines, missed it once on bitcoin#34923 and never again. That is the usual profile of a load-dependent test failure, and the reason to fix it by inspection after one sighting rather than wait for a pattern.

What made it hard to debug?

Nothing. fanquake's report had the log, ryanofsky named the cause within the hour, and the fix (cc0b23fc323c) is a named constant of 30 s. The one detail worth keeping from the log is the failing case's duration, 1051610 us, which is the test's 50 ms releaser delay plus the 1000 ms deadline: the child was late, not stuck, so the production code was not suspected. Without that arithmetic a "timeout waiting for child" in a post-fork safety test would have looked like the deadlock the test exists to catch.

Lesson

Size a test's failure deadline for the slowest machine that will run it, not for the time a healthy run takes, since a healthy run never waits it out; and when such a deadline fires, check the elapsed time against the deadline before treating the timeout as the bug it was meant to detect.

Notes

Classification

The survey's classification of this bug. The explorer charts these fields across all bugs; the method page explains them.

Field Value
Symptom timeout
Worst effect observed test-failure-only
Seen in mptest
Scope test-code
Trigger Starting a child process (fork-exec)
Phase startup
Side n/a
Component test-harness
Root cause kind assumption-violated
Fix kind test-only
Detection ci-intermittent
Needs a peer that is not libmultiprocess C++ no
Needed a sanitizer to see no
Confidence high