test: `feature_index_prune.py` timeout failure #29082

Is there an existing issue for this?

• I have searched the existing issues

Current behaviour

The test/functional/test_runner.py --extended --jobs=8 command raises an AssertionError: Block sync timed out after 60s when running the feature_index_prune.py suite.

Also tried with --jobs=4.

Very similar to #27091.

Expected behaviour

I expected the test to complete successfully.

Steps to reproduce

git clone https://github.com/bitcoin/bitcoin

# install dependencies listed here
# https://github.com/bitcoin/bitcoin/blob/master/doc/build-unix.md#ubuntu--debian

cd bitcoin && git checkout 44d8b13c81e5276eb610c99f227a4d090cc532f6 # v26.0
./autogen.sh
./configure --disable-bench --disable-fuzz-binary --enable-debug --without-gui --enable-suppress-external-warnings
make

Relevant log output

cat /tmp/test_runner_₿_🏃_20231214_201839/feature_index_prune_285/test_framework.log                                                         ─╯
2023-12-14T19:18:47.127000Z TestFramework (INFO): PRNG seed is: 4893185459191269752
2023-12-14T19:18:47.127000Z TestFramework (DEBUG): Setting up network thread
2023-12-14T19:18:47.147000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20231214_201839/feature_index_prune_285
2023-12-14T19:18:47.147000Z TestFramework (DEBUG): Copy cache directory /home/user/projects/bitcoin/test/cache/node0 to node 0
2023-12-14T19:18:47.189000Z TestFramework (DEBUG): Copy cache directory /home/user/projects/bitcoin/test/cache/node0 to node 1
2023-12-14T19:18:47.219000Z TestFramework (DEBUG): Copy cache directory /home/user/projects/bitcoin/test/cache/node0 to node 2
2023-12-14T19:18:47.243000Z TestFramework (DEBUG): Copy cache directory /home/user/projects/bitcoin/test/cache/node0 to node 3
2023-12-14T19:18:47.291000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
2023-12-14T19:18:47.297000Z TestFramework.node1 (DEBUG): bitcoind started, waiting for RPC to come up
2023-12-14T19:18:47.310000Z TestFramework.node2 (DEBUG): bitcoind started, waiting for RPC to come up
2023-12-14T19:18:47.319000Z TestFramework.node3 (DEBUG): bitcoind started, waiting for RPC to come up
2023-12-14T19:18:47.827000Z TestFramework.node0 (DEBUG): RPC successfully started
2023-12-14T19:18:47.841000Z TestFramework.node1 (DEBUG): RPC successfully started
2023-12-14T19:18:47.844000Z TestFramework.node2 (DEBUG): RPC successfully started
2023-12-14T19:18:47.846000Z TestFramework.node3 (DEBUG): RPC successfully started
2023-12-14T19:18:47.853000Z TestFramework (DEBUG): Generate a block with current time
2023-12-14T19:18:47.853000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2023-12-14T19:18:48.094000Z TestFramework (INFO): check if we can access blockfilters and coinstats when pruning is enabled but no blocks are actually pruned
2023-12-14T19:19:36.583000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2023-12-14T19:20:43.193000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/user/projects/bitcoin/test/functional/test_framework/test_framework.py", line 131, in main
    self.run_test()
  File "/home/user/projects/bitcoin/test/functional/feature_index_prune.py", line 68, in run_test
    self.mine_batches(500)
  File "/home/user/projects/bitcoin/test/functional/feature_index_prune.py", line 47, in mine_batches
    self.generate(self.nodes[0], 250)
  File "/home/user/projects/bitcoin/test/functional/test_framework/test_framework.py", line 682, in generate
    sync_fun() if sync_fun else self.sync_all()
                                ^^^^^^^^^^^^^^^
  File "/home/user/projects/bitcoin/test/functional/test_framework/test_framework.py", line 746, in sync_all
    self.sync_blocks(nodes)
  File "/home/user/projects/bitcoin/test/functional/test_framework/test_framework.py", line 717, in sync_blocks
    raise AssertionError("Block sync timed out after {}s:{}".format(
AssertionError: Block sync timed out after 60s:
  '0919fd3682761b020dc9fbfd43cf4fec5b8e78df3758d199db41f9c18c6a1e83'
  '792bbaa4494fba4f5dd4cba2ca1b3430bf66bd9688cb009ef5a417171705a50d'
  '2c0de27105a7e3027d2b09a740b67d4893c4bbb67beafc923a2b9275d8cb3475'
  '5016bee19325909a87fe6cfc5ec6d840ae439f1479bade4f72ffe234b9963fe0'
2023-12-14T19:20:43.200000Z TestFramework (DEBUG): Closing down network thread
2023-12-14T19:20:43.250000Z TestFramework (INFO): Stopping nodes
2023-12-14T19:20:43.251000Z TestFramework.node0 (DEBUG): Stopping node
2023-12-14T19:20:43.252000Z TestFramework.node1 (DEBUG): Stopping node
2023-12-14T19:20:43.253000Z TestFramework.node2 (DEBUG): Stopping node
2023-12-14T19:20:43.255000Z TestFramework.node3 (DEBUG): Stopping node
2023-12-14T19:20:43.457000Z TestFramework.node0 (DEBUG): Node stopped
2023-12-14T19:20:44.559000Z TestFramework.node1 (DEBUG): Node stopped
2023-12-14T19:20:44.559000Z TestFramework.node2 (DEBUG): Node stopped
2023-12-14T19:20:44.560000Z TestFramework.node3 (DEBUG): Node stopped
2023-12-14T19:20:44.560000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20231214_201839/feature_index_prune_285
2023-12-14T19:20:44.560000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20231214_201839/feature_index_prune_285/test_framework.log
2023-12-14T19:20:44.560000Z TestFramework (ERROR): 
2023-12-14T19:20:44.561000Z TestFramework (ERROR): Hint: Call /home/user/projects/bitcoin/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20231214_201839/feature_index_prune_285' to consolidate all logs
2023-12-14T19:20:44.561000Z TestFramework (ERROR): 
2023-12-14T19:20:44.561000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2023-12-14T19:20:44.561000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2023-12-14T19:20:44.561000Z TestFramework (ERROR):

How did you obtain Bitcoin Core

Compiled from source

What version of Bitcoin Core are you using?

v26.0

Operating system and version

Debian 12 (bookworm)

Machine specifications

• Intel i5-8250U 8-core
• 8GB RAM
• 512GB nVME PCI4.0
• 1Gbps LAN, 700Mbps WAN

Does it pass if you increase the timeout factor? See ./test/functional/test_runner.py --help | grep factor?

Setting --timeout-factor=2 did the trick. Thank you @maflcko.

I ran into errors with this test as well. Very similar output to #27091. Setting --timeout-factor=2 does do the trick.

Was testing here #29521#pullrequestreview-1968183010 Same issue on the base commit for that PR, also on 27.x and 26.x branches.

<details> <summary> Output </summary>

2/301 - feature_index_prune.py failed, Duration: 197 s

stdout:
2024-03-29T09:41:19.756000Z TestFramework (INFO): PRNG seed is: 4178992134959664795
2024-03-29T09:41:19.757000Z TestFramework (INFO): Initializing test directory /mnt/tmp/test_runner_₿_🏃_20240329_104112/feature_index_prune_298
2024-03-29T09:41:20.577000Z TestFramework (INFO): check if we can access blockfilters and coinstats when pruning is enabled but no blocks are actually pruned
2024-03-29T09:42:34.750000Z TestFramework (INFO): prune some blocks
2024-03-29T09:42:34.849000Z TestFramework (INFO): check if we can access the tips blockfilter and coinstats when we have pruned some blocks
2024-03-29T09:42:34.873000Z TestFramework (INFO): check if we can access the blockfilter and coinstats of a pruned block
2024-03-29T09:42:44.412000Z TestFramework (INFO): make sure trying to access the indices throws errors
2024-03-29T09:43:34.374000Z TestFramework (INFO): prune exactly up to the indices best blocks while the indices are disabled
2024-03-29T09:43:36.834000Z TestFramework (INFO): make sure that we can continue with the partially synced indices after having pruned up to the index height
2024-03-29T09:44:36.891000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        self.wait_until(lambda: self.nodes[1].getindexinfo() == expected_stats)
'''
2024-03-29T09:44:36.895000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/chris/Documents/Code/bitcoin-core/test/functional/test_framework/test_framework.py", line 132, in main
    self.run_test()
  File "/home/chris/Documents/Code/bitcoin-core/test/functional/feature_index_prune.py", line 117, in run_test
    self.sync_index(height=1500)
  File "/home/chris/Documents/Code/bitcoin-core/test/functional/feature_index_prune.py", line 34, in sync_index
    self.wait_until(lambda: self.nodes[1].getindexinfo() == expected_stats)
  File "/home/chris/Documents/Code/bitcoin-core/test/functional/test_framework/test_framework.py", line 780, in wait_until
    return wait_until_helper_internal(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/chris/Documents/Code/bitcoin-core/test/functional/test_framework/util.py", line 293, in wait_until_helper_internal
    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
AssertionError: Predicate ''''
        self.wait_until(lambda: self.nodes[1].getindexinfo() == expected_stats)
''' not true after 60 seconds
2024-03-29T09:44:36.948000Z TestFramework (INFO): Stopping nodes
2024-03-29T09:44:37.162000Z TestFramework (WARNING): Not cleaning up dir /mnt/tmp/test_runner_₿_🏃_20240329_104112/feature_index_prune_298
2024-03-29T09:44:37.162000Z TestFramework (ERROR): Test failed. Test logging available at /mnt/tmp/test_runner_₿_🏃_20240329_104112/feature_index_prune_298/test_framework.log
2024-03-29T09:44:37.162000Z TestFramework (ERROR): 
2024-03-29T09:44:37.162000Z TestFramework (ERROR): Hint: Call /home/chris/Documents/Code/bitcoin-core/test/functional/combine_logs.py '/mnt/tmp/test_runner_₿_🏃_20240329_104112/feature_index_prune_298' to consolidate all logs
2024-03-29T09:44:37.163000Z TestFramework (ERROR): 
2024-03-29T09:44:37.163000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2024-03-29T09:44:37.163000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2024-03-29T09:44:37.163000Z TestFramework (ERROR): 


stderr:


43/301 - wallet_listtransactions.py --descriptors passed, Duration: 27 s

</details>