Fully validated AssumeUTXO starts revalidating after restart

l0rinc commented at 11:19 pm on March 10, 2025: contributor

After fully validating the recent update to AssumeUTXO until 880k in the background:

 02025-03-08T09:58:19Z UpdateTip: new best=00000000000000000001b5d3d95fe8153004c0a8e4f5fbd08e4fead4298897ff height=886840 version=0x246ea000 log2_work=95.483816 tx=1163409635 date='2025-03-08T09:58:50Z' progress=1.000000 cache=136.3MiB(966526txo)
 12025-03-08T10:00:03Z [background validation] UpdateTip: new best=0000000000000000000159629ce4f039b1ec8287b2942acd13b1bde150343c2c height=878000 version=0x20306000 log2_work=95.369968 tx=1140089747 date='2025-01-05T22:13:51Z' progress=0.969631 cache=4287.4MiB(28845142txo)
 22025-03-08T10:01:05Z New block-relay-only v2 peer connected: version: 70016, blocks=886840, peer=179
 32025-03-08T10:13:17Z New block-relay-only v1 peer connected: version: 70016, blocks=886840, peer=180
 42025-03-08T10:13:25Z [background validation] UpdateTip: new best=000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880 height=880000 version=0x268be000 log2_work=95.396383 tx=1145604538 date='2025-01-20T01:42:23Z' progress=0.976559 cache=5145.5MiB(35241631txo)
 52025-03-08T10:13:25Z [warning] Flushing large (5 GiB) UTXO set to disk, it may take several minutes
 62025-03-08T10:17:26Z [snapshot] computing UTXO stats for background chainstate to validate snapshot - this could take a few minutes
 7*2025-03-08T10:32:23Z [snapshot] snapshot beginning at 000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880 has been fully validated*
 82025-03-08T10:32:23Z [snapshot] allocating all cache to the snapshot chainstate
 92025-03-08T10:32:23Z Opening LevelDB in ~/bitcoin/chainstate_snapshot
102025-03-08T10:32:23Z Opened LevelDB successfully
112025-03-08T10:32:23Z Using obfuscation key for ~/bitcoin/chainstate_snapshot: 67720f7b17c65cc7
122025-03-08T10:32:23Z [Chainstate [snapshot] @ height 886840 (00000000000000000001b5d3d95fe8153004c0a8e4f5fbd08e4fead4298897ff)] resized coinsdb cache to 8.0 MiB
132025-03-08T10:32:23Z [Chainstate [snapshot] @ height 886840 (00000000000000000001b5d3d95fe8153004c0a8e4f5fbd08e4fead4298897ff)] resized coinstip cache to 9990.0 MiB
142025-03-08T10:32:23Z [snapshot] re-enabling NODE_NETWORK services
152025-03-08T10:32:23Z [snapshot] restarting indexes
162025-03-08T10:32:23Z Flushed fee estimates to fee_estimates.dat.
172025-03-08T10:32:23Z Saw new header hash=000000000000000000012962b376caa8878516abce31ca476e569e70fb7fb964 height=886841
18[...]
192025-03-08T10:49:53Z UpdateTip: new best=0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b height=886849 version=0x20400000 log2_work=95.483928 tx=1163418786 date='2025-03-08T10:49:44Z' progress=1.000000 cache=140.5MiB(1002553txo)
202025-03-08T10:50:10Z tor: Thread interrupt
212025-03-08T10:50:10Z torcontrol thread exit
222025-03-08T10:50:10Z addcon thread exit
232025-03-08T10:50:10Z opencon thread exit
242025-03-08T10:50:10Z Shutdown: In progress...
252025-03-08T10:50:11Z net thread exit
262025-03-08T10:50:11Z msghand thread exit
272025-03-08T10:50:11Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat started
282025-03-08T10:50:11Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
292025-03-08T10:50:11Z scheduler thread exit
302025-03-08T10:50:11Z Writing 2481 mempool transactions to file...
312025-03-08T10:50:12Z Writing 0 unbroadcast transactions to file.
322025-03-08T10:50:12Z Dumped mempool: 0.003s to copy, 0.890s to dump, 37229324 bytes dumped to file
332025-03-08T10:50:12Z Flushed fee estimates to fee_estimates.dat.
342025-03-08T10:50:16Z Shutdown: done

When I restart the node, it seems to retrigger the snapshot validation:

 0[...]
 12025-03-10T23:07:38Z init message: Loading block index…
 22025-03-10T23:07:38Z Assuming ancestors of block 00000000000000000001b658dd1120e82e66d2790811f89ede9742ada3ed6d77 have valid signatures.
 32025-03-10T23:07:38Z Setting nMinimumChainWork=0000000000000000000000000000000000000000b1f3b93b65b16d035a82be84
 42025-03-10T23:07:38Z [snapshot] detected active snapshot chainstate (~/bitcoin/chainstate_snapshot) - loading
 52025-03-10T23:07:38Z [snapshot] switching active chainstate to Chainstate [snapshot] @ height -1 (null)
 62025-03-10T23:07:47Z [snapshot] set m_chain_tx_count=1145604538 for 000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880
 72025-03-10T23:07:53Z LoadBlockIndexDB: last block file = 4817
 82025-03-10T23:07:53Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=53, size=92824607, heights=879796...879999, time=2025-01-18...2025-01-20)
 92025-03-10T23:07:53Z Checking all blk files are present...
102025-03-10T23:08:00Z Initializing chainstate Chainstate [ibd] @ height -1 (null)
112025-03-10T23:08:00Z Opening LevelDB in ~/bitcoin/chainstate
122025-03-10T23:08:00Z Opened LevelDB successfully
132025-03-10T23:08:00Z Using obfuscation key for ~/bitcoin/chainstate: ab3f38a96955367d
142025-03-10T23:08:00Z Loaded best chain: hashBestChain=000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880 height=880000 date=2025-01-20T01:42:23Z progress=0.983528
152025-03-10T23:08:00Z Initializing chainstate Chainstate [snapshot] @ height -1 (null)
162025-03-10T23:08:00Z Opening LevelDB in ~/bitcoin/chainstate_snapshot
172025-03-10T23:08:00Z Opened LevelDB successfully
182025-03-10T23:08:00Z Using obfuscation key for ~/bitcoin/chainstate_snapshot: 67720f7b17c65cc7
192025-03-10T23:08:00Z Loaded best chain: hashBestChain=0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b height=886849 date=2025-03-08T10:49:44Z progress=0.999139
202025-03-10T23:08:00Z Opening LevelDB in ~/bitcoin/chainstate
212025-03-10T23:08:00Z Opened LevelDB successfully
222025-03-10T23:08:00Z Using obfuscation key for ~/bitcoin/chainstate: ab3f38a96955367d
232025-03-10T23:08:00Z [Chainstate [ibd] @ height 880000 (000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880)] resized coinsdb cache to 0.4 MiB
242025-03-10T23:08:00Z [Chainstate [ibd] @ height 880000 (000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880)] resized coinstip cache to 22.0 MiB
252025-03-10T23:08:00Z Opening LevelDB in ~/bitcoin/chainstate_snapshot
262025-03-10T23:08:00Z Opened LevelDB successfully
272025-03-10T23:08:00Z Using obfuscation key for ~/bitcoin/chainstate_snapshot: 67720f7b17c65cc7
282025-03-10T23:08:00Z [Chainstate [snapshot] @ height 886849 (0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b)] resized coinsdb cache to 7.6 MiB
292025-03-10T23:08:00Z [Chainstate [snapshot] @ height 886849 (0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b)] resized coinstip cache to 418.0 MiB
30*2025-03-10T23:08:00Z [snapshot] computing UTXO stats for background chainstate to validate snapshot - this could take a few minutes*
31[cancelled revalidation]
322025-03-10T23:08:08Z [error] UTXO snapshot failed to validate. Restart to resume normal initial block download, or try loading a different snapshot.
332025-03-10T23:08:08Z Shutdown: In progress...
342025-03-10T23:08:08Z scheduler thread exit
352025-03-10T23:08:08Z Flushed fee estimates to fee_estimates.dat.
36Error: UTXO snapshot failed to validate. Restart to resume normal initial block download, or try loading a different snapshot.
372025-03-10T23:08:08Z Shutdown: done
38
39Process finished with exit code 1

This seems like an error, after fully validating it I would expect all traces of AssumeUTXO seeding to be gone.

mzumsande commented at 11:46 pm on March 10, 2025: contributor

What do you mean with “[cancelled it]”, did you abort bitcoind with Ctrl+C or similar?

As described in the design document, all traces of AssumeUtxo are only gone after the next restart. Not sure why the UTXO stats check is repeated, maybe to prevent circumventing the check by terminating before, or something similar.

Sjors commented at 8:07 am on March 11, 2025: member

From the logs it seems the background sync was finished and the node was cleanly shut down. But the error suggests something was missed in the shutdown sequence?

There’s still some open issues related to AssumeUTXO that may or may not be relevant here: #31382, #30610, #30214.

cc @ryanofsky, @TheCharlatan

It seems very unlikely that this is related to the new snapshot added in #31969.

l0rinc commented at 10:07 am on March 11, 2025: contributor

all traces of AssumeUtxo are only gone after the next restart

Yes, after fully validating I have restarted the node and it wants to validate again, which I haven’t done (cancelled the process)

mzumsande commented at 1:24 pm on March 11, 2025: contributor

I’m pretty sure this is being done on purpose, see this comment, so I wouldn’t call it a bug.

But that doesn’t mean it’s ideal - if we want to skip the second UTXO stats check after restart, I think it would be wrong to just skip it from the init code path - instead I think we’d need to persist additional validation progress to disk (so that a user that Ctrl+C’s out of the first check doesn’t skip the check with the next restart).

How long does the UTXO stats computation for mainnet take with current snapshots - still a few minutes?

Sjors commented at 1:35 pm on March 11, 2025: member

@mzumsande from that code comment it seems (the delayed) cleaning up is intentional, but not redoing validation.

fjahr commented at 1:38 pm on March 11, 2025: contributor

I’m pretty sure this is being done on purpose, see this comment, so I wouldn’t call it a bug.

Yes, and there is more context in the comment on the implementation: https://github.com/bitcoin/bitcoin/blob/45719390a1434ad7377a5ed05dcd73028130cf2d/src/validation.cpp#L6102

fjahr commented at 1:42 pm on March 11, 2025: contributor

I guess that the revalidation is expected could be added in the design doc here as well: https://github.com/bitcoin/bitcoin/blob/45719390a1434ad7377a5ed05dcd73028130cf2d/doc/design/assumeutxo.md#bitcoind-restarts-sometime-after-snapshot-validation-has-completed

l0rinc commented at 2:11 pm on March 11, 2025: contributor

Thanks for the context @mzumsande, @Sjors, @fjahr.

so that a user that Ctrl+C’s out of the first check

The first check finished fully (took me several nights), but now if I want to use that node, I still can’t because it’s validating again.

I didn’t cancel it this time, the new validation after restart took 23.5 more minutes (it’s frustrating to wait here, maybe #31645 helps), telling me yet again that has been fully validated:

  0[...]
  12025-03-11T13:27:26Z init message: Loading block index…
  22025-03-11T13:27:26Z Assuming ancestors of block 00000000000000000001b658dd1120e82e66d2790811f89ede9742ada3ed6d77 have valid signatures.
  32025-03-11T13:27:26Z Setting nMinimumChainWork=0000000000000000000000000000000000000000b1f3b93b65b16d035a82be84
  42025-03-11T13:27:26Z [snapshot] detected active snapshot chainstate (bitcoin/chainstate_snapshot) - loading
  52025-03-11T13:27:26Z [snapshot] switching active chainstate to Chainstate [snapshot] @ height -1 (null)
  62025-03-11T13:27:39Z [snapshot] set m_chain_tx_count=1145604538 for 000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880
  72025-03-11T13:27:48Z LoadBlockIndexDB: last block file = 4817
  82025-03-11T13:27:49Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=53, size=92824607, heights=879796...879999, time=2025-01-18...2025-01-20)
  92025-03-11T13:27:49Z Checking all blk files are present...
 102025-03-11T13:27:59Z Initializing chainstate Chainstate [ibd] @ height -1 (null)
 112025-03-11T13:27:59Z Opening LevelDB in bitcoin/chainstate
 122025-03-11T13:27:59Z Opened LevelDB successfully
 132025-03-11T13:27:59Z Using obfuscation key for bitcoin/chainstate: ab3f38a96955367d
 142025-03-11T13:28:00Z Loaded best chain: hashBestChain=000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880 height=880000 date=2025-01-20T01:42:23Z progress=0.983327
 152025-03-11T13:28:00Z Initializing chainstate Chainstate [snapshot] @ height -1 (null)
 162025-03-11T13:28:00Z Opening LevelDB in bitcoin/chainstate_snapshot
 172025-03-11T13:28:00Z Opened LevelDB successfully
 182025-03-11T13:28:00Z Using obfuscation key for bitcoin/chainstate_snapshot: 67720f7b17c65cc7
 192025-03-11T13:28:00Z Loaded best chain: hashBestChain=0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b height=886849 date=2025-03-08T10:49:44Z progress=0.998934
 202025-03-11T13:28:00Z Opening LevelDB in bitcoin/chainstate
 212025-03-11T13:28:01Z Opened LevelDB successfully
 222025-03-11T13:28:01Z Using obfuscation key for bitcoin/chainstate: ab3f38a96955367d
 232025-03-11T13:28:01Z [Chainstate [ibd] @ height 880000 (000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880)] resized coinsdb cache to 0.4 MiB
 242025-03-11T13:28:01Z [Chainstate [ibd] @ height 880000 (000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880)] resized coinstip cache to 22.0 MiB
 252025-03-11T13:28:01Z Opening LevelDB in bitcoin/chainstate_snapshot
 262025-03-11T13:28:01Z Opened LevelDB successfully
 272025-03-11T13:28:01Z Using obfuscation key for bitcoin/chainstate_snapshot: 67720f7b17c65cc7
 282025-03-11T13:28:01Z [Chainstate [snapshot] @ height 886849 (0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b)] resized coinsdb cache to 7.6 MiB
 292025-03-11T13:28:01Z [Chainstate [snapshot] @ height 886849 (0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b)] resized coinstip cache to 418.0 MiB
 30*2025-03-11T13:28:01Z [snapshot] computing UTXO stats for background chainstate to validate snapshot - this could take a few minutes*
 31*2025-03-11T13:51:22Z [snapshot] snapshot beginning at 000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880 has been fully validated*
 322025-03-11T13:51:22Z [snapshot] allocating all cache to the snapshot chainstate
 332025-03-11T13:51:22Z Opening LevelDB in bitcoin/chainstate_snapshot
 342025-03-11T13:51:22Z Opened LevelDB successfully
 352025-03-11T13:51:22Z Using obfuscation key for bitcoin/chainstate_snapshot: 67720f7b17c65cc7
 362025-03-11T13:51:22Z [Chainstate [snapshot] @ height 886849 (0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b)] resized coinsdb cache to 8.0 MiB
 372025-03-11T13:51:22Z [Chainstate [snapshot] @ height 886849 (0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b)] resized coinstip cache to 440.0 MiB
 382025-03-11T13:51:22Z [snapshot] cleaning up unneeded background chainstate, then reinitializing
 392025-03-11T13:51:22Z [snapshot] deleting background chainstate directory (now unnecessary) (bitcoin/chainstate)
 402025-03-11T13:51:22Z [snapshot] moving snapshot chainstate (bitcoin/chainstate_snapshot) to default chainstate directory (bitcoin/chainstate)
 412025-03-11T13:51:22Z Removing leveldb dir at bitcoin/chainstate_todelete
 422025-03-11T13:51:23Z [snapshot] deleted background chainstate directory (bitcoin/chainstate)
 432025-03-11T13:51:45Z LoadBlockIndexDB: last block file = 4817
 442025-03-11T13:51:45Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=53, size=92824607, heights=879796...879999, time=2025-01-18...2025-01-20)
 452025-03-11T13:51:45Z Checking all blk files are present...
 462025-03-11T13:51:51Z Initializing chainstate Chainstate [ibd] @ height -1 (null)
 472025-03-11T13:51:51Z Opening LevelDB in bitcoin/chainstate
 482025-03-11T13:51:51Z Opened LevelDB successfully
 492025-03-11T13:51:51Z Using obfuscation key for bitcoin/chainstate: 67720f7b17c65cc7
 502025-03-11T13:51:51Z Loaded best chain: hashBestChain=0000000000000000000069aed813954edef3972f9c8ee36632f3113a72dad42b height=886849 date=2025-03-08T10:49:44Z progress=0.998928
 512025-03-11T13:51:51Z init message: Verifying blocks…
 522025-03-11T13:51:51Z Verifying last 6 blocks at level 3
 532025-03-11T13:51:51Z Verification progress: 0%
 542025-03-11T13:51:52Z Verification progress: 16%
 552025-03-11T13:51:53Z Verification progress: 33%
 562025-03-11T13:51:53Z Verification progress: 50%
 572025-03-11T13:51:54Z Verification progress: 66%
 582025-03-11T13:51:54Z Verification progress: 83%
 592025-03-11T13:51:55Z Verification progress: 99%
 602025-03-11T13:51:55Z Verification: No coin database inconsistencies in last 6 blocks (4258 transactions)
 612025-03-11T13:51:55Z Block index and chainstate loaded
 622025-03-11T13:51:55Z Setting NODE_NETWORK on non-prune mode
 632025-03-11T13:51:55Z block tree size = 886850
 642025-03-11T13:51:55Z nBestHeight = 886849
 652025-03-11T13:51:55Z initload thread start
 662025-03-11T13:51:55Z torcontrol thread start
 672025-03-11T13:51:55Z Bound to 127.0.0.1:8334
 682025-03-11T13:51:55Z Bound to [::]:8333
 692025-03-11T13:51:55Z Bound to 0.0.0.0:8333
 702025-03-11T13:51:55Z Loading 2481 mempool transactions from file...
 712025-03-11T13:51:55Z Loaded 2 addresses from "anchors.dat"
 722025-03-11T13:51:55Z 2 block-relay-only anchors will be tried for connections.
 732025-03-11T13:51:55Z init message: Starting network threads…
 742025-03-11T13:51:55Z net thread start
 752025-03-11T13:51:55Z dnsseed thread start
 762025-03-11T13:51:55Z addcon thread start
 772025-03-11T13:51:55Z Waiting 300 seconds before querying DNS seeds.
 782025-03-11T13:51:55Z opencon thread start
 792025-03-11T13:51:55Z msghand thread start
 802025-03-11T13:51:55Z init message: Done loading
 812025-03-11T13:51:56Z New block-relay-only v1 peer connected: version: 70016, blocks=887330, peer=0
 822025-03-11T13:51:57Z Synchronizing blockheaders, height: 887330 (~100.00%)
 832025-03-11T13:51:58Z New block-relay-only v2 peer connected: version: 70016, blocks=887330, peer=1
 842025-03-11T13:51:58Z New outbound-full-relay v2 peer connected: version: 70016, blocks=887330, peer=2
 852025-03-11T13:52:08Z UpdateTip: new best=00000000000000000001bc8d0bd8e993c8a950e34a9fe759bb69d4f6fb3ff601 height=886850 version=0x20000000 log2_work=95.483940 tx=1163419416 date='2025-03-08T10:52:27Z' progress=0.998929 cache=5.7MiB(41768txo)
 862025-03-11T13:52:11Z UpdateTip: new best=0000000000000000000098bb1d32f1db914e955c90a86f30691086470a336f91 height=886851 version=0x20000000 log2_work=95.483953 tx=1163423117 date='2025-03-08T11:22:58Z' progress=0.998936 cache=8.9MiB(64502txo)
 872025-03-11T13:52:13Z UpdateTip: new best=0000000000000000000216605d549288023c708ec74cef2955bc03d4566fb754 height=886852 version=0x27d9c000 log2_work=95.483965 tx=1163425811 date='2025-03-08T11:34:56Z' progress=0.998939 cache=10.7MiB(79356txo)
 882025-03-11T13:52:15Z UpdateTip: new best=000000000000000000003f6193d78eb1cb084ba739184ca177820e7e373241fb height=886853 version=0x24170000 log2_work=95.483977 tx=1163427357 date='2025-03-08T11:41:24Z' progress=0.998940 cache=12.5MiB(93006txo)
 892025-03-11T13:52:19Z UpdateTip: new best=000000000000000000024825fa49ef89d063e87deae43f15d5d8323b461b239e height=886854 version=0x26000000 log2_work=95.483990 tx=1163427517 date='2025-03-08T11:42:06Z' progress=0.998941 cache=14.8MiB(104619txo)
 902025-03-11T13:52:19Z Progress loading mempool transactions from file: 10% (tried 249, 2232 remaining)
 912025-03-11T13:52:21Z UpdateTip: new best=00000000000000000000a1463806753da06c0b843fa40c0444721533605e1801 height=886855 version=0x21c18000 log2_work=95.484002 tx=1163430820 date='2025-03-08T12:01:23Z' progress=0.998945 cache=16.9MiB(121461txo)
 922025-03-11T13:52:25Z UpdateTip: new best=000000000000000000012e657fa846faa9d0006a3948dcd2a39ecbce21726848 height=886856 version=0x3fffe000 log2_work=95.484014 tx=1163433043 date='2025-03-08T12:12:41Z' progress=0.998948 cache=19.2MiB(140436txo)
 932025-03-11T13:52:31Z UpdateTip: new best=00000000000000000001cad81aac3de33314551dda3ef92944f4ccd12f847937 height=886857 version=0x3a000000 log2_work=95.484027 tx=1163436098 date='2025-03-08T12:25:33Z' progress=0.998951 cache=23.1MiB(170213txo)
 942025-03-11T13:52:32Z New outbound-full-relay v2 peer connected: version: 70016, blocks=887330, peer=3
 952025-03-11T13:52:34Z New outbound-full-relay v2 peer connected: version: 70016, blocks=887330, peer=5
 962025-03-11T13:52:38Z Progress loading mempool transactions from file: 20% (tried 497, 1984 remaining)
 972025-03-11T13:52:39Z P2P peers available. Skipped DNS seeding.
 982025-03-11T13:52:39Z dnsseed thread exit
 992025-03-11T13:52:40Z UpdateTip: new best=00000000000000000001a4b0a704457e12191036d6499a18bd0b0e9ee1239ec5 height=886858 version=0x27a48000 log2_work=95.484039 tx=1163437354 date='2025-03-08T12:32:00Z' progress=0.998952 cache=29.5MiB(210586txo)
1002025-03-11T13:52:42Z New outbound-full-relay v1 peer connected: version: 70016, blocks=887330, peer=7
1012025-03-11T13:52:46Z UpdateTip: new best=00000000000000000000d8573406a7297e2a3336cc03b5ad99267a2dfff93ed7 height=886859 version=0x30000000 log2_work=95.484051 tx=1163440929 date='2025-03-08T13:01:21Z' progress=0.998959 cache=34.3MiB(243502txo)
1022025-03-11T13:52:46Z New outbound-full-relay v2 peer connected: version: 70016, blocks=887330, peer=9
1032025-03-11T13:52:52Z UpdateTip: new best=0000000000000000000267c4fbb29182edf534d40d7a65082126203600691bb7 height=886860 version=0x2739e000 log2_work=95.484064 tx=1163444622 date='2025-03-08T13:08:23Z' progress=0.998961 cache=38.9MiB(277068txo)
1042025-03-11T13:52:54Z New outbound-full-relay v2 peer connected: version: 70016, blocks=887330, peer=13
1052025-03-11T13:52:58Z UpdateTip: new best=000000000000000000023a03aa87dfacf8af4a2d2998bc833c5cf1a420245f19 height=886861 version=0x20800000 log2_work=95.484076 tx=1163446006 date='2025-03-08T13:10:29Z' progress=0.998962 cache=42.7MiB(308818txo)
1062025-03-11T13:53:02Z UpdateTip: new best=0000000000000000000099fdced634a90b5db9873e1343286174163202c99c84 height=886862 version=0x25de2000 log2_work=95.484089 tx=1163450400 date='2025-03-08T13:13:36Z' progress=0.998962 cache=45.4MiB(328728txo)
1072025-03-11T13:53:02Z Progress loading mempool transactions from file: 30% (tried 745, 1736 remaining)
1082025-03-11T13:53:07Z New outbound-full-relay v1 peer connected: version: 70016, blocks=887330, peer=14
1092025-03-11T13:53:07Z New outbound-full-relay v1 peer connected: version: 70016, blocks=887330, peer=15
1102025-03-11T13:53:10Z UpdateTip: new best=00000000000000000000237471f0d5c35d042fa79f83fff00d928fef9ae806b0 height=886863 version=0x24282000 log2_work=95.484101 tx=1163455028 date='2025-03-08T13:24:30Z' progress=0.998965 cache=50.6MiB(368964txo)
1112025-03-11T13:53:11Z Progress loading mempool transactions from file: 40% (tried 993, 1488 remaining)
1122025-03-11T13:53:12Z Progress loading mempool transactions from file: 50% (tried 1241, 1240 remaining)
1132025-03-11T13:53:12Z Progress loading mempool transactions from file: 60% (tried 1489, 992 remaining)
1142025-03-11T13:53:13Z Progress loading mempool transactions from file: 70% (tried 1737, 744 remaining)
1152025-03-11T13:53:13Z Progress loading mempool transactions from file: 80% (tried 1985, 496 remaining)
1162025-03-11T13:53:13Z Progress loading mempool transactions from file: 90% (tried 2233, 248 remaining)
1172025-03-11T13:53:14Z Imported mempool transactions from file: 2354 succeeded, 127 failed, 0 expired, 0 already there, 0 waiting for initial broadcast
1182025-03-11T13:53:14Z initload thread exit
1192025-03-11T13:53:18Z UpdateTip: new best=00000000000000000001d30ecf16085b9c35f95510a19e08ac5779c6e268872b height=886864 version=0x20006000 log2_work=95.484113 tx=1163459502 date='2025-03-08T13:39:08Z' progress=0.998968 cache=53.2MiB(387901txo)
1202025-03-11T13:53:27Z UpdateTip: new best=0000000000000000000079a14b7bcddfcb0c14695976a6cd6c32a0940707e78b height=886865 version=0x2194c000 log2_work=95.484126 tx=1163461688 date='2025-03-08T13:40:23Z' progress=0.998969 cache=54.0MiB(394261txo)
1212025-03-11T13:53:28Z UpdateTip: new best=000000000000000000003d18f17b2169024941402cdea04ecc626c80acb0e89a height=886866 version=0x2b2d8000 log2_work=95.484138 tx=1163465087 date='2025-03-08T13:53:11Z' progress=0.998972 cache=55.1MiB(402887txo)
1222025-03-11T13:53:28Z UpdateTip: new best=00000000000000000000c00bd3d85620ef4bda2947d2ba88084ffd3aab7e3d0e height=886867 version=0x20102000 log2_work=95.484150 tx=1163469194 date='2025-03-08T14:13:03Z' progress=0.998976 cache=59.6MiB(412811txo)
1232025-03-11T13:53:29Z UpdateTip: new best=00000000000000000001b97ac94fb6f856e8e24a1cd60e51dc4453449331819b height=886868 version=0x2318c000 log2_work=95.484163 tx=1163473194 date='2025-03-08T14:19:21Z' progress=0.998978 cache=60.7MiB(421109txo)
1242025-03-11T13:53:30Z UpdateTip: new best=000000000000000000012c3a92ccdb68121d7f057d02ea93ffbc47b7f7339b22 height=886869 version=0x2ced0000 log2_work=95.484175 tx=1163477257 date='2025-03-08T14:26:28Z' progress=0.998979 cache=61.9MiB(428630txo)
1252025-03-11T13:53:31Z UpdateTip: new best=000000000000000000000f7e132315c7413e2b0e9d911e70d389f61b3015f03a height=886870 version=0x20d86000 log2_work=95.484187 tx=1163480480 date='2025-03-08T14:30:09Z' progress=0.998980 cache=62.8MiB(434619txo)
1262025-03-11T13:53:41Z New outbound-full-relay v1 peer connected: version: 70016, blocks=887330, peer=17
1272025-03-11T13:53:43Z UpdateTip: new best=00000000000000000000f24d62e2974dd598a84f0531bc21360b24baddd25973 height=886871 version=0x2012a000 log2_work=95.484200 tx=1163483324 date='2025-03-08T14:30:20Z' progress=0.998980 cache=63.6MiB(440837txo)
1282025-03-11T13:53:58Z Synchronizing blockheaders, height: 887331 (~100.00%)
1292025-03-11T13:54:14Z UpdateTip: new best=0000000000000000000050e1e989fb3b6fd38ba21692da8c4b97c3a4e9d77f9c height=886872 version=0x28c54000 log2_work=95.484212 tx=1163484525 date='2025-03-08T14:32:39Z' progress=0.998981 cache=64.1MiB(444953txo)
1302025-03-11T13:54:42Z UpdateTip: new best=000000000000000000010e28d4693b477da839300a598eb3551c02fd0fd2e9f4 height=886873 version=0x2e87e000 log2_work=95.484225 tx=1163484964 date='2025-03-08T14:34:05Z' progress=0.998981 cache=64.9MiB(450601txo)
1312025-03-11T13:54:46Z New outbound-full-relay v2 peer connected: version: 70016, blocks=887331, peer=18
1322025-03-11T13:55:06Z UpdateTip: new best=000000000000000000027aab9b0c69b12a2fdb0705e49c1673557aaa78997c6c height=886874 version=0x23a7a000 log2_work=95.484237 tx=1163488893 date='2025-03-08T14:59:41Z' progress=0.998987 cache=66.3MiB(461780txo)
1332025-03-11T13:55:24Z UpdateTip: new best=00000000000000000001e0b27f66401eff799d0f00433d04f5c41ee0759c4bbf height=886875 version=0x2aec4000 log2_work=95.484249 tx=1163491105 date='2025-03-08T15:02:06Z' progress=0.998988 cache=66.8MiB(466128txo)
1342025-03-11T13:55:49Z UpdateTip: new best=00000000000000000001a835f33b3682ff2a791818012018166e3c9270733c84 height=886876 version=0x236f4000 log2_work=95.484262 tx=1163493698 date='2025-03-08T15:13:41Z' progress=0.998990 cache=67.9MiB(473837txo)
1352025-03-11T13:56:07Z tor: Thread interrupt
1362025-03-11T13:56:07Z Shutdown: In progress...
1372025-03-11T13:56:07Z torcontrol thread exit
1382025-03-11T13:56:07Z addcon thread exit
1392025-03-11T13:56:07Z opencon thread exit
1402025-03-11T13:56:07Z net thread exit
1412025-03-11T13:56:07Z UpdateTip: new best=00000000000000000001d408572cb2afd223a9725e4790584496c20f4f0c0c62 height=886877 version=0x2e3ba000 log2_work=95.484274 tx=1163496262 date='2025-03-08T15:21:35Z' progress=0.998992 cache=68.7MiB(480984txo)
1422025-03-11T13:56:07Z msghand thread exit
1432025-03-11T13:56:07Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat started
1442025-03-11T13:56:07Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
1452025-03-11T13:56:07Z scheduler thread exit
1462025-03-11T13:56:07Z Writing 2076 mempool transactions to file...
1472025-03-11T13:56:08Z Writing 0 unbroadcast transactions to file.
1482025-03-11T13:56:08Z Dumped mempool: 0.003s to copy, 1.239s to dump, 30830490 bytes dumped to file
1492025-03-11T13:56:08Z Flushed fee estimates to fee_estimates.dat.
1502025-03-11T13:56:11Z Shutdown: done

Restarted after this multiple times and the node seems to be functional now.

We should either make this clear in the logs that a restart is needed to finish the process (if a restart and revalidation is needed the first validation wasn’t “full” in my opinion) and update the design docs or figure out how to clean it up after full validation finishes.

mzumsande commented at 6:07 pm on March 11, 2025: contributor

23.5 more minutes

That’s way longer than I thought it would take but I guess the UTXO set has grown a lot over the last years.

My idea of a fix would be to set some kind of DB flag such as (DB_ASSUMEUTXO_VALIDATED) in the background chainstate after the assumeutxo hash was successfully validated the first time, and then skip the check at next startup if that flag was set. I think I’ll try that out / open a PR if it works.

l0rinc commented at 7:40 pm on March 11, 2025: contributor

23 minutes on my M4 Max - likely ~40 minutes on commodity hardware

fjahr commented at 11:53 pm on March 11, 2025: contributor

23 minutes on my M4 Max - likely ~40 minutes on commodity hardware

Huh, that sounds wrong, were you using a dev/debug build? Or is this probably caused by low resource allocation?

This is me on a vanilla M4 and gettoutsetinfo shouldn’t do much different in total time than verifying the hash of the snapshot since calculating the hash should be the only expensive part…

 0$ time build/src/bitcoin-cli gettxoutsetinfo
 1{
 2  "height": 887381,
 3  "bestblock": "000000000000000000023ce7c194520dd6ef38a1d2633f8a726e3a7346549c09",
 4  "txouts": 174298133,
 5  "bogosize": 13621053583,
 6  "hash_serialized_3": "141ef6fe62a3790ee8c1cb3d953ed28a08dbf1c3f657f108f29aa40772d4ef63",
 7  "total_amount": 19835347.85105552,
 8  "transactions": 120619254,
 9  "disk_size": 11960167091
10}
11
12real	0m56.478s
13user	0m0.001s
14sys	0m0.002s

l0rinc commented at 11:48 am on March 12, 2025: contributor

Thanks for the clarification @fjahr, I thought the reverification causes the utxo set to dump again (it’s why I though #31645 could help) - which incidentally took about the same time for me in previous runs.

It’s possible that this final run (when I didn’t cancel the reverification) was indeed in debug mode - (though gettxoutsetinfo in Debug “only” takes 13 minutes). @mzumsande, the DB_ASSUMEUTXO_VALIDATED experiment may not be necessary in light of this, probably just a better message preparing the user that “final validation” isn’t actually the last time we’re validating it.

fjahr commented at 0:03 am on March 14, 2025: contributor

I would still be concept ACK on a PR from @mzumsande if it doesn’t turn out to be too complicated. I think James built in a lot of belts and suspenders because initially not everyone was fully on board with the concept and it makes sense to clean this up now if it’s just redundant work.

willcl-ark added the label Feature on Mar 19, 2025

willcl-ark added the label Validation on Mar 19, 2025

Fully validated AssumeUTXO starts revalidating after restart #32029