p2p_permissions intermittent timeout #26852

issue maflcko openend this issue on January 9, 2023

maflcko commented at 1:14 pm on January 9, 2023: member

 0wget https://drahtbot.space/temp_scratch/p2p_permissions.tar.xz
 1tar -xvf p2p_permissions.tar.xz
 2test/functional/combine_logs.py -c ./p2p_permissions_15/ | tail -131 | head -33
 3 test  2023-01-09T13:02:23.385000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
 4                                               self.wait_until(lambda: txid in self.nodes[0].getrawmempool())
 5                                   '''
 6 test  2023-01-09T13:02:23.386000Z TestFramework (ERROR): Assertion failed 
 7                                   Traceback (most recent call last):
 8                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
 9                                       self.run_test()
10                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_permissions.py", line 34, in run_test
11                                       self.check_tx_relay()
12                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_permissions.py", line 128, in check_tx_relay
13                                       self.wait_until(lambda: txid in self.nodes[0].getrawmempool())
14                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 732, in wait_until
15                                       return wait_until_helper(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor)
16                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 281, in wait_until_helper
17                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
18                                   AssertionError: Predicate ''''
19                                               self.wait_until(lambda: txid in self.nodes[0].getrawmempool())
20                                   ''' not true after 2400.0 seconds

maflcko added the label Bug on Jan 9, 2023

maflcko commented at 2:13 pm on January 9, 2023: member

Excerpt from when the bug occurs:

 0...
 1 test  2023-01-09T12:22:23.228000Z TestFramework (DEBUG): Check that node[1] will send the tx to node[0] even though it is already in the mempool
 2 node1 2023-01-09T12:22:23.228783Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
 3 node1 2023-01-09T12:22:23.228986Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 4 node0 2023-01-09T12:22:23.231535Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40640
 5 node0 2023-01-09T12:22:23.231734Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 6 node1 2023-01-09T12:22:23.233267Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
 7 node1 2023-01-09T12:22:23.233445Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__
 8 node1 2023-01-09T12:22:23.233642Z [httpworker.1] [net.cpp:456] [ConnectNode] [net:debug] trying connection 127.0.0.1:11180 lastseen=0.0hrs
 9 node1 2023-01-09T12:22:23.234022Z [httpworker.1] [net.cpp:2763] [CNode] [net] Added connection peer=1
10 node0 2023-01-09T12:22:23.234192Z [net] [net.cpp:2763] [CNode] [net] Added connection peer=1
11 node1 2023-01-09T12:22:23.234279Z [httpworker.1] [net.cpp:2776] [PushMessage] [net] sending version (114 bytes) peer=1
12 node0 2023-01-09T12:22:23.234381Z [net] [net.cpp:1037] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:42510 accepted
13 node1 2023-01-09T12:22:23.234458Z [httpworker.1] [net_processing.cpp:1396] [PushNodeVersion] [net] send version message: version 70016, blocks=100, txrelay=1, peer=1
14 node0 2023-01-09T12:22:23.234721Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: version (114 bytes) peer=1
15 node0 2023-01-09T12:22:23.234817Z [msghand] [net.cpp:2776] [PushMessage] [net] sending version (114 bytes) peer=1
16 node0 2023-01-09T12:22:23.234991Z [msghand] [net_processing.cpp:1396] [PushNodeVersion] [net] send version message: version 70016, blocks=100, txrelay=1, peer=1
17 node1 2023-01-09T12:22:23.235034Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
18 node0 2023-01-09T12:22:23.235044Z [msghand] [net.cpp:2776] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1
19 node0 2023-01-09T12:22:23.235153Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1
20 node1 2023-01-09T12:22:23.235220Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
21 node0 2023-01-09T12:22:23.237171Z [msghand] [net.cpp:2776] [PushMessage] [net] sending verack (0 bytes) peer=1
22 node0 2023-01-09T12:22:23.237312Z [msghand] [net_processing.cpp:3352] [ProcessMessage] [net] receive version message: /Satoshi:24.99.0(testnode1)/: version 70016, blocks=100, us=[::]:0, txrelay=1, peer=1
23 node1 2023-01-09T12:22:23.277409Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: version (114 bytes) peer=1
24 node1 2023-01-09T12:22:23.277514Z [msghand] [net.cpp:2776] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1
25 node1 2023-01-09T12:22:23.277691Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1
26 node0 2023-01-09T12:22:23.278071Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1
27 node0 2023-01-09T12:22:23.278225Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: sendaddrv2 (0 bytes) peer=1
28 node1 2023-01-09T12:22:23.279894Z [msghand] [net.cpp:2776] [PushMessage] [net] sending verack (0 bytes) peer=1
29 node1 2023-01-09T12:22:23.288745Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
30 node1 2023-01-09T12:22:23.288981Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
31 node1 2023-01-09T12:22:23.292375Z [msghand] [net.cpp:2776] [PushMessage] [net] sending getaddr (0 bytes) peer=1
32 node0 2023-01-09T12:22:23.292524Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: verack (0 bytes) peer=1
33 node1 2023-01-09T12:22:23.292533Z [msghand] [net_processing.cpp:3352] [ProcessMessage] [net] receive version message: /Satoshi:24.99.0(testnode0)/: version 70016, blocks=100, us=[::]:0, txrelay=1, peer=1
34 node0 2023-01-09T12:22:23.292608Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1
35 node1 2023-01-09T12:22:23.292609Z [msghand] [timedata.cpp:57] [AddTimeData] [net] added time data, samples 2, offset +0 (+0 minutes)
36 node0 2023-01-09T12:22:23.292856Z [msghand] [net.cpp:2776] [PushMessage] [net] sending ping (8 bytes) peer=1
37 node0 2023-01-09T12:22:23.293028Z [msghand] [net.cpp:2776] [PushMessage] [net] sending getheaders (613 bytes) peer=1
38 node0 2023-01-09T12:22:23.293179Z [msghand] [net_processing.cpp:5416] [SendMessages] [net] initial getheaders (99) to peer=1 (startheight:100)
39 node0 2023-01-09T12:22:23.293354Z [msghand] [net.cpp:2776] [PushMessage] [net] sending feefilter (8 bytes) peer=1
40 node0 2023-01-09T12:22:23.293634Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: getaddr (0 bytes) peer=1
41 node0 2023-01-09T12:22:23.294846Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40640
42 node0 2023-01-09T12:22:23.295037Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
43 node1 2023-01-09T12:22:23.297221Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
44 node1 2023-01-09T12:22:23.297634Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
45 node1 2023-01-09T12:22:23.298425Z [httpworker.0] [logging/timer.h:57] [Log] [lock] Enter: lock contention m_peer_mutex, net_processing.cpp:1537 started
46 node1 2023-01-09T12:22:23.298514Z [httpworker.0] [logging/timer.h:57] [Log] [lock] Enter: lock contention m_peer_mutex, net_processing.cpp:1537 completed (27μs)
47 node0 2023-01-09T12:22:23.300825Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40640
48 node0 2023-01-09T12:22:23.300993Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
49 test  2023-01-09T12:22:23.303000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11181: msg_tx(tx=CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=d925626975d73bd782c38ce1eed34aed6eee030680271e7982197873289c747f n=0) scriptSig= nSequence=4294967295)] vout=[CTxOut(nValue=5.00000000 scriptPubKey=00204ae81572f06e1b88fd5ced7a1a000945432e83e1551e6f721ee9c00b8cc33260)] wit=CTxWitness(CScriptWitness(51)) nLockTime=0))
50 test  2023-01-09T12:22:23.303000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11181: msg_ping(nonce=00000003)
51 node1 2023-01-09T12:22:23.303821Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: tx (99 bytes) peer=0
52 test  2023-01-09T12:22:23.304000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:11181: msg_pong(nonce=00000003)
53 node1 2023-01-09T12:22:23.304012Z [msghand] [net_processing.cpp:4020] [ProcessMessage] Force relaying tx 15d85d00f224f10cecaa12a6eba4994045f2abbe0f929e1c16bba06cfc0ddc39 from peer=0
54 node1 2023-01-09T12:22:23.304267Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1
55 node1 2023-01-09T12:22:23.304402Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: sendaddrv2 (0 bytes) peer=1
56 node1 2023-01-09T12:22:23.304502Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: ping (8 bytes) peer=0
57 node1 2023-01-09T12:22:23.304562Z [msghand] [net.cpp:2776] [PushMessage] [net] sending pong (8 bytes) peer=0
58 node1 2023-01-09T12:22:23.305109Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: verack (0 bytes) peer=1
59 node1 2023-01-09T12:22:23.305702Z [msghand] [net_processing.cpp:3395] [ProcessMessage] New outbound peer connected: version: 70016, blocks=100, peer=1 (manual)
60 node1 2023-01-09T12:22:23.305759Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1
61 node1 2023-01-09T12:22:23.305930Z [msghand] [net.cpp:2776] [PushMessage] [net] sending ping (8 bytes) peer=1
62...

maflcko closed this on Jan 12, 2023
bitcoin locked this on Jan 12, 2024

Contributors
maflcko

Labels
Bug