test: Intermittent issue in p2p_leak_tx.py in test_notfound_on_replaced

maflcko commented at 12:39 PM on March 11, 2024: member

Commit 4cc99df44aec4d104590aee46cf18318e22a8568. Using the s390x CI config.

Datadir: https://drahtbot.space/temp_scratch/p2p_leak_tx_111_222.tar.xz

Log:

 test  2024-03-10T01:18:14.344000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000000) 
 test  2024-03-10T01:18:14.350000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000002) 
 node0 2024-03-10T01:18:14.351976Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 node0 2024-03-10T01:18:14.352184Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
 node0 2024-03-10T01:18:14.352571Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 node0 2024-03-10T01:18:14.352692Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
 test  2024-03-10T01:18:14.422000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000000) 
 test  2024-03-10T01:18:14.428000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000002) 
 node0 2024-03-10T01:18:14.521350Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40684 
 node0 2024-03-10T01:18:14.521881Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=sendrawtransaction user=__cookie__ 
 node0 2024-03-10T01:18:14.526372Z [httpworker.0] [txmempool.cpp:662] [check] [mempool] Checking mempool with 1 transactions and 1 inputs 
 node0 2024-03-10T01:18:14.528387Z [httpworker.0] [validation.cpp:1125] [Finalize] [mempool] replacing tx d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a (wtxid=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6) with 0668eb571427ae4ed5ee1f9d9d3d0c6de4261bba44335d033a75be0183d87a46 (wtxid=fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870) for 0.00009 additional fees, 0 delta bytes 
 node0 2024-03-10T01:18:14.529256Z [httpworker.0] [validationinterface.cpp:200] [TransactionRemovedFromMempool] [validation] Enqueuing TransactionRemovedFromMempool: txid=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a wtxid=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6 reason=replaced 
 node0 2024-03-10T01:18:14.529918Z [scheduler] [validationinterface.cpp:200] [operator()] [validation] TransactionRemovedFromMempool: txid=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a wtxid=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6 reason=replaced 
 node0 2024-03-10T01:18:14.530970Z [httpworker.0] [validationinterface.cpp:191] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=0668eb571427ae4ed5ee1f9d9d3d0c6de4261bba44335d033a75be0183d87a46 wtxid=fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870 
 node0 2024-03-10T01:18:14.531186Z [scheduler] [validationinterface.cpp:191] [operator()] [validation] TransactionAddedToMempool: txid=0668eb571427ae4ed5ee1f9d9d3d0c6de4261bba44335d033a75be0183d87a46 wtxid=fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870 
 node0 2024-03-10T01:18:14.531430Z [httpworker.0] [txmempool.cpp:662] [check] [mempool] Checking mempool with 1 transactions and 1 inputs 
 node0 2024-03-10T01:18:24.002988Z [msghand] [net.cpp:3755] [PushMessage] [net] sending inv (37 bytes) peer=1 
 test  2024-03-10T01:18:24.010000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_inv(inv=[CInv(type=WTX hash=fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870)]) 
 test  2024-03-10T01:18:24.100000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_getdata(inv=[CInv(type=WTX hash=fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870)]) 
 node0 2024-03-10T01:18:24.103797Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: getdata (37 bytes) peer=1 
 node0 2024-03-10T01:18:24.103960Z [msghand] [net_processing.cpp:3990] [ProcessMessage] [net] received getdata (1 invsz) peer=1 
 node0 2024-03-10T01:18:24.104051Z [msghand] [net_processing.cpp:3993] [ProcessMessage] [net] received getdata for: wtx fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870 peer=1 
 node0 2024-03-10T01:18:24.104242Z [msghand] [net.cpp:3755] [PushMessage] [net] sending tx (133 bytes) peer=1 
 node0 2024-03-10T01:18:24.104524Z [msghand] [txmempool.cpp:1037] [RemoveUnbroadcastTx] [mempool] Removed 0668eb571427ae4ed5ee1f9d9d3d0c6de4261bba44335d033a75be0183d87a46 from set of unbroadcast txns 
 test  2024-03-10T01:18:24.192000Z TestFramework (INFO): Re-request of tx_a after replacement is answered with notfound 
 test  2024-03-10T01:18:24.201000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_getdata(inv=[CInv(type=TX hash=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a), CInv(type=WTX hash=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6)]) 
 test  2024-03-10T01:18:24.209000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_tx(tx=CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=fab2396e3f726e1801b9e7303cf294783a3fd7e19ddc8f2dfa55e25b01575b3e n=0) scriptSig= nSequence=0)] vout=[CTxOut(nValue=49.99959800 scriptPubKey=51202913b252fe537830f843bfdc5fa7d20ba48639a87c86ff837b92d083c55ad7c1)] wit=CTxWitness(CScriptWitness(51,c00000000000000000000000000000000000000000000000000000000000000001)) nLockTime=0)) 
 node0 2024-03-10T01:18:24.211497Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: getdata (73 bytes) peer=1 
 node0 2024-03-10T01:18:24.211811Z [msghand] [net_processing.cpp:3990] [ProcessMessage] [net] received getdata (2 invsz) peer=1 
 node0 2024-03-10T01:18:24.212064Z [msghand] [net_processing.cpp:3993] [ProcessMessage] [net] received getdata for: tx d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a peer=1 
 node0 2024-03-10T01:18:24.377046Z [msghand] [net.cpp:3755] [PushMessage] [net] sending notfound (73 bytes) peer=1 
 test  2024-03-10T01:18:24.380000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000000) 
 test  2024-03-10T01:18:24.394000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000003) 
 test  2024-03-10T01:18:24.388000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_notfound(vec=[CInv(type=TX hash=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a), CInv(type=WTX hash=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6)]) 
 node0 2024-03-10T01:18:24.396550Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 node0 2024-03-10T01:18:24.396727Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
 node0 2024-03-10T01:18:24.397194Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 node0 2024-03-10T01:18:24.397319Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
 test  2024-03-10T01:18:24.403000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000000) 
 test  2024-03-10T01:18:24.408000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000003) 
 test  2024-03-10T01:18:24.579000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/ci_container_base/ci/scratch/build/bitcoin-s390x-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
                                       self.run_test()
                                     File "/ci_container_base/ci/scratch/build/bitcoin-s390x-linux-gnu/test/functional/p2p_leak_tx.py", line 30, in run_test
                                       self.test_notfound_on_replaced_tx()
                                     File "/ci_container_base/ci/scratch/build/bitcoin-s390x-linux-gnu/test/functional/p2p_leak_tx.py", line 75, in test_notfound_on_replaced_tx
                                       assert "tx" not in inbound_peer.last_message
                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                   AssertionError

maflcko added the label Tests on Mar 11, 2024

maflcko added the label CI failed on Mar 11, 2024

maflcko commented at 12:40 PM on March 11, 2024: member

Maybe a transaction from a previous sub-test is leaking into this sub-test?

theStack commented at 3:20 PM on March 12, 2024: contributor

Looking at the following part in test_framework.log:

2024-03-10T01:18:24.192000Z TestFramework (INFO): Re-request of tx_a after replacement is answered with notfound
2024-03-10T01:18:24.201000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_getdata(inv=[CInv(type=TX hash=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a), CInv(type=WTX hash=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6)])
2024-03-10T01:18:24.209000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_tx(tx=CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=fab2396e3f726e1801b9e7303cf294783a3fd7e19ddc8f2dfa55e25b01575b3e n=0) scriptSig= nSequence=0)] vout=[CTxOut(nValue=49.99959800 scriptPubKey=51202913b252fe537830f843bfdc5fa7d20ba48639a87c86ff837b92d083c55ad7c1)] wit=CTxWitness(CScriptWitness(51,c00000000000000000000000000000000000000000000000000000000000000001)) nLockTime=0))
2024-03-10T01:18:24.380000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000000)
2024-03-10T01:18:24.394000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000003)
2024-03-10T01:18:24.388000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_notfound(vec=[CInv(type=TX hash=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a), CInv(type=WTX hash=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6)])
2024-03-10T01:18:24.403000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000000)
2024-03-10T01:18:24.408000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000003)
2024-03-10T01:18:24.579000Z TestFramework (ERROR): Assertion failed

it seems like the tx causing the assertion is tx_b from the same sub-test (test_notfound_on_replaced_tx) a few lines above, for which the getdata request is answered later than expected. The mystery though is, how could this following line before ever pass, if the tx didn't arrive earlier? 🤔

https://github.com/bitcoin/bitcoin/blob/d14c7286b653ad09a5a196aa351b325f97db546b/test/functional/p2p_leak_tx.py#L60

mzumsande commented at 6:00 PM on March 14, 2024: contributor

The mystery though is, how could this following line before ever pass, if the tx didn't arrive earlier? 🤔

yes, I added that wait in #27864 to deal with the same problem - I also don't understand why it could pass that line without receiving the tx. Not sure if relevant, but just noting that the failed run used --v2transport.

maflcko commented at 9:50 AM on March 15, 2024: member

The mystery though is, how could this following line before ever pass, if the tx didn't arrive earlier? 🤔

yes, I added that wait in #27864 to deal with the same problem - I also don't understand why it could pass that line without receiving the tx. Not sure if relevant, but just noting that the failed run used --v2transport.

Hmm. I guess conceptually a duplicate of #25128

maflcko commented at 8:58 AM on June 7, 2024: member

https://drahtbot.space/temp_scratch/p2p_leak_tx_115_b.tar.zstd

 test  2024-06-07T02:34:22.778000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
                                       self.run_test()
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p_leak_tx.py", line 30, in run_test
                                       self.test_notfound_on_replaced_tx()
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p_leak_tx.py", line 75, in test_notfound_on_replaced_tx
                                       assert "tx" not in inbound_peer.last_message
                                   AssertionError

fanquake closed this on Jul 31, 2024

fanquake referenced this in commit be969292db on Jul 31, 2024

PastaPastaPasta referenced this in commit 4eaa331dbb on Oct 25, 2024

PastaPastaPasta referenced this in commit e4e5605ef8 on Oct 27, 2024

bitcoin locked this on Jul 31, 2025

test: Intermittent issue in p2p_leak_tx.py in test_notfound_on_replaced_tx #29621