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

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

265/315 - wallet_assumeutxo.py --descriptors failed, Duration: 5 s

stdout:
2024-12-20T12:54:28.609000Z TestFramework (INFO): PRNG seed is: 187204816715607970

2024-12-20T12:54:28.641000Z TestFramework (INFO): Initializing test directory D:\a\_temp\test_runner_₿_🏃_20241220_123237\wallet_assumeutxo_48

2024-12-20T12:54:30.237000Z TestFramework (INFO): -- Testing assumeutxo

2024-12-20T12:54:30.237000Z TestFramework (INFO): Creating a UTXO snapshot at height 299

2024-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

2024-12-20T12:54:31.884000Z TestFramework (INFO): Backup from the snapshot height can be loaded during background sync

2024-12-20T12:54:31.916000Z TestFramework (INFO): Backup from before the snapshot height can't be loaded during background sync

2024-12-20T12:54:31.932000Z TestFramework (INFO): Restarting node to stop at height 359

2024-12-20T12:54:32.812000Z TestFramework (INFO): Restarted node before snapshot validation completed, reloading...

2024-12-20T12:54:33.193000Z TestFramework (INFO): Ensuring snapshot chain syncs to tip. (399)

2024-12-20T12:54:33.246000Z TestFramework (INFO): Ensuring background validation completes

2024-12-20T12:54:33.383000Z TestFramework (INFO): Ensuring wallet can be restored from a backup that was created before the snapshot height

2024-12-20T12:54:33.421000Z TestFramework (ERROR): Assertion failed

Traceback (most recent call last):

  File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 135, in main

    self.run_test()

  File "D:\a\bitcoin\bitcoin/test/functional/wallet_assumeutxo.py", line 188, in run_test

    assert_equal(n1.getbalance(), 340)

  File "D:\a\bitcoin\bitcoin\test\functional\test_framework\util.py", line 77, in assert_equal

    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))

AssertionError: not(10.00000000 == 340)

2024-12-20T12:54:33.474000Z TestFramework (INFO): Stopping nodes

Is it reproducible?

Is it reproducible?

It seems intermittent.

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:

diff --git a/test/functional/wallet_assumeutxo.py b/test/functional/wallet_assumeutxo.py
index 76cd2097a3..d0c74b123f 100755
--- a/test/functional/wallet_assumeutxo.py
+++ b/test/functional/wallet_assumeutxo.py
@@ -149,6 +149,16 @@ class AssumeutxoTest(BitcoinTestFramework):
         # Balance of w wallet is still still 0 because n1 has not synced yet
         assert_equal(n1.getbalance(), 0)
 
+        # Directly sync nodes to display balance bug
+        self.connect_nodes(0, 1);
+        self.wait_until(lambda: len(n1.getchainstates()['chainstates']) == 1)
+        # wrong balance after background sync finished
+        self.wait_until(lambda:(n1.getbalance() == 1))
+        # any next block that arrives will correct the balance
+        self.generate(n1, nblocks=1, sync_fun=self.no_op)
+        self.wait_until(lambda:(n1.getbalance() == 34))
+        exit()
+
         self.log.info("Backup from before the snapshot height can't be loaded during background sync")
         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.

See #31556 for a fix.