Occasional ipc_test failures (macOS?)

[Sjors]

I'm seeing this test fail occasionally, both locally (on macOS) and on CI:
https://github.com/bitcoin/bitcoin/actions/runs/13161509993/job/36731182334?pr=31802#step:7:2568

Not sure if it's a macOS specific thing, that's just based on the above CI run that also happens to be macOS. I'll keep an eye on it.

[fanquake]

Copied the output so we aren't relying on GH actions to retain it.

test/ipc_tests.cpp:11: Entering test suite "ipc_tests"
test/ipc_tests.cpp:12: Entering test case "ipc_tests"
libc++abi: terminating due to uncaught exception of type std::__1::system_error: mutex lock failed: Invalid argument
2025-02-05T16:12:45.463402Z [unknown] [test/util/random.cpp:48] [SeedRandomStateForTest] Setting random seed for current tests to RANDOM_CTX_SEED=40e3ae01ebf0dcb2dc43849f963c573142c9f0ec38096c9feb4f14563c55cb78
2025-02-05T16:12:45.472556Z [test] [init/common.cpp:153] [LogPackageVersion] Bitcoin Core version v28.99.0-cd63f7b213c7-dirty (release build)
2025-02-05T16:12:45.472716Z [test] [kernel/context.cpp:20] [operator()] Using the 'arm_shani(1way,2way)' SHA256 implementation
2025-02-05T16:12:45.483530Z [test] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client first request from current thread, constructing waiter
2025-02-05T16:12:45.483734Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.add$Params (a = 1, b = 2)
2025-02-05T16:12:45.483815Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #1 FooInterface.add$Params (a = 1, b = 2)
2025-02-05T16:12:45.483854Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #1 FooInterface.add$Results (result = 3)
2025-02-05T16:12:45.483883Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.add$Results (result = 3)
2025-02-05T16:12:45.484420Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.passOutPoint$Params (arg = "d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000")
2025-02-05T16:12:45.484443Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #2 FooInterface.passOutPoint$Params (arg = "d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000")
2025-02-05T16:12:45.484458Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #2 FooInterface.passOutPoint$Results (result = "d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000")
2025-02-05T16:12:45.484477Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.passOutPoint$Results (result = "d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000")
2025-02-05T16:12:45.484688Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.passUniValue$Params (arg = "{\\"i\\":1,\\"s\\":\\"two\\"}")
2025-02-05T16:12:45.484710Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #3 FooInterface.passUniValue$Params (arg = "{\\"i\\":1,\\"s\\":\\"two\\"}")
2025-02-05T16:12:45.484724Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #3 FooInterface.passUniValue$Results (result = "{\\"i\\":1,\\"s\\":\\"two\\"}")
2025-02-05T16:12:45.484741Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.passUniValue$Results (result = "{\\"i\\":1,\\"s\\":\\"two\\"}")
2025-02-05T16:12:45.484770Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.passTransaction$Params (arg = "\\002\\000\\000\\000\\001d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000\\000\\377\\377\\377\\377\\001\\000\\341\\365\\005\\000\\000\\000\\000\\000\\003\\000\\000\\000")
2025-02-05T16:12:45.484790Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #4 FooInterface.passTransaction$Params (arg = "\\002\\000\\000\\000\\001d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000\\000\\377\\377\\377\\377\\001\\000\\341\\365\\005\\000\\000\\000\\000\\000\\003\\000\\000\\000")
2025-02-05T16:12:45.484966Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #4 FooInterface.passTransaction$Results (result = "\\002\\000\\000\\000\\001d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000\\000\\377\\377\\377\\377\\001\\000\\341\\365\\005\\000\\000\\000\\000\\000\\003\\000\\000\\000")
2025-02-05T16:12:45.485063Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.passTransaction$Results (result = "\\002\\000\\000\\000\\001d\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\310\\000\\000\\000\\000\\377\\377\\377\\377\\001\\000\\341\\365\\005\\000\\000\\000\\000\\000\\003\\000\\000\\000")
2025-02-05T16:12:45.485124Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.passVectorChar$Params (arg = "Hello")
2025-02-05T16:12:45.485171Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #5 FooInterface.passVectorChar$Params (arg = "Hello")
2025-02-05T16:12:45.485198Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #5 FooInterface.passVectorChar$Results (result = "Hello")
2025-02-05T16:12:45.485239Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.passVectorChar$Results (result = "Hello")
2025-02-05T16:12:45.485430Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.passBlockState$Params (arg = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
2025-02-05T16:12:45.485488Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #6 FooInterface.passBlockState$Params (arg = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
2025-02-05T16:12:45.485525Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #6 FooInterface.passBlockState$Results (result = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
2025-02-05T16:12:45.485571Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.passBlockState$Results (result = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
2025-02-05T16:12:45.485619Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.passBlockState$Params (arg = (mode = 0, result = 0, rejectReason = "", debugMessage = ""))
2025-02-05T16:12:45.485663Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #7 FooInterface.passBlockState$Params (arg = (mode = 0, result = 0, rejectReason = "", debugMessage = ""))
2025-02-05T16:12:45.485693Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #7 FooInterface.passBlockState$Results (result = (mode = 0, result = 0, rejectReason = "", debugMessage = ""))
2025-02-05T16:12:45.485737Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.passBlockState$Results (result = (mode = 0, result = 0, rejectReason = "", debugMessage = ""))
2025-02-05T16:12:45.485793Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client send FooInterface.passScript$Params (arg = "[")
2025-02-05T16:12:45.485833Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server recv request  #8 FooInterface.passScript$Params (arg = "[")
2025-02-05T16:12:45.485858Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server send response #8 FooInterface.passScript$Results (result = "[")
2025-02-05T16:12:45.485898Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/b-test-54829} IPC client recv FooInterface.passScript$Results (result = "[")
2025-02-05T16:12:45.486162Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} IPC server destroy N2mp11ProxyServerIN3gen12FooInterfaceEEE
2025-02-05T16:12:45.486271Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} EventLoop::loop done, cancelling event listeners.
2025-02-05T16:12:45.486283Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-22316/54830} EventLoop::loop bye.

132/140 Test #135: wallet_crypto_tests ..................   Passed    3.05 sec
133/140 Test #134: spend_tests ..........................   Passed    3.68 sec
134/140 Test   #8: secp256k1_exhaustive_tests ...........   Passed   27.97 sec
135/140 Test #139: walletload_tests .....................   Passed    4.45 sec
136/140 Test  #10: bench_sanity_check_high_priority .....   Passed   28.82 sec
137/140 Test #136: wallet_tests .........................   Passed    9.35 sec
138/140 Test #127: coinselector_tests ...................   Passed   20.56 sec
139/140 Test   #6: secp256k1_noverify_tests .............   Passed   42.48 sec
Errors while running CTest
140/140 Test   #7: secp256k1_tests ......................   Passed   59.80 sec

99% tests passed, 1 tests failed out of 140

Total Test time (real) =  59.82 sec

The following tests FAILED:
	140 - ipc_tests (Subprocess aborted)

[ryanofsky]

This is probably caused by the same bug reported in #128 based on the "mutex lock failed: Invalid argument" error. But the version reported here might be easier to debug because the crash is happening in a unit test instead of in a python test.

If you can reproduce this problem locally sometimes, maybe you could run it in a loop until it crashes and try to get a stack trace? This script might work:

#!/bin/bash
while true; do
    lldb --batch -o "run" -o "bt" -- build/src/test/test_bitcoin -t ipc_tests
    status=$?
    if [[ $status -ne 0 ]]; then
        echo "Program crashed with exit code $status. Stopping."
        break
    fi
done

(script from chatgpt of course...)

[ryanofsky]

I couldn't reproduce this but I think I can see how this problem might be happening.

The "mutex lock failed" exception is thrown from libc++ mutex::lock method when there's any failure to lock the mutex.

In this case I think the exception might being thrown in the the ~CapnpProtocol destructor when it is calling EventLoop::removeClient to decrement the last reference count on the event loop. Decrementing the count will cause the event loop to exit, and for the event loop thread to destroy it here.

The problem is that while the event loop thread is destroying the event loop object, the ~CapnpProtocol destructor thread could be trying to lock the EventLoop::m_mutex member here after it calls write(post_fd).

I think a simple fix for this would look like:

--- a/src/ipc/libmultiprocess/src/mp/proxy.cpp
+++ b/src/ipc/libmultiprocess/src/mp/proxy.cpp
@@ -240,10 +240,12 @@ void EventLoop::removeClient(std::unique_lock<std::mutex>& lock)
     if (done(lock)) {
         m_cv.notify_all();
         int post_fd{m_post_fd};
-        Unlock(lock, [&] {
-            char buffer = 0;
-            KJ_SYSCALL(write(post_fd, &buffer, 1)); // NOLINT(bugprone-suspicious-semicolon)
-        });
+        // Intentionally do not unlock/relock the mutex around this final write
+        // call, so clients are free to destroy the EventLoop object immediately
+        // after the loop() method exits, and code here will not be trying to
+        // relock the event loop mutex after it was destroyed.
+        char buffer = 0;
+        KJ_SYSCALL(write(post_fd, &buffer, 1)); // NOLINT(bugprone-suspicious-semicolon)
     }
 }
 

[ryanofsky]

The change in bitcoin/bitcoin#31815 should be a better fix for this issue than the change suggested #154 (comment), which is a less direct fix and could also theoretically cause deadlocks if the write(post_fd) call blocks.

Assuming the issue is the CapnpProtocol::startLoop calling m_loop.reset() too early, adding a mutex around that call is a more direct fix than holding onto the lock in EventLoop::removeClient so EventLoop::loop call can't exit and m_loop.reset() is indirectly delayed.