Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

test: feature_index_prune.py timeout failure #29082

Closed
1 task done
LeoSpyke opened this issue Dec 14, 2023 · 3 comments
Closed
1 task done

test: feature_index_prune.py timeout failure #29082

LeoSpyke opened this issue Dec 14, 2023 · 3 comments
Labels
Tests

Comments

@LeoSpyke
Copy link

LeoSpyke commented Dec 14, 2023 •
edited

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
@LeoSpyke LeoSpyke changed the title test: feature_index_prune.py timeout failure test: feature_index_prune.py timeout failure Dec 14, 2023
@maflcko
Copy link
Member

maflcko commented Dec 14, 2023

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

@maflcko maflcko added the Tests label Dec 14, 2023
@LeoSpyke
Copy link
Author

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

@cbergqvist
Copy link
Contributor

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 (review)
Same issue on the base commit for that PR, also on 27.x and 26.x branches.

Output 
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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Tests
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@cbergqvist @maflcko @LeoSpyke