Skip to content

Commit

Permalink
Merge bitcoin#29791: test: Bump timeouts in feature_index_prune and w…
Browse files Browse the repository at this point in the history 
…allet_importdescriptors

49c0b8b 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 bitcoin#27091 on MacOS, and for `wallet_importdescriptors.py --descriptors` in bitcoin#27282 on Alpine & CI.

ACKs for top commit:
  maflcko:
    lgtm ACK 49c0b8b
  tdb3:
    ACK for 49c0b8b
  itornaza:
    approach ACK 49c0b8b
  BrandonOdiwuor:
    crACK 49c0b8b

Tree-SHA512: f62ade74701588d76bfe838b7e7bbda1db38fd98688fd5d13c2c008064027add2ee9d053dee602d84919fab4c9bf53183c31819d94a6174066f237d0f6a62086
  • Loading branch information
@fanquake
fanquake committed Apr 7, 2024
2 parents 0f0e36d + 49c0b8b commit 03e94f8
Show file tree
Hide file tree
Showing 2 changed files with 2 additions and 2 deletions.
2 changes: 1 addition & 1 deletion test/functional/feature_index_prune.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@ def sync_index(self, height):
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)
Expand Down
2 changes: 1 addition & 1 deletion test/functional/wallet_importdescriptors.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -688,7 +688,7 @@ def run_test(self):

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
Expand Down

0 comments on commit 03e94f8

Please sign in to comment.