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:

 0 test  2024-03-10T01:18:14.344000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000000) 
 1 test  2024-03-10T01:18:14.350000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000002) 
 2 node0 2024-03-10T01:18:14.351976Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 3 node0 2024-03-10T01:18:14.352184Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
 4 node0 2024-03-10T01:18:14.352571Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 5 node0 2024-03-10T01:18:14.352692Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
 6 test  2024-03-10T01:18:14.422000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000000) 
 7 test  2024-03-10T01:18:14.428000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000002) 
 8 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 
 9 node0 2024-03-10T01:18:14.521881Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=sendrawtransaction user=__cookie__ 
10 node0 2024-03-10T01:18:14.526372Z [httpworker.0] [txmempool.cpp:662] [check] [mempool] Checking mempool with 1 transactions and 1 inputs 
11 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 
12 node0 2024-03-10T01:18:14.529256Z [httpworker.0] [validationinterface.cpp:200] [TransactionRemovedFromMempool] [validation] Enqueuing TransactionRemovedFromMempool: txid=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a wtxid=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6 reason=replaced 
13 node0 2024-03-10T01:18:14.529918Z [scheduler] [validationinterface.cpp:200] [operator()] [validation] TransactionRemovedFromMempool: txid=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a wtxid=dac681f4f5a7b4a4a537558ec353982bc5740f57a9eb8e3fb6624758c77c1aa6 reason=replaced 
14 node0 2024-03-10T01:18:14.530970Z [httpworker.0] [validationinterface.cpp:191] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=0668eb571427ae4ed5ee1f9d9d3d0c6de4261bba44335d033a75be0183d87a46 wtxid=fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870 
15 node0 2024-03-10T01:18:14.531186Z [scheduler] [validationinterface.cpp:191] [operator()] [validation] TransactionAddedToMempool: txid=0668eb571427ae4ed5ee1f9d9d3d0c6de4261bba44335d033a75be0183d87a46 wtxid=fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870 
16 node0 2024-03-10T01:18:14.531430Z [httpworker.0] [txmempool.cpp:662] [check] [mempool] Checking mempool with 1 transactions and 1 inputs 
17 node0 2024-03-10T01:18:24.002988Z [msghand] [net.cpp:3755] [PushMessage] [net] sending inv (37 bytes) peer=1 
18 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)]) 
19 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)]) 
20 node0 2024-03-10T01:18:24.103797Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: getdata (37 bytes) peer=1 
21 node0 2024-03-10T01:18:24.103960Z [msghand] [net_processing.cpp:3990] [ProcessMessage] [net] received getdata (1 invsz) peer=1 
22 node0 2024-03-10T01:18:24.104051Z [msghand] [net_processing.cpp:3993] [ProcessMessage] [net] received getdata for: wtx fb50fb4c8bc48d4e4bbe91019fc90bef70c49fe214649eac375ff43e1edf6870 peer=1 
23 node0 2024-03-10T01:18:24.104242Z [msghand] [net.cpp:3755] [PushMessage] [net] sending tx (133 bytes) peer=1 
24 node0 2024-03-10T01:18:24.104524Z [msghand] [txmempool.cpp:1037] [RemoveUnbroadcastTx] [mempool] Removed 0668eb571427ae4ed5ee1f9d9d3d0c6de4261bba44335d033a75be0183d87a46 from set of unbroadcast txns 
25 test  2024-03-10T01:18:24.192000Z TestFramework (INFO): Re-request of tx_a after replacement is answered with notfound 
26 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)]) 
27 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)) 
28 node0 2024-03-10T01:18:24.211497Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: getdata (73 bytes) peer=1 
29 node0 2024-03-10T01:18:24.211811Z [msghand] [net_processing.cpp:3990] [ProcessMessage] [net] received getdata (2 invsz) peer=1 
30 node0 2024-03-10T01:18:24.212064Z [msghand] [net_processing.cpp:3993] [ProcessMessage] [net] received getdata for: tx d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a peer=1 
31 node0 2024-03-10T01:18:24.377046Z [msghand] [net.cpp:3755] [PushMessage] [net] sending notfound (73 bytes) peer=1 
32 test  2024-03-10T01:18:24.380000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000000) 
33 test  2024-03-10T01:18:24.394000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000003) 
34 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)]) 
35 node0 2024-03-10T01:18:24.396550Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
36 node0 2024-03-10T01:18:24.396727Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
37 node0 2024-03-10T01:18:24.397194Z [msghand] [net_processing.cpp:3388] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
38 node0 2024-03-10T01:18:24.397319Z [msghand] [net.cpp:3755] [PushMessage] [net] sending pong (8 bytes) peer=1 
39 test  2024-03-10T01:18:24.403000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000000) 
40 test  2024-03-10T01:18:24.408000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000003) 
41 test  2024-03-10T01:18:24.579000Z TestFramework (ERROR): Assertion failed 
42                                   Traceback (most recent call last):
43                                     File "/ci_container_base/ci/scratch/build/bitcoin-s390x-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
44                                       self.run_test()
45                                     File "/ci_container_base/ci/scratch/build/bitcoin-s390x-linux-gnu/test/functional/p2p_leak_tx.py", line 30, in run_test
46                                       self.test_notfound_on_replaced_tx()
47                                     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
48                                       assert "tx" not in inbound_peer.last_message
49                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
50                                   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:

02024-03-10T01:18:24.192000Z TestFramework (INFO): Re-request of tx_a after replacement is answered with notfound
12024-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)])
22024-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))
32024-03-10T01:18:24.380000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000000)
42024-03-10T01:18:24.394000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:12332: msg_ping(nonce=00000003)
52024-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)])
62024-03-10T01:18:24.403000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000000)
72024-03-10T01:18:24.408000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12332: msg_pong(nonce=00000003)
82024-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

0 test  2024-06-07T02:34:22.778000Z TestFramework (ERROR): Assertion failed 
1                                   Traceback (most recent call last):
2                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
3                                       self.run_test()
4                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p_leak_tx.py", line 30, in run_test
5                                       self.test_notfound_on_replaced_tx()
6                                     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
7                                       assert "tx" not in inbound_peer.last_message
8                                   AssertionError

fanquake closed this on Jul 31, 2024

fanquake referenced this in commit be969292db on Jul 31, 2024

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