intermittent issue in wallet_backwards_compatibility (BerkeleyEnvironment::Open: Error -30974 opening database environment: DB_RUNRECOVERY: Fatal error, run database recovery)

maflcko commented at 8:11 am on January 11, 2023: member

 0$ wget https://drahtbot.space/temp_scratch/wallet_backwards_compatibility_113.tar.xz
 1$ tar xvf wallet_backwards_compatibility_113.tar.xz
 2$ ./test/functional/combine_logs.py -c ./wallet_backwards_compatibility_113 | tail -525 | head -13
 3 node2 2023-01-11T00:21:39.903849Z [httpworker.2] [wallet/bdb.cpp:145] [Open] BerkeleyEnvironment::Open: LogDir=/root/bitcoin-core/ci/scratch/test_runner/test_runner_₿_🏃_20230111_000842/wallet_backwards_compatibility_113/node2/regtest/wallets/w1/database ErrorFile=/root/bitcoin-core/ci/scratch/test_runner/test_runner_₿_🏃_20230111_000842/wallet_backwards_compatibility_113/node2/regtest/wallets/w1/db.log 
 4 node2 2023-01-11T00:21:39.906405Z [httpworker.2] [wallet/bdb.cpp:172] [Open] BerkeleyEnvironment::Open: Error -30974 opening database environment: DB_RUNRECOVERY: Fatal error, run database recovery 
 5 test  2023-01-11T00:21:39.909000Z TestFramework (ERROR): JSONRPC error 
 6                                   Traceback (most recent call last):
 7                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
 8                                       self.run_test()
 9                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/wallet_backwards_compatibility.py", line 185, in run_test
10                                       node.loadwallet(wallet_name)
11                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/coverage.py", line 49, in __call__
12                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
13                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 146, in __call__
14                                       raise JSONRPCException(response['error'], status)
15                                   test_framework.authproxy.JSONRPCException: Wallet file verification failed. Error initializing wallet database environment "/root/bitcoin-core/ci/scratch/test_runner/test_runner_₿_🏃_20230111_000842/wallet_backwards_compatibility_113/node2/regtest/wallets/w1"! This error could occur if this wallet was not shutdown cleanly and was last loaded using a build with a newer version of Berkeley DB. If so, please use the software that last loaded this wallet (-4)

maflcko added the label Bug on Jan 11, 2023

maflcko commented at 8:26 am on January 11, 2023: member

(Happened in the asan ci task, if relevant)

john-moffett commented at 7:33 pm on January 11, 2023: contributor

Contents of db.log from the w1 wallet in node2:

0Unacceptable log file /root/bitcoin-core/ci/scratch/test_runner/test_runner_₿_🏃_20230111_000842/wallet_backwards_compatibility_113/node2/regtest/wallets/w1/database/log.0000000001: unsupported log version 19
1Invalid log file: log.0000000001: Invalid argument
2PANIC: Invalid argument
3process-private: unable to find environment

Same error from this comment, which seemed to be a genuine incompatibility issue.

Edit: It looks like asan uses --with-incompatible-bdb. Could that be the problem? I’d imagine it wouldn’t be intermittent, though.

maflcko commented at 10:18 pm on January 11, 2023: member

I wonder why there are any logs, given that the wallet was unloaded before

maflcko added the label Tests on Jan 11, 2023

maflcko added the label Wallet on Jan 11, 2023

john-moffett commented at 11:25 pm on January 11, 2023: contributor

Hmm, good point. I’d also assumed that unloading the wallet would remove the log.0000000001 file, but maybe that only happens on shutdown?

maflcko commented at 9:11 am on January 12, 2023: member

So the bug either is that unloadwallet doesn’t flush or that the test assumes it does? cc @Sjors

Sjors commented at 11:54 am on January 12, 2023: member

I don’t think the purpose of our backwards compatibility test is to find every conceivable way in which a wallet is uncleanly closed. So I would be fine with having the test wipe log files - or do a complete node shutdown instead of merely unloading - if it prevents intermittent failures.

john-moffett commented at 7:32 pm on January 13, 2023: contributor

It seems like DB_LOG_AUTO_REMOVE is the source of the non-determinism since there aren’t guarantees when it’ll run.

Maybe the best solution is to skip copying the wallet database directory when copying the wallets to the old nodes?

Something like:

0for node in legacy_nodes:
1    # Copy wallets to previous version
2    for wallet in os.listdir(node_master_wallets_dir):
3        shutil.copytree(
4            os.path.join(node_master_wallets_dir, wallet),
5            os.path.join(self.nodes_wallet_dir(node), wallet),
6            # Do not copy the database log files
7            ignore=shutil.ignore_patterns("database")
8        )

maflcko commented at 3:35 pm on February 7, 2023: member

Discussion: #26915 (comment)

maflcko commented at 10:21 am on February 8, 2023: member

Looks like this is a CI system bug, which will be fixed in https://github.com/bitcoin/bitcoin/pull/27033

maflcko closed this on Feb 8, 2023

bitcoin locked this on Feb 8, 2024

intermittent issue in wallet_backwards_compatibility (BerkeleyEnvironment::Open: Error -30974 opening database environment: DB_RUNRECOVERY: Fatal error, run database recovery) #26869