Bitcoin core start-up issue with undo data

laanwj commented at 4:14 pm on October 28, 2014: member

Today, running master, letting an instance that hasn’t run for a while catch up with the chain, I suddenly have problems with corrupted undo data due to “end of file” errors.

02014-10-28 15:49:13 Verifying last 288 blocks at level 3
12014-10-28 15:49:23 ERROR: ReadFromDisk : Deserialize or I/O error - CAutoFile::read : end of file
22014-10-28 15:49:23 ERROR: VerifyDB() : *** found bad undo data at 324562, hash=0000000000000000092e4ee01f6c144f4a97bf1307e1c5e7bd49f49328c28f35

When starting with checklevel=0, the error is bypassed, however the next start of the program it fails in another place:

02014-10-28 15:53:06 Verifying last 288 blocks at level 3
12014-10-28 15:53:09 ERROR: ReadFromDisk : Deserialize or I/O error - CAutoFile::read : end of file
22014-10-28 15:53:09 ERROR: VerifyDB() : *** found bad undo data at 324695, hash=0000000000000000066a32130499df7e116f6467f418da77673748b0407bc30b

I again start with checklevel=0, and I get a whole slew of “UpdateTips” in AppInit2, after loading the wallet but before the start of the RPC threads and such.

02014-10-28 15:53:17 LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=85, size=26356604, heights=324524...325547, time=2014-10-09...2014-10-16)
12014-10-28 15:53:17 Checking all blk files are present...
22014-10-28 15:53:17 LoadBlockIndexDB(): transaction index disabled
32014-10-28 15:53:18 LoadBlockIndexDB(): hashBestChain=000000000000000009e2bf4621d87d730adf6a975688f854ba39d60cdd763271 height=324859 date=2014-10-11 14:31:06 progress=0.949969
4...
52014-10-28 15:53:19 UpdateTip: new best=0000000000000000185b8f003088ef1eff57ae472055a72c5d5ef07a3ba6c477  height=324860  log2_work=81.048227  tx=48668445  date=2014-10-11 14:38:47 progress=0.949985  cache=1168
6...
72014-10-28 15:54:52 UpdateTip: new best=00000000000000000db8f35a7986efdf8bc254660768b92105a717d5210a5594  height=325079  log2_work=81.067102  tx=48770279  date=2014-10-13 03:43:47 progress=0.9
854534  cache=38094
92014-10-28 15:54:52 mapBlockIndex.size() = 327377

So I wonder, is my undo data corrupted (and should I just -reindex), or could something else be going on that is worth debugging further, thinking it should have undo data for a block that hasn’t been processed yet?

rdponticelli commented at 4:34 pm on October 28, 2014: contributor

I’ve seen this problem too. I was debugging it to discard any blame on my own code, but yes, it looks like an off by one error somewhere in the undo handling code.

rdponticelli commented at 2:20 pm on November 13, 2014: contributor

Might this be related to the breakage of IsInitialBlockDownload? I think I haven’t seen this issue since I’m running #5158 in my test nodes….

sipa commented at 2:48 pm on November 13, 2014: member

This may be fixed by #5241; before that was not always a guarantee that data is synced to disk before a database record is written that refers to it. Though I would be surprised if it was introduced recently; it’s been that way since 0.8.0.

sipa commented at 2:50 pm on November 13, 2014: member

@rdponticelli Oh, IsInitialBlockDownload() not working would indeed potentially make this worse, as there used to be a sync call only when not in IBD.

laanwj commented at 11:36 am on December 5, 2014: member

Closing this, I haven’t had this issue running master for a long time.

laanwj closed this on Dec 5, 2014

unsystemizer commented at 12:48 pm on February 28, 2016: contributor

Just noticed the error in v0.12. Check level 4, as you can see. No obvious reason as far as I can tell. I haven’t used the wallet on this instance, don’t know if that may be relevant.

 0$ tail -f /blockchain/bitcoin/debug.log
 12016-02-28 12:40:57 * Using 3.0MiB for block index database
 22016-02-28 12:40:57 * Using 10.5MiB for chain state database
 32016-02-28 12:40:57 * Using 10.5MiB for in-memory UTXO set
 42016-02-28 12:40:57 init message: Loading block index...
 52016-02-28 12:40:57 Opening LevelDB in /blockchain/bitcoin/blocks/index
 62016-02-28 12:40:58 Opened LevelDB successfully
 72016-02-28 12:40:58 Using obfuscation key for /blockchain/bitcoin/blocks/index: 0000000000000000
 82016-02-28 12:40:58 Opening LevelDB in /blockchain/bitcoin/chainstate
 92016-02-28 12:40:59 Opened LevelDB successfully
102016-02-28 12:40:59 Using obfuscation key for /blockchain/bitcoin/chainstate: 0000000000000000
112016-02-28 12:41:27 LoadBlockIndexDB: last block file = 455
122016-02-28 12:41:27 LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=25, size=19372704, heights=399135...400158, time=2016-02-19...2016-02-26)
132016-02-28 12:41:27 Checking all blk files are present...
142016-02-28 12:41:28 LoadBlockIndexDB: transaction index enabled
152016-02-28 12:41:28 LoadBlockIndexDB(): address index enabled
162016-02-28 12:41:28 LoadBlockIndexDB: hashBestChain=00000000000000000163b2dc23a6bd86ba7ff0d01bafb8d8d70e6485fa313449 height=399596 date=2016-02-22 17:06:37 progress=0.995791
172016-02-28 12:41:28 init message: Verifying blocks...
182016-02-28 12:41:28 Verifying last 24 blocks at level 4
192016-02-28 12:42:17 No coin database inconsistencies in last 4 blocks (9089 transactions)
202016-02-28 12:42:17  block index           79978ms
212016-02-28 12:42:17 init message: Loading wallet...
222016-02-28 12:42:17 nFileVersion = 120000
232016-02-28 12:42:17 Keys: 102 plaintext, 0 encrypted, 102 w/ metadata, 102 total
242016-02-28 12:42:17  wallet                  171ms
252016-02-28 12:42:17 init message: Activating best chain...
262016-02-28 12:42:17 mapBlockIndex.size() = 400396
272016-02-28 12:42:17 nBestHeight = 399596
282016-02-28 12:42:17 setKeyPool.size() = 101
292016-02-28 12:42:17 mapWallet.size() = 0
302016-02-28 12:42:17 mapAddressBook.size() = 1
312016-02-28 12:42:17 torcontrol thread start
322016-02-28 12:42:17 init message: Loading addresses...
332016-02-28 12:42:17 ERROR: Read: Deserialize or I/O error - CAutoFile::read: end of file
342016-02-28 12:42:17 Invalid or missing banlist.dat; recreating
352016-02-28 12:42:17 Loaded 128 addresses from peers.dat  6ms

laanwj commented at 1:56 pm on March 3, 2016: member

@unsystemizer I read over it thrice, there’s no verification error in that log at all?

02016-02-28 12:41:28 init message: Verifying blocks...
12016-02-28 12:41:28 Verifying last 24 blocks at level 4
22016-02-28 12:42:17 No coin database inconsistencies in last 4 blocks (9089 transactions)

Also please open a new issue if you’re having problems, don’t post to an issue from years ago (which in retrospect had to do with a dying storage device).

unsystemizer commented at 2:14 pm on March 3, 2016: contributor

@laanwj - one of the questions raised in the original post was that Read: Deserialize or I/O error - CAutoFile::read: end of file was appearing even though no corruption was present, but if I misread that then it was a mistake to post a follow up on that. I didn’t intend to pollute the issue with unrelated stuff, sorry.

laanwj commented at 2:19 pm on March 3, 2016: member

That one is harmless, it has to do with peers.dat or banlist.dat which will should just be recreated next time.

MarcoFalke locked this on Sep 8, 2021

Bitcoin core start-up issue with undo data #5156