ci: intermittent issue in rpc_misc.py node0 stderr terminate called after throwing an instance of 'kj::ExceptionImpl' [15:12:14.943] what(): mp/proxy.cpp:242: disconnected: write(m_post_fd, &buffer, 1): Broken pipe [15:12:14.943] stack: 657ed083 657ed86e f7ac7d20 f7713156 f77a7e07

maflcko commented at 3:27 pm on October 24, 2024: member

https://cirrus-ci.com/task/5442110629871616?logs=ci#L3430

 0[15:12:14.943]  node0 2024-10-24T15:12:14.578291Z [shutoff] [src/logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block and undo data to disk started 
 1[15:12:14.943]  node0 2024-10-24T15:12:14.578357Z [shutoff] [src/logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block and undo data to disk completed (0.06ms) 
 2[15:12:14.943]  node0 2024-10-24T15:12:14.578365Z [shutoff] [src/logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block index to disk started 
 3[15:12:14.943]  node0 2024-10-24T15:12:14.578381Z [shutoff] [src/logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block index to disk completed (0.01ms) 
 4[15:12:14.943]  node0 2024-10-24T15:12:14.578390Z [shutoff] [src/logging/timer.h:58] [Log] [bench] FlushStateToDisk: write coins cache to disk (0 coins, 262kB) started 
 5[15:12:14.943]  node0 2024-10-24T15:12:14.578406Z [shutoff] [src/txdb.cpp:146] [BatchWrite] [coindb] Writing final batch of 0.00 MiB 
 6[15:12:14.943]  node0 2024-10-24T15:12:14.578614Z [shutoff] [src/txdb.cpp:148] [BatchWrite] [coindb] Committed 0 changed transaction outputs (out of 0) to coin database... 
 7[15:12:14.943]  node0 2024-10-24T15:12:14.578640Z [shutoff] [src/logging/timer.h:58] [Log] [bench] FlushStateToDisk: write coins cache to disk (0 coins, 262kB) completed (0.24ms) 
 8[15:12:14.943]  node0 2024-10-24T15:12:14.578654Z [shutoff] [src/validationinterface.cpp:245] [ChainStateFlushed] [validation] Enqueuing ChainStateFlushed: block hash=08088a81df63d1c115663bb817c7ce81057d3e9e57dc706c85e4f3878390e828 
 9[15:12:14.943]  node0 2024-10-24T15:12:14.585972Z [shutoff] [src/init.cpp:398] [Shutdown] Shutdown: done 
10[15:12:14.943]  node0 2024-10-24T15:12:14.586061Z [capnp-loop] [src/ipc/capnp/protocol.cpp:35] [IpcLogFn] [ipc] {bitcoin-node-21814/b-capnp-loop-21841} EventLoop::loop done, cancelling event listeners. 
11[15:12:14.943]  node0 2024-10-24T15:12:14.586078Z [capnp-loop] [src/ipc/capnp/protocol.cpp:35] [IpcLogFn] [ipc] {bitcoin-node-21814/b-capnp-loop-21841} EventLoop::loop bye. 
12[15:12:14.943]  test  2024-10-24T15:12:14.621000Z TestFramework (ERROR): Assertion failed 
13[15:12:14.943]                                    Traceback (most recent call last):
14[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_framework.py", line 132, in main
15[15:12:14.943]                                        self.run_test()
16[15:12:14.943]                                      File "/ci_container_base/ci/scratch/build-i686-pc-linux-gnu/test/functional/rpc_misc.py", line 83, in run_test
17[15:12:14.943]                                        self.restart_node(0, ["-txindex", "-blockfilterindex", "-coinstatsindex"])
18[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_framework.py", line 595, in restart_node
19[15:12:14.943]                                        self.stop_node(i)
20[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_framework.py", line 581, in stop_node
21[15:12:14.943]                                        self.nodes[i].stop_node(expected_stderr, wait=wait)
22[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_node.py", line 410, in stop_node
23[15:12:14.943]                                        self.wait_until_stopped(expected_stderr=expected_stderr)
24[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_node.py", line 445, in wait_until_stopped
25[15:12:14.943]                                        self.wait_until(lambda: self.is_node_stopped(**kwargs), timeout=timeout)
26[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_node.py", line 843, in wait_until
27[15:12:14.943]                                        return wait_until_helper_internal(test_function, timeout=timeout, timeout_factor=self.timeout_factor)
28[15:12:14.943]                                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
29[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/util.py", line 292, in wait_until_helper_internal
30[15:12:14.943]                                        if predicate():
31[15:12:14.943]                                           ^^^^^^^^^^^
32[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_node.py", line 445, in <lambda>
33[15:12:14.943]                                        self.wait_until(lambda: self.is_node_stopped(**kwargs), timeout=timeout)
34[15:12:14.943]                                                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
35[15:12:14.943]                                      File "/ci_container_base/test/functional/test_framework/test_node.py", line 430, in is_node_stopped
36[15:12:14.943]                                        raise AssertionError("Unexpected stderr {} != {}".format(stderr, expected_stderr))
37[15:12:14.943]                                    AssertionError: Unexpected stderr terminate called after throwing an instance of 'kj::ExceptionImpl'
38[15:12:14.943]                                      what():  mp/proxy.cpp:242: disconnected: write(m_post_fd, &buffer, 1): Broken pipe
39[15:12:14.943]                                    stack: 657ed083 657ed86e f7ac7d20 f7713156 f77a7e07 !=
40[15:12:14.943]  test  2024-10-24T15:12:14.623000Z TestFramework (DEBUG): Closing down network thread 
41[15:12:14.943]  test  2024-10-24T15:12:14.673000Z TestFramework (INFO): Stopping nodes 
42[15:12:14.943]  test  2024-10-24T15:12:14.673000Z TestFramework.node0 (DEBUG): Stopping node 
43[15:12:14.943] 
44[15:12:14.943]  node0 stderr terminate called after throwing an instance of 'kj::ExceptionImpl'
45[15:12:14.943]   what():  mp/proxy.cpp:242: disconnected: write(m_post_fd, &buffer, 1): Broken pipe
46[15:12:14.943] stack: 657ed083 657ed86e f7ac7d20 f7713156 f77a7e07

maflcko added the label interfaces on Oct 24, 2024

maflcko added the label CI failed on Oct 24, 2024

fanquake commented at 3:29 pm on October 24, 2024: member

cc @ryanofsky

ryanofsky commented at 1:05 pm on October 29, 2024: contributor

Assuming this is a new error, it is possible this is caused by #31105 which was merged a week ago and changed some parts of IPC shutdown sequence.

It seems this failure here is happening because some code is trying to use the IPC event loop after it is closed. Specifically some code is calling the mp::EventLoop::removeClient which fails writing to the event loop’s local pipe at https://github.com/chaincodelabs/libmultiprocess/blob/abe254b9734f2e2b220d1456de195532d6e6ac1e/src/mp/proxy.cpp#L242

ryanofsky commented at 1:35 pm on October 29, 2024: contributor

Looking more closely at changes in #31105, I don’t see anything that directly relates to this code, so it seems possible this is an older bug or a different bug. Looking up the “Broken pipe” error, it also seems like that can only be triggered if something is closing the EventLoop::m_wait_fd file descriptor before the write(m_post_fd, ...) call happens. But I don’t see a code path where that would happen. May need to reproduce locally to debug. Would be curious to know if this happens more.

ci: intermittent issue in rpc_misc.py node0 stderr terminate called after throwing an instance of ‘kj::ExceptionImpl’ [15:12:14.943] what(): mp/proxy.cpp:242: disconnected: write(m_post_fd, &buffer, 1): Broken pipe [15:12:14.943] stack: 657ed083 657ed86e f7ac7d20 f7713156 f77a7e07 #31151