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

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

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

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:

 node0 2023-02-14T20:07:56.675702Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=2
 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.

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

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

 test  2023-03-05T21:26:43.074000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
 node0 2023-03-05T21:26:43.265731Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
 node0 2023-03-05T21:26:43.267295Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 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 
 node0 2023-03-05T21:26:43.271568Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
 node0 2023-03-05T21:26:55.588032Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 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 
 node0 2023-03-05T21:26:55.731504Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=2 
 test  2023-03-05T21:27:43.097000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           test_function = lambda: self.is_connected
                                   '''
 test  2023-03-05T21:27:43.097000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     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
                                       self.run_test()
                                     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
                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
                                     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
                                       p2p_conn.wait_for_connect()
                                     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
                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
                                     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
                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
                                   AssertionError: Predicate ''''
                                           test_function = lambda: self.is_connected
                                   ''' not true after 60.0 seconds
 test  2023-03-05T21:27:43.102000Z TestFramework (DEBUG): Closing down network thread 
 test  2023-03-05T21:27:53.123000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
                                   '''
 node0 2023-03-05T21:28:08.198208Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=1 from eviction 
 node0 2023-03-05T21:28:08.201820Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=1 

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

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

#27208