test: timeouts in feature_init.py #23646

issue fanquake openend this issue on December 2, 2021

fanquake commented at 1:17 am on December 2, 2021: member

Seen this multiple times this on master: https://cirrus-ci.com/task/5568647696482304?logs=ci#L4671 https://cirrus-ci.com/task/5005697743060992?logs=ci#L4821 https://cirrus-ci.com/task/4507850702585856?logs=ci#L4968

 0 node0 2021-12-01T19:22:13.787335Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 31922 bytes of dynamic environment data into RNG 
 1 node0 2021-12-01T19:23:13.801695Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 31928 bytes of dynamic environment data into RNG 
 2 test  2021-12-01T19:24:12.774000Z TestFramework (ERROR): Assertion failed 
 3                                   Traceback (most recent call last):
 4                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 512, in assert_start_raises_init_error
 5                                       ret = self.process.wait(timeout=self.rpc_timeout)
 6                                     File "/usr/lib/python3.8/subprocess.py", line 1083, in wait
 7                                       return self._wait(timeout=timeout)
 8                                     File "/usr/lib/python3.8/subprocess.py", line 1798, in _wait
 9                                       raise TimeoutExpired(self.args, timeout)
10                                   subprocess.TimeoutExpired: Command '['bitcoin-node', '-datadir=/tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner_₿_🏃_20211201_182901/feature_init_38/node0', '-logtimemicros', '-debug', '-debugexclude=libevent', '-debugexclude=leveldb', '-uacomment=testnode0', '-logthreadnames', '-logsourcelocations']' timed out after 2400 seconds
11                                   During handling of the above exception, another exception occurred:
12                                   Traceback (most recent call last):
13                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
14                                       self.run_test()
15                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/feature_init.py", line 168, in run_test
16                                       node.assert_start_raises_init_error(
17                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 542, in assert_start_raises_init_error
18                                       self._raise_assertion_error(assert_msg)
19                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 167, in _raise_assertion_error
20                                       raise AssertionError(self._node_msg(msg))
21                                   AssertionError: [node 0] bitcoind should have exited within 2400s with expected error Error opening block database.

fanquake added the label Tests on Dec 2, 2021
jamesob commented at 8:45 pm on December 2, 2021: member

I’ll try to reproduce locally in the next few hours.

For background, the bit of the test that is failing removes various chainstate/blockindex .ldb files and then ensures that startup fails.

I can’t offhand think of why this would timeout sporadically other than if the mechanism for polling the logfile somehow misses updates occasionally. But that it’s only happening on this particular part of the test is curious.

fanquake commented at 1:00 am on December 7, 2021: member

Seen again in #23686: https://cirrus-ci.com/task/6221467223326720?logs=ci#L3975:

 0 node0 2021-12-06T20:26:25.172715Z [net] [logging/timer.h:57] [Log] Enter: lock contention m_nodes_mutex, net.cpp:1310 started 
 1 node0 2021-12-06T20:26:25.172854Z [net] [logging/timer.h:57] [Log] Enter: lock contention m_nodes_mutex, net.cpp:1310 completed (17μs) 
 2 test  2021-12-06T20:26:26.580000Z TestFramework (ERROR): Assertion failed 
 3                                   Traceback (most recent call last):
 4                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 512, in assert_start_raises_init_error
 5                                       ret = self.process.wait(timeout=self.rpc_timeout)
 6                                     File "/usr/lib/python3.9/subprocess.py", line 1189, in wait
 7                                       return self._wait(timeout=timeout)
 8                                     File "/usr/lib/python3.9/subprocess.py", line 1909, in _wait
 9                                       raise TimeoutExpired(self.args, timeout)
10                                   subprocess.TimeoutExpired: Command '['/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/src/bitcoind', '-datadir=/tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner_₿_🏃_20211206_193347/feature_init_38/node0', '-logtimemicros', '-debug', '-debugexclude=libevent', '-debugexclude=leveldb', '-uacomment=testnode0', '-logthreadnames', '-logsourcelocations']' timed out after 2400 seconds
11                                   During handling of the above exception, another exception occurred:
12                                   Traceback (most recent call last):
13                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
14                                       self.run_test()
15                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_init.py", line 168, in run_test
16                                       node.assert_start_raises_init_error(
17                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 542, in assert_start_raises_init_error
18                                       self._raise_assertion_error(assert_msg)
19                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 167, in _raise_assertion_error
20                                       raise AssertionError(self._node_msg(msg))
21                                   AssertionError: [node 0] bitcoind should have exited within 2400s with expected error Error opening block database.

jamesob commented at 1:11 am on December 7, 2021: member

After a bunch of rerunning, was able to reproduce a separate failure locally, but not the one related to removing ldb files:

 0node0 2021-12-03T11:11:14.927999Z [init] [net.cpp:2589] [Start] DNS seeding disabled 
 1 node0 2021-12-03T11:11:14.928042Z [loadblk] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "loadblk" 
 2 node0 2021-12-03T11:11:14.928062Z [net] [util/thread.cpp:17] [TraceThread] net thread start 
 3 node0 2021-12-03T11:11:14.928102Z [loadblk] [validation.cpp:4615] [LoadMempool] Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast 
 4 node0 2021-12-03T11:11:14.928117Z [loadblk] [util/thread.cpp:19] [TraceThread] loadblk thread exit 
 5 node0 2021-12-03T11:11:14.928128Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
 6 node0 2021-12-03T11:11:14.928148Z [msghand] [util/thread.cpp:17] [TraceThread] msghand thread start 
 7 node0 2021-12-03T11:11:14.928200Z [addcon] [util/thread.cpp:17] [TraceThread] addcon thread start 
 8 node0 2021-12-03T11:11:14.928254Z [net] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "net" 
 9 node0 2021-12-03T11:11:14.928288Z [msghand] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "msghand" 
10 node0 2021-12-03T11:11:14.928311Z [init] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "init" 
11 node0 2021-12-03T11:11:14.928604Z [addcon] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "addcon" 
12 test  2021-12-03T11:11:24.777000Z TestFramework (ERROR): Assertion failed 
13                                   Traceback (most recent call last):
14                                     File "/home/james/src/bitcoin2/test/functional/test_framework/test_framework.py", line 132, in main
15                                       self.run_test()
16                                     File "./test/functional/feature_init.py", line 105, in run_test
17                                       raise AssertionError(
18                                   AssertionError: missed line net thread start; terminating now after 153 lines
19 test  2021-12-03T11:11:24.778000Z TestFramework (DEBUG): Closing down network thread 
20 test  2021-12-03T11:11:24.828000Z TestFramework (INFO): Stopping nodes 
21 test  2021-12-03T11:11:24.829000Z TestFramework.node0 (DEBUG): Stopping node

Note that the line that the test thinks it missed is clearly in the logs.

MarcoFalke commented at 11:53 am on December 10, 2021: member

I am running into another issue in the test, but it can’t be debugged because the debug log was deleted:

 0Traceback (most recent call last):
 1  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/combine_logs.py", line 201, in <module>
 2    main()
 3  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/combine_logs.py", line 72, in main
 4    print_logs_plain(log_events, colors)
 5  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/combine_logs.py", line 182, in print_logs_plain
 6    print("{0} {1: <5} {2} {3}".format(colors[event.source.rstrip()], event.source, lines[0], colors["reset"]))
 7IndexError: list index out of range
 8177/226 - feature_init.py failed, Duration: 65 s
 9stdout:
102021-12-09T14:26:52.717000Z TestFramework (INFO): Initializing test directory /tmp/cirrus-ci-build/bitcoin-core/ci/scratch/test_runner/test_runner_₿_🏃_20211209_132901/feature_init_39
112021-12-09T14:27:20.347000Z TestFramework (INFO): Starting node and will exit after line 'scheduler thread start'
122021-12-09T14:27:20.395000Z TestFramework (INFO): Starting node and will exit after line 'Loading P2P addresses'
132021-12-09T14:27:43.196000Z TestFramework (INFO): Starting node and will exit after line 'Loading banlist'
142021-12-09T14:27:57.804000Z TestFramework (ERROR): Assertion failed
15Traceback (most recent call last):
16  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
17    self.run_test()
18  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_init.py", line 104, in run_test
19    raise AssertionError(f"node failed to start (line: '{terminate_line}')")
20AssertionError: node failed to start (line: 'Loading banlist')
212021-12-09T14:27:57.895000Z TestFramework (INFO): Stopping nodes
22[node 0] Cleaning up leftover process
23stderr:
24Traceback (most recent call last):
25  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_init.py", line 182, in <module>
26    InitStressTest().main()
27  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 155, in main
28    exit_code = self.shutdown()
29  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 304, in shutdown
30    self.stop_nodes()
31  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 555, in stop_nodes
32    node.stop_node(wait=wait, wait_until_stopped=False)
33  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 336, in stop_node
34    self.stop(wait=wait)
35  File "/tmp/cirrus-ci-build/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 184, in __getattr__
36    assert self.rpc_connected and self.rpc is not None, self._node_msg("Error: no RPC connection")
37AssertionError: [node 0] Error: no RPC connection

MarcoFalke commented at 11:53 am on December 10, 2021: member

I think as a first step we should stop deleting the logs: #23289 (review)

darosior commented at 1:15 pm on December 10, 2021: member

Here is a datadir of a feature_init failure, if that can help (don’t have time to debug it at the moment).

 0226/228 - feature_init.py failed, Duration: 84 s                                                                                                                                                                                                                                                                                                                           
 1                                                                                                                                                                                                                                                                                                                                                                           
 2stdout:                                                                                                                                                                                                                                                                                                                                                                    
 32021-12-10T13:07:19.502000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20211210_140427/feature_init_38                                                                                                                                                                                                                                        
 42021-12-10T13:07:20.225000Z TestFramework (INFO): Starting node and will exit after line 'scheduler thread start'                                                                                                                                                                                                                                                          
 52021-12-10T13:07:20.230000Z TestFramework (INFO): Starting node and will exit after line 'Loading P2P addresses'                                                                                                                                                                                                                                                           
 62021-12-10T13:07:20.697000Z TestFramework (INFO): Starting node and will exit after line 'Loading banlist'                                                                                                                                                                                                                                                                 
 72021-12-10T13:07:21.106000Z TestFramework (INFO): Starting node and will exit after line 'Loading block index'                                                                                                                                                                                                                                                             
 82021-12-10T13:07:21.588000Z TestFramework (INFO): Starting node and will exit after line 'Switching active chainstate'                                                                                                                                                                                                                                                     
 92021-12-10T13:07:22.029000Z TestFramework (INFO): Starting node and will exit after line 'Loaded best chain:'                                                                                                                                                                                                                                                              
102021-12-10T13:07:22.445000Z TestFramework (INFO): Starting node and will exit after line 'init message: Verifying blocks'                                                                                                                                                                                                                                                  
112021-12-10T13:07:23.039000Z TestFramework (INFO): Starting node and will exit after line 'loadblk thread start'                                                                                                                                                                                                                                                            
122021-12-10T13:07:23.517000Z TestFramework (INFO): Starting node and will exit after line 'net thread start'                                                                                                                                                                                                                                                                
132021-12-10T13:07:24.045000Z TestFramework (INFO): Starting node and will exit after line 'addcon thread start'                                                                                                                                                                                                                                                             
142021-12-10T13:07:24.613000Z TestFramework (INFO): Starting node and will exit after line 'msghand thread start'                                                                                                                                                                                                                                                            
152021-12-10T13:07:25.081000Z TestFramework (INFO): Starting node and will exit after line 'Verifying wallet'                                                                                                                                                                                                                                                                
162021-12-10T13:07:26.177000Z TestFramework (INFO): Terminate at some random point in the init process (max logs: 145)                                                                                                                                                                                                                                                       
172021-12-10T13:07:43.749000Z TestFramework (INFO): Test startup errors after removing certain essential files                                                                                                                                                                                                                                                               
182021-12-10T13:07:43.749000Z TestFramework (INFO): Tweaking file to ensure failure /tmp/test_runner_₿_🏃_20211210_140427/feature_init_38/node0/regtest/blocks/index/000074.ldb                                                                                                                                                                                              
192021-12-10T13:08:43.753000Z TestFramework (ERROR): Assertion failed                                                                                                                                                                                                                                                                                                        
20Traceback (most recent call last):                                                                                                                                                                                                                                                                                                                                         
21  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_node.py", line 512, in assert_start_raises_init_error                                                                                                                                                                                                                                          
22    ret = self.process.wait(timeout=self.rpc_timeout)                                                                                                                                                                                                                                                                                                                      
23  File "/usr/lib/python3.9/subprocess.py", line 1189, in wait                                                                                                                                                                                                                                                                                                              
24    return self._wait(timeout=timeout)                                                                                                                                                                                                                                                                                                                                     
25  File "/usr/lib/python3.9/subprocess.py", line 1909, in _wait                                                                                                                                                                                                                                                                                                             
26    raise TimeoutExpired(self.args, timeout)                                                                                                                                                                                                                                                                                                                               
27subprocess.TimeoutExpired: Command '['/home/darosior/projects/bitcoin/src/bitcoind', '-datadir=/tmp/test_runner_₿_🏃_20211210_140427/feature_init_38/node0', '-logtimemicros', '-debug', '-debugexclude=libevent', '-debugexclude=leveldb', '-uacomment=testnode0', '-logthreadnames', '-logsourcelocations', '-sandbox=log-and-abort']' timed out after 60 seconds        
28                                                                                                                                                                                                                                                                                                                                                                           
29During handling of the above exception, another exception occurred:                                                                                                                                                                                                                                                                                                        
30                                                                                                                                                                                                                                                                                                                                                                           
31Traceback (most recent call last):                                                                                                                                                                                                                                                                                                                                         
32  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main                                                                                                                                                                                                                                                               
33    self.run_test()                                                                                                                                                                                                                                                                                                                                                        
34  File "/home/darosior/projects/bitcoin/test/functional/feature_init.py", line 168, in run_test                                                                                                                                                                                                                                                                            
35    node.assert_start_raises_init_error(                                                                                                                                                                                                                                                                                                                                   
36  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_node.py", line 542, in assert_start_raises_init_error                                                                                                                                                                                                                                          
37    self._raise_assertion_error(assert_msg)                                                                                                                                                                                                                                                                                                                                
38  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_node.py", line 167, in _raise_assertion_error                                                                                                                                                                                                                                                  
39    raise AssertionError(self._node_msg(msg))                                                                                                                                                                                                                                                                                                                              
40AssertionError: [node 0] bitcoind should have exited within 60s with expected error Error opening block database.

feature_init_failure_testdir.tar.gz

MarcoFalke referenced this in commit d69af93223 on Jan 3, 2022
MarcoFalke closed this on Jan 3, 2022
DrahtBot locked this on Jan 3, 2023

Contributors
fanquake jamesob MarcoFalke darosior

Labels
Tests