test: fix p2p_leak_tx.py #33121

pull mzumsande wants to merge 3 commits into bitcoin:master from mzumsande:202508_fix_p2p_leak_tx.py changing 1 files +35 −26
  1. mzumsande commented at 10:22 pm on August 1, 2025: contributor

    This fixes two issues with p2p_leak_tx.py:

    1.) #33090: As far as I can see, this is just the randomness of NextInvToInbounds/ rand_exp_duration, which has a probability of e^-(60s/5s) = 6.14×10^−6 to result in a period > 60s (our waiting time), so that the test would fail every 160k runs… Doubling the timeout should be sufficient to lower the probability drastically.

    2.) The subtest test_notfound_on_unannounced_tx has some (w)txid confusion: we send a MSG_TX-type getdata with a wtxid in it, which necessarily always results in a NOTFOUND. Fixed this, and change the subtest to be more deterministic based on mocktime.

  2. DrahtBot added the label Tests on Aug 1, 2025
  3. DrahtBot commented at 10:22 pm on August 1, 2025: contributor

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    Code Coverage & Benchmarks

    For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/33121.

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK vasild, stratospher, davidgumberg
    Concept ACK jonatack, naiyoma, enirox001

    If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

  4. DrahtBot added the label CI failed on Aug 2, 2025
  5. fanquake commented at 10:37 am on August 2, 2025: member
  6. jonatack commented at 3:51 pm on August 4, 2025: member
    Concept ACK
  7. DrahtBot removed the label CI failed on Aug 5, 2025
  8. stratospher commented at 11:44 am on August 5, 2025: contributor

    Nice detective work! Just 1 question, will ACK after that.

    1. I tried some modifications of the test locally but wasn’t able to enter the “else branch” where “tx was already announced to us”. Were you able to test it?
    2. Could also change MAX_REPEATS to a lower number. I’m getting bad-txns-inputs-missingorspent at run 47 when I remove the break in the loop. So don’t think the test would work for full 100 runs anyways.

    Not sure if this is essential for the test, but we could add a random delay of 2-3s to trigger both paths on a regular basis.

    Hmm I’m fine either ways. On one hand - point of the test is to make sure that node responds with NOTFOUND for unannounced transactions, on the other hand - silent errors like the one fixed in this PR can slip through undetected.

  9. mzumsande commented at 5:20 pm on August 6, 2025: contributor

    I tried some modifications of the test locally but wasn’t able to enter the “else branch” where “tx was already announced to us”. Were you able to test it?

    No, but with a time.sleep(3) before inbound_peer.send_and_ping(want_tx) it would go into that branch regularly. because the NextInvToInbounds will often generate a random interval <3s - that’s why I mentioned it above.

    In general I was a bit unsure about the main point of the subtest (maybe @maflcko you can help?). Is the goal to have both branches executed regularly, or are we just interested in the notfound branch and the rest is there mostly to avoid intermittent failure? By the way, the failure from 1) could also be easily avoided by setting self.noban_tx_relay = True, but that seemed to be at odds with the general intention of the test.

    Could also change MAX_REPEATS to a lower number

    True, depending on whether we put a sleep in or not.

  10. maflcko commented at 10:50 am on August 7, 2025: member

    are we just interested in the notfound branch and the rest is there mostly to avoid intermittent failure?

    Yes.

    I think mocktime could be used to remove the loop and just do a one-shot notfound message?

  11. naiyoma commented at 6:48 pm on August 8, 2025: contributor

    Concept ACK

    Increasing timeout to 120 reduces probability to P(120s) = e^(-120/5) = e^(-24) ≈ 3.78×10^-11 (~1 in 26.5B runs)

  12. naiyoma commented at 7:12 pm on August 8, 2025: contributor

    but with a time.sleep(3) before inbound_peer.send_and_ping(want_tx) it would go into that branch regularly.

    time.sleep(8) after wtxid = self.miniwallet.send_self_transfer(from_node=self.gen_node)["wtxid"] also works

  13. enirox001 commented at 2:24 pm on August 23, 2025: contributor

    Concept ACK ab43e0b on fixing the test flakiness.

    I took a shot at making test_notfound_on_unannounced_tx() more deterministic using mocktime. Feel free to use it if helpful:

     0diff --git a/test/functional/p2p_leak_tx.py b/test/functional/p2p_leak_tx.py
     1index 3fd324a029..f50993e932 100755
     2--- a/test/functional/p2p_leak_tx.py
     3+++ b/test/functional/p2p_leak_tx.py
     4@@ -11,6 +11,7 @@ from test_framework.util import (
     5     assert_equal,
     6 )
     7 from test_framework.wallet import MiniWallet
     8+import time
     9 
    10 
    11 class P2PNode(P2PDataStore):
    12@@ -79,27 +80,33 @@ class P2PLeakTxTest(BitcoinTestFramework):
    13         self.gen_node.disconnect_p2ps()
    14         inbound_peer = self.gen_node.add_p2p_connection(P2PNode())  # An "attacking" inbound peer
    15 
    16-        MAX_REPEATS = 100
    17-        self.log.info("Running test up to {} times.".format(MAX_REPEATS))
    18-        for i in range(MAX_REPEATS):
    19-            self.log.info('Run repeat {}'.format(i + 1))
    20-            wtxid = self.miniwallet.send_self_transfer(from_node=self.gen_node)["wtxid"]
    21-
    22-            want_tx = msg_getdata()
    23-            want_tx.inv.append(CInv(t=MSG_WTX, h=int(wtxid, 16)))
    24-            with p2p_lock:
    25-                inbound_peer.last_message.pop('notfound', None)
    26-            inbound_peer.send_and_ping(want_tx)
    27-            if inbound_peer.last_message.get('notfound'):
    28-                self.log.debug('tx {} was not yet announced to us.'.format(wtxid))
    29-                self.log.debug("node has responded with a notfound message. End test.")
    30-                assert_equal(inbound_peer.last_message['notfound'].vec[0].hash, int(wtxid, 16))
    31+        MOCK_DELTA = 120
    32+        MAX_REPEATS = 10
    33+        try:
    34+            self.gen_node.setmocktime(int(time.time()) + MOCK_DELTA)
    35+            for i in range(MAX_REPEATS):
    36+                self.log.info('Run repeat {}'.format(i + 1))
    37+                wtxid = self.miniwallet.send_self_transfer(from_node=self.gen_node)["wtxid"]
    38+                want_tx = msg_getdata()
    39+                want_tx.inv.append(CInv(t=MSG_WTX, h=int(wtxid, 16)))
    40                 with p2p_lock:
    41-                    inbound_peer.last_message.pop('notfound')
    42-                break
    43+                    inbound_peer.last_message.pop('notfound', None)
    44+                    inbound_peer.last_message.pop('tx', None)
    45+                inbound_peer.send_and_ping(want_tx)
    46+                inbound_peer.wait_until(lambda: inbound_peer.last_message.get('notfound') or inbound_peer.last_message.get('tx'), timeout=10)
    47+                if inbound_peer.last_message.get('notfound'):
    48+                    self.log.debug('tx {} was not yet announced to us.'.format(wtxid))
    49+                    assert_equal(inbound_peer.last_message['notfound'].vec[0].hash, int(wtxid, 16))
    50+                    with p2p_lock:
    51+                        inbound_peer.last_message.pop('notfound')
    52+                    break
    53+                else:
    54+                    self.log.debug('tx {} was already announced to us. Try test again.'.format(wtxid))
    55+                    assert int(wtxid, 16) in [inv.hash for inv in inbound_peer.last_message['inv'].inv]
    56             else:
    57-                self.log.debug('tx {} was already announced to us. Try test again.'.format(wtxid))
    58-                assert int(wtxid, 16) in [inv.hash for inv in inbound_peer.last_message['inv'].inv]
    59+                raise AssertionError("Test failed after {} attempts - transactions kept being announced".format(MAX_REPEATS))
    60+        finally:
    61+            self.gen_node.setmocktime(0)
    62 
    63 
    64 if __name__ == '__main__':
    

    This uses mocktime to control announcement timing more deterministically while keeping a small retry loop for robustness.

  14. davidgumberg commented at 10:35 pm on August 27, 2025: contributor

    Ideally, p2p_leak_tx.py would be rewritten so that it would deterministically exercise both branches, my impression is the that we only really care about the first case, that tx’es that haven’t been inv’ed don’t get leaked, but exercising the second case is a good validation of the assumptions of the test, and would have caught that the existing test was broken.

    One solution is to set a mocktime as suggested by @enirox001 above so that no time passes and no inv’s can be sent and the getdata will surely fail, then disable mocktimes and wait until an inv is sent, then send the same getdata again and check that we get the expected tx response.

    e.g. https://github.com/davidgumberg/bitcoin/commit/f56c27662ddd3dab5b58cd5d8c8fb91b432c94c5

     0def test_notfound_on_unannounced_tx(self):
     1    self.log.info("Check that we don't leak txs to inbound peers that we haven't yet announced to")
     2    self.gen_node.disconnect_p2ps()
     3    inbound_peer = self.gen_node.add_p2p_connection(P2PNode())  # An "attacking" inbound peer
     4
     5    # Set a mock time so that time does not pass, and gen_node never announces the transaction
     6    self.gen_node.setmocktime(1)
     7    wtxid = int(self.miniwallet.send_self_transfer(from_node=self.gen_node)["wtxid"], 16)
     8
     9    want_tx = msg_getdata()
    10    want_tx.inv.append(CInv(t=MSG_WTX, h=wtxid))
    11    with p2p_lock:
    12        inbound_peer.last_message.pop('notfound', None)
    13    inbound_peer.send_and_ping(want_tx)
    14    inbound_peer.wait_until(lambda: "notfound" in inbound_peer.last_message)
    15    with p2p_lock:
    16        assert_equal(inbound_peer.last_message.get("notfound").vec[0].hash, wtxid)
    17        inbound_peer.last_message.pop('notfound')
    18
    19    # Disable mocktime and wait for the announcement.
    20    inbound_peer.last_message.pop('inv', None)
    21    self.gen_node.setmocktime(0)
    22
    23    # Checking that the inv contains the wtxid would have a 1 in 10^6 chance
    24    # of spuriously failing, and the getdata response will show what we really
    25    # care about, so we don't check it.
    26    self.wait_until(lambda: "inv" in inbound_peer.last_message)
    27
    28    # Send the getdata again, this time the node should send us a TX message.
    29    inbound_peer.last_message.pop('tx', None)
    30    inbound_peer.send_and_ping(want_tx)
    31    self.wait_until(lambda: "tx" in inbound_peer.last_message)
    32    assert_equal(wtxid, int(inbound_peer.last_message["tx"].tx.wtxid_hex, 16))
    
  15. mzumsande commented at 10:48 pm on August 27, 2025: contributor
    Thanks for the reviews and suggestions - I was busy the last couple of weeks, but I’ll look at them in detail / update the PR next week!
  16. mzumsande force-pushed on Sep 5, 2025
  17. mzumsande force-pushed on Sep 5, 2025
  18. mzumsande commented at 7:22 pm on September 5, 2025: contributor

    I have now pushed an update - I went with the approach of @davidgumberg because it’s simpler - when we use mocktime, MAX_REPEATS should no longer be necessary.

    I made small changes to the suggestion above:

    • used current time with setmocktime, going back in time seems brittle.
    • I didn’t understand the comment “Checking that the inv contains the wtxid would have a 1 in 10^6 chance of spuriously failing (…)”, so I didn’t take that part. If NextInvToInbounds doesn’t fire, we should just get no inv and the wait_until should fail (I also used 120s timeout here to make that less likely), but if we receive an inv, shouldn’t it always contain the wtxid?
  19. mzumsande force-pushed on Sep 5, 2025
  20. davidgumberg commented at 9:16 pm on September 5, 2025: contributor

    If NextInvToInbounds doesn’t fire, we should just get no inv and the wait_until should fail (I also used 120s timeout here to make that less likely), but if we receive an inv, shouldn’t it always contain the wtxid?

    My understanding of Peer::TxRelay::m_tx_inventory_known_filter is that it will occasionally indicate that a transaction is known to a peer when it isn’t, and then we won’t include it in an INV:

    https://github.com/bitcoin/bitcoin/blob/e04cb9c1bdf2199127cc8cf9c87f25e46b8cac7b/src/net_processing.cpp#L5784-L5786

    But I guess my comment was mistaken, since in this particular test there is only one transaction to announce and that would result in the peer not sending any INV message at all:

    https://github.com/bitcoin/bitcoin/blob/e04cb9c1bdf2199127cc8cf9c87f25e46b8cac7b/src/net_processing.cpp#L5807-L5808

    Maybe this is also a suspect for the spurious failure in #33090?

    But, there are other tests that wait for INV’s with exact contents, e.g.: https://github.com/bitcoin/bitcoin/blob/e04cb9c1bdf2199127cc8cf9c87f25e46b8cac7b/test/functional/p2p_segwit.py#L1263-L1267

    and I can’t find any reports about them spuriously failing, so maybe I’m misunderstanding something or this failure case is sufficiently rare that it hasn’t been seen or #33090 is the first sighting.

  21. mzumsande commented at 3:31 pm on September 9, 2025: contributor

    My understanding of Peer::TxRelay::m_tx_inventory_known_filter is that it will occasionally indicate that a transaction is known to a peer when it isn’t, and then we won’t include it in an INV:

    Good point, I didn’t think of that possibility.

    Maybe this is also a suspect for the spurious failure in #33090?

    I don’t think we can determine what happened in the failed run, but 10^-6 is 6x smaller than the probability of NextInvToInbounds > 60s, so it still seems ok to bump the timeout.

  22. in test/functional/p2p_leak_tx.py:103 in e14825ace2
    119+        # Disable mocktime and wait for the announcement.
    120+        inbound_peer.last_message.pop('inv', None)
    121+        self.gen_node.setmocktime(0)
    122+
    123+        self.wait_until(lambda: "inv" in inbound_peer.last_message, timeout=120)
    124+        assert wtxid in [inv.hash for inv in inbound_peer.last_message['inv'].inv]
    


    davidgumberg commented at 0:09 am on September 12, 2025:

    nanonit, only if retouching:

    0        inbound_peer.wait_for_inv([CInv(t=MSG_WTX, h=wtxid)], timeout=120)
    

    mzumsande commented at 8:41 pm on September 23, 2025:
    done
  23. davidgumberg approved
  24. davidgumberg commented at 0:25 am on September 12, 2025: contributor

    ACK e14825ace2a8c6abcf11fdfb

  25. DrahtBot requested review from jonatack on Sep 12, 2025
  26. DrahtBot requested review from stratospher on Sep 12, 2025
  27. DrahtBot requested review from naiyoma on Sep 12, 2025
  28. DrahtBot requested review from enirox001 on Sep 12, 2025
  29. DrahtBot added the label Needs rebase on Sep 23, 2025
  30. mzumsande force-pushed on Sep 23, 2025
  31. mzumsande commented at 8:43 pm on September 23, 2025: contributor
    e14825a to a52c148: Rebased due to conflict with #33448, addressed nit.
  32. DrahtBot removed the label Needs rebase on Sep 23, 2025
  33. mzumsande force-pushed on Sep 23, 2025
  34. davidgumberg approved
  35. in test/functional/p2p_leak_tx.py:50 in a52c148ece
    46@@ -47,7 +47,7 @@ def test_tx_in_block(self):
    47         assert_equal(pi["inv_to_send"], 1) # and our tx has been queued
    48         self.gen_node.setmocktime(0)
    49 
    50-        inbound_peer.wait_until(lambda: "inv" in inbound_peer.last_message and inbound_peer.last_message.get("inv").inv[0].hash == int(wtxid, 16))
    51+        inbound_peer.wait_until(lambda: "inv" in inbound_peer.last_message and inbound_peer.last_message.get("inv").inv[0].hash == int(wtxid, 16), timeout=120)
    


    vasild commented at 1:57 pm on September 25, 2025:

    In the first commit, it is possible to generate fake time passage without spending wall clock time of the test. That is, fix the problem and make the test faster:

     0     def test_tx_in_block(self):
     1         self.log.info("Check that a transaction in the last block is uploaded (beneficial for compact block relay)")
     2+        self.gen_node.setmocktime(int(time.time()) - 120) # pause time based activities
     3         inbound_peer = self.gen_node.add_p2p_connection(P2PNode())
     4         
     5         self.log.debug("Generate transaction and block")
     6         inbound_peer.last_message.pop("inv", None)
     7 
     8-        self.gen_node.setmocktime(int(time.time())) # pause time based activities
     9         wtxid = self.miniwallet.send_self_transfer(from_node=self.gen_node)["wtxid"]
    10         rawmp = self.gen_node.getrawmempool(False, True)
    11         pi = self.gen_node.getpeerinfo()[0]
    12         assert_equal(rawmp["mempool_sequence"], 2) # our tx cause mempool activity
    13         assert_equal(pi["last_inv_sequence"], 1) # that is after the last inv
    14         assert_equal(pi["inv_to_send"], 1) # and our tx has been queued
    15         self.gen_node.setmocktime(0)
    16 
    17-        inbound_peer.wait_until(lambda: "inv" in inbound_peer.last_message and inbound_peer.last_message.get("inv").inv[0].hash == int(wtxid, 16), timeout=120)
    18+        inbound_peer.wait_until(lambda: "inv" in inbound_peer.last_message and inbound_peer.last_message.get("inv").inv[0].hash == int(wtxid, 16))
    19         
    20         rawmp = self.gen_node.getrawmempool(False, True)
    

    Edit: to clarify, the first setmocktime() sets the time to 120s in the past, recording that in m_next_inv_to_inbounds, then when the time comes for bitcoind to wait for that delay, the second setmocktime(0) lets time flow normally and the current time is about 120s more than m_next_inv_to_inbounds, so there is no waiting.


    vasild commented at 10:42 am on September 26, 2025:

    Here is a change against master that could replace the first commit in this PR. It solves the same problem - when NextInvToInbounds() decides to wait more than the test timeout. In addition, by using mocktime, the diff below eliminates the waits in a few places of the test due to the NextInvToInbounds() delays. As a result the test passes in about 1 second instead of the current random few seconds to few tens of seconds.

     0--- i/test/functional/p2p_leak_tx.py
     1+++ w/test/functional/p2p_leak_tx.py
     2@@ -24,31 +24,34 @@ class P2PLeakTxTest(BitcoinTestFramework):
     3         self.num_nodes = 1
     4 
     5     def run_test(self):
     6         self.gen_node = self.nodes[0]  # The block and tx generating node
     7         self.miniwallet = MiniWallet(self.gen_node)
     8 
     9+        self.mocktime = int(time.time())
    10+
    11         self.test_tx_in_block()
    12         self.test_notfound_on_replaced_tx()
    13         self.test_notfound_on_unannounced_tx()
    14 
    15     def test_tx_in_block(self):
    16         self.log.info("Check that a transaction in the last block is uploaded (beneficial for compact block relay)")
    17+        self.gen_node.setmocktime(self.mocktime)
    18         inbound_peer = self.gen_node.add_p2p_connection(P2PNode())
    19 
    20         self.log.debug("Generate transaction and block")
    21         inbound_peer.last_message.pop("inv", None)
    22 
    23-        self.gen_node.setmocktime(int(time.time())) # pause time based activities
    24         wtxid = self.miniwallet.send_self_transfer(from_node=self.gen_node)["wtxid"]
    25         rawmp = self.gen_node.getrawmempool(False, True)
    26         pi = self.gen_node.getpeerinfo()[0]
    27         assert_equal(rawmp["mempool_sequence"], 2) # our tx cause mempool activity
    28         assert_equal(pi["last_inv_sequence"], 1) # that is after the last inv
    29         assert_equal(pi["inv_to_send"], 1) # and our tx has been queued
    30-        self.gen_node.setmocktime(0)
    31+        self.mocktime += 120
    32+        self.gen_node.setmocktime(self.mocktime)
    33 
    34         inbound_peer.wait_until(lambda: "inv" in inbound_peer.last_message and inbound_peer.last_message.get("inv").inv[0].hash == int(wtxid, 16))
    35 
    36         rawmp = self.gen_node.getrawmempool(False, True)
    37         pi = self.gen_node.getpeerinfo()[0]
    38         assert_equal(rawmp["mempool_sequence"], 2) # no mempool update
    39@@ -62,21 +65,26 @@ class P2PLeakTxTest(BitcoinTestFramework):
    40         inbound_peer.last_message.pop("tx", None)
    41         inbound_peer.send_and_ping(want_tx)
    42         assert_equal(inbound_peer.last_message.get("tx").tx.wtxid_hex, wtxid)
    43 
    44     def test_notfound_on_replaced_tx(self):
    45         self.gen_node.disconnect_p2ps()
    46+        self.gen_node.setmocktime(self.mocktime)
    47         inbound_peer = self.gen_node.add_p2p_connection(P2PTxInvStore())
    48 
    49         self.log.info("Transaction tx_a is broadcast")
    50         tx_a = self.miniwallet.send_self_transfer(from_node=self.gen_node)
    51-        inbound_peer.wait_for_broadcast(txns=[tx_a["wtxid"]])
    52+        self.mocktime += 120
    53+        self.gen_node.setmocktime(self.mocktime)
    54+        inbound_peer.wait_until(lambda: "inv" in inbound_peer.last_message and inbound_peer.last_message.get("inv").inv[0].hash == int(tx_a['wtxid'], 16))
    55 
    56         tx_b = tx_a["tx"]
    57         tx_b.vout[0].nValue -= 9000
    58         self.gen_node.sendrawtransaction(tx_b.serialize().hex())
    59+        self.mocktime += 120
    60+        self.gen_node.setmocktime(self.mocktime)
    61         inbound_peer.wait_until(lambda: "tx" in inbound_peer.last_message and inbound_peer.last_message.get("tx").tx.wtxid_hex == tx_b.wtxid_hex)
    62 
    63         self.log.info("Re-request of tx_a after replacement is answered with notfound")
    64         req_vec = [
    65             CInv(t=MSG_TX, h=int(tx_a["txid"], 16)),
    66             CInv(t=MSG_WTX, h=int(tx_a["wtxid"], 16)),
    

    mzumsande commented at 8:00 pm on September 30, 2025:
    done with the latest push. I also adjusted the third commit with the new test in a similar way.
  36. vasild approved
  37. vasild commented at 10:45 am on September 26, 2025: contributor

    ACK a52c148ece2296f22e2fe1b7e9584d49e23f03f2

    The changes are an improvement. It seems some of that maybe can be done better, see #33121 (review). I do not see that as a blocker.

  38. test: increase timeout in p2p_leak_tx.py
    With a low but not negligible probability in the order
    of 10^-6 the exponential timer NextInvToInBounds can lead
    to an interval >60s, making the test fail.
    Also uses mocktime to speed up the test and fixes a
    non-matching on_inv override.
    
    Co-authored-by: Vasil Dimov <vd@FreeBSD.org>
    576dd97cb9
  39. test: fix (w)txid confusion in p2p_leak_tx.py
    Before, we'd send a MSG_TX with a wtxid in it, which
    would always result in a notfound answer
    99bc552980
  40. test: make notfound_on_unannounced more reliable
    By using mocktime, we will always hit both the notfound
    branch and the tx sent branch.
    The previous version didn't achieve that due to timing
    issues.
    
    Co-authored-by: Martin Zumsande <mzumsande@gmail.com>
    14ae71f323
  41. mzumsande force-pushed on Sep 30, 2025
  42. mzumsande commented at 8:01 pm on September 30, 2025: contributor

    a52c148 to 14ae71f:

    • Used mocktime everywhere to speed up the test.
    • corrected on_inv override variable name in 1st commit (my IDE complained about that)
  43. vasild approved
  44. vasild commented at 10:31 am on October 1, 2025: contributor
    ACK 14ae71f323dd011c6d51470ea15cf00750970f65
  45. DrahtBot requested review from davidgumberg on Oct 1, 2025
  46. stratospher commented at 10:50 am on October 3, 2025: contributor
    ACK 14ae71f. nice restructuring using mocktime!
  47. fanquake merged this on Oct 3, 2025
  48. fanquake closed this on Oct 3, 2025

  49. mzumsande deleted the branch on Oct 3, 2025

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-10-10 12:13 UTC

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