qa: Assertion in `p2p_v2_misbehaving.py` #34035

From the CI log in OmniOS CI job:

169/281 - p2p_v2_misbehaving.py failed, Duration: 40 s

stdout:
2025-12-09T04:30:26.705442Z TestFramework (INFO): PRNG seed is: 8231439354065845951
2025-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
2025-12-09T04:30:27.106102Z TestFramework (INFO): Sending ellswift bytes in parts to ensure that response from responder is received only when
2025-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")
2025-12-09T04:30:27.107282Z TestFramework (INFO): Sending first 4 bytes of ellswift which match network magic
2025-12-09T04:30:27.107449Z TestFramework (INFO): If a response is received, assertion failure would happen in our custom data_received() function
2025-12-09T04:30:27.162726Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is
2025-12-09T04:30:27.163083Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure
2025-12-09T04:30:27.218285Z TestFramework (INFO): successful disconnection since modified ellswift was sent as response
2025-12-09T04:31:07.237755Z TestFramework (ERROR): Unexpected exception
Traceback (most recent call last):
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_framework.py", line 142, in main
    self.run_test()
    ~~~~~~~~~~~~~^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_v2_misbehaving.py", line 134, in run_test
    self.test_v2disconnection()
    ~~~~~~~~~~~~~~~~~~~~~~~~~^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_v2_misbehaving.py", line 177, in test_v2disconnection
    with node0.assert_debug_log(expected_debug_message[test_type.value], timeout=5):
         ~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/contextlib.py", line 148, in __exit__
    next(self.gen)
    ~~~~^^^^^^^^^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_node.py", line 576, in assert_debug_log
    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_node.py", line 229, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['V2 transport error: missing garbage terminator, peer=1']" does not partially match log:

 - 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
 - 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__
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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)
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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
 - 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__
 - 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
 - 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__


2025-12-09T04:31:07.294475Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
2025-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
2025-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
2025-12-09T04:31:07.295209Z TestFramework (ERROR): 
2025-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
2025-12-09T04:31:07.295454Z TestFramework (ERROR): 
2025-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.
2025-12-09T04:31:07.295791Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2025-12-09T04:31:07.295864Z TestFramework (ERROR): 


stderr:
[node 0] Cleaning up leftover process

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

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.