intermittent ipc_tests (Timeout) #31921

issue maflcko openend this issue on February 20, 2025

maflcko commented at 10:27 pm on February 20, 2025: member

https://cirrus-ci.com/task/4822889158934528?logs=ci#L4124

 0test/ipc_tests.cpp(11): Entering test suite "ipc_tests"
 1test/ipc_tests.cpp(12): Entering test case "ipc_tests"
 22025-02-20T19:40:40.807963Z [unknown] [test/util/random.cpp:48] [SeedRandomStateForTest] Setting random seed for current tests to RANDOM_CTX_SEED=d9d17e81b3c451b4796c66be71a75826f4089e0ed585b15f9fe9784685ea3f80
 32025-02-20T19:40:40.809986Z [test] [init/common.cpp:151] [LogPackageVersion] Bitcoin Core version v28.99.0-46a9c73083e0-dirty (debug build)
 42025-02-20T19:40:40.810894Z [test] [kernel/context.cpp:20] [operator()] Using the 'standard,sse41(4way),avx2(8way)' SHA256 implementation
 52025-02-20T19:40:40.810937Z [test] [random.cpp:114] [ReportHardwareRand] Using RdSeed as an additional entropy source
 62025-02-20T19:40:40.810975Z [test] [random.cpp:117] [ReportHardwareRand] Using RdRand as an additional entropy source
 72025-02-20T19:40:40.826220Z [test] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client first request from current thread, constructing waiter
 82025-02-20T19:40:40.827720Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client send FooInterface.add$Params (a = 1, b = 2)
 92025-02-20T19:40:40.828045Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server recv request  [#1](/bitcoin-bitcoin/1/) FooInterface.add$Params (a = 1, b = 2)
102025-02-20T19:40:40.828157Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server send response [#1](/bitcoin-bitcoin/1/) FooInterface.add$Results (result = 3)
112025-02-20T19:40:40.828302Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client recv FooInterface.add$Results (result = 3)
122025-02-20T19:40:40.832153Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} 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")
132025-02-20T19:40:40.832304Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server recv request  [#2](/bitcoin-bitcoin/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")
142025-02-20T19:40:40.832425Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server send response [#2](/bitcoin-bitcoin/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")
152025-02-20T19:40:40.832517Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} 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")
162025-02-20T19:40:40.832728Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client send FooInterface.passUniValue$Params (arg = "{\\"i\\":1,\\"s\\":\\"two\\"}")
172025-02-20T19:40:40.832922Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server recv request  [#3](/bitcoin-bitcoin/3/) FooInterface.passUniValue$Params (arg = "{\\"i\\":1,\\"s\\":\\"two\\"}")
182025-02-20T19:40:40.833020Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server send response [#3](/bitcoin-bitcoin/3/) FooInterface.passUniValue$Results (result = "{\\"i\\":1,\\"s\\":\\"two\\"}")
192025-02-20T19:40:40.833140Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client recv FooInterface.passUniValue$Results (result = "{\\"i\\":1,\\"s\\":\\"two\\"}")
202025-02-20T19:40:40.833338Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} 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")
212025-02-20T19:40:40.833528Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server recv request  [#4](/bitcoin-bitcoin/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")
222025-02-20T19:40:40.833680Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server send response [#4](/bitcoin-bitcoin/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")
232025-02-20T19:40:40.833790Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} 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")
242025-02-20T19:40:40.833984Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client send FooInterface.passVectorChar$Params (arg = "Hello")
252025-02-20T19:40:40.834140Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server recv request  [#5](/bitcoin-bitcoin/5/) FooInterface.passVectorChar$Params (arg = "Hello")
262025-02-20T19:40:40.834235Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server send response [#5](/bitcoin-bitcoin/5/) FooInterface.passVectorChar$Results (result = "Hello")
272025-02-20T19:40:40.834336Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client recv FooInterface.passVectorChar$Results (result = "Hello")
282025-02-20T19:40:40.834535Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client send FooInterface.passBlockState$Params (arg = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
292025-02-20T19:40:40.834732Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server recv request  [#6](/bitcoin-bitcoin/6/) FooInterface.passBlockState$Params (arg = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
302025-02-20T19:40:40.834826Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server send response [#6](/bitcoin-bitcoin/6/) FooInterface.passBlockState$Results (result = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
312025-02-20T19:40:40.834941Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client recv FooInterface.passBlockState$Results (result = (mode = 1, result = 8, rejectReason = "reject reason", debugMessage = "debug message"))
322025-02-20T19:40:40.835129Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8395} IPC client send FooInterface.passBlockState$Params (arg = (mode = 0, result = 0, rejectReason = "", debugMessage = ""))
332025-02-20T19:40:40.835274Z [unknown] [test/ipc_test.cpp:60] [operator()] LOG0: {IpcPipeTest-8395/b-test-8396} IPC server recv request  [#7](/bitcoin-bitcoin/7/) FooInterface.passBlockState$Params (arg = (mode = 0, result = 0, rejectReason = "", debugMessage = ""))
3499% tests passed, 1 tests failed out of 140
35Total Test time (real) = 2508.25 sec
36The following tests FAILED:
37	140 - ipc_tests (Timeout)
38Errors while running CTest
39Exit status: 8

maflcko added the label CI failed on Feb 20, 2025
ryanofsky commented at 11:09 pm on February 20, 2025: contributor

Seems possible this is the same bug as https://github.com/chaincodelabs/libmultiprocess/issues/154 but causing a deadlock instead of a “mutex lock failed” error due to platform differences. The fix for the bug is https://github.com/chaincodelabs/libmultiprocess/pull/159 and is included in 1746618e081d582673b458091c46bb3f71ba3a56 from #31741. But maybe I should make that commit a separate PR?
maflcko commented at 7:55 am on February 21, 2025: member

Yeah, it looks like #31741 needs rebase and feature freeze was yesterday, so I am not sure if it is going to make it in as a bugfix into 29.x.

Might be best carve out the bugfix commit for now.
maflcko added this to the milestone 29.0 on Feb 21, 2025

Contributors
maflcko ryanofsky

Labels
CI failed

Milestone
29.0