Skip to content

tests: the python test framework mixes/confuses messages to different peers #30543

@vasild

Description

@vasild

Is there an existing issue for this?

  • I have searched the existing issues

Current behaviour

The P2PInterface.last_message['tx'] is unreliable because it may end up with a transaction sent to another peer. To observe this:

  • Modify Bitcoin Core so that it repeatedly sends back a transaction to the peer it received it from.
  • Write a test with one Bitcoin Core node and two python P2PInterface peers and have each peer send one transaction to the node, e.g. peer0 sends tx0 and peer1 sends tx1. Expect peer0 to repeatedly receive back tx0 from the node and peer1 to repeatedly receive back tx1.
  • The test fails because either peer0 receives back tx1 or peer1 receives back tx0.

This looks so strange that I think that I must be doing something wrong.

Modification to Bitcoin Core to repeatedly echo back a transaction
diff --git c/src/net_processing.cpp i/src/net_processing.cpp
index d674758abd..00204e47cd 100644
--- c/src/net_processing.cpp
+++ i/src/net_processing.cpp
@@ -2504,15 +2504,17 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv&
                 // CMerkleBlock just contains hashes, so also push any transactions in the block the client did not see
                 // This avoids hurting performance by pointlessly requiring a round-trip
                 // Note that there is currently no way for a node to request any single transactions we didn't send here -
                 // they must either disconnect and retry or request the full block.
                 // Thus, the protocol spec specified allows for us to provide duplicate txn here,
                 // however we MUST always provide at least what the remote peer needs
+#if 0
                 typedef std::pair<unsigned int, uint256> PairType;
                 for (PairType& pair : merkleBlock.vMatchedTxn)
                     MakeAndPushMessage(pfrom, NetMsgType::TX, TX_NO_WITNESS(*pblock->vtx[pair.first]));
+#endif
             }
             // else
             // no response
         } else if (inv.IsMsgCmpctBlk()) {
             // If a peer is asking for old blocks, we're almost guaranteed
             // they won't have a useful mempool to match against a compact block,
@@ -2591,15 +2593,17 @@ void PeerManagerImpl::ProcessGetData(CNode& pfrom, Peer& peer, const std::atomic
             // peers and peers that asked us not to announce transactions.
             continue;
         }
 
         CTransactionRef tx = FindTxForGetData(*tx_relay, ToGenTxid(inv));
         if (tx) {
+#if 0
             // WTX and WITNESS_TX imply we serialize with witness
             const auto maybe_with_witness = (inv.IsMsgTx() ? TX_NO_WITNESS : TX_WITH_WITNESS);
             MakeAndPushMessage(pfrom, NetMsgType::TX, maybe_with_witness(*tx));
+#endif
             m_mempool.RemoveUnbroadcastTx(tx->GetHash());
         } else {
             vNotFound.push_back(inv);
         }
     }
 
@@ -3652,12 +3656,15 @@ void PeerManagerImpl::ProcessCompactBlockTxns(CNode& pfrom, Peer& peer, const Bl
         // in compact block optimistic reconstruction handling.
         ProcessBlock(pfrom, pblock, /*force_processing=*/true, /*min_pow_checked=*/true);
     }
     return;
 }
 
+// Remember which peer send us which transaction and then echo it back repeatedly.
+static std::unordered_map<NodeId, CTransactionRef> g_echo_tx;
+
 void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, DataStream& vRecv,
                                      const std::chrono::microseconds time_received,
                                      const std::atomic<bool>& interruptMsgProc)
 {
     AssertLockHeld(g_msgproc_mutex);
 
@@ -4497,12 +4504,15 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
         if (m_chainman.IsInitialBlockDownload()) return;
 
         CTransactionRef ptx;
         vRecv >> TX_WITH_WITNESS(ptx);
         const CTransaction& tx = *ptx;
 
+        // Save the received transaction with the peer id.
+        g_echo_tx.emplace(pfrom.GetId(), ptx);
+
         const uint256& txid = ptx->GetHash();
         const uint256& wtxid = ptx->GetWitnessHash();
 
         const uint256& hash = peer->m_wtxid_relay ? wtxid : txid;
         AddKnownTx(*peer, hash);
 
@@ -5327,12 +5337,19 @@ bool PeerManagerImpl::ProcessMessages(CNode* pfrom, std::atomic<bool>& interrupt
     if (peer == nullptr) return false;
 
     // For outbound connections, ensure that the initial VERSION message
     // has been sent first before processing any incoming messages
     if (!pfrom->IsInboundConn() && !peer->m_outbound_version_message_sent) return false;
 
+    // If this peer has sent us a transaction before, then send it back
+    // on each call to ProcessMessages().
+    auto it = g_echo_tx.find(pfrom->GetId());
+    if (it != g_echo_tx.end()) {
+        MakeAndPushMessage(*pfrom, NetMsgType::TX, TX_WITH_WITNESS(*it->second));
+    }
+
     {
         LOCK(peer->m_getdata_requests_mutex);
         if (!peer->m_getdata_requests.empty()) {
             ProcessGetData(*pfrom, *peer, interruptMsgProc);
         }
     }
Attach a name to each P2PInterface() and use it in the logs to make it easy to distinguish which peer logged what
diff --git c/test/functional/test_framework/p2p.py i/test/functional/test_framework/p2p.py
index 4f1265eb54..18f19d40a6 100755
--- c/test/functional/test_framework/p2p.py
+++ i/test/functional/test_framework/p2p.py
@@ -158,13 +158,14 @@ class P2PConnection(asyncio.Protocol):
     - deserializing and serializing the P2P message header
     - logging messages as they are sent and received
 
     This class contains no logic for handing the P2P message payloads. It must be
     sub-classed and the on_message() callback overridden."""
 
-    def __init__(self):
+    def __init__(self, name):
+        self.name = name
         # The underlying transport of the connection.
         # Should only call methods on this from the NetworkThread, c.f. call_soon_threadsafe
         self._transport = None
         # This lock is acquired before sending messages over the socket. There's an implied lock order and
         # p2p_lock must not be acquired after _send_lock as it could result in deadlocks.
         self._send_lock = threading.Lock()
@@ -419,16 +420,17 @@ class P2PConnection(asyncio.Protocol):
             tmsg += h[:4]
             tmsg += data
             return tmsg
 
     def _log_message(self, direction, msg):
         """Logs a message being sent or received over the connection."""
+        log_message = f"[{self.name}] "
         if direction == "send":
-            log_message = "Send message to "
+            log_message += "Send message to "
         elif direction == "receive":
-            log_message = "Received message from "
+            log_message += "Received message from "
         log_message += "%s:%d: %s" % (self.dstaddr, self.dstport, repr(msg)[:500])
         if len(log_message) > 500:
             log_message += "... (msg truncated)"
         logger.debug(log_message)
 
 
@@ -438,14 +440,14 @@ class P2PInterface(P2PConnection):
     This class provides high-level callbacks for processing P2P message
     payloads, as well as convenience methods for interacting with the
     node over P2P.
 
     Individual testcases should subclass this and override the on_* methods
     if they want to alter message handling behaviour."""
-    def __init__(self, support_addrv2=False, wtxidrelay=True):
-        super().__init__()
+    def __init__(self, name, support_addrv2=False, wtxidrelay=True):
+        super().__init__(name)
 
         # Track number of messages of each type received.
         # Should be read-only in a test.
         self.message_count = defaultdict(int)
 
         # Track the most recent message of each type.
A test that should pass
#!/usr/bin/env python3
# Copyright (c) 2017-present The Bitcoin Core developers
# Distributed under the MIT software license, see the accompanying
# file COPYING or http://www.opensource.org/licenses/mit-license.php.
"""
"""

from test_framework.p2p import (
    P2PInterface,
)
from test_framework.messages import (
    msg_tx,
)
from test_framework.test_framework import (
    BitcoinTestFramework,
)
from test_framework.wallet import (
    MiniWallet,
)


class P2PTtt(BitcoinTestFramework):
    def set_test_params(self):
        self.num_nodes = 1

    def run_test(self):
        node0 = self.nodes[0]
        p0 = node0.add_outbound_p2p_connection(P2PInterface("p0"), p2p_idx=0)
        p1 = node0.add_outbound_p2p_connection(P2PInterface("p1"), p2p_idx=1)

        wallet = MiniWallet(node0)

        txs = wallet.create_self_transfer_chain(chain_length=2)
        self.log.info(f"Created txid={txs[0]['txid']}, spends {txs[0]['tx'].vin[0].prevout}")
        self.log.info(f"Created txid={txs[1]['txid']}, spends {txs[1]['tx'].vin[0].prevout}")

        p0.send_message(msg_tx(txs[0]["tx"]))
        p1.send_message(msg_tx(txs[1]["tx"]))

        self.wait_until(lambda: len(node0.getrawmempool()) > 0)
        self.wait_until(lambda: p0.message_count["tx"] > 0)
        self.wait_until(lambda: p1.message_count["tx"] > 0)
        while p1.message_count["tx"] < 10:
            if txs[0]["txid"] != p0.last_message["tx"].tx.rehash():
                self.log.error(f"p0 was expecting transaction {txs[0]['txid']} "
                               f"but instead received transaction {p0.last_message['tx'].tx.rehash()}")
                assert False
            if txs[1]["txid"] != p1.last_message["tx"].tx.rehash():
                self.log.error(f"p1 was expecting transaction {txs[1]['txid']} "
                               f"but instead received transaction {p1.last_message['tx'].tx.rehash()}")
                assert False


if __name__ == "__main__":
    P2PTtt(__file__).main()

Expected behaviour

The test should pass.

Steps to reproduce

Modify Bitcoin Core with the attached patch and run the attached test.

Relevant log output

# this is ok, as expected, p0 receives tx 3833 which spends ff07:0
 test  2024-07-29T14:52:48.905000Z TestFramework.p2p (DEBUG): [p0] Received message from 0:0: msg_tx(tx=CTransaction(version=2 vin=[CTxIn(prevout=COutPoint(hash=ff07cc811d2826c6f5a6386dce61cdd3adfcdbacad4de26f3024d68d6dc16d13 n=0) scriptSig= nSequence=0)] vout=[CTxOut(nValue=49.99968800 scriptPubKey=51202913b252fe537830f843bfdc5fa7d20ba48639a87c86ff837b92d083c55ad7c1)] wit=CTxWitness(CScriptWitness(51,c00000000000000000000000000000000000000000000000000000000000000001)) nLockTime=0)) 

# this is ok, as expected, p1 receives tx e746 which spends 3833:0
 test  2024-07-29T14:52:48.905000Z TestFramework.p2p (DEBUG): [p1] Received message from 0:0: msg_tx(tx=CTransaction(version=2 vin=[CTxIn(prevout=COutPoint(hash=38335600f2465c0f8bb2b86d5830a34851d86fa879800c0e1434ddfc78c42898 n=0) scriptSig= nSequence=0)] vout=[CTxOut(nValue=49.99937600 scriptPubKey=51202913b252fe537830f843bfdc5fa7d20ba48639a87c86ff837b92d083c55ad7c1)] wit=CTxWitness(CScriptWitness(51,c00000000000000000000000000000000000000000000000000000000000000001)) nLockTime=0)) 

# there are no other "TestFramework.p2p ... Received message ... msg_tx" messages

# then p0.last_message["tx"].tx.rehash() contains e746!?
 test  2024-07-29T14:52:48.956000Z TestFramework (ERROR): p0 was expecting transaction 38335600f2465c0f8bb2b86d5830a34851d86fa879800c0e1434ddfc78c42898 but instead received transaction e74691cbd1b181269301baed4266a2174cd4198fcf95591048c4ad17640f9f5b 

full_log.txt

How did you obtain Bitcoin Core

Compiled from source

What version of Bitcoin Core are you using?

master@8754d055c65e11fd2afa59f9e5de7c60a9e0ec23

Operating system and version

Python 3.11.9

Machine specifications

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions