Coinstats index corrupted after invalidateblock and clean shutdown

vostrnad commented at 7:05 pm on May 2, 2023: none

Is there an existing issue for this?

I have searched the existing issues

Current behaviour

I tried running invalidateblock on a block a few hundred blocks behind the chain tip. While this command was running, I also ran stop and the node apparently shut down cleanly:

 02023-05-02T18:31:17Z UpdateTip: new best=00000000000000000003518599da068e68cca93b3d74bcc25e240229f7a86293 height=787853 version=0x23608000 log2_work=94.154224 tx=830684559 date='2023-05-01T19:44:33Z' progress=0.999711 cache=18.5MiB(104112txo)
 12023-05-02T18:31:21Z UpdateTip: new best=00000000000000000003e3254dbe0c37627c01adf82b4582d40cdd9d40065e3b height=787852 version=0x3359c000 log2_work=94.154210 tx=830681309 date='2023-05-01T19:16:08Z' progress=0.999705 cache=19.1MiB(109976txo)
 22023-05-02T18:31:27Z UpdateTip: new best=00000000000000000001722f9798d3009acf467a22b15324cbd3a730df7b81d2 height=787851 version=0x32264000 log2_work=94.154197 tx=830676978 date='2023-05-01T19:08:10Z' progress=0.999704 cache=20.2MiB(119117txo)
 32023-05-02T18:31:31Z UpdateTip: new best=00000000000000000004fb8e18d4aa564406708db9dcf2e5a19841fb5243c2c5 height=787850 version=0x20000000 log2_work=94.154183 tx=830673049 date='2023-05-01T18:56:27Z' progress=0.999701 cache=21.2MiB(127290txo)
 42023-05-02T18:31:32Z addcon thread exit
 52023-05-02T18:31:32Z Shutdown: In progress...
 62023-05-02T18:31:32Z net thread exit
 72023-05-02T18:31:34Z opencon thread exit
 82023-05-02T18:31:35Z UpdateTip: new best=00000000000000000003b325732590843673742d287f78699f018e4be50f72b6 height=787849 version=0x20000000 log2_work=94.154169 tx=830668665 date='2023-05-01T18:42:36Z' progress=0.999698 cache=22.4MiB(137486txo)
 92023-05-02T18:31:35Z msghand thread exit
102023-05-02T18:31:35Z InvalidChainFound: invalid block=00000000000000000004fb8e18d4aa564406708db9dcf2e5a19841fb5243c2c5  height=787850  log2_work=94.154183  date=2023-05-01T18:56:27Z
112023-05-02T18:31:35Z InvalidChainFound:  current best=00000000000000000003b325732590843673742d287f78699f018e4be50f72b6  height=787849  log2_work=94.154169  date=2023-05-01T18:42:36Z
122023-05-02T18:31:35Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat started
132023-05-02T18:31:35Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
142023-05-02T18:31:35Z scheduler thread exit
152023-05-02T18:31:35Z Writing 0 unbroadcast transactions to disk.
162023-05-02T18:31:35Z Dumped mempool: 0.00475053s to copy, 0.0185962s to dump
172023-05-02T18:31:35Z Shutdown: done

However, after starting the node again, a corrupted coinstats index is detected and the node shuts down:

 02023-05-02T18:31:53Z Bitcoin Core version v24.0.1 (release build)
 12023-05-02T18:31:53Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -upnp=0
 22023-05-02T18:31:53Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -natpmp=0
 32023-05-02T18:31:53Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -discover=0
 42023-05-02T18:31:53Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -listenonion=0
 52023-05-02T18:31:53Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -i2pacceptincoming=0
 62023-05-02T18:31:53Z Using the 'x86_shani(1way,2way)' SHA256 implementation
 72023-05-02T18:31:53Z Using RdSeed as an additional entropy source
 82023-05-02T18:31:53Z Using RdRand as an additional entropy source
 92023-05-02T18:31:53Z Default data directory /home/***/.bitcoin
102023-05-02T18:31:53Z Using data directory /home/***/.bitcoin
112023-05-02T18:31:53Z Config file: /home/***/.bitcoin/bitcoin.conf
122023-05-02T18:31:53Z Config file arg: coinstatsindex="1"
132023-05-02T18:31:53Z Config file arg: dbcache="50"
142023-05-02T18:31:53Z Config file arg: disablewallet="1"
152023-05-02T18:31:53Z Config file arg: listen="0"
162023-05-02T18:31:53Z Config file arg: maxmempool="50"
172023-05-02T18:31:53Z Config file arg: maxorphantx="10"
182023-05-02T18:31:53Z Config file arg: prune="550"
192023-05-02T18:31:53Z Config file arg: rpcauth=****
202023-05-02T18:31:53Z Config file arg: server="1"
212023-05-02T18:31:53Z Config file arg: zmqpubhashblock="tcp://127.0.0.1:28332"
222023-05-02T18:31:53Z Command-line arg: daemon=""
232023-05-02T18:31:53Z Using at most 125 automatic connections (1024 file descriptors available)
242023-05-02T18:31:53Z Using 16 MiB out of 16 MiB requested for signature cache, able to store 524288 elements
252023-05-02T18:31:53Z Using 16 MiB out of 16 MiB requested for script execution cache, able to store 524288 elements
262023-05-02T18:31:53Z Script verification uses 1 additional threads
272023-05-02T18:31:53Z Wallet disabled!
282023-05-02T18:31:53Z scheduler thread start
292023-05-02T18:31:53Z [http] creating work queue of depth 16
302023-05-02T18:31:53Z Using random cookie authentication.
312023-05-02T18:31:53Z Generated RPC authentication cookie /home/***/.bitcoin/.cookie
322023-05-02T18:31:53Z Using rpcauth authentication.
332023-05-02T18:31:53Z [http] starting 4 worker threads
342023-05-02T18:31:53Z Using /16 prefix for IP bucketing
352023-05-02T18:31:53Z init message: Loading P2P addresses…
362023-05-02T18:31:53Z Loaded 67959 addresses from peers.dat  156ms
372023-05-02T18:31:53Z init message: Loading banlist…
382023-05-02T18:31:53Z SetNetworkActive: true
392023-05-02T18:31:53Z Cache configuration:
402023-05-02T18:31:53Z * Using 2.0 MiB for block index database
412023-05-02T18:31:53Z * Using 8.0 MiB for chain state database
422023-05-02T18:31:53Z * Using 40.0 MiB for in-memory UTXO set (plus up to 47.7 MiB of unused mempool space)
432023-05-02T18:31:53Z init message: Loading block index…
442023-05-02T18:31:53Z Assuming ancestors of block 00000000000000000009c97098b5295f7e5f183ac811fb5d1534040adb93cabd have valid signatures.
452023-05-02T18:31:53Z Setting nMinimumChainWork=00000000000000000000000000000000000000003404ba0801921119f903495e
462023-05-02T18:31:53Z Prune configured to target 550 MiB on disk for block and undo files.
472023-05-02T18:31:53Z Switching active chainstate to Chainstate [ibd] @ height -1 (null)
482023-05-02T18:31:53Z Opening LevelDB in /home/***/.bitcoin/blocks/index
492023-05-02T18:31:53Z Opened LevelDB successfully
502023-05-02T18:31:53Z Using obfuscation key for /home/***/.bitcoin/blocks/index: 0000000000000000
512023-05-02T18:31:56Z LoadBlockIndexDB: last block file = 3574
522023-05-02T18:31:56Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=70, size=115412032, heights=787490...787975, time=2023-04-29...2023-05-02)
532023-05-02T18:31:56Z Checking all blk files are present...
542023-05-02T18:31:56Z LoadBlockIndexDB(): Block files have previously been pruned
552023-05-02T18:31:57Z Opening LevelDB in /home/***/.bitcoin/chainstate
562023-05-02T18:31:57Z Opened LevelDB successfully
572023-05-02T18:31:57Z Using obfuscation key for /home/***/.bitcoin/chainstate: 7b252df66097f97f
582023-05-02T18:31:57Z Loaded best chain: hashBestChain=00000000000000000003b325732590843673742d287f78699f018e4be50f72b6 height=787849 date=2023-05-01T18:42:36Z progress=0.999698
592023-05-02T18:31:57Z init message: Verifying blocks…
602023-05-02T18:31:57Z Verifying last 6 blocks at level 3
612023-05-02T18:31:57Z [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE].
622023-05-02T18:32:21Z No coin database inconsistencies in last 6 blocks (22146 transactions)
632023-05-02T18:32:21Z  block index           27842ms
642023-05-02T18:32:21Z Opening LevelDB in /home/***/.bitcoin/indexes/coinstats/db
652023-05-02T18:32:21Z Opened LevelDB successfully
662023-05-02T18:32:21Z Using obfuscation key for /home/***/.bitcoin/indexes/coinstats/db: 0000000000000000
672023-05-02T18:32:21Z ERROR: CustomInit: Cannot read current coinstatsindex state; index may be corrupted
682023-05-02T18:32:21Z Shutdown: In progress...
692023-05-02T18:32:21Z scheduler thread exit
702023-05-02T18:32:21Z Shutdown: done

Expected behaviour

Coinstats index should not be corrupted.

Steps to reproduce

With coinstats index turned on run invalidateblock and while that’s running run stop.

Relevant log output

No response

How did you obtain Bitcoin Core

Pre-built binaries

What version of Bitcoin Core are you using?

v24.0.1

Operating system and version

Debian GNU/Linux 11 (bullseye)

Machine specifications

No response

willcl-ark commented at 12:43 pm on May 3, 2023: member

Thanks for this report @vostrnad.

I have reproduced this issue sucessfully and am looking into the root cause.

 02023-05-03T12:40:07Z InvalidChainFound: invalid block=0000002217824449bf6b7d8f9bc3cdb3407927712114a462376a991fea9f74af  height=141000  log2_work=40.653563  date=2023-05-01T05:44:57Z
 12023-05-03T12:40:07Z InvalidChainFound:  current best=0000010052eca20e8afb2fd62cb0b07ef3cbbaffe43068c825f2e09f80b2ab35  height=140999  log2_work=40.653552  date=2023-05-01T05:37:27Z
 22023-05-03T12:40:08Z tor: Thread interrupt
 32023-05-03T12:40:08Z Shutdown: In progress...
 42023-05-03T12:40:08Z opencon thread exit
 52023-05-03T12:40:08Z torcontrol thread exit
 62023-05-03T12:40:08Z addcon thread exit
 72023-05-03T12:40:08Z net thread exit
 82023-05-03T12:40:08Z msghand thread exit
 92023-05-03T12:40:08Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat started
102023-05-03T12:40:08Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.01s)
112023-05-03T12:40:08Z scheduler thread exit
122023-05-03T12:40:08Z Writing 0 unbroadcast transactions to disk.
132023-05-03T12:40:08Z Dumped mempool: 9.263e-06s to copy, 0.00437868s to dump
142023-05-03T12:40:08Z Shutdown: done
15
16
17
18
19
202023-05-03T12:40:23Z Bitcoin Core version v24.0.1 (release build)
212023-05-03T12:40:23Z Signet derived magic (message start): 0a03cf40
222023-05-03T12:40:23Z Using the 'x86_shani(1way,2way)' SHA256 implementation
232023-05-03T12:40:23Z Using RdSeed as an additional entropy source
242023-05-03T12:40:23Z Using RdRand as an additional entropy source
252023-05-03T12:40:23Z Default data directory /home/will/.bitcoin
262023-05-03T12:40:23Z Using data directory /home/will/.bitcoin/signet
272023-05-03T12:40:23Z Config file: /home/will/.bitcoin/bitcoin.conf
282023-05-03T12:40:23Z Config file arg: [signet] blocksdir="/media/will/crucial1/bitcoin"
292023-05-03T12:40:23Z Config file arg: [signet] coinstatsindex="1"
302023-05-03T12:40:23Z Config file arg: [signet] daemon="1"
312023-05-03T12:40:23Z Config file arg: [signet] fallbackfee="0.00001000"
322023-05-03T12:40:23Z Config file arg: [signet] listen="1"
332023-05-03T12:40:23Z Config file arg: [signet] port="38333"
342023-05-03T12:40:23Z Config file arg: [signet] rpcpassword=****
352023-05-03T12:40:23Z Config file arg: [signet] rpcuser=****
362023-05-03T12:40:23Z Config file arg: [signet] server="1"
372023-05-03T12:40:23Z Command-line arg: signet=""
382023-05-03T12:40:23Z Using at most 125 automatic connections (1024 file descriptors available)
392023-05-03T12:40:23Z Using 16 MiB out of 16 MiB requested for signature cache, able to store 524288 elements
402023-05-03T12:40:23Z Using 16 MiB out of 16 MiB requested for script execution cache, able to store 524288 elements
412023-05-03T12:40:23Z Script verification uses 15 additional threads
422023-05-03T12:40:23Z scheduler thread start
432023-05-03T12:40:23Z [http] creating work queue of depth 16
442023-05-03T12:40:23Z Config options rpcuser and rpcpassword will soon be deprecated. Locally-run instances may remove rpcuser to use cookie-based auth, or may be replaced with rpcauth. Please see share/rpcauth for rpcauth auth generation.
452023-05-03T12:40:23Z [http] starting 4 worker threads
462023-05-03T12:40:23Z Using wallet directory /home/will/.bitcoin/signet/wallets
472023-05-03T12:40:23Z init message: Verifying wallet(s)…
482023-05-03T12:40:23Z Using /16 prefix for IP bucketing
492023-05-03T12:40:23Z init message: Loading P2P addresses…
502023-05-03T12:40:23Z Loaded 2022 addresses from peers.dat  20ms
512023-05-03T12:40:23Z init message: Loading banlist…
522023-05-03T12:40:23Z SetNetworkActive: true
532023-05-03T12:40:23Z Cache configuration:
542023-05-03T12:40:23Z * Using 2.0 MiB for block index database
552023-05-03T12:40:23Z * Using 8.0 MiB for chain state database
562023-05-03T12:40:23Z * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
572023-05-03T12:40:23Z init message: Loading block index…
582023-05-03T12:40:23Z Assuming ancestors of block 000000d1a0e224fa4679d2fb2187ba55431c284fa1b74cbc8cfda866fd4d2c09 have valid signatures.
592023-05-03T12:40:23Z Setting nMinimumChainWork=000000000000000000000000000000000000000000000000000001291fc22898
602023-05-03T12:40:23Z Switching active chainstate to Chainstate [ibd] @ height -1 (null)
612023-05-03T12:40:23Z Opening LevelDB in /home/will/.bitcoin/signet/blocks/index
622023-05-03T12:40:23Z Opened LevelDB successfully
632023-05-03T12:40:23Z Using obfuscation key for /home/will/.bitcoin/signet/blocks/index: 0000000000000000
642023-05-03T12:40:24Z LoadBlockIndexDB: last block file = 4
652023-05-03T12:40:24Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=32218, size=117995451, heights=109096...141321, time=2022-09-22...2023-05-03)
662023-05-03T12:40:24Z Checking all blk files are present...
672023-05-03T12:40:25Z Opening LevelDB in /home/will/.bitcoin/signet/chainstate
682023-05-03T12:40:25Z Opened LevelDB successfully
692023-05-03T12:40:25Z Using obfuscation key for /home/will/.bitcoin/signet/chainstate: 279a4349025ab109
702023-05-03T12:40:25Z Loaded best chain: hashBestChain=0000010052eca20e8afb2fd62cb0b07ef3cbbaffe43068c825f2e09f80b2ab35 height=140999 date=2023-05-01T05:37:27Z progress=0.997935
712023-05-03T12:40:25Z init message: Verifying blocks…
722023-05-03T12:40:25Z Verifying last 6 blocks at level 3
732023-05-03T12:40:25Z [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE].
742023-05-03T12:40:25Z No coin database inconsistencies in last 6 blocks (9 transactions)
752023-05-03T12:40:25Z  block index            2022ms
762023-05-03T12:40:25Z Opening LevelDB in /home/will/.bitcoin/signet/indexes/coinstats/db
772023-05-03T12:40:25Z Opened LevelDB successfully
782023-05-03T12:40:25Z Using obfuscation key for /home/will/.bitcoin/signet/indexes/coinstats/db: 0000000000000000
792023-05-03T12:40:25Z ERROR: CustomInit: Cannot read current coinstatsindex state; index may be corrupted
802023-05-03T12:40:25Z Shutdown: In progress...
812023-05-03T12:40:25Z scheduler thread exit
822023-05-03T12:40:25Z Shutdown: done

edit: I think this even occurred on my node after the invalidateblock command had finished

fanquake commented at 12:45 pm on May 3, 2023: member

cc @mzumsande

mzumsande commented at 6:36 pm on May 3, 2023: contributor

I haven’t looked into the root cause yet, but some quick tests seem to suggest that this could be fixed by #25193 - at least I could reproduce it with master, but not with that branch.

mzumsande commented at 9:00 pm on May 3, 2023: contributor

A more detailed explanation: The indexes have a Rewind() function to reverse the effects of blocks (which calls CustomRewind for the coinstats index). However, once the index is synced, Rewind will only be invoked through BlockConnected() validationinterface signals, not when blocks are disconnected. So when invalidateblock is called, the state of the coinstatsindex will still point to the old block (unless a new block is connected before the node is stopped).

After restarting the node, the current logic in master sets the best block to the fork in the chain based on a locator - however, it doesn’t rewind the state of the coinstatsindex as would be necessary to prevent corruption. With commit 5fafeec47185cd3fd0c079fcdc77f037971e8188 of #25193, we’d keep on loading the previous best block, and ThreadSync would then do the rewinding to the invalidated block - that way, corruption shouldn’t be possible.

An additional change that would make sense to me is to let the indexes react to BlockDisconnected signals (by rewinding right when they happen). That would rewind the index immediately, and not only after the next startup, and seems useful in general. Of course it wouldn’t help when the node is stopped midway through invalidateblock.

willcl-ark commented at 8:38 am on May 4, 2023: member

Thanks @mzumsande, I can confirm that that patch does fix the described issue for me too.

ryanofsky closed this on May 17, 2023

bitcoin locked this on May 16, 2024

Coinstats index corrupted after invalidateblock and clean shutdown #27558