Intermittent issue in p2p_ibd_stalling.py self.wait_until(lambda: self.total_bytes_recv_for

maflcko commented at 4:41 pm on February 16, 2023: member

0wget https://drahtbot.space/temp_scratch/p2p_ibd_stalling_96.tar.xz
1tar -xvf p2p_ibd_stalling_96.tar.xz
2test/functional/combine_logs.py -c  ./p2p_ibd_stalling_96

 0 test  2023-02-14T20:54:45.479000Z TestFramework (ERROR): Assertion failed 
 1                                   Traceback (most recent call last):
 2                                     File "/root/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 "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 83, in run_test
 5                                       self.wait_until(lambda: self.total_bytes_recv_for_blocks() == 172761)
 6                                     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
 7                                       return wait_until_helper(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor)
 8                                     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
 9                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
10                                   AssertionError: Predicate ''''
11                                           self.wait_until(lambda: self.total_bytes_recv_for_blocks() == 172761)
12                                   ''' not true after 2400.0 seconds

maflcko added the label Bug on Feb 16, 2023

maflcko added the label Tests on Feb 16, 2023

mzumsande commented at 5:45 am on February 25, 2023: contributor

The reason for the test failure is that peer 0 gets disconnected because of headers sync timeout after >25 minutes runtime, ruining the test, which should be much faster under normal conditions. node0 2023-02-14T20:26:20.075032Z [msghand] [net_processing.cpp:5768] [SendMessages] Timeout downloading headers from peer=0, disconnecting

It looks to me like something strange is going on in the test environment - the test node appears to “freeze” multiple times for no apparent reason, with nothing happening in the log, like here for almost 7 minutes:

0 node0 2023-02-14T20:07:56.675702Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=2
1 node0 2023-02-14T20:14:33.853767Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=2 from eviction

Not sure if it’s worth to harden the functional tests against these kind of shenanigans.

maflcko commented at 10:51 am on February 27, 2023: member

Ok, thank you. It was running all tests in parallel in valgrind, which may explain why things went slow.

maflcko closed this on Feb 27, 2023

maflcko removed the label Bug on Feb 27, 2023

maflcko added the label Questions and Help on Feb 27, 2023

fanquake commented at 9:49 pm on March 5, 2023: member

I’ve also just had p2p_ibd_stalling.py fail under Valgrind (40c6c85c05812ee8bf824b639307b1ac17a001c4):

 0 test  2023-03-05T21:26:43.074000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
 1 node0 2023-03-05T21:26:43.265731Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
 2 node0 2023-03-05T21:26:43.267295Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 3 node0 2023-03-05T21:26:43.269862Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40916 
 4 node0 2023-03-05T21:26:43.271568Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
 5 node0 2023-03-05T21:26:55.588032Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 6 node0 2023-03-05T21:26:55.709062Z [httpworker.0] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12173 lastseen=0.0hrs 
 7 node0 2023-03-05T21:26:55.731504Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=2 
 8 test  2023-03-05T21:27:43.097000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
 9                                           test_function = lambda: self.is_connected
10                                   '''
11 test  2023-03-05T21:27:43.097000Z TestFramework (ERROR): Assertion failed 
12                                   Traceback (most recent call last):
13                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
14                                       self.run_test()
15                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 77, in run_test
16                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
17                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 663, in add_outbound_p2p_connection
18                                       p2p_conn.wait_for_connect()
19                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 467, in wait_for_connect
20                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
21                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 281, in wait_until_helper
22                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
23                                   AssertionError: Predicate ''''
24                                           test_function = lambda: self.is_connected
25                                   ''' not true after 60.0 seconds
26 test  2023-03-05T21:27:43.102000Z TestFramework (DEBUG): Closing down network thread 
27 test  2023-03-05T21:27:53.123000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
28                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
29                                   '''
30 node0 2023-03-05T21:28:08.198208Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=1 from eviction 
31 node0 2023-03-05T21:28:08.201820Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=1

maflcko commented at 9:16 am on March 6, 2023: member

Looks like a different issue, so maybe open a new one? Also, we should probably increase the default timeout when --valgrind

fanquake commented at 9:30 am on March 6, 2023: member

Looks like a different issue, so maybe open a new one?

#27208

fanquake referenced this in commit f088949fcf on Mar 13, 2023

sidhujag referenced this in commit 58324bbc35 on Mar 13, 2023

sidhujag referenced this in commit 85f1a41dbd on Mar 15, 2023

bitcoin locked this on Mar 5, 2024

Intermittent issue in p2p_ibd_stalling.py self.wait_until(lambda: self.total_bytes_recv_for_blocks() == 172761) #27112