test: Intermittent issue in p2p_leak_tx.py in test_notfound_on_replaced_tx #29621
Description
Commit 4cc99df. Using the s390x CI config.
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