ci: failure in `wallet_basic.py --descriptors`

fanquake commented at 3:08 pm on December 18, 2023: member

https://cirrus-ci.com/task/5898005006516224?logs=ci#L2515:

 0_20231218_134952/wallet_basic_259/node0/regtest/wallets/default_wallet/wallet.dat] SQLite Statement: ROLLBACK TRANSACTION 
 1 node0 2023-12-18T13:53:29.193915Z [scheduler] [wallet/sqlite.cpp:400] [Close] SQLiteBatch: Batch closed unexpectedly without the transaction being explicitly committed or aborted 
 2 node0 2023-12-18T13:53:29.194038Z [scheduler] [wallet/sqlite.cpp:53] [TraceSqlCallback] [/ci_container_base/ci/scratch/test_runner/test_runner_₿_🏃_20231218_134952/wallet_basic_259/node0/regtest/wallets/zeroconf/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 3 node0 2023-12-18T13:53:29.194122Z [scheduler] [wallet/sqlite.cpp:53] [TraceSqlCallback] [/ci_container_base/ci/scratch/test_runner/test_runner_₿_🏃_20231218_134952/wallet_basic_259/node0/regtest/wallets/zeroconf/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 4 test  2023-12-18T13:53:29.196000Z TestFramework (ERROR): JSONRPC error 
 5                                   Traceback (most recent call last):
 6                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
 7                                       self.run_test()
 8                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/wallet_basic.py", line 786, in run_test
 9                                       self.test_chain_listunspent()
10                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/wallet_basic.py", line 792, in test_chain_listunspent
11                                       self.nodes[0].get_wallet_rpc(self.default_wallet_name).sendtoaddress(self.wallet.get_address(), "5")
12                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/coverage.py", line 50, in __call__
13                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
14                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 129, in __call__
15                                       raise JSONRPCException(response['error'], status)
16                                   test_framework.authproxy.JSONRPCException: Error during descriptors keypool top up. Cannot commit changes for wallet [default_wallet] (-1)
17 node0 2023-12-18T13:53:29.196028Z [httpworker.2] [wallet/sqlite.cpp:53] [TraceSqlCallback] [/ci_container_base/ci/scratch/test_runner/test_runner_₿_🏃_20231218_134952/wallet_basic_259/node0/regtest/wallets/default_wallet/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
18 test  2023-12-18T13:53:29.198000Z TestFramework (DEBUG): Closing down network thread 
19 test  2023-12-18T13:53:29.248000Z TestFramework (INFO): Stopping nodes 
20 test  2023-12-18T13:53:29.248000Z TestFramework.node0 (DEBUG): Stopping node

fanquake added the label Tests on Dec 18, 2023

maflcko added the label Wallet on Dec 18, 2023

achow101 commented at 8:05 pm on December 18, 2023: member

It looks like the SQLiteBatch being used to write data to disk is being destroyed unexpectedly, which causes subsequent writes using the same object(??) to have the wrong db transaction state that triggers this error.

Edit: I’m thinking that this might actually be due to a race condition? If there were two SQLiteBatch objects with one beginning a transaction, when the other executes its actions, and then destructs, it would detect that a transaction is in progress that it hadn’t started, and thus do ROLLBACK which would result in the first batch object expecting a transaction when the other had aborted it.

Looking at this further, I think the ChainStateFlushed that happens after we see BEGIN TRANSACTION is the culprit. The wallet makes a new batch for flushing the chainstate, and when this is destroyed, it also aborts the other batch’s transaction.

furszy commented at 9:44 pm on December 18, 2023: member

Yeah. The description is accurate achow. I had something for this in the past for #25297. We currently support a single db connection at time; when multiple WalletBatch are created on different threads, the first one destructed has priority over the others.

IIRC, I had a database manager class providing db references, mapping the thread id to the db ref. So different threads can wait until other processes finish dumping data, acting accordantly, before making use of the db. I think I never pushed it because I wanted to go further (and also because #25297 didn’t get much attention); wanted to make the db manager class provide db txns at the software level (not db engine level), enabling real parallelism and also letting us batch writes even across data from different processes.

bitcoin deleted a comment on Dec 23, 2023

bitcoin deleted a comment on Dec 25, 2023

maflcko removed the label Tests on Jan 11, 2024

maflcko added the label Bug on Jan 11, 2024

maflcko added this to the milestone 27.0 on Jan 11, 2024

maflcko commented at 3:29 pm on January 11, 2024: member

Added milestone, because this seems like a blocker?

bitcoin deleted a comment on Jan 15, 2024

fanquake commented at 11:02 am on January 17, 2024: member

https://cirrus-ci.com/task/6509037848625152?logs=ci#L2502

maflcko added the label CI failed on Jan 24, 2024

ryanofsky closed this on Feb 8, 2024

ci: failure in wallet_basic.py --descriptors #29110

ci: failure in `wallet_basic.py --descriptors` #29110