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

$ wget https://drahtbot.space/temp_scratch/wallet_backwards_compatibility_113.tar.xz
$ tar xvf wallet_backwards_compatibility_113.tar.xz
$ ./test/functional/combine_logs.py -c ./wallet_backwards_compatibility_113 | tail -525 | head -13
 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 
 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 
 test  2023-01-11T00:21:39.909000Z TestFramework (ERROR): JSONRPC error 
                                   Traceback (most recent call last):
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
                                       self.run_test()
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/wallet_backwards_compatibility.py", line 185, in run_test
                                       node.loadwallet(wallet_name)
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/coverage.py", line 49, in __call__
                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 146, in __call__
                                       raise JSONRPCException(response['error'], status)
                                   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)

(Happened in the asan ci task, if relevant)

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

Unacceptable 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
Invalid log file: log.0000000001: Invalid argument
PANIC: Invalid argument
process-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.

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

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

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

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.

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:

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

Discussion: #26915 (comment)

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