ERROR: ReadRawBlockFromDisk: Read from block file failed: CAutoFile::read: end of file: iostream error for CBlockDiskPos(nFile=0, nPos=16830050) #14933

Bitcoin-qt.exe suddenly stopped working. The symptom looked like #14447, an "assertion failed" error message popped up. debug.log said:

ERROR: ReadRawBlockFromDisk: Read from block file failed: CAutoFile::read: end of file: iostream error for CBlockDiskPos(nFile=0, nPos=16830050)

Bitcoin Core v0.17.0.1 x64 Windows 10 17763 x64

Running Electrum Personal Server with Cygwin x64.

bitcoin.conf:

txindex=1
server=1
addresstype=p2sh-segwit
rpcbind=127.0.0.1:8332
rpcuser=USERNAME
rpcpassword=PASSWORD
rpcallowip=127.0.0.1
zmqpubrawblock=tcp://127.0.0.1:18501
zmqpubrawtx=tcp://127.0.0.1:18501
externalip=DDNS_DOMAIN_NAME
discover=1

Specified -blocksdir by command line to migrate block storage to HDD.

Looks like a standard disk corruption... Since everything gets validated, Bitcoin Core is very good in spotting all sorts of corruption on lower levels.

Looks like a standard disk corruption...

After that crash, I tried to restart bitcoin-qt, it launched successfully, without any complain. The S.M.A.R.T data didn't report anything wrong, either.

debug.log:

2018-12-12T04:07:21Z Pre-allocating up to position 0x5000000 in blk01459.dat
2018-12-12T04:07:21Z UpdateTip: new best=0000000000000000002fc33ac46fe482972e0e9e479377e5ce1f5b6d13ec4b58 height=553481 version=0x20000000 log2_work=90.117717 tx=363835988 date='2018-12-12T04:06:32Z' progress=1.000000 cache=76.2MiB(566931txo) warning='最后100个区块中的34个包含未知的版本号'
2018-12-12T04:14:40Z UpdateTip: new best=0000000000000000002fa928a8c2ecf79f1d8f962745c49a8ba4f98e32de3f05 height=553482 version=0x20000000 log2_work=90.117743 tx=363838797 date='2018-12-12T04:14:27Z' progress=1.000000 cache=76.5MiB(569323txo) warning='最后100个区块中的33个包含未知的版本号'
2018-12-12T04:15:44Z UpdateTip: new best=000000000000000000189ffff78b77d6c408a36b99098c41fb4be2d4ff6ffceb height=553483 version=0x20000000 log2_work=90.117769 tx=363839216 date='2018-12-12T04:15:40Z' progress=1.000000 cache=76.5MiB(569447txo) warning='最后100个区块中的33个包含未知的版本号'
2018-12-12T04:24:19Z socket recv error [远程主机强迫关闭了一个现有的连接。(This string was stored as GBK, I've converted it to UTF-8)]  (10054)
2018-12-12T04:24:48Z New outbound peer connected: version: 70015, blocks=553483, peer=1707
2018-12-12T04:30:31Z socket receive timeout: 1201s
2018-12-12T04:46:45Z Potential stale tip detected, will try using extra outbound peer (last tip update: 1861 seconds ago)
2018-12-12T04:47:07Z New outbound peer connected: version: 70015, blocks=553483, peer=1769
2018-12-12T04:52:56Z Pre-allocating up to position 0xa00000 in rev01459.dat
2018-12-12T04:52:56Z UpdateTip: new best=0000000000000000001cf0ebf56562a16461f1fea099950fcec09e1f2686b8a7 height=553484 version=0x20000000 log2_work=90.117795 tx=363842195 date='2018-12-12T04:51:50Z' progress=1.000000 cache=8.4MiB(12725txo) warning='最后100个区块中的33个包含未知的版本号'
2018-12-12T05:02:45Z UpdateTip: new best=00000000000000000001396826d49b72e9e1061665039553ac783a26a75e6dfc height=553485 version=0x20000000 log2_work=90.117821 tx=363844765 date='2018-12-12T05:02:33Z' progress=1.000000 cache=9.5MiB(21314txo) warning='最后100个区块中的32个包含未知的版本号'
2018-12-12T05:09:16Z ERROR: ReadRawBlockFromDisk: Read from block file failed: CAutoFile::read: end of file: iostream error for CBlockDiskPos(nFile=0, nPos=16830050)
2018-12-12T05:10:13Z 




2018-12-12T05:10:13Z Bitcoin Core version v0.17.0.1 (release build)
2018-12-12T05:10:13Z InitParameterInteraction: parameter interaction: -whitelistforcerelay=1 -> setting -whitelistrelay=1
2018-12-12T05:10:14Z Assuming ancestors of block 0000000000000000002e63058c023a9a1de233554f28c7b21380b6c9003f36a8 have valid signatures.
2018-12-12T05:10:14Z Setting nMinimumChainWork=0000000000000000000000000000000000000000028822fef1c230963535a90d
2018-12-12T05:10:14Z Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
2018-12-12T05:10:14Z Using RdRand as an additional entropy source
2018-12-12T05:10:15Z Default data directory C:\Users\user\AppData\Roaming\Bitcoin
2018-12-12T05:10:15Z Using data directory S:\Bitcoin
2018-12-12T05:10:15Z Using config file S:\Bitcoin\bitcoin.conf
2018-12-12T05:10:15Z Using at most 125 automatic connections (2048 file descriptors available)
2018-12-12T05:10:15Z GUI: "registerShutdownBlockReason: Successfully registered: Bitcoin Core 尚未安全退出"
2018-12-12T05:10:15Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2018-12-12T05:10:15Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2018-12-12T05:10:15Z Using 8 threads for script verification
2018-12-12T05:10:15Z scheduler thread start
2018-12-12T05:10:15Z HTTP: creating work queue of depth 16
2018-12-12T05:10:15Z 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.
2018-12-12T05:10:15Z HTTP: starting 4 worker threads
2018-12-12T05:10:15Z Using wallet directory S:\Bitcoin
2018-12-12T05:10:15Z init message: 正在检测钱包的完整性...
2018-12-12T05:10:15Z Using BerkeleyDB version Berkeley DB 4.8.30: (April  9, 2010)
2018-12-12T05:10:15Z Using wallet wallet.dat
2018-12-12T05:10:15Z BerkeleyEnvironment::Open: LogDir=S:\Bitcoin\database ErrorFile=S:\Bitcoin\db.log
2018-12-12T05:10:15Z AddLocal(117.65.15.106:8333,4)
2018-12-12T05:10:15Z Cache configuration:
2018-12-12T05:10:15Z * Using 2.0MiB for block index database
2018-12-12T05:10:15Z * Using 15.8MiB for transaction index database
2018-12-12T05:10:15Z * Using 8.0MiB for chain state database
2018-12-12T05:10:15Z * Using 102.2MiB for in-memory UTXO set (plus up to 286.1MiB of unused mempool space)
2018-12-12T05:10:15Z init message: 正在加载区块索引...
2018-12-12T05:10:15Z Opening LevelDB in S:\Bitcoin\blocks\index
2018-12-12T05:10:15Z Opened LevelDB successfully
2018-12-12T05:10:15Z Using obfuscation key for S:\Bitcoin\blocks\index: 0000000000000000
2018-12-12T05:10:18Z LoadBlockIndexDB: last block file = 1459
2018-12-12T05:10:18Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=63, size=70173409, heights=553421...553483, time=2018-12-11...2018-12-12)
2018-12-12T05:10:18Z Checking all blk files are present...
2018-12-12T05:10:19Z Opening LevelDB in S:\Bitcoin\chainstate
2018-12-12T05:10:19Z Opened LevelDB successfully
2018-12-12T05:10:19Z Using obfuscation key for S:\Bitcoin\chainstate: d2e993e4daed8602
2018-12-12T05:10:20Z Loaded best chain: hashBestChain=000000000000000000189ffff78b77d6c408a36b99098c41fb4be2d4ff6ffceb height=553483 date=2018-12-12T04:15:40Z progress=0.999978
2018-12-12T05:10:20Z init message: 回退区块
2018-12-12T05:10:21Z init message: 正在验证区块...
2018-12-12T05:10:21Z Verifying last 6 blocks at level 3
2018-12-12T05:10:21Z [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE].
2018-12-12T05:10:23Z No coin database inconsistencies in last 6 blocks (8507 transactions)
2018-12-12T05:10:23Z  block index            8173ms
2018-12-12T05:10:23Z Opening LevelDB in S:\Bitcoin\indexes\txindex
2018-12-12T05:10:23Z Opened LevelDB successfully
2018-12-12T05:10:23Z Using obfuscation key for S:\Bitcoin\indexes\txindex: 0000000000000000
2018-12-12T05:10:23Z txindex thread start
2018-12-12T05:10:23Z txindex is enabled at height 553483
2018-12-12T05:10:23Z txindex thread exit
2018-12-12T05:10:23Z init message: 正在加载钱包...
2018-12-12T05:10:23Z [default wallet] nFileVersion = 170001
2018-12-12T05:10:23Z [default wallet] Keys: 0 plaintext, 4016 encrypted, 8018 w/ metadata, 4016 total. Unknown wallet records: 1
2018-12-12T05:10:23Z [default wallet] Wallet completed loading in              78ms
2018-12-12T05:10:23Z [default wallet] setKeyPool.size() = 1999
2018-12-12T05:10:23Z [default wallet] mapWallet.size() = 18
2018-12-12T05:10:23Z [default wallet] mapAddressBook.size() = 4019
2018-12-12T05:10:23Z mapBlockIndex.size() = 553488
2018-12-12T05:10:23Z nBestHeight = 553483
2018-12-12T05:10:23Z torcontrol thread start
2018-12-12T05:10:23Z upnp thread start
2018-12-12T05:10:23Z Bound to [::]:8333
2018-12-12T05:10:23Z Bound to 0.0.0.0:8333
2018-12-12T05:10:23Z init message: 正在加载P2P地址...
2018-12-12T05:10:23Z Imported mempool transactions from disk: 572 succeeded, 0 failed, 0 expired, 0 already there
2018-12-12T05:10:24Z Loaded 70317 addresses from peers.dat  203ms
2018-12-12T05:10:24Z init message: 正在加载黑名单...
2018-12-12T05:10:24Z init message: 正在启动网络线程...
2018-12-12T05:10:24Z net thread start
2018-12-12T05:10:24Z dnsseed thread start
2018-12-12T05:10:24Z addcon thread start
2018-12-12T05:10:24Z opencon thread start
2018-12-12T05:10:24Z init message: 加载完成

BTW: I came across some problem pasting the log above...😓 The log file contains Chinese charaters with different encoding - both UTF8 and GBK. When I was trying to copy them to the browser, I found that the GBK-encoded Chinese character string "远程主机强迫关闭了一个现有的连接。"(The remote host has forcibly closed an existing connection.) turned into a glitch.

@jonasschnelli This problem came up once again. The assertion came from here: https://github.com/bitcoin/bitcoin/blob/cb52cee29d0d8be062c22e59299b8e332da340c5/src/net_processing.cpp#L1186

This time I didn't keep Electrum Personal Server running in background.

Looks really like a data corruption. What filesystem are you using? Is you disk attached over some sort of a NAS?

Please try a different (internal) disk to see where the corruption comes from.

Looks really like a data corruption.

Maybe... But I didn't come across such problem before using blocksdir. I'm going to do reindex multiple times - with or without blocksdir - to figure out the exact reason.

What filesystem are you using? Is you disk attached over some sort of a NAS? Please try a different (internal) disk to see where the corruption comes from.

NTFS with BitLocker enabled. Blocks are stored in the internal HDD, while other data is stored in the internal SSD.

Just now, I restarted bitcoin-qt.exe with -reindex -rescan, then I found Deserialize or I/O error in debug.log:

2018-12-20T08:32:35Z init message: 正在加载P2P地址...
2018-12-20T08:32:36Z Loaded 70571 addresses from peers.dat  251ms
2018-12-20T08:32:36Z init message: 正在加载黑名单...
2018-12-20T08:32:36Z init message: 正在启动网络线程...
2018-12-20T08:32:36Z net thread start
2018-12-20T08:32:36Z dnsseed thread start
2018-12-20T08:32:36Z addcon thread start
2018-12-20T08:32:36Z opencon thread start
2018-12-20T08:32:36Z init message: 加载完成
2018-12-20T08:32:36Z msghand thread start
2018-12-20T08:32:36Z GUI: Platform customization: "windows"
2018-12-20T08:32:36Z GUI: PaymentServer::LoadRootCAs: Loaded  119  root certificates
2018-12-20T08:32:37Z No valid UPnP IGDs found
2018-12-20T08:32:37Z upnp thread exit
2018-12-20T08:32:47Z Loading addresses from DNS seeds (could take a while)
2018-12-20T08:32:47Z New outbound peer connected: version: 70015, blocks=554598, peer=0
2018-12-20T08:32:49Z 162 addresses found from DNS seeds
2018-12-20T08:32:49Z dnsseed thread exit
2018-12-20T08:32:54Z New outbound peer connected: version: 70015, blocks=554598, peer=1
2018-12-20T08:33:00Z New outbound peer connected: version: 70015, blocks=554598, peer=3
2018-12-20T08:33:00Z LoadExternalBlockFile: Deserialize or I/O error - CBufferedFile::Fill: end of file: iostream error
2018-12-20T08:33:00Z Loaded 59344 blocks from external file in 25213ms
2018-12-20T08:33:00Z Reindexing block file blk00001.dat...
2018-12-20T08:33:02Z Reindexing block file blk00002.dat...
2018-12-20T08:33:03Z Reindexing block file blk00003.dat...
2018-12-20T08:33:05Z Reindexing block file blk00004.dat...
2018-12-20T08:33:06Z Reindexing block file blk00005.dat...

tail of debug.log:

2018-12-20T09:05:37Z Reindexing block file blk01468.dat...
2018-12-20T09:05:38Z Reindexing finished
2018-12-20T09:05:38Z Pre-allocating up to position 0x100000 in rev00000.dat
2018-12-20T09:06:06Z Pre-allocating up to position 0x200000 in rev00000.dat
2018-12-20T09:06:30Z Pre-allocating up to position 0x300000 in rev00000.dat
2018-12-20T09:06:47Z Pre-allocating up to position 0x400000 in rev00000.dat
2018-12-20T09:06:48Z Imported mempool transactions from disk: 3947 succeeded, 671 failed, 0 expired, 0 already there
2018-12-20T09:07:47Z Pre-allocating up to position 0x2000000 in blk00000.dat
2018-12-20T09:07:56Z Peer=9 is stalling block download, disconnecting

Now I'm waiting for the download/sync process to complete.

@jonasschnelli 1st pass of reindex: All blkXXXXX.dat files had "last modified" timestamps of two month ago (should be the date I got initial sync done), before they got overwritten by freshly downloaded data - so does it mean that my HDD is indeedly faulted? If so, why didn't I receive any warning/error report from Bitcoin Core during this reindex process? CrystalDiskInfo didn't report anything wrong, either. I also found something suspicious in debug.log such as Deserialize or I/O error (pasted above), but I'm still not sure whether it is related with hardware problems. 2nd pass of reindex: Everything went smoothly, except that the weird Deserialize or I/O error appeared in debug.log again:

2018-12-20T16:43:23Z init message: 加载完成
2018-12-20T16:43:23Z opencon thread start
2018-12-20T16:43:23Z msghand thread start
2018-12-20T16:43:23Z GUI: Platform customization: "windows"
2018-12-20T16:43:23Z GUI: PaymentServer::LoadRootCAs: Loaded  119  root certificates
2018-12-20T16:43:25Z No valid UPnP IGDs found
2018-12-20T16:43:25Z upnp thread exit
2018-12-20T16:43:29Z New outbound peer connected: version: 70015, blocks=554655, peer=0
2018-12-20T16:43:34Z Loading addresses from DNS seeds (could take a while)
2018-12-20T16:43:36Z 161 addresses found from DNS seeds
2018-12-20T16:43:36Z dnsseed thread exit
2018-12-20T16:43:47Z LoadExternalBlockFile: Deserialize or I/O error - Read attempted past buffer limit: iostream error
2018-12-20T16:43:58Z New outbound peer connected: version: 70015, blocks=554655, peer=1
2018-12-20T16:44:11Z New outbound peer connected: version: 70015, blocks=554655, peer=2
2018-12-20T16:44:17Z Loaded 119629 blocks from external file in 54223ms
2018-12-20T16:44:17Z Reindexing block file blk00001.dat...
2018-12-20T16:44:25Z Loaded 10817 blocks from external file in 8572ms
2018-12-20T16:44:25Z Reindexing block file blk00002.dat...
2018-12-20T16:44:32Z Loaded 5880 blocks from external file in 6399ms
2018-12-20T16:44:32Z Reindexing block file blk00003.dat...
2018-12-20T16:44:38Z Loaded 5856 blocks from external file in 6496ms
2018-12-20T16:44:38Z Reindexing block file blk00004.dat...
2018-12-20T16:44:44Z Loaded 5994 blocks from external file in 6098ms
2018-12-20T16:44:44Z Reindexing block file blk00005.dat...
2018-12-20T16:44:51Z Loaded 7793 blocks from external file in 7099ms

3rd pass of reindex: Before starting, I moved the datadir from SSD to HDD, then I made a NTFS junction link of indexes pointing to SSD. bitcoin-qt.exe was started without blocksdir. Again, everything went smoothly, Deserialize or I/O error also appeared in debug.log. 4th pass: Deleted all the block files. I made bitcoin-qt to do a initial sync from scratch. Everything went smoothly. This time no Deserialize or I/O error appeared. 5th pass of reindex: Before starting, I moved the datadir (except the blocks subdir) back to SSD. A blocksdir=path_to_hdd line was also added to bitcoin.conf. Similarly, everything went smoothly. No Deserialize or I/O error appeared.

I've also done read-only chkdsk on my SSD and HDD, no problem was found. BTW, A BSOD once happened to me recently, which might be the cause of data corruption.

Cannot reproduce. Closing this.