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

issue vasild openend this issue on July 29, 2024
  1. vasild commented at 3:01 pm on July 29, 2024: contributor

    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.

     0diff --git c/src/net_processing.cpp i/src/net_processing.cpp
     1index d674758abd..00204e47cd 100644
     2--- c/src/net_processing.cpp
     3+++ i/src/net_processing.cpp
     4@@ -2504,15 +2504,17 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv&
     5                 // CMerkleBlock just contains hashes, so also push any transactions in the block the client did not see
     6                 // This avoids hurting performance by pointlessly requiring a round-trip
     7                 // Note that there is currently no way for a node to request any single transactions we didn't send here -
     8                 // they must either disconnect and retry or request the full block.
     9                 // Thus, the protocol spec specified allows for us to provide duplicate txn here,
    10                 // however we MUST always provide at least what the remote peer needs
    11+#if 0
    12                 typedef std::pair<unsigned int, uint256> PairType;
    13                 for (PairType& pair : merkleBlock.vMatchedTxn)
    14                     MakeAndPushMessage(pfrom, NetMsgType::TX, TX_NO_WITNESS(*pblock->vtx[pair.first]));
    15+#endif
    16             }
    17             // else
    18             // no response
    19         } else if (inv.IsMsgCmpctBlk()) {
    20             // If a peer is asking for old blocks, we're almost guaranteed
    21             // they won't have a useful mempool to match against a compact block,
    22@@ -2591,15 +2593,17 @@ void PeerManagerImpl::ProcessGetData(CNode& pfrom, Peer& peer, const std::atomic
    23             // peers and peers that asked us not to announce transactions.
    24             continue;
    25         }
    26 
    27         CTransactionRef tx = FindTxForGetData(*tx_relay, ToGenTxid(inv));
    28         if (tx) {
    29+#if 0
    30             // WTX and WITNESS_TX imply we serialize with witness
    31             const auto maybe_with_witness = (inv.IsMsgTx() ? TX_NO_WITNESS : TX_WITH_WITNESS);
    32             MakeAndPushMessage(pfrom, NetMsgType::TX, maybe_with_witness(*tx));
    33+#endif
    34             m_mempool.RemoveUnbroadcastTx(tx->GetHash());
    35         } else {
    36             vNotFound.push_back(inv);
    37         }
    38     }
    39 
    40@@ -3652,12 +3656,15 @@ void PeerManagerImpl::ProcessCompactBlockTxns(CNode& pfrom, Peer& peer, const Bl
    41         // in compact block optimistic reconstruction handling.
    42         ProcessBlock(pfrom, pblock, /*force_processing=*/true, /*min_pow_checked=*/true);
    43     }
    44     return;
    45 }
    46 
    47+// Remember which peer send us which transaction and then echo it back repeatedly.
    48+static std::unordered_map<NodeId, CTransactionRef> g_echo_tx;
    49+
    50 void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, DataStream& vRecv,
    51                                      const std::chrono::microseconds time_received,
    52                                      const std::atomic<bool>& interruptMsgProc)
    53 {
    54     AssertLockHeld(g_msgproc_mutex);
    55 
    56@@ -4497,12 +4504,15 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
    57         if (m_chainman.IsInitialBlockDownload()) return;
    58 
    59         CTransactionRef ptx;
    60         vRecv >> TX_WITH_WITNESS(ptx);
    61         const CTransaction& tx = *ptx;
    62 
    63+        // Save the received transaction with the peer id.
    64+        g_echo_tx.emplace(pfrom.GetId(), ptx);
    65+
    66         const uint256& txid = ptx->GetHash();
    67         const uint256& wtxid = ptx->GetWitnessHash();
    68 
    69         const uint256& hash = peer->m_wtxid_relay ? wtxid : txid;
    70         AddKnownTx(*peer, hash);
    71 
    72@@ -5327,12 +5337,19 @@ bool PeerManagerImpl::ProcessMessages(CNode* pfrom, std::atomic<bool>& interrupt
    73     if (peer == nullptr) return false;
    74 
    75     // For outbound connections, ensure that the initial VERSION message
    76     // has been sent first before processing any incoming messages
    77     if (!pfrom->IsInboundConn() && !peer->m_outbound_version_message_sent) return false;
    78 
    79+    // If this peer has sent us a transaction before, then send it back
    80+    // on each call to ProcessMessages().
    81+    auto it = g_echo_tx.find(pfrom->GetId());
    82+    if (it != g_echo_tx.end()) {
    83+        MakeAndPushMessage(*pfrom, NetMsgType::TX, TX_WITH_WITNESS(*it->second));
    84+    }
    85+
    86     {
    87         LOCK(peer->m_getdata_requests_mutex);
    88         if (!peer->m_getdata_requests.empty()) {
    89             ProcessGetData(*pfrom, *peer, interruptMsgProc);
    90         }
    91     }
    
     0diff --git c/test/functional/test_framework/p2p.py i/test/functional/test_framework/p2p.py
     1index 4f1265eb54..18f19d40a6 100755
     2--- c/test/functional/test_framework/p2p.py
     3+++ i/test/functional/test_framework/p2p.py
     4@@ -158,13 +158,14 @@ class P2PConnection(asyncio.Protocol):
     5     - deserializing and serializing the P2P message header
     6     - logging messages as they are sent and received
     7 
     8     This class contains no logic for handing the P2P message payloads. It must be
     9     sub-classed and the on_message() callback overridden."""
    10 
    11-    def __init__(self):
    12+    def __init__(self, name):
    13+        self.name = name
    14         # The underlying transport of the connection.
    15         # Should only call methods on this from the NetworkThread, c.f. call_soon_threadsafe
    16         self._transport = None
    17         # This lock is acquired before sending messages over the socket. There's an implied lock order and
    18         # p2p_lock must not be acquired after _send_lock as it could result in deadlocks.
    19         self._send_lock = threading.Lock()
    20@@ -419,16 +420,17 @@ class P2PConnection(asyncio.Protocol):
    21             tmsg += h[:4]
    22             tmsg += data
    23             return tmsg
    24 
    25     def _log_message(self, direction, msg):
    26         """Logs a message being sent or received over the connection."""
    27+        log_message = f"[{self.name}] "
    28         if direction == "send":
    29-            log_message = "Send message to "
    30+            log_message += "Send message to "
    31         elif direction == "receive":
    32-            log_message = "Received message from "
    33+            log_message += "Received message from "
    34         log_message += "%s:%d: %s" % (self.dstaddr, self.dstport, repr(msg)[:500])
    35         if len(log_message) > 500:
    36             log_message += "... (msg truncated)"
    37         logger.debug(log_message)
    38 
    39 
    40@@ -438,14 +440,14 @@ class P2PInterface(P2PConnection):
    41     This class provides high-level callbacks for processing P2P message
    42     payloads, as well as convenience methods for interacting with the
    43     node over P2P.
    44 
    45     Individual testcases should subclass this and override the on_* methods
    46     if they want to alter message handling behaviour."""
    47-    def __init__(self, support_addrv2=False, wtxidrelay=True):
    48-        super().__init__()
    49+    def __init__(self, name, support_addrv2=False, wtxidrelay=True):
    50+        super().__init__(name)
    51 
    52         # Track number of messages of each type received.
    53         # Should be read-only in a test.
    54         self.message_count = defaultdict(int)
    55 
    56         # Track the most recent message of each type.
    
     0#!/usr/bin/env python3
     1# Copyright (c) 2017-present The Bitcoin Core developers
     2# Distributed under the MIT software license, see the accompanying
     3# file COPYING or http://www.opensource.org/licenses/mit-license.php.
     4"""
     5"""
     6
     7from test_framework.p2p import (
     8    P2PInterface,
     9)
    10from test_framework.messages import (
    11    msg_tx,
    12)
    13from test_framework.test_framework import (
    14    BitcoinTestFramework,
    15)
    16from test_framework.wallet import (
    17    MiniWallet,
    18)
    19
    20
    21class P2PTtt(BitcoinTestFramework):
    22    def set_test_params(self):
    23        self.num_nodes = 1
    24
    25    def run_test(self):
    26        node0 = self.nodes[0]
    27        p0 = node0.add_outbound_p2p_connection(P2PInterface("p0"), p2p_idx=0)
    28        p1 = node0.add_outbound_p2p_connection(P2PInterface("p1"), p2p_idx=1)
    29
    30        wallet = MiniWallet(node0)
    31
    32        txs = wallet.create_self_transfer_chain(chain_length=2)
    33        self.log.info(f"Created txid={txs[0]['txid']}, spends {txs[0]['tx'].vin[0].prevout}")
    34        self.log.info(f"Created txid={txs[1]['txid']}, spends {txs[1]['tx'].vin[0].prevout}")
    35
    36        p0.send_message(msg_tx(txs[0]["tx"]))
    37        p1.send_message(msg_tx(txs[1]["tx"]))
    38
    39        self.wait_until(lambda: len(node0.getrawmempool()) > 0)
    40        self.wait_until(lambda: p0.message_count["tx"] > 0)
    41        self.wait_until(lambda: p1.message_count["tx"] > 0)
    42        while p1.message_count["tx"] < 10:
    43            if txs[0]["txid"] != p0.last_message["tx"].tx.rehash():
    44                self.log.error(f"p0 was expecting transaction {txs[0]['txid']} "
    45                               f"but instead received transaction {p0.last_message['tx'].tx.rehash()}")
    46                assert False
    47            if txs[1]["txid"] != p1.last_message["tx"].tx.rehash():
    48                self.log.error(f"p1 was expecting transaction {txs[1]['txid']} "
    49                               f"but instead received transaction {p1.last_message['tx'].tx.rehash()}")
    50                assert False
    51
    52
    53if __name__ == "__main__":
    54    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

    0# this is ok, as expected, p0 receives tx 3833 which spends ff07:0
    1 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)) 
    2
    3# this is ok, as expected, p1 receives tx e746 which spends 3833:0
    4 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)) 
    5
    6# there are no other "TestFramework.p2p ... Received message ... msg_tx" messages
    7
    8# then p0.last_message["tx"].tx.rehash() contains e746!?
    9 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

  2. mzumsande commented at 8:39 pm on July 29, 2024: contributor

    Expect peer0 to repeatedly receive back tx0 from the node and peer1 to repeatedly receive back tx1.

    I don’t understand. Why shouldn’t p0 also get tx1, since the full node does transaction relay?

  3. vasild commented at 5:00 am on July 30, 2024: contributor

    @mzumsande, thank you for looking at this!

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

    Why shouldn’t p0 also get tx1, since the full node does transaction relay?

    There you go! There is a flaw in the test - it could fail for a legit reason due to transaction relay. I will further modify the node to stop that so that only the received transactions are sent back.

    However, this still does not explain the logs from the python framework (in the “Relevant log output” section of the OP) where it only logged that p0 received tx0 and p1 received tx1 and then tx1 was in p0’s last_message['tx'].

  4. vasild commented at 5:19 am on July 30, 2024: contributor
    I disabled the normal transaction relay and updated the patch “Modification to Bitcoin Core to repeatedly echo back a transaction” in the OP. Still the test fails. Also, in the full_log.txt there are no “inv” messages sent in either direction, so normal transaction relay did not happen (before the test failed).
  5. maflcko commented at 1:44 pm on July 30, 2024: member
    Does it also happen with a different message type? For example a new message type with a small payload, like {b"test_ping", b"id_1"}? This should avoid any possible message-type specific handling or interaction.
  6. mzumsande commented at 8:16 pm on July 30, 2024: contributor
    @vasild: I think you are right, this looks like a bug! If tried to use self.last_message[msgtype] = copy.deepcopy(message) in on_message, and then the behavior is as expected. Though I don’t understand yet why it happens, and why for tx and (apparently) not for other messages like version.
  7. maflcko commented at 8:20 pm on July 30, 2024: member
    This could also explain many of the intermittent issues: #29621 (comment)
  8. mzumsande commented at 9:41 pm on July 30, 2024: contributor

    Ok, I think I found the root cause, it’s python default args:

    msg_tx is initialized with a default arg of CTransaction(), see https://github.com/bitcoin/bitcoin/blob/d367a4e36f7357c4ebd018e8e1c9c5071db2e1c2/test/functional/test_framework/messages.py#L1297C9-L1297C17 . This is incorrect because default args are evaluated in python once, when the function is defined, not with each call to the function.

    Reminds me of a very similar bug in #24748 (review) some months ago.

    See #30552 for a fix.

  9. fanquake closed this on Jul 31, 2024

  10. fanquake referenced this in commit be969292db on Jul 31, 2024

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: 2024-09-29 04:12 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me