p2p_filter intermittent failure (assert not filter_peer.tx

maflcko commented at 2:38 pm on May 13, 2022: member

https://cirrus-ci.com/task/5227425125629952?logs=ci#L3810

0 test  2022-05-13T10:12:44.237000Z TestFramework (ERROR): Assertion failed 
1                                   Traceback (most recent call last):
2                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 133, in main
3                                       self.run_test()
4                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_filter.py", line 224, in run_test
5                                       self.test_filter(filter_peer)
6                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_filter.py", line 204, in test_filter
7                                       assert not filter_peer.tx_received
8                                   AssertionError

Looks like a tx from a previous test is received, but I don’t see how this could happen:

0 test  2022-05-13T10:12:44.211000Z TestFramework (INFO): Check that request for filtered blocks is ignored if no filter is set 
1 test  2022-05-13T10:12:44.195000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:15536: msg_tx(tx=CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=f42858379b446cd7252015d8e86c6d7efc471f21869c1f205c44fd87bab1e9b2 n=0) scriptSig= nSequence=0)] vout=[CTxOut(nValue=42.99999000 scriptPubKey=51202913b252fe537830f843bfdc5fa7d20ba48639a87c86ff837b92d083c55ad7c1), CTxOut(nValue=7.00000000 scriptPubKey=0014ad24a8b5432802973418b25352d5606492c24e4d)] wit=CTxWitness(CScriptWitness(51,c00000000000000000000000000000000000000000000000000000000000000001)) nLockTime=0))... (msg truncated)

maflcko added the label Bug on May 13, 2022

maflcko added the label Tests on May 13, 2022

maflcko closed this on Sep 20, 2022

maflcko reopened this on Jan 4, 2023

maflcko commented at 11:25 am on January 4, 2023: member

Reproduced: https://drahtbot.space/temp_scratch/p2p_filter.tar.xz

0 test  2022-12-30T09:33:49.167000Z TestFramework (ERROR): Assertion failed 
1                                   Traceback (most recent call last):
2                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
3                                       self.run_test()
4                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_filter.py", line 240, in run_test
5                                       self.test_filter(filter_peer_without_nrelay)
6                                     File "/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_filter.py", line 204, in test_filter
7                                       assert not filter_peer.tx_received
8                                   AssertionError

maflcko commented at 12:06 pm on January 4, 2023: member

I still don’t understand how this can happen.

on_message takes the p2p_lock to update last_message and call on_msgtype under the same lock:

https://github.com/bitcoin/bitcoin/blob/2ec97825e70882262ee2b7d53dc1def788a60162/test/functional/test_framework/p2p.py#L377-L390

The wait should also take the p2p_lock internally: https://github.com/bitcoin/bitcoin/blob/2ec97825e70882262ee2b7d53dc1def788a60162/test/functional/p2p_filter.py#L194

The tx_received property is also guarded by the p2p_lock: https://github.com/bitcoin/bitcoin/blob/2ec97825e70882262ee2b7d53dc1def788a60162/test/functional/p2p_filter.py#L69-L80

As I fail to see how the lock is release in between, tx_received and last_message should be updated in one go. So the wait should only succeed if tx_received was also updated.

However, from the log it looks like the p2p_lock was intermittently released in the on_message function??

0 test  2022-12-30T09:33:48.464000Z TestFramework (INFO): Check that request for filtered blocks is ignored if no filter is set 
1 test  2022-12-30T09:33:48.288000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12488: msg_tx(tx=CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=17576cfafe2ea026d9ab00f6082fe7cc81caf31f5060a1872693f5bf73bf6b11 n=0) scriptSig= nSequence=0)] vout=[CTxOut(nValue=42.99999000 scriptPubKey=51202913b252fe537830f843bfdc5fa7d20ba48639a87c86ff837b92d083c55ad7c1), CTxOut(nValue=7.00000000 scriptPubKey=512009f79ded0947576f92dc6be2a39c6e083bf6d239574d9b0d47226c1813d52539)] wit=CTxWitness(CScriptWitness(51,c00000000000000000000000000000000000000000000000000000000000000001)) nLockTime=... (msg truncated)

maflcko commented at 2:12 pm on January 30, 2023: member

https://cirrus-ci.com/task/6016550344327168?logs=ci#L4478

maflcko commented at 10:22 am on December 4, 2023: member

Locally: https://drahtbot.space/temp_scratch/p2p_filter_2.tar.xz

maflcko commented at 10:40 am on December 4, 2023: member

However, from the log it looks like the p2p_lock was intermittently released in the on_message function??

0 test  2022-12-30T09:33:48.464000Z TestFramework (INFO): Check that request for filtered blocks is ignored if no filter is set 
1 test  2022-12-30T09:33:48.288000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12488: msg_tx(tx=CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=17576cfafe2ea026d9ab00f6082fe7cc81caf31f5060a1872693f5bf73bf6b11 n=0) scriptSig= nSequence=0)] vout=[CTxOut(nValue=42.99999000 scriptPubKey=51202913b252fe537830f843bfdc5fa7d20ba48639a87c86ff837b92d083c55ad7c1), CTxOut(nValue=7.00000000 scriptPubKey=512009f79ded0947576f92dc6be2a39c6e083bf6d239574d9b0d47226c1813d52539)] wit=CTxWitness(CScriptWitness(51,c00000000000000000000000000000000000000000000000000000000000000001)) nLockTime=... (msg truncated)

Moreover, the timing seems off??

48.46 (seconds) appears larger than 48.28 (seconds), so the log messages are in the wrong order?

maflcko added the label Upstream on Dec 4, 2023

maflcko added the label Brainstorming on Dec 4, 2023

maflcko added the label Linux/Unix on Dec 4, 2023

maflcko added the label CI failed on Jan 24, 2024

fanquake closed this on Jul 31, 2024

fanquake referenced this in commit be969292db on Jul 31, 2024

p2p_filter intermittent failure (assert not filter_peer.tx_received) #25128