diff options
author | fanquake <fanquake@gmail.com> | 2024-04-07 10:36:42 +0100 |
---|---|---|
committer | fanquake <fanquake@gmail.com> | 2024-04-07 10:38:59 +0100 |
commit | 03e94f8b90c2a7b7d3ee2b11899c046ec3a67394 (patch) | |
tree | 9efbf34748d7d4b0c0caf0f6d5a6e8b4068564dc /test | |
parent | 0f0e36de5f53f82d31416dc05a24d2885781ce57 (diff) | |
parent | 49c0b8b2288e60ae22fcac5d03811cf36ecec058 (diff) | |
download | bitcoin-03e94f8b90c2a7b7d3ee2b11899c046ec3a67394.tar.xz |
Merge bitcoin/bitcoin#29791: test: Bump timeouts in feature_index_prune and wallet_importdescriptors
49c0b8b2288e60ae22fcac5d03811cf36ecec058 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 49c0b8b2288e60ae22fcac5d03811cf36ecec058
tdb3:
ACK for 49c0b8b2288e60ae22fcac5d03811cf36ecec058
itornaza:
approach ACK 49c0b8b2288e60ae22fcac5d03811cf36ecec058
BrandonOdiwuor:
crACK 49c0b8b2288e60ae22fcac5d03811cf36ecec058
Tree-SHA512: f62ade74701588d76bfe838b7e7bbda1db38fd98688fd5d13c2c008064027add2ee9d053dee602d84919fab4c9bf53183c31819d94a6174066f237d0f6a62086
Diffstat (limited to 'test')
-rwxr-xr-x | test/functional/feature_index_prune.py | 2 | ||||
-rwxr-xr-x | test/functional/wallet_importdescriptors.py | 2 |
2 files changed, 2 insertions, 2 deletions
diff --git a/test/functional/feature_index_prune.py b/test/functional/feature_index_prune.py index b3bf35b524..66c0a4f615 100755 --- a/test/functional/feature_index_prune.py +++ b/test/functional/feature_index_prune.py @@ -31,7 +31,7 @@ class FeatureIndexPruneTest(BitcoinTestFramework): expected_stats = { 'coinstatsindex': {'synced': True, 'best_block_height': height} } - self.wait_until(lambda: self.nodes[1].getindexinfo() == expected_stats) + self.wait_until(lambda: self.nodes[1].getindexinfo() == expected_stats, timeout=150) expected = {**expected_filter, **expected_stats} self.wait_until(lambda: self.nodes[2].getindexinfo() == expected) diff --git a/test/functional/wallet_importdescriptors.py b/test/functional/wallet_importdescriptors.py index 420bdffc49..f9d05a2fe4 100755 --- a/test/functional/wallet_importdescriptors.py +++ b/test/functional/wallet_importdescriptors.py @@ -688,7 +688,7 @@ class ImportDescriptorsTest(BitcoinTestFramework): encrypted_wallet.walletpassphrase("passphrase", 99999) with concurrent.futures.ThreadPoolExecutor(max_workers=1) as thread: - with self.nodes[0].assert_debug_log(expected_msgs=["Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)"], timeout=5): + with self.nodes[0].assert_debug_log(expected_msgs=["Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)"], timeout=10): importing = thread.submit(encrypted_wallet.importdescriptors, requests=[descriptor]) # Set the passphrase timeout to 1 to test that the wallet remains unlocked during the rescan |