test: timeouts in feature_init.py #23646

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

 node0 2021-12-01T19:22:13.787335Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 31922 bytes of dynamic environment data into RNG 
 node0 2021-12-01T19:23:13.801695Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 31928 bytes of dynamic environment data into RNG 
 test  2021-12-01T19:24:12.774000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     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
                                       ret = self.process.wait(timeout=self.rpc_timeout)
                                     File "/usr/lib/python3.8/subprocess.py", line 1083, in wait
                                       return self._wait(timeout=timeout)
                                     File "/usr/lib/python3.8/subprocess.py", line 1798, in _wait
                                       raise TimeoutExpired(self.args, timeout)
                                   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
                                   During handling of the above exception, another exception occurred:
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/feature_init.py", line 168, in run_test
                                       node.assert_start_raises_init_error(
                                     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
                                       self._raise_assertion_error(assert_msg)
                                     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
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 0] bitcoind should have exited within 2400s with expected error Error opening block database.

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.

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

 node0 2021-12-06T20:26:25.172715Z [net] [logging/timer.h:57] [Log] Enter: lock contention m_nodes_mutex, net.cpp:1310 started 
 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) 
 test  2021-12-06T20:26:26.580000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     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
                                       ret = self.process.wait(timeout=self.rpc_timeout)
                                     File "/usr/lib/python3.9/subprocess.py", line 1189, in wait
                                       return self._wait(timeout=timeout)
                                     File "/usr/lib/python3.9/subprocess.py", line 1909, in _wait
                                       raise TimeoutExpired(self.args, timeout)
                                   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
                                   During handling of the above exception, another exception occurred:
                                   Traceback (most recent call last):
                                     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
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_init.py", line 168, in run_test
                                       node.assert_start_raises_init_error(
                                     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
                                       self._raise_assertion_error(assert_msg)
                                     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
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 0] bitcoind should have exited within 2400s with expected error Error opening block database.

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

node0 2021-12-03T11:11:14.927999Z [init] [net.cpp:2589] [Start] DNS seeding disabled 
 node0 2021-12-03T11:11:14.928042Z [loadblk] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "loadblk" 
 node0 2021-12-03T11:11:14.928062Z [net] [util/thread.cpp:17] [TraceThread] net thread start 
 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 
 node0 2021-12-03T11:11:14.928117Z [loadblk] [util/thread.cpp:19] [TraceThread] loadblk thread exit 
 node0 2021-12-03T11:11:14.928128Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
 node0 2021-12-03T11:11:14.928148Z [msghand] [util/thread.cpp:17] [TraceThread] msghand thread start 
 node0 2021-12-03T11:11:14.928200Z [addcon] [util/thread.cpp:17] [TraceThread] addcon thread start 
 node0 2021-12-03T11:11:14.928254Z [net] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "net" 
 node0 2021-12-03T11:11:14.928288Z [msghand] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "msghand" 
 node0 2021-12-03T11:11:14.928311Z [init] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "init" 
 node0 2021-12-03T11:11:14.928604Z [addcon] [util/syscall_sandbox.cpp:918] [SetSyscallSandboxPolicy] Syscall filter installed for thread "addcon" 
 test  2021-12-03T11:11:24.777000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/home/james/src/bitcoin2/test/functional/test_framework/test_framework.py", line 132, in main
                                       self.run_test()
                                     File "./test/functional/feature_init.py", line 105, in run_test
                                       raise AssertionError(
                                   AssertionError: missed line net thread start; terminating now after 153 lines
 test  2021-12-03T11:11:24.778000Z TestFramework (DEBUG): Closing down network thread 
 test  2021-12-03T11:11:24.828000Z TestFramework (INFO): Stopping nodes 
 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.

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

Traceback (most recent call last):
  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>
    main()
  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
    print_logs_plain(log_events, colors)
  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
    print("{0} {1: <5} {2} {3}".format(colors[event.source.rstrip()], event.source, lines[0], colors["reset"]))
IndexError: list index out of range
177/226 - feature_init.py failed, Duration: 65 s
stdout:
2021-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
2021-12-09T14:27:20.347000Z TestFramework (INFO): Starting node and will exit after line 'scheduler thread start'
2021-12-09T14:27:20.395000Z TestFramework (INFO): Starting node and will exit after line 'Loading P2P addresses'
2021-12-09T14:27:43.196000Z TestFramework (INFO): Starting node and will exit after line 'Loading banlist'
2021-12-09T14:27:57.804000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  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
    self.run_test()
  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
    raise AssertionError(f"node failed to start (line: '{terminate_line}')")
AssertionError: node failed to start (line: 'Loading banlist')
2021-12-09T14:27:57.895000Z TestFramework (INFO): Stopping nodes
[node 0] Cleaning up leftover process
stderr:
Traceback (most recent call last):
  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>
    InitStressTest().main()
  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
    exit_code = self.shutdown()
  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
    self.stop_nodes()
  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
    node.stop_node(wait=wait, wait_until_stopped=False)
  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
    self.stop(wait=wait)
  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__
    assert self.rpc_connected and self.rpc is not None, self._node_msg("Error: no RPC connection")
AssertionError: [node 0] Error: no RPC connection

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

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

226/228 - feature_init.py failed, Duration: 84 s                                                                                                                                                                                                                                                                                                                           
                                                                                                                                                                                                                                                                                                                                                                           
stdout:                                                                                                                                                                                                                                                                                                                                                                    
2021-12-10T13:07:19.502000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20211210_140427/feature_init_38                                                                                                                                                                                                                                        
2021-12-10T13:07:20.225000Z TestFramework (INFO): Starting node and will exit after line 'scheduler thread start'                                                                                                                                                                                                                                                          
2021-12-10T13:07:20.230000Z TestFramework (INFO): Starting node and will exit after line 'Loading P2P addresses'                                                                                                                                                                                                                                                           
2021-12-10T13:07:20.697000Z TestFramework (INFO): Starting node and will exit after line 'Loading banlist'                                                                                                                                                                                                                                                                 
2021-12-10T13:07:21.106000Z TestFramework (INFO): Starting node and will exit after line 'Loading block index'                                                                                                                                                                                                                                                             
2021-12-10T13:07:21.588000Z TestFramework (INFO): Starting node and will exit after line 'Switching active chainstate'                                                                                                                                                                                                                                                     
2021-12-10T13:07:22.029000Z TestFramework (INFO): Starting node and will exit after line 'Loaded best chain:'                                                                                                                                                                                                                                                              
2021-12-10T13:07:22.445000Z TestFramework (INFO): Starting node and will exit after line 'init message: Verifying blocks'                                                                                                                                                                                                                                                  
2021-12-10T13:07:23.039000Z TestFramework (INFO): Starting node and will exit after line 'loadblk thread start'                                                                                                                                                                                                                                                            
2021-12-10T13:07:23.517000Z TestFramework (INFO): Starting node and will exit after line 'net thread start'                                                                                                                                                                                                                                                                
2021-12-10T13:07:24.045000Z TestFramework (INFO): Starting node and will exit after line 'addcon thread start'                                                                                                                                                                                                                                                             
2021-12-10T13:07:24.613000Z TestFramework (INFO): Starting node and will exit after line 'msghand thread start'                                                                                                                                                                                                                                                            
2021-12-10T13:07:25.081000Z TestFramework (INFO): Starting node and will exit after line 'Verifying wallet'                                                                                                                                                                                                                                                                
2021-12-10T13:07:26.177000Z TestFramework (INFO): Terminate at some random point in the init process (max logs: 145)                                                                                                                                                                                                                                                       
2021-12-10T13:07:43.749000Z TestFramework (INFO): Test startup errors after removing certain essential files                                                                                                                                                                                                                                                               
2021-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                                                                                                                                                                                              
2021-12-10T13:08:43.753000Z TestFramework (ERROR): Assertion failed                                                                                                                                                                                                                                                                                                        
Traceback (most recent call last):                                                                                                                                                                                                                                                                                                                                         
  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_node.py", line 512, in assert_start_raises_init_error                                                                                                                                                                                                                                          
    ret = self.process.wait(timeout=self.rpc_timeout)                                                                                                                                                                                                                                                                                                                      
  File "/usr/lib/python3.9/subprocess.py", line 1189, in wait                                                                                                                                                                                                                                                                                                              
    return self._wait(timeout=timeout)                                                                                                                                                                                                                                                                                                                                     
  File "/usr/lib/python3.9/subprocess.py", line 1909, in _wait                                                                                                                                                                                                                                                                                                             
    raise TimeoutExpired(self.args, timeout)                                                                                                                                                                                                                                                                                                                               
subprocess.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        
                                                                                                                                                                                                                                                                                                                                                                           
During handling of the above exception, another exception occurred:                                                                                                                                                                                                                                                                                                        
                                                                                                                                                                                                                                                                                                                                                                           
Traceback (most recent call last):                                                                                                                                                                                                                                                                                                                                         
  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main                                                                                                                                                                                                                                                               
    self.run_test()                                                                                                                                                                                                                                                                                                                                                        
  File "/home/darosior/projects/bitcoin/test/functional/feature_init.py", line 168, in run_test                                                                                                                                                                                                                                                                            
    node.assert_start_raises_init_error(                                                                                                                                                                                                                                                                                                                                   
  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_node.py", line 542, in assert_start_raises_init_error                                                                                                                                                                                                                                          
    self._raise_assertion_error(assert_msg)                                                                                                                                                                                                                                                                                                                                
  File "/home/darosior/projects/bitcoin/test/functional/test_framework/test_node.py", line 167, in _raise_assertion_error                                                                                                                                                                                                                                                  
    raise AssertionError(self._node_msg(msg))                                                                                                                                                                                                                                                                                                                              
AssertionError: [node 0] bitcoind should have exited within 60s with expected error Error opening block database.

feature_init_failure_testdir.tar.gz