49c0b8b228 test: Bump timeouts in feature_index_prune and wallet_importdescriptors (Christopher Bergqvist)
Pull request description:
Timeout issues where encountered when running functional tests with `--jobs=16 --extended`.
Note that running `--extended` without `--jobs=16` does not trigger the issues.
Tested under NixOS on a Xeon CPU with 16 logical cores.
(A few tests are skipped locally as I haven't enabled BPF and a few other things).
## Measurements
Line in `feature_index_prune.py` took 101.6s, 96.6s, 103.0s across 3 runs on my machine.
Default limit is 60, suggested to increase limit to 150 seconds.
Line in the `wallet_importdescriptors.py --descriptors` took 5.4s, 5.7s, 6.0s across 3 runs.
Suggested to increase from 5 to 10 seconds.
## Logs
Output slightly modified by separate change that lets code run past given timeouts and the provides more information - "Took 101.6 seconds to complete, 69.4% over the given limit.".
<details>
<summary>
Click to expand.
</summary>
### feature_index_prune.py
```
52/305 - feature_index_prune.py failed, Duration: 250 s
stdout:
2024-04-01T22:25:24.010000Z TestFramework (INFO): PRNG seed is: 990421162716295219
2024-04-01T22:25:24.014000Z TestFramework (INFO): Initializing test directory /mnt/tmp/test_runner_₿_🏃_20240402_002516/feature_index_prune_302
2024-04-01T22:25:24.913000Z TestFramework (INFO): check if we can access blockfilters and coinstats when pruning is enabled but no blocks are actually pruned
2024-04-01T22:26:48.417000Z TestFramework (INFO): prune some blocks
2024-04-01T22:26:48.460000Z TestFramework (INFO): check if we can access the tips blockfilter and coinstats when we have pruned some blocks
2024-04-01T22:26:48.483000Z TestFramework (INFO): check if we can access the blockfilter and coinstats of a pruned block
2024-04-01T22:26:59.175000Z TestFramework (INFO): make sure trying to access the indices throws errors
2024-04-01T22:27:50.422000Z TestFramework (INFO): prune exactly up to the indices best blocks while the indices are disabled
2024-04-01T22:27:52.596000Z TestFramework (INFO): make sure that we can continue with the partially synced indices after having pruned up to the index height
2024-04-01T22:29:34.242000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''
self.wait_until(lambda: self.nodes[1].getindexinfo() == expected_stats)#, timeout=150)
'''
2024-04-01T22:29:34.244000Z 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)#, timeout=150)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
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 305, in wait_until_helper_internal
raise AssertionError(m)
AssertionError: Predicate '''
self.wait_until(lambda: self.nodes[1].getindexinfo() == expected_stats)#, timeout=150)
''' not true after 60 seconds. Took 101.6 seconds to complete, 69.4% over the given limit.
2024-04-01T22:29:34.298000Z TestFramework (INFO): Stopping nodes
2024-04-01T22:29:34.511000Z TestFramework (WARNING): Not cleaning up dir /mnt/tmp/test_runner_₿_🏃_20240402_002516/feature_index_prune_302
2024-04-01T22:29:34.511000Z TestFramework (ERROR): Test failed. Test logging available at /mnt/tmp/test_runner_₿_🏃_20240402_002516/feature_index_prune_302/test_framework.log
2024-04-01T22:29:34.511000Z TestFramework (ERROR):
2024-04-01T22:29:34.512000Z TestFramework (ERROR): Hint: Call /home/chris/Documents/Code/bitcoin-core/test/functional/combine_logs.py '/mnt/tmp/test_runner_₿_🏃_20240402_002516/feature_index_prune_302' to consolidate all logs
2024-04-01T22:29:34.512000Z TestFramework (ERROR):
2024-04-01T22:29:34.512000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2024-04-01T22:29:34.512000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2024-04-01T22:29:34.512000Z TestFramework (ERROR):
stderr:
53/305 - p2p_blockfilters.py passed, Duration: 130 s
```
### wallet_importdescriptors.py --descriptors
```
297/305 - wallet_importdescriptors.py --descriptors failed, Duration: 76 s
stdout:
2024-04-01T22:48:27.663000Z TestFramework (INFO): PRNG seed is: 8528678505617325332
2024-04-01T22:48:27.664000Z TestFramework (INFO): Initializing test directory /mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98
2024-04-01T22:48:28.021000Z TestFramework (INFO): Setting up wallets
2024-04-01T22:48:28.100000Z TestFramework (INFO): Mining coins
2024-04-01T22:48:29.714000Z TestFramework (INFO): Import should fail if a descriptor is not provided
2024-04-01T22:48:29.725000Z TestFramework (INFO): Should import a p2pkh descriptor
2024-04-01T22:48:29.740000Z TestFramework (INFO): Test can import same descriptor with public key twice
2024-04-01T22:48:29.760000Z TestFramework (INFO): Test can update descriptor label
2024-04-01T22:48:29.785000Z TestFramework (INFO): Internal addresses cannot have labels
2024-04-01T22:48:29.788000Z TestFramework (INFO): Internal addresses should be detected as such
2024-04-01T22:48:29.854000Z TestFramework (INFO): Should not import a p2sh-p2wpkh descriptor without checksum
2024-04-01T22:48:29.855000Z TestFramework (INFO): Should not import a p2sh-p2wpkh descriptor that has range specified
2024-04-01T22:48:29.858000Z TestFramework (INFO): Should not import a p2sh-p2wpkh descriptor and have it set to active
2024-04-01T22:48:29.860000Z TestFramework (INFO): Should import a (non-active) p2sh-p2wpkh descriptor
2024-04-01T22:48:29.984000Z TestFramework (INFO): Should import a 1-of-2 bare multisig from descriptor
2024-04-01T22:48:30.002000Z TestFramework (INFO): Should not treat individual keys from the imported bare multisig as watchonly
2024-04-01T22:48:30.005000Z TestFramework (INFO): Ranged descriptors cannot have labels
2024-04-01T22:48:30.014000Z TestFramework (INFO): Private keys required for private keys enabled wallet
2024-04-01T22:48:30.027000Z TestFramework (INFO): Ranged descriptor import should warn without a specified range
2024-04-01T22:48:30.065000Z TestFramework (INFO): Should not import a ranged descriptor that includes xpriv into a watch-only wallet
2024-04-01T22:48:30.070000Z TestFramework (INFO): Should not import a descriptor with hardened derivations when private keys are disabled
2024-04-01T22:48:30.108000Z TestFramework (INFO): Verify we can only extend descriptor's range
2024-04-01T22:48:30.364000Z TestFramework (INFO): Check we can change descriptor internal flag
2024-04-01T22:48:30.536000Z TestFramework (INFO): Key ranges should be imported in order
2024-04-01T22:48:30.708000Z TestFramework (INFO): Check we can change next_index
2024-04-01T22:48:30.838000Z TestFramework (INFO): Check imported descriptors are not active by default
2024-04-01T22:48:30.870000Z TestFramework (INFO): Check can activate inactive descriptor
2024-04-01T22:48:30.903000Z TestFramework (INFO): Check can deactivate active descriptor
2024-04-01T22:48:30.924000Z TestFramework (INFO): Verify activation state is persistent
2024-04-01T22:48:30.973000Z TestFramework (INFO): Should import a descriptor with a WIF private key as spendable
2024-04-01T22:48:30.987000Z TestFramework (INFO): Test can import same descriptor with private key twice
2024-04-01T22:48:32.173000Z TestFramework (INFO): Test that multisigs can be imported, signed for, and getnewaddress'd
2024-04-01T22:48:43.803000Z TestFramework (INFO): Multisig with distributed keys
2024-04-01T22:48:48.895000Z TestFramework (INFO): We can create and use a huge multisig under P2WSH
2024-04-01T22:49:05.628000Z TestFramework (INFO): Under P2SH, multisig are standard with up to 15 compressed keys
2024-04-01T22:49:20.258000Z TestFramework (INFO): Amending multisig with new private keys
2024-04-01T22:49:23.306000Z TestFramework (INFO): Combo descriptors cannot be active
2024-04-01T22:49:23.313000Z TestFramework (INFO): Descriptors with no type cannot be active
2024-04-01T22:49:23.348000Z TestFramework (INFO): Test importing a descriptor to an encrypted wallet
2024-04-01T22:49:43.957000Z 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/wallet_importdescriptors.py", line 691, in run_test
with self.nodes[0].assert_debug_log(expected_msgs=["Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)"], timeout=5):#10):
File "/nix/store/rac8pxbi1vapwrlqzbrkycbyg521djzw-python3-3.11.6/lib/python3.11/contextlib.py", line 144, in __exit__
next(self.gen)
File "/home/chris/Documents/Code/bitcoin-core/test/functional/test_framework/test_node.py", line 493, in assert_debug_log
self._raise_assertion_error(f'Expected messages "{expected_msgs}" found too late, took {now - start:.1f} seconds, {((now - start) / (time_end - start)) - 1:.1%} over the given limit. Log:\n\n{print_log}\n\n')
File "/home/chris/Documents/Code/bitcoin-core/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)']" found too late, took 5.4 seconds, 8.9% over the given limit. Log:
- 2024-04-01T22:49:33.066512Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for /wallet/encrypted_wallet from 127.0.0.1:47658
- 2024-04-01T22:49:33.066668Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=importdescriptors user=__cookie__
- 2024-04-01T22:49:33.070999Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: INSERT INTO main VALUES(?, ?)
- 2024-04-01T22:49:33.071061Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: DELETE FROM main WHERE key = ?
- 2024-04-01T22:49:33.071137Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: BEGIN TRANSACTION
- 2024-04-01T22:49:33.074190Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?)
- 2024-04-01T22:49:33.075564Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?)
...<thousands of almost identical lines>...
- 2024-04-01T22:49:38.416139Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?)
- 2024-04-01T22:49:38.416528Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?)
- 2024-04-01T22:49:38.427946Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: COMMIT TRANSACTION
- 2024-04-01T22:49:38.429778Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?)
- 2024-04-01T22:49:38.429916Z [httpworker.0] [wallet/sqlite.cpp:57] [TraceSqlCallback] [/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/node0/regtest/wallets/encrypted_wallet/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?)
- 2024-04-01T22:49:38.430001Z [httpworker.0] [wallet/wallet.h:933] [WalletLogPrintf] [encrypted_wallet] Setting spkMan to active: id = c6149b35399517457b0b1d8ccdd7efda25a2f20fc7f8167adda8e79b10e260b7, type = legacy, internal = false
- 2024-04-01T22:49:38.430134Z [httpworker.0] [wallet/wallet.h:933] [WalletLogPrintf] [encrypted_wallet] RescanFromTime: Rescanning last 329 blocks
- 2024-04-01T22:49:38.430170Z [httpworker.0] [wallet/wallet.h:933] [WalletLogPrintf] [encrypted_wallet] Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)
- 2024-04-01T22:49:38.441914Z [httpworker.0] [wallet/scriptpubkeyman.h:258] [WalletLogPrintf] [encrypted_wallet] MarkUnusedAddresses: Detected a used keypool item at index 4000, mark all keypool items up to this item as used
2024-04-01T22:49:44.029000Z TestFramework (INFO): Stopping nodes
2024-04-01T22:49:44.132000Z TestFramework (WARNING): Not cleaning up dir /mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98
2024-04-01T22:49:44.132000Z TestFramework (ERROR): Test failed. Test logging available at /mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98/test_framework.log
2024-04-01T22:49:44.132000Z TestFramework (ERROR):
2024-04-01T22:49:44.133000Z TestFramework (ERROR): Hint: Call /home/chris/Documents/Code/bitcoin-core/test/functional/combine_logs.py '/mnt/tmp/test_runner_₿_🏃_20240402_004231/wallet_importdescriptors_98' to consolidate all logs
2024-04-01T22:49:44.133000Z TestFramework (ERROR):
2024-04-01T22:49:44.133000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2024-04-01T22:49:44.133000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2024-04-01T22:49:44.133000Z TestFramework (ERROR):
stderr:
Remaining jobs: [feature_pruning.py, feature_dbcrash.py, feature_assumeutxo.py, rpc_scantxoutset.py, feature_coinstatsindex.py, p2p_node_network_limited.py --v1transport, p2p_node_network_limited.py --v2transport, feature_config_args.py]
298/305 - p2p_node_network_limited.py --v1transport passed, Duration: 24 s
```
</details>
## Related
Almost identical timeout in `feature_index_prune.py` in #27091 on MacOS, and for `wallet_importdescriptors.py --descriptors` in #27282 on Alpine & CI.
ACKs for top commit:
maflcko:
lgtm ACK 49c0b8b228
tdb3:
ACK for 49c0b8b228
itornaza:
approach ACK 49c0b8b228
BrandonOdiwuor:
crACK 49c0b8b228
Tree-SHA512: f62ade74701588d76bfe838b7e7bbda1db38fd98688fd5d13c2c008064027add2ee9d053dee602d84919fab4c9bf53183c31819d94a6174066f237d0f6a62086
Bitcoin Core connects to the Bitcoin peer-to-peer network to download and fully
validate blocks and transactions. It also includes a wallet and graphical user
interface, which can be optionally built.
Further information about Bitcoin Core is available in the doc folder.
The master branch is regularly built (see doc/build-*.md for instructions) and tested, but it is not guaranteed to be
completely stable. Tags are created
regularly from release branches to indicate new official, stable release versions of Bitcoin Core.
The https://github.com/bitcoin-core/gui repository is used exclusively for the
development of the GUI. Its master branch is identical in all monotree
repositories. Release branches and tags do not exist, so please do not fork
that repository unless it is for development reasons.
Testing and code review is the bottleneck for development; we get more pull
requests than we can review and test on short notice. Please be patient and help out by testing
other people's pull requests, and remember this is a security-critical project where any mistake might cost people
lots of money.
Automated Testing
Developers are strongly encouraged to write unit tests for new code, and to
submit new unit tests for old code. Unit tests can be compiled and run
(assuming they weren't disabled in configure) with: make check. Further details on running
and extending unit tests can be found in /src/test/README.md.
The CI (Continuous Integration) systems make sure that every pull request is built for Windows, Linux, and macOS,
and that unit/sanity tests are run automatically.
Manual Quality Assurance (QA) Testing
Changes should be tested by somebody other than the developer who wrote the
code. This is especially important for large or high-risk changes. It is useful
to add a test plan to the pull request description if testing the changes is
not straightforward.
03e94f8b90