qa: Assertion in p2p_v2_misbehaving.py #34035

issue hebasto openend this issue on December 9, 2025
  1. hebasto commented at 11:50 am on December 9, 2025: member

    From the CI log in OmniOS CI job:

     0
 1169/281 - p2p_v2_misbehaving.py failed, Duration: 40 s
 2
 3stdout:
 42025-12-09T04:30:26.705442Z TestFramework (INFO): PRNG seed is: 8231439354065845951
 52025-12-09T04:30:26.706779Z TestFramework (INFO): Initializing test directory /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251209_041712/p2p_v2_misbehaving_132
 62025-12-09T04:30:27.106102Z TestFramework (INFO): Sending ellswift bytes in parts to ensure that response from responder is received only when
 72025-12-09T04:30:27.106393Z TestFramework (INFO): ellswift bytes have a mismatch from the 16 bytes(network magic followed by "version\x00\x00\x00\x00\x00")
 82025-12-09T04:30:27.107282Z TestFramework (INFO): Sending first 4 bytes of ellswift which match network magic
 92025-12-09T04:30:27.107449Z TestFramework (INFO): If a response is received, assertion failure would happen in our custom data_received() function
102025-12-09T04:30:27.162726Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is
112025-12-09T04:30:27.163083Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure
122025-12-09T04:30:27.218285Z TestFramework (INFO): successful disconnection since modified ellswift was sent as response
132025-12-09T04:31:07.237755Z TestFramework (ERROR): Unexpected exception
14Traceback (most recent call last):
15  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_framework.py", line 142, in main
16    self.run_test()
17    ~~~~~~~~~~~~~^^
18  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_v2_misbehaving.py", line 134, in run_test
19    self.test_v2disconnection()
20    ~~~~~~~~~~~~~~~~~~~~~~~~~^^
21  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_v2_misbehaving.py", line 177, in test_v2disconnection
22    with node0.assert_debug_log(expected_debug_message[test_type.value], timeout=5):
23         ~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
24  File "/usr/lib/python3.13/contextlib.py", line 148, in __exit__
25    next(self.gen)
26    ~~~~^^^^^^^^^^
27  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_node.py", line 576, in assert_debug_log
28    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
29    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
30  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_node.py", line 229, in _raise_assertion_error
31    raise AssertionError(self._node_msg(msg))
32AssertionError: [node 0] Expected messages "['V2 transport error: missing garbage terminator, peer=1']" does not partially match log:
33
34 - 2025-12-09T04:30:27.219068Z (mocktime: 2025-12-09T04:30:31Z) [http] [httpserver.cpp:307] [void http_request_cb(evhttp_request*, void*)] [http] Received a POST request for / from 127.0.0.1:36185
35 - 2025-12-09T04:30:27.219261Z (mocktime: 2025-12-09T04:30:31Z) [httpworker.0] [rpc/request.cpp:243] [void JSONRPCRequest::parse(const UniValue&)] [rpc] ThreadRPCServer method=setmocktime user=__cookie__
36 - 2025-12-09T04:30:27.224046Z (mocktime: 2025-12-09T04:30:27Z) [net] [net.cpp:3858] [CNode::CNode(NodeId, std::shared_ptr<Sock>, const CAddress&, uint64_t, uint64_t, const CService&, const std::string&, ConnectionType, bool, uint64_t, CNodeOptions&&)] [net] Added connection peer=1
37 - 2025-12-09T04:30:27.224092Z (mocktime: 2025-12-09T04:30:27Z) [net] [net.cpp:1860] [void CConnman::CreateNodeFromAcceptedSocket(std::unique_ptr<Sock>&&, NetPermissionFlags, const CService&, const CService&)] [net] connection from 127.0.0.1:44555 accepted
38 - 2025-12-09T04:30:27.225456Z (mocktime: 2025-12-09T04:30:27Z) [net] [net.cpp:3858] [CNode::CNode(NodeId, std::shared_ptr<Sock>, const CAddress&, uint64_t, uint64_t, const CService&, const std::string&, ConnectionType, bool, uint64_t, CNodeOptions&&)] [net] Added connection peer=2
39 - 2025-12-09T04:30:27.225490Z (mocktime: 2025-12-09T04:30:27Z) [net] [net.cpp:1860] [void CConnman::CreateNodeFromAcceptedSocket(std::unique_ptr<Sock>&&, NetPermissionFlags, const CService&, const CService&)] [net] connection from 127.0.0.1:44830 accepted
40 - 2025-12-09T04:30:27.290527Z (mocktime: 2025-12-09T04:30:27Z) [net] [net.cpp:1191] [bool V2Transport::ProcessReceivedGarbageBytes()] [net] V2 transport error: missing garbage terminator, peer=2
41 - 2025-12-09T04:30:27.290568Z (mocktime: 2025-12-09T04:30:27Z) [net] [net.cpp:2183] [void CConnman::SocketHandlerConnected(const std::vector<CNode*>&, const Sock::EventsPerSock&)] [net] receiving message bytes failed, disconnecting peer=2
42 - 2025-12-09T04:30:27.290582Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3426] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] received: version (111 bytes) peer=1
43 - 2025-12-09T04:30:27.290635Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending version (114 bytes) peer=1
44 - 2025-12-09T04:30:27.290746Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:1542] [void {anonymous}::PeerManagerImpl::PushNodeVersion(CNode&, const {anonymous}::Peer&)] [net] send version message: version 70016, blocks=200, txrelay=1, peer=1
45 - 2025-12-09T04:30:27.290770Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending wtxidrelay (0 bytes) peer=1
46 - 2025-12-09T04:30:27.290791Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending sendaddrv2 (0 bytes) peer=1
47 - 2025-12-09T04:30:27.291319Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending verack (0 bytes) peer=1
48 - 2025-12-09T04:30:27.291363Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3623] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=127.0.0.1:12584, txrelay=1, peer=1
49 - 2025-12-09T04:30:27.292113Z (mocktime: 2025-12-09T04:30:27Z) [net] [net.cpp:560] [void CNode::CloseSocketDisconnect()] [net] Resetting socket for peer=2
50 - 2025-12-09T04:30:27.292174Z (mocktime: 2025-12-09T04:30:27Z) [net] [net_processing.cpp:1660] [virtual void {anonymous}::PeerManagerImpl::FinalizeNode(const CNode&)] [net] Cleared nodestate for peer=2
51 - 2025-12-09T04:30:27.296338Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3426] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] received: wtxidrelay (0 bytes) peer=1
52 - 2025-12-09T04:30:27.296374Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3426] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] received: verack (0 bytes) peer=1
53 - 2025-12-09T04:30:27.296395Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3666] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] New inbound v2 peer connected: version: 70016, blocks=-1, peer=1
54 - 2025-12-09T04:30:27.296418Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending sendcmpct (9 bytes) peer=1
55 - 2025-12-09T04:30:27.296450Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending ping (8 bytes) peer=1
56 - 2025-12-09T04:30:27.296524Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending getheaders (645 bytes) peer=1
57 - 2025-12-09T04:30:27.296558Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:5550] [virtual bool {anonymous}::PeerManagerImpl::SendMessages(CNode*)] [net] initial getheaders (199) to peer=1 (startheight:-1)
58 - 2025-12-09T04:30:27.296586Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending feefilter (8 bytes) peer=1
59 - 2025-12-09T04:30:27.296615Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3426] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] received: getaddr (0 bytes) peer=1
60 - 2025-12-09T04:30:27.296674Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [addrman.cpp:849] [std::vector<CAddress> AddrManImpl::GetAddr_(size_t, size_t, std::optional<Network>, bool) const] [addrman] GetAddr returned 0 random addresses
61 - 2025-12-09T04:30:27.301877Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3426] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] received: pong (8 bytes) peer=1
62 - 2025-12-09T04:30:27.329896Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3426] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] received: ping (8 bytes) peer=1
63 - 2025-12-09T04:30:27.329925Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending pong (8 bytes) peer=1
64 - 2025-12-09T04:30:27.329985Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net_processing.cpp:3426] [virtual void {anonymous}::PeerManagerImpl::ProcessMessage(CNode&, const std::string&, DataStream&, std::chrono::microseconds, const std::atomic<bool>&)] [net] received: ping (8 bytes) peer=1
65 - 2025-12-09T04:30:27.330004Z (mocktime: 2025-12-09T04:30:27Z) [msghand] [net.cpp:3902] [void CConnman::PushMessage(CNode*, CSerializedNetMsg&&)] [net] sending pong (8 bytes) peer=1
66 - 2025-12-09T04:30:27.380276Z (mocktime: 2025-12-09T04:30:27Z) [http] [httpserver.cpp:307] [void http_request_cb(evhttp_request*, void*)] [http] Received a POST request for / from 127.0.0.1:36185
67 - 2025-12-09T04:30:27.380464Z (mocktime: 2025-12-09T04:30:27Z) [httpworker.0] [rpc/request.cpp:243] [void JSONRPCRequest::parse(const UniValue&)] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
68 - 2025-12-09T04:30:27.381597Z (mocktime: 2025-12-09T04:30:27Z) [http] [httpserver.cpp:307] [void http_request_cb(evhttp_request*, void*)] [http] Received a POST request for / from 127.0.0.1:36185
69 - 2025-12-09T04:30:27.381776Z (mocktime: 2025-12-09T04:30:27Z) [httpworker.0] [rpc/request.cpp:243] [void JSONRPCRequest::parse(const UniValue&)] [rpc] ThreadRPCServer method=setmocktime user=__cookie__
70
71
722025-12-09T04:31:07.294475Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
732025-12-09T04:31:07.294652Z TestFramework (WARNING): Not cleaning up dir /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251209_041712/p2p_v2_misbehaving_132
742025-12-09T04:31:07.294764Z TestFramework (ERROR): Test failed. Test logging available at /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251209_041712/p2p_v2_misbehaving_132/test_framework.log
752025-12-09T04:31:07.295209Z TestFramework (ERROR): 
762025-12-09T04:31:07.295373Z TestFramework (ERROR): Hint: Call /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/combine_logs.py '/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251209_041712/p2p_v2_misbehaving_132' to consolidate all logs
772025-12-09T04:31:07.295454Z TestFramework (ERROR): 
782025-12-09T04:31:07.295511Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
792025-12-09T04:31:07.295791Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
802025-12-09T04:31:07.295864Z TestFramework (ERROR): 
81
82
83stderr:
84[node 0] Cleaning up leftover process
  2. mzumsande commented at 4:42 pm on December 9, 2025: contributor
    In the failed run the peer that the test framework connects second is seen by the node as the first peer, so that the log message V2 transport error: missing garbage terminator is logged for peer=2 and not peer=1 as the test expects. FYI @stratospher
  3. stratospher commented at 10:01 am on December 12, 2025: contributor

    ok looks like python event loop asynchronous behaviour.

    • it’s scheduling connection to peer1 and then scheduling a connection to peer2
    • but it is actually connecting to peer2 first (which gets assigned peer id = 1 on c++ side) and only later connecting to the peer we’re interested in peer1 (which gets assigned peer id = 2 on c++ side) and we’re seeing a log mismatch

    ideally, we let the event loop do whatever it wants and then use the actual peer id in expected_debug_message - as in we check for V2 transport error: missing garbage terminator, peer={} instead of V2 transport error: missing garbage terminator, peer=1. but it would require more invasive changes in the test framework code since peer id is assigned on the C++ side.

    i think simplest solution is just removing the hard-coded peer id from the debug message - as in just checking V2 transport error: missing garbage terminator instead of V2 transport error: missing garbage terminator, peer=1. since we’re checking that peer2 in the functional test remains connected, disconnection should come from the peer (peer1) which we’re expecting to disconnect.

    will open a fix.

  4. maflcko added the label CI failed on Dec 16, 2025
  5. fanquake closed this on Dec 16, 2025
  6. fanquake referenced this in commit cbafd3ddf8 on Dec 16, 2025


hebasto mzumsande stratospher

Labels
CI failed

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: 2025-12-17 06:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me