IPC stability bugs

Bug 22

Spawned node process aborts at shutdown with a "Broken pipe" error

Status
Fixed
Symptom
Crash; worst effect seen: crash
Where seen
Bitcoin Core functional tests
Trigger
A peer disconnects cleanly
First reported
2024-10-24 (first report)
Fixed
2025-01-27
Fix
mp#129
Shipped to Bitcoin Core
bitcoin#31740
In released binaries
No; the code was in source releases only
Defect ever on master
Yes

Summary

A bitcoin-node child process spawned over IPC could abort at shutdown with terminate called after throwing an instance of 'kj::ExceptionImpl' what(): mp/proxy.cpp:242: disconnected: write(m_post_fd, &buffer, 1): Broken pipe. Other threads wake the event loop by writing a byte to a pipe, and the loop closes that pipe when it exits. EventLoop::removeClient sometimes wrote an extra wake-up byte before the loop was really done, so the loop could exit and close its pipe just before another thread's final wake-up write. That write then failed with EPIPE and threw an exception nothing caught. It made rpc_misc.py fail intermittently in Bitcoin Core CI. Source builds of v22 through v28 with multiprocess enabled have it. Fixed in mp#129.

What happened

Root cause

EventLoop::loop() (src/mp/proxy.cpp) exits when it wakes on its m_wait_fd pipe and sees m_num_clients == 0 && m_async_fns.empty(), closing both pipe ends. EventLoop::removeClient wrote a wake-up byte whenever m_num_clients reached zero, without checking m_async_fns.empty(), so it could write more than once before the loop was really done.

During ~Connection, the destructor thread calls startAsyncThread and then removeClient, which could see zero clients and write one byte. The async cleanup thread then took a client reference for each queued cleanup and released it. If it was preempted between decrementing m_num_clients and its own write(), the loop thread consumed the earlier byte, saw the done condition, closed the pipe, and the async thread's late write() failed with EPIPE. KJ_SYSCALL turned that into an exception nothing caught.

Separately, the loop read m_num_clients, m_async_fns and m_post_fd without holding m_mutex. ryanofsky clarified that only the extra-write race caused the observed failures; the missing lock was a second, theoretical cause fixed in the same commit.

The echoipc test spawns and shuts down a whole bitcoin-node child on each run, the one place under CI load where a process's event loop shut down through this sequence, and bitcoin#30975 ran it on more CI configurations.

The code

Quoted from 0e4f88d3f9c6^, src/mp/proxy.cpp. EventLoop::removeClient wakes the event loop whenever the client count reaches zero, and EventLoop::loop() exits when a wake-up finds no clients and no queued async cleanups:

void EventLoop::removeClient(std::unique_lock<std::mutex>& lock)
{
    assert(m_num_clients > 0);
    m_num_clients -= 1;
    if (m_num_clients == 0) {
        m_cv.notify_all();
        Unlock(lock, [&] {
            char buffer = 0;
            KJ_SYSCALL(write(m_post_fd, &buffer, 1)); // NOLINT(bugprone-suspicious-semicolon)
        });
    }
}
// ...
        m_cv.notify_all();
        if (m_num_clients == 0 && m_async_fns.empty()) {
            // ...
            break;
        }
    }
    wait_stream = nullptr;
    m_wait_fd = -1;
    KJ_SYSCALL(::close(m_post_fd));

~Connection ends with m_loop.startAsyncThread(lock); m_loop.removeClient(lock);, and the async thread wraps each cleanup it runs in addClient(lock) / removeClient(lock). So one disconnect can write two wake-up bytes, and the loop can act on the first while the second write is still pending:

  1. Event loop, in ~Connection: queues the async cleanups and starts the async thread; removeClient drops the count to 0 and writes a byte, although m_async_fns is not empty.
  2. Async thread: runs the cleanup, removeClient drops the count to 0 again and releases the mutex, then is preempted before its write().
  3. Event loop: reads the byte from step 1, sees no clients and no async functions, leaves the loop and closes the pipe.
  4. Async thread: write(m_post_fd, ...) fails with EPIPE, and KJ_SYSCALL throws "Broken pipe".

The loop also read m_num_clients and m_async_fns without holding m_mutex. The fix (0e4f88d3f9c6) adds a done() check that requires the lock, and uses it in both places (the new done() function and the post_fd copies are omitted):

@@ -233,13 +236,13 @@ void EventLoop::addClient(std::unique_lock<std::mutex>& lock) { m_num_clients +=
 void EventLoop::removeClient(std::unique_lock<std::mutex>& lock)
 {
-    assert(m_num_clients > 0);
     m_num_clients -= 1;
-    if (m_num_clients == 0) {
+    if (done(lock)) {
         m_cv.notify_all();
@@ -188,29 +188,31 @@ void EventLoop::loop()
-        m_cv.notify_all();
-        if (m_num_clients == 0 && m_async_fns.empty()) {
-            log() << "EventLoop::loop done, cancelling event listeners.";
-            m_task_set.reset();
-            log() << "EventLoop::loop bye.";
+        if (read_bytes != 1) throw std::logic_error("EventLoop wait_stream closed unexpectedly");
+        std::unique_lock<std::mutex> lock(m_mutex);
+        if (m_post_fn) {
+            Unlock(lock, *m_post_fn);
+            m_post_fn = nullptr;
+            m_cv.notify_all();
+        } else if (done(lock)) {
             break;

~Connection holds m_mutex while it queues the cleanups and calls removeClient, so done() is false there and no byte is written in step 1. Only the removeClient call that actually finishes the work writes, and the loop cannot exit before reading that byte, so the write always lands on an open pipe.

Fix

The fix commit 0e4f88d3f9c6 in mp#129 ("Fix 'disconnected: write(m_post_fd, &buffer, 1): Broken pipe' EventLoop shutdown races"), co-authored by @vasild, adds EventLoop::done(), which requires the lock, makes removeClient write only when done() is true, has loop() re-check done() under the lock and not exit while a posted function (m_post_fn) is pending, and copies m_post_fd into a local before unlocking (+32/-19). No test was added.

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 Locks, waits and wakeups: A done signal sent too early

  • Prevented by a design rule, lock annotations
  • Earliest detector ThreadSanitizer (did not exist then)
  • Diagnosis hard
  • Fix design moderate
  • Debugging aids core dumps, a reproduction script, sanitizer output
  • Rust partly

Would Rust have prevented it? Partly. The unlocked read of m_num_clients and m_async_fns would be rejected because they would live inside the Mutex, but the premature done byte written on a partial condition, and the write to a pipe the receiver already closed, are protocol errors that compile fine. More on Rust

Could it have been prevented?

Yes. The loop's exit condition was m_num_clients == 0 && m_async_fns.empty(), but the wake-up that announced it was written on m_num_clients == 0 alone, so the "done" byte could be sent while work was still queued and a second byte was owed later; the loop took the first, closed the pipe, and the second write hit EPIPE. Two rules would have prevented it. One predicate for "done", evaluated under the lock at every site that signals or tests it: the fix (0e4f88d3f9c6) adds EventLoop::done(lock) and uses it in both removeClient and loop(). And no reads of shared members outside m_mutex: the loop's exit test was unlocked, which -Wthread-safety annotations would have rejected at compile time, though ryanofsky noted the unlocked read was not the cause of the observed failures. Both were knowable in 2019 and are what a review of the wake-up protocol would have asked: does every signal mean the condition holds?

Could it have been found sooner?

Yes, with the library built under ThreadSanitizer and its shutdown run in a loop. ryanofsky reported that -fsanitize=thread, used on the library for the first time during this fix, flagged the unlocked read immediately and the write/close race after about thirty minutes. Neither repository ran the library under TSan in 2019, and Bitcoin Core's TSan job did not build multiprocess until bitcoin#30975 was in progress. Without a tool it needed a workload that shut a whole process down through ~Connection hundreds of times, which only the echoipc child under CI load provided, and then only on i686 and CentOS.

What made it hard to debug?

The failure was intermittent and lived in a spawned child whose logs the test did not keep. The report sat for three months while the wrong PR was suspected; when a recurrence restarted it, the reproduction was a stripped-down rpc_misc.py looped for 20 to 30 minutes per crash, and adding a log file to the child made the race disappear overnight. What worked was a core dump: the backtrace put the failed write on the async cleanup thread inside removeClient, and from that ryanofsky reasoned out the three-thread interleaving by hand before TSan confirmed it. Core dumps from spawned children as a CI artifact, and a TSan build of the library, are the two things that would have shortened this from three months to a day.

Lesson

When threads signal "done" to a loop that tears itself down on receipt, make the signal and the exit test one predicate evaluated under one lock, and never send the signal for a partial condition; each extra wake-up is a chance for the receiver to be gone when the last one arrives.

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 crash
Worst effect observed crash
Seen in functional-test
Scope production
Trigger Clean disconnect (clean-disconnect)
Phase shutdown
Side eventloop
Component eventloop
Root cause kind ordering
Fix kind local-fix
Detection ci-intermittent
Needs a peer that is not libmultiprocess C++ no
Needed a sanitizer to see no
Defect ever on master yes
Released source
Confidence high