Intermittent failure of p2p_private_broadcast.py #34631

issue sedited openend this issue on February 20, 2026
  1. sedited commented at 8:26 am on February 20, 2026: contributor

    Not sure if this is from the original PR or #34329

      0455/455 - p2p_private_broadcast.py failed, Duration: 84 s                              
  1
  2stdout:
  32026-02-20T08:16:52.932185Z TestFramework (INFO): PRNG seed is: 5474091116900090230
  42026-02-20T08:16:52.932503Z TestFramework (INFO): Initializing test directory /tmp/merging_clang_build_Debug/test_runner_₿_🏃_20260220_091548/p2p_private_broadcast_74
  52026-02-20T08:16:58.196783Z TestFramework (INFO): Created txid=2db3a22f9370eb32f110597882acebef1c76cf319837bac69b829917730d2349: for basic test
  62026-02-20T08:16:58.196839Z TestFramework (INFO): Created txid=1586df3125397f95009109f8978a656d966eba39b36bb7552d0cfa703e58d84a: for broadcast with dependency in mempool + rebroadcast
  72026-02-20T08:16:58.196858Z TestFramework (INFO): Created txid=f4580414da8808a9772291d522281ba7d3c5d4ad480cde6580b5363590ec79d2: for broadcast with dependency not in mempool
  82026-02-20T08:17:13.762676Z TestFramework (INFO): Outbound connection i=10: the private broadcast target received and further relayed the transaction
  92026-02-20T08:17:13.762865Z TestFramework (INFO): Basic: ok: outbound connection i=11 is private broadcast of txid=2db3a22f9370eb32f110597882acebef1c76cf319837bac69b829917730d2349
 102026-02-20T08:17:13.762948Z TestFramework (INFO): Basic: ok: outbound connection i=12 is private broadcast of txid=2db3a22f9370eb32f110597882acebef1c76cf319837bac69b829917730d2349
 112026-02-20T08:17:13.764109Z TestFramework (INFO): Resending the same transaction via RPC again (it is not in the mempool yet)
 122026-02-20T08:17:13.765058Z TestFramework (INFO): Sending a malleated transaction with an invalid witness via RPC
 132026-02-20T08:17:13.766052Z TestFramework (INFO): Checking that the transaction is not in the originator node's mempool
 142026-02-20T08:17:13.766348Z TestFramework (INFO): Sending INV and waiting for GETDATA from node
 152026-02-20T08:17:13.817260Z TestFramework (INFO): Waiting for normal broadcast to another peer
 162026-02-20T08:17:16.720760Z TestFramework (INFO): Checking getprivatebroadcastinfo no longer reports the transaction after it is received back
 172026-02-20T08:17:16.721406Z TestFramework (INFO): Checking abortprivatebroadcast removes a pending private-broadcast transaction
 182026-02-20T08:17:16.723782Z TestFramework (INFO): Checking abortprivatebroadcast fails for non-existent transaction
 192026-02-20T08:17:16.724255Z TestFramework (INFO): Sending a transaction that is already in the mempool
 202026-02-20T08:17:16.925456Z TestFramework (INFO): Broadcast of mempool transaction: ok: outbound connection i=13 is private broadcast of txid=2db3a22f9370eb32f110597882acebef1c76cf319837bac69b829917730d2349
 212026-02-20T08:17:16.975699Z TestFramework (INFO): Broadcast of mempool transaction: ok: outbound connection i=14 is private broadcast of txid=2db3a22f9370eb32f110597882acebef1c76cf319837bac69b829917730d2349
 222026-02-20T08:17:17.075987Z TestFramework (INFO): Broadcast of mempool transaction: ok: outbound connection i=15 is private broadcast of txid=2db3a22f9370eb32f110597882acebef1c76cf319837bac69b829917730d2349
 232026-02-20T08:17:17.076719Z TestFramework (INFO): Sending a transaction with a dependency in the mempool
 242026-02-20T08:17:17.228560Z TestFramework (INFO): Dependency in mempool: ok: outbound connection i=16 is private broadcast of txid=1586df3125397f95009109f8978a656d966eba39b36bb7552d0cfa703e58d84a
 252026-02-20T08:17:17.278785Z TestFramework (INFO): Dependency in mempool: ok: outbound connection i=17 is private broadcast of txid=1586df3125397f95009109f8978a656d966eba39b36bb7552d0cfa703e58d84a
 262026-02-20T08:17:17.328990Z TestFramework (INFO): Dependency in mempool: ok: outbound connection i=18 is private broadcast of txid=1586df3125397f95009109f8978a656d966eba39b36bb7552d0cfa703e58d84a
 272026-02-20T08:17:17.329712Z TestFramework (INFO): Sending a transaction with a dependency not in the mempool (should be rejected)
 282026-02-20T08:17:17.331228Z TestFramework (INFO): Checking that rebroadcast works
 292026-02-20T08:18:17.331354Z TestFramework (ERROR): Unexpected exception:
 30Traceback (most recent call last):
 31  File "/home/user/bitcoin/test/functional/test_framework/test_framework.py", line 142, in main
 32    self.run_test()
 33  File "/home/user/bitcoin/clang_build/Debug/test/functional/p2p_private_broadcast.py", line 429, in run_test
 34    with tx_originator.busy_wait_for_debug_log(expected_msgs=[rebroadcast_msg.encode()]):
 35  File "/usr/lib/python3.12/contextlib.py", line 144, in __exit__
 36    next(self.gen)
 37  File "/home/user/bitcoin/test/functional/test_framework/test_node.py", line 616, in busy_wait_for_debug_log
 38    self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} '
 39  File "/home/user/bitcoin/test/functional/test_framework/test_node.py", line 229, in _raise_assertion_error
 40    raise AssertionError(self._node_msg(msg))
 41AssertionError: [node 0] Expected message(s) [b'Reattempting broadcast of stale txid=1586df3125397f95009109f8978a656d966eba39b36bb7552d0cfa703e58d84a'] not found in log:
 42
 43 - 2026-02-20T08:17:17.331379Z [http] [httpserver.cpp:233] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:36796
 44 - 2026-02-20T08:17:17.331431Z [http_pool_1] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__
 45 - 2026-02-20T08:17:17.331568Z (mocktime: 2026-02-20T08:37:17Z) [http] [httpserver.cpp:233] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:36796
 46 - 2026-02-20T08:17:17.331669Z (mocktime: 2026-02-20T08:37:17Z) [http_pool_0] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=mockscheduler user=__cookie__
 47 - 2026-02-20T08:17:17.331823Z (mocktime: 2026-02-20T08:37:17Z) [scheduler] [net.cpp:2438] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers
 48 - 2026-02-20T08:17:17.333250Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=2
 49 - 2026-02-20T08:17:17.333389Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=2
 50 - 2026-02-20T08:17:17.333462Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=2 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 51 - 2026-02-20T08:17:17.333508Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=19
 52 - 2026-02-20T08:17:17.333530Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5012] [ProcessMessage] [privatebroadcast] Got a PONG (the transaction will probably reach the network), marking for disconnect, peer=19
 53 - 2026-02-20T08:17:17.333574Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=7
 54 - 2026-02-20T08:17:17.333613Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 started
 55 - 2026-02-20T08:17:17.333631Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 completed (0μs)
 56 - 2026-02-20T08:17:17.333648Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending inv (37 bytes) peer=7
 57 - 2026-02-20T08:17:17.333662Z (mocktime: 2026-02-20T08:37:17Z) [net] [net.cpp:558] [CloseSocketDisconnect] [net] Resetting socket for peer=19
 58 - 2026-02-20T08:17:17.333687Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=7
 59 - 2026-02-20T08:17:17.333749Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=7 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 60 - 2026-02-20T08:17:17.333802Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=1
 61 - 2026-02-20T08:17:17.333900Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=1
 62 - 2026-02-20T08:17:17.333936Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->cs_vSend, net.cpp:2072 started
 63 - 2026-02-20T08:17:17.333953Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->cs_vSend, net.cpp:2072 completed (0μs)
 64 - 2026-02-20T08:17:17.333964Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=1 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 65 - 2026-02-20T08:17:17.334016Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=6
 66 - 2026-02-20T08:17:17.334055Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 started
 67 - 2026-02-20T08:17:17.334067Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 completed (0μs)
 68 - 2026-02-20T08:17:17.334078Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=6
 69 - 2026-02-20T08:17:17.334150Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=6 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 70 - 2026-02-20T08:17:17.334192Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=9
 71 - 2026-02-20T08:17:17.334265Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=9
 72 - 2026-02-20T08:17:17.334340Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=9 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 73 - 2026-02-20T08:17:17.334378Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=3
 74 - 2026-02-20T08:17:17.334470Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=3
 75 - 2026-02-20T08:17:17.334526Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 started
 76 - 2026-02-20T08:17:17.334542Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=3 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 77 - 2026-02-20T08:17:17.334551Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 completed (0μs)
 78 - 2026-02-20T08:17:17.334568Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=0
 79 - 2026-02-20T08:17:17.334609Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->cs_vSend, net.cpp:2072 started
 80 - 2026-02-20T08:17:17.334622Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->cs_vSend, net.cpp:2072 completed (4μs)
 81 - 2026-02-20T08:17:17.334656Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=0
 82 - 2026-02-20T08:17:17.334719Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=0 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 83 - 2026-02-20T08:17:17.334749Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=5
 84 - 2026-02-20T08:17:17.334830Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=5
 85 - 2026-02-20T08:17:17.334893Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=5 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 86 - 2026-02-20T08:17:17.334941Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=8
 87 - 2026-02-20T08:17:17.334972Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 started
 88 - 2026-02-20T08:17:17.334983Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->m_sock_mutex, net.cpp:2138 completed (0μs)
 89 - 2026-02-20T08:17:17.335000Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=8
 90 - 2026-02-20T08:17:17.335068Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=8 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 91 - 2026-02-20T08:17:17.335110Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=4
 92 - 2026-02-20T08:17:17.335163Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->cs_vSend, net.cpp:2072 started
 93 - 2026-02-20T08:17:17.335177Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention pnode->cs_vSend, net.cpp:2072 completed (0μs)
 94 - 2026-02-20T08:17:17.335190Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=4
 95 - 2026-02-20T08:17:17.335247Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5339] [ConsiderEviction] [net] sending getheaders to outbound peer=4 to verify chain work (current best known block:<none>, benchmark blockhash: 76b181cf5782e03af6adb8f990404168f05f9abd940e7a4e92a33e6044d1f6a5)
 96 - 2026-02-20T08:17:17.335294Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1680 started
 97 - 2026-02-20T08:17:17.335304Z (mocktime: 2026-02-20T08:37:17Z) [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1680 completed (0μs)
 98 - 2026-02-20T08:17:17.335311Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=0
 99 - 2026-02-20T08:17:17.335335Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:5614 started
100 - 2026-02-20T08:17:17.335343Z (mocktime: 2026-02-20T08:37:17Z) [net] [net_processing.cpp:1750] [FinalizeNode] [net] Cleared nodestate for peer=19
101 - 2026-02-20T08:17:17.335351Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:5614 completed (0μs)
102 - 2026-02-20T08:17:17.335403Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=3
103 - 2026-02-20T08:17:17.335455Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=7
104 - 2026-02-20T08:17:17.335481Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=5
105 - 2026-02-20T08:17:17.335506Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=4
106 - 2026-02-20T08:17:17.335532Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=2
107 - 2026-02-20T08:17:17.335557Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=1
108 - 2026-02-20T08:17:17.335583Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=8
109 - 2026-02-20T08:17:17.335606Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=6
110 - 2026-02-20T08:17:17.335632Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=9
111 - 2026-02-20T08:17:17.335727Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: getdata (37 bytes) peer=7
112 - 2026-02-20T08:17:17.335735Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:4225] [ProcessMessage] [net] received getdata (1 invsz) peer=7
113 - 2026-02-20T08:17:17.335744Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:4228] [ProcessMessage] [net] received getdata for: wtx 300386bebae3d16bdf431a264212a900e15716f784d3888fd800b583d235a389 peer=7
114 - 2026-02-20T08:17:17.335777Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending tx (133 bytes) peer=7
115 - 2026-02-20T08:17:17.342789Z (mocktime: 2026-02-20T08:37:17Z) [scheduler] [txmempool.cpp:435] [check] [mempool] Checking mempool with 1 transactions and 1 inputs
116 - 2026-02-20T08:17:17.342847Z (mocktime: 2026-02-20T08:37:17Z) [scheduler] [net_processing.cpp:1663] [ReattemptPrivateBroadcast] [privatebroadcast] Giving up broadcast attempts for txid=2db3a22f9370eb32f110597882acebef1c76cf319837bac69b829917730d2349 wtxid=300386bebae3d16bdf431a264212a900e15716f784d3888fd800b583d235a389: txn-already-in-mempool
117 - 2026-02-20T08:17:17.343326Z (mocktime: 2026-02-20T08:37:17Z) [scheduler] [net.cpp:2401] [DumpAddresses] [net] Flushed 100 addresses to peers.dat  0ms
118 - 2026-02-20T08:17:17.603367Z (mocktime: 2026-02-20T08:37:17Z) [opencon] [addrman.cpp:786] [Select_] [addrman] Selected [80::1]:8333 from new
119 - 2026-02-20T08:17:17.603457Z (mocktime: 2026-02-20T08:37:17Z) [opencon] [net.cpp:396] [ConnectNode] [net] trying v1 connection [80::1]:8333 lastseen=0.3hrs
120 - 2026-02-20T08:17:17.603487Z (mocktime: 2026-02-20T08:37:17Z) [opencon] [net.cpp:486] [ConnectNode] [proxy] Using proxy: 127.0.0.1:11890 to connect to [80::1]:8333
121 - 2026-02-20T08:17:17.603607Z (mocktime: 2026-02-20T08:37:17Z) [opencon] [netbase.cpp:396] [Socks5] [net] SOCKS5 connecting 80::1
122 - 2026-02-20T08:17:17.603898Z (mocktime: 2026-02-20T08:37:17Z) [opencon] [netbase.cpp:435] [Socks5] [proxy] SOCKS5 sending proxy authentication b498d4efaac06cd7-20:b498d4efaac06cd7-20
123 - 2026-02-20T08:17:17.603975Z (mocktime: 2026-02-20T08:37:17Z) [opencon] [netbase.cpp:514] [Socks5] [net] SOCKS5 connected 80::1
124 - 2026-02-20T08:17:17.604089Z (mocktime: 2026-02-20T08:37:17Z) [opencon] [net.cpp:4006] [CNode] [net] Added connection peer=20
125 - 2026-02-20T08:17:17.636870Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending version (114 bytes) peer=20
126 - 2026-02-20T08:17:17.636987Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:1595] [PushNodeVersion] [net] send version message: version=70016, blocks=200, txrelay=0, peer=20
127 - 2026-02-20T08:17:17.655393Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: version (111 bytes) peer=20
128 - 2026-02-20T08:17:17.655440Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3702] [ProcessMessage] [net] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=0.0.0.0:0, txrelay=1, peer=20
129 - 2026-02-20T08:17:17.655453Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=20
130 - 2026-02-20T08:17:17.655510Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=20
131 - 2026-02-20T08:17:17.655559Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending verack (0 bytes) peer=20
132 - 2026-02-20T08:17:17.655679Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [addrman.cpp:676] [Good_] [addrman] Moved [80::1]:8333 to tried[35][47]
133 - 2026-02-20T08:17:17.655695Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [node/timeoffsets.cpp:31] [Add] [net] Added time offset -1200s, total samples 11
134 - 2026-02-20T08:17:17.655879Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=20
135 - 2026-02-20T08:17:17.656325Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: verack (0 bytes) peer=20
136 - 2026-02-20T08:17:17.656342Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3842] [ProcessMessage] New block-relay-only peer connected: transport: v1, version: 70016, blocks=-1 peer=20
137 - 2026-02-20T08:17:17.656359Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending sendcmpct (9 bytes) peer=20
138 - 2026-02-20T08:17:17.656428Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending ping (8 bytes) peer=20
139 - 2026-02-20T08:17:17.656487Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net.cpp:4074] [PushMessage] [net] sending getheaders (645 bytes) peer=20
140 - 2026-02-20T08:17:17.656544Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:5811] [SendMessages] [net] initial getheaders (199) to peer=20 (startheight:-1)
141 - 2026-02-20T08:17:17.697564Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [net_processing.cpp:3582] [ProcessMessage] [net] received: pong (8 bytes) peer=20
142 - 2026-02-20T08:17:17.898187Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [logging/timer.h:58] [Log] [lock] Enter: lock contention connman.m_nodes_mutex, net.h:1812 started
143 - 2026-02-20T08:17:17.898212Z (mocktime: 2026-02-20T08:37:17Z) [msghand] [logging/timer.h:58] [Log] [lock] Enter: lock contention connman.m_nodes_mutex, net.h:1812 completed (1μs)
144 - 2026-02-20T08:17:21.077693Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session 76611381d8 with 127.0.0.1:1
145 - 2026-02-20T08:17:21.077810Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
146 - 2026-02-20T08:17:21.077857Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1
147 - 2026-02-20T08:17:29.077977Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session ad468d1474 with 127.0.0.1:1
148 - 2026-02-20T08:17:29.078063Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
149 - 2026-02-20T08:17:29.078100Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1
150 - 2026-02-20T08:17:38.078194Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session 857489dee6 with 127.0.0.1:1
151 - 2026-02-20T08:17:38.078258Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
152 - 2026-02-20T08:17:38.078285Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1
153 - 2026-02-20T08:17:48.078396Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session 583b195c09 with 127.0.0.1:1
154 - 2026-02-20T08:17:48.078489Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
155 - 2026-02-20T08:17:48.078525Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1
156 - 2026-02-20T08:17:59.078597Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session d5af5b3c3c with 127.0.0.1:1
157 - 2026-02-20T08:17:59.078672Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
158 - 2026-02-20T08:17:59.078701Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1
159 - 2026-02-20T08:18:02.331914Z (mocktime: 2026-02-20T08:37:17Z) [scheduler] [net_processing.cpp:5393] [operator()] [net] keeping block-relay-only peer=20 chosen for eviction (connect time: 1771576637, blocks_in_flight: 0)
160 - 2026-02-20T08:18:11.078881Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session 3d08732ffb with 127.0.0.1:1
161 - 2026-02-20T08:18:11.079007Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
162 - 2026-02-20T08:18:11.079052Z (mocktime: 2026-02-20T08:37:17Z) [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1
163
164
1652026-02-20T08:18:17.391487Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
  2. fanquake commented at 8:39 am on February 20, 2026: member
    cc @vasild @andrewtoth
  3. fanquake added this to the milestone 31.0 on Feb 20, 2026
  4. maflcko commented at 9:13 am on February 20, 2026: member
    I guess that one is different from #34387
  5. maflcko added the label Tests on Feb 20, 2026
  6. maflcko added the label CI failed on Feb 20, 2026
  7. maflcko commented at 10:13 am on February 20, 2026: member
    I was thinking this is just a assert_debug_log timeout issue, but the traceback shows tx_originator.busy_wait_for_debug_log(expected_msgs=[rebroadcast_msg.encode()]), so this must be somethign else.
  8. maflcko commented at 2:31 pm on February 20, 2026: member

    There is also a third failure: https://github.com/bitcoin/bitcoin/actions/runs/22211364381/job/64246250770?pr=34628#step:9:8320:

    0p2p_private_broadcast.py", line 432, in run_test
1                                       self.check_broadcasts("Rebroadcast", txs[1], 1, skip_destinations)
2                                     File "/home/admin/actions-runner/_work/bitcoin/bitcoin/ci_build/test/functional/p2p_private_broadcast.py", line 284, in check_broadcasts
3                                       assert_equal(peer.message_count, {
4                                     File "/home/admin/actions-runner/_work/bitcoin/bitcoin/test/functional/test_framework/util.py", line 78, in assert_equal
5                                       raise AssertionError("not(%s == %s)\n  in particular not(%s == %s)" % (thing1, thing2, d1, d2))
6                                   AssertionError: not(defaultdict(<class 'int'>, {'version': 1, 'verack': 1, 'inv': 1}) == {'version': 1, 'verack': 1, 'inv': 1, 'tx': 1, 'ping': 1})
7                                     in particular not({} == {'ping': 1, 'tx': 1})
  9. vasild commented at 6:14 pm on February 21, 2026: contributor

    There is also a third failure … not({} == {‘ping’: 1, ’tx’: 1})

    This one is fixed in #34646.

    I am not sure about the issue from the OP. There is some blocks-only connection involved which means it might be fixed by #34410. Do you have the full log?


sedited fanquake maflcko vasild

Labels
Tests CI failed

Milestone
31.0

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-02-22 18:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me