qa: Intermittent `AssertionError: not(10.00000000 == 340)` in `wallet

hebasto commented at 1:19 pm on December 20, 2024: member

https://github.com/hebasto/bitcoin/actions/runs/12431224655/job/34708713770:

 0265/315 - wallet_assumeutxo.py --descriptors failed, Duration: 5 s
 1
 2stdout:
 32024-12-20T12:54:28.609000Z TestFramework (INFO): PRNG seed is: 187204816715607970
 4
 52024-12-20T12:54:28.641000Z TestFramework (INFO): Initializing test directory D:\a\_temp\test_runner_₿_🏃_20241220_123237\wallet_assumeutxo_48
 6
 72024-12-20T12:54:30.237000Z TestFramework (INFO): -- Testing assumeutxo
 8
 92024-12-20T12:54:30.237000Z TestFramework (INFO): Creating a UTXO snapshot at height 299
10
112024-12-20T12:54:31.490000Z TestFramework (INFO): Loading snapshot into second node from D:\a\_temp\test_runner_₿_🏃_20241220_123237\wallet_assumeutxo_48\node0\regtest\utxos.dat
12
132024-12-20T12:54:31.884000Z TestFramework (INFO): Backup from the snapshot height can be loaded during background sync
14
152024-12-20T12:54:31.916000Z TestFramework (INFO): Backup from before the snapshot height can't be loaded during background sync
16
172024-12-20T12:54:31.932000Z TestFramework (INFO): Restarting node to stop at height 359
18
192024-12-20T12:54:32.812000Z TestFramework (INFO): Restarted node before snapshot validation completed, reloading...
20
212024-12-20T12:54:33.193000Z TestFramework (INFO): Ensuring snapshot chain syncs to tip. (399)
22
232024-12-20T12:54:33.246000Z TestFramework (INFO): Ensuring background validation completes
24
252024-12-20T12:54:33.383000Z TestFramework (INFO): Ensuring wallet can be restored from a backup that was created before the snapshot height
26
272024-12-20T12:54:33.421000Z TestFramework (ERROR): Assertion failed
28
29Traceback (most recent call last):
30
31  File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 135, in main
32
33    self.run_test()
34
35  File "D:\a\bitcoin\bitcoin/test/functional/wallet_assumeutxo.py", line 188, in run_test
36
37    assert_equal(n1.getbalance(), 340)
38
39  File "D:\a\bitcoin\bitcoin\test\functional\test_framework\util.py", line 77, in assert_equal
40
41    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
42
43AssertionError: not(10.00000000 == 340)
44
452024-12-20T12:54:33.474000Z TestFramework (INFO): Stopping nodes

hebasto added the label Tests on Dec 20, 2024

hebasto added the label Wallet on Dec 20, 2024

maflcko added the label Windows on Dec 20, 2024

maflcko commented at 1:48 pm on December 20, 2024: member

Is it reproducible?

hebasto renamed this:
~~qa: `AssertionError: not(10.00000000 == 340)` in `wallet_assumeutxo.py --descriptors`~~
qa: Intermittent `AssertionError: not(10.00000000 == 340)` in `wallet_assumeutxo.py --descriptors`
on Dec 20, 2024

hebasto commented at 4:14 pm on December 20, 2024: member

Is it reproducible?

It seems intermittent.

mzumsande commented at 11:34 pm on December 20, 2024: contributor

I looked into this (thanks @furszy who helped me understand the wallet part of this) and believe that this is a bug in validation:

When the snapshot block is connected at the end of the background sync, MaybeCompleteSnapshotValidation is called from ConnectTip() (deactivating one chainstate), and the BlockConnected() signal for the snapshot height (which logically belongs to the background chainstate) is sent out after this. Since the background chainstate does no longer exist by this time, the signal will be sent for the active chainstate, and the wallet (which would ignore signals for the background chainstate) will process it and set m_last_block_processed_height to the (ancient) snapshot height. As a result, GetTxDepthInMainChain is wrong and the wallet will show an incorrect getbalance until the next block arrives (which is 10 minutes on average because our tip is synced).

So this is not a test-only issue: It would affect any user with an active wallet who syncs with assumeutxo - they could see their balance temporarily vanish right after the background sync completed. It can be reproduced non-intermittently with the following diff:

 0diff --git a/test/functional/wallet_assumeutxo.py b/test/functional/wallet_assumeutxo.py
 1index 76cd2097a3..d0c74b123f 100755
 2--- a/test/functional/wallet_assumeutxo.py
 3+++ b/test/functional/wallet_assumeutxo.py
 4@@ -149,6 +149,16 @@ class AssumeutxoTest(BitcoinTestFramework):
 5         # Balance of w wallet is still still 0 because n1 has not synced yet
 6         assert_equal(n1.getbalance(), 0)
 7 
 8+        # Directly sync nodes to display balance bug
 9+        self.connect_nodes(0, 1);
10+        self.wait_until(lambda: len(n1.getchainstates()['chainstates']) == 1)
11+        # wrong balance after background sync finished
12+        self.wait_until(lambda:(n1.getbalance() == 1))
13+        # any next block that arrives will correct the balance
14+        self.generate(n1, nblocks=1, sync_fun=self.no_op)
15+        self.wait_until(lambda:(n1.getbalance() == 34))
16+        exit()
17+
18         self.log.info("Backup from before the snapshot height can't be loaded during background sync")
19         assert_raises_rpc_error(-4, "Wallet loading failed. Error loading wallet. Wallet requires blocks to be downloaded, and software does not currently support loading wallets while blocks are being downloaded out of order when using assumeutxo snapshots. Wallet should be able to load successfully after node sync reaches height 299", n1.restorewallet, "w2", "backup_w2.dat")

The correct behavior would be to either assign the BlockConnected() notification for the snapshot block to the background chainstate, not the active chainstate - or maybe not send it out at all, because arguably the block was already “connected” by loading the snapshot earlier.

I’ll open a fix soon.

qa: Intermittent AssertionError: not(10.00000000 == 340) in wallet_assumeutxo.py --descriptors #31546

qa: Intermittent `AssertionError: not(10.00000000 == 340)` in `wallet_assumeutxo.py --descriptors` #31546