test: wallet_importdescriptors.py --descriptors failure #27282

issue fanquake openend this issue on March 20, 2023
  1. fanquake commented at 11:11 am on March 20, 2023: member

    Seen on a aarch64 Alpine box. Master @ https://github.com/bitcoin/bitcoin/commit/40e1c4d4024b8ad35f2511b2e10bf80c5531dfde. Binaries compiled with Clang 15.0.7. Valgrind valgrind-3.21.0.GIT.

    We saw some issues with this test recently (#27229), but this looks like a different issue:

      0261/262 - wallet_importdescriptors.py --descriptors failed, Duration: 411 s
      1
      2stdout:
      32023-03-20T10:39:03.422000Z TestFramework (INFO): PRNG seed is: 4441145092714460381
      42023-03-20T10:39:03.423000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20230320_101936/wallet_importdescriptors_88
      52023-03-20T10:39:08.174000Z TestFramework (INFO): Setting up wallets
      62023-03-20T10:39:09.056000Z TestFramework (INFO): Mining coins
      72023-03-20T10:39:10.636000Z TestFramework (INFO): Import should fail if a descriptor is not provided
      82023-03-20T10:39:10.649000Z TestFramework (INFO): Should import a p2pkh descriptor
      92023-03-20T10:39:10.799000Z TestFramework (INFO): Test can import same descriptor with public key twice
     102023-03-20T10:39:10.835000Z TestFramework (INFO): Test can update descriptor label
     112023-03-20T10:39:10.870000Z TestFramework (INFO): Internal addresses cannot have labels
     122023-03-20T10:39:10.874000Z TestFramework (INFO): Internal addresses should be detected as such
     132023-03-20T10:39:10.915000Z TestFramework (INFO): Should not import a p2sh-p2wpkh descriptor without checksum
     142023-03-20T10:39:10.919000Z TestFramework (INFO): Should not import a p2sh-p2wpkh descriptor that has range specified
     152023-03-20T10:39:10.926000Z TestFramework (INFO): Should not import a p2sh-p2wpkh descriptor and have it set to active
     162023-03-20T10:39:10.930000Z TestFramework (INFO): Should import a (non-active) p2sh-p2wpkh descriptor
     172023-03-20T10:39:11.107000Z TestFramework (INFO): Should import a 1-of-2 bare multisig from descriptor
     182023-03-20T10:39:11.147000Z TestFramework (INFO): Should not treat individual keys from the imported bare multisig as watchonly
     192023-03-20T10:39:11.151000Z TestFramework (INFO): Ranged descriptors cannot have labels
     202023-03-20T10:39:11.160000Z TestFramework (INFO): Private keys required for private keys enabled wallet
     212023-03-20T10:39:11.177000Z TestFramework (INFO): Ranged descriptor import should warn without a specified range
     222023-03-20T10:39:11.234000Z TestFramework (INFO): Should not import a ranged descriptor that includes xpriv into a watch-only wallet
     232023-03-20T10:39:11.242000Z TestFramework (INFO): Should not import a descriptor with hardened derivations when private keys are disabled
     242023-03-20T10:39:11.281000Z TestFramework (INFO): Verify we can only extend descriptor's range
     252023-03-20T10:39:11.765000Z TestFramework (INFO): Check we can change descriptor internal flag
     262023-03-20T10:39:12.046000Z TestFramework (INFO): Key ranges should be imported in order
     272023-03-20T10:39:12.431000Z TestFramework (INFO): Check we can change next_index
     282023-03-20T10:39:12.709000Z TestFramework (INFO): Check imported descriptors are not active by default
     292023-03-20T10:39:12.754000Z TestFramework (INFO): Check can activate inactive descriptor
     302023-03-20T10:39:12.811000Z TestFramework (INFO): Check can deactivate active descriptor
     312023-03-20T10:39:12.862000Z TestFramework (INFO): Verify activation state is persistent
     322023-03-20T10:39:12.942000Z TestFramework (INFO): Should import a descriptor with a WIF private key as spendable
     332023-03-20T10:39:12.978000Z TestFramework (INFO): Test can import same descriptor with private key twice
     342023-03-20T10:39:14.574000Z TestFramework (INFO): Test that multisigs can be imported, signed for, and getnewaddress'd
     352023-03-20T10:39:35.707000Z TestFramework (INFO): Multisig with distributed keys
     362023-03-20T10:39:46.670000Z TestFramework (INFO): We can create and use a huge multisig under P2WSH
     372023-03-20T10:40:19.550000Z TestFramework (INFO): Under P2SH, multisig are standard with up to 15 compressed keys
     382023-03-20T10:40:45.496000Z TestFramework (INFO): Amending multisig with new private keys
     392023-03-20T10:40:51.063000Z TestFramework (INFO): Combo descriptors cannot be active
     402023-03-20T10:40:51.068000Z TestFramework (INFO): Descriptors with no type cannot be active
     412023-03-20T10:40:51.127000Z TestFramework (INFO): Test importing a descriptor to an encrypted wallet
     422023-03-20T10:41:54.188000Z TestFramework (INFO): Stopping nodes
     432023-03-20T10:45:54.240000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
     44    def is_node_stopped(self):
     45        """Checks whether the node has stopped.
     46
     47        Returns True if the node has stopped. False otherwise.
     48        This method is responsible for freeing resources (self.process)."""
     49        if not self.running:
     50            return True
     51        return_code = self.process.poll()
     52        if return_code is None:
     53            return False
     54
     55        # process has stopped. Assert that it didn't return an error code.
     56        assert return_code == 0, self._node_msg(
     57            "Node returned non-zero exit code (%d) when stopping" % return_code)
     58        self.running = False
     59        self.process = None
     60        self.rpc_connected = False
     61        self.rpc = None
     62        self.log.debug("Node stopped")
     63        return True
     64'''
     65[node 1] Cleaning up leftover process
     66[node 0] Cleaning up leftover process
     67
     68
     69stderr:
     70Exception in thread Thread-1:
     71Traceback (most recent call last):
     72  File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
     73    self.run()
     74  File "/usr/lib/python3.10/threading.py", line 953, in run
     75    self._target(*self._args, **self._kwargs)
     76  File "/bitcoin/test/functional/test_framework/coverage.py", line 49, in __call__
     77    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
     78  File "/bitcoin/test/functional/test_framework/authproxy.py", line 149, in __call__
     79    raise JSONRPCException(response['error'], status)
     80test_framework.authproxy.JSONRPCException: Error: Please enter the wallet passphrase with walletpassphrase first. (-13)
     81Traceback (most recent call last):
     82  File "/bitcoin/test/functional/wallet_importdescriptors.py", line 717, in <module>
     83    ImportDescriptorsTest().main()
     84  File "/bitcoin/test/functional/test_framework/test_framework.py", line 155, in main
     85    exit_code = self.shutdown()
     86  File "/bitcoin/test/functional/test_framework/test_framework.py", line 314, in shutdown
     87    self.stop_nodes()
     88  File "/bitcoin/test/functional/test_framework/test_framework.py", line 582, in stop_nodes
     89    node.wait_until_stopped()
     90  File "/bitcoin/test/functional/test_framework/test_node.py", line 388, in wait_until_stopped
     91    wait_until_helper(self.is_node_stopped, timeout=timeout, timeout_factor=self.timeout_factor)
     92  File "/bitcoin/test/functional/test_framework/util.py", line 281, in wait_until_helper
     93    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
     94AssertionError: Predicate ''''
     95    def is_node_stopped(self):
     96        """Checks whether the node has stopped.
     97
     98        Returns True if the node has stopped. False otherwise.
     99        This method is responsible for freeing resources (self.process)."""
    100        if not self.running:
    101            return True
    102        return_code = self.process.poll()
    103        if return_code is None:
    104            return False
    105
    106        # process has stopped. Assert that it didn't return an error code.
    107        assert return_code == 0, self._node_msg(
    108            "Node returned non-zero exit code (%d) when stopping" % return_code)
    109        self.running = False
    110        self.process = None
    111        self.rpc_connected = False
    112        self.rpc = None
    113        self.log.debug("Node stopped")
    114        return True
    115''' not true after 240 seconds
    
  2. fanquake added the label Tests on Mar 20, 2023
  3. maflcko commented at 12:22 pm on March 20, 2023: member
    What is the combined log?
  4. maflcko added the label Wallet on Mar 20, 2023
  5. maflcko commented at 4:22 pm on March 20, 2023: member

    Same error/cause in another test file:

    https://cirrus-ci.com/task/4914078427119616?logs=ci#L3898

     02023-03-20T15:27:58.304000Z TestFramework (INFO): Stopping nodes
     12023-03-20T15:27:58.935000Z TestFramework (INFO): Cleaning up /tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner_₿_🏃_20230320_151651/wallet_transactiontime_rescan_149 on exit
     22023-03-20T15:27:58.935000Z TestFramework (INFO): Tests successful
     3stderr:
     4Exception in thread Thread-1:
     5Traceback (most recent call last):
     6  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
     7    self.run()
     8  File "/usr/lib/python3.8/threading.py", line 870, in run
     9    self._target(*self._args, **self._kwargs)
    10  File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/coverage.py", line 49, in __call__
    11    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
    12  File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 149, in __call__
    13    raise JSONRPCException(response['error'], status)
    14test_framework.authproxy.JSONRPCException: Error: Please enter the wallet passphrase with walletpassphrase first. (-13)
    
  6. maflcko commented at 7:17 am on March 21, 2023: member
    Can remove --valgrind from title? See also #27199#pullrequestreview-1349425797
  7. maflcko commented at 8:38 am on March 21, 2023: member
    Looks like there are several issues here. The first one, unrelated to the test failure is that the return value is thrown away (thread.join() returns None, always)
  8. maflcko commented at 9:03 am on March 21, 2023: member
  9. fanquake renamed this:
    test: `wallet_importdescriptors.py --descriptors` failure under `--valgrind`
    test: `wallet_importdescriptors.py --descriptors` failure
    on Mar 21, 2023
  10. fanquake commented at 11:49 am on March 21, 2023: member
  11. maflcko commented at 3:44 pm on March 21, 2023: member

    See also https://gist.github.com/fanquake/a458badc73abb47f8c06f009d15e1916 (combined log).

    This just looks like a timeout factor error

  12. maflcko added this to the milestone 25.0 on Mar 27, 2023
  13. maflcko commented at 1:53 pm on March 28, 2023: member
    Is this still an issue with a recent version of Bitcoin Core? If yes, what are the steps to reproduce?
  14. fanquake commented at 2:42 pm on March 28, 2023: member

    If yes, what are the steps to reproduce?

    Haven’t seen this lately. Can close.

  15. fanquake closed this on Mar 28, 2023

  16. maflcko commented at 7:53 am on March 31, 2023: member

    Ok, this still happens: https://cirrus-ci.com/task/5541464030052352?logs=ci#L2622

    However, it looks like there is another unrelated bug in the rpc proxy to dispatch the same RPC twice? There really shouldn’t be any reason to blindly run the same RPC twice without the user (test developer) asking for it.

    I presume running the RPC twice will also discard the earlier result, so still no luck debugging this issue.

  17. maflcko reopened this on Mar 31, 2023

  18. maflcko commented at 11:45 am on April 15, 2023: member
    I wonder if this is still an issue, now that the RPC proxy was fixed to not dispatch the same call twice?
  19. fanquake commented at 11:47 am on April 15, 2023: member
    I don’t think I’ve seen this again, only occurence seemed to be Cirrus above (before the fix). Guess we can reclose for now? Will remove from the milestone in any case.
  20. fanquake removed this from the milestone 25.0 on Apr 15, 2023
  21. maflcko commented at 11:48 am on April 15, 2023: member
    sgtm. Closing for now, until this happens again.
  22. maflcko closed this on Apr 15, 2023

  23. bitcoin deleted a comment on Nov 19, 2023
  24. fanquake referenced this in commit 03e94f8b90 on Apr 7, 2024
  25. bitcoin locked this on Nov 18, 2024

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-11-24 12:12 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me