Deserialization or I/O error - ReadCompactSize() too large

[presstab]

2017-03-17 17:32:23 block time=1489706692 adjusted time=1489771943 is proof of stake=1 2017-03-17 17:32:23 ERROR: GetTransaction : Deserialize or I/O error - ReadCompactSize() : size too large 2017-03-17 17:32:23 ERROR: CheckProofOfStake() : INFO: read txPrev failed 2017-03-17 17:32:23 WARNING: ProcessBlock(): check proof-of-stake failed for block 302e0c73f8f5a28a49b1b54342f970700bab170f750781a8b8127ed41eefaeeb

[Fuzzbawls]

here is a rather long issue thread related to this (circa 2015 bitcoin core)
bitcoin#5668

[presstab]

BU guys think this is a corruption that is caused by using an SSD BitcoinUnlimited/BitcoinUnlimited#293

[sugar84]

There are 5 guys in our chat, who got the same problem few times. And all of us used HDD to install PIVX on it.
As for me I get this problem every 2-3 days
OpenSuse 13.2, 64bit

[sugar84]

sorry, one of the guys who gets this problem too often is on SDD other four are on HDD

mb i can show some useful info that could be help you in fixing bug?
some libraries versions mb

[presstab]

@sugar84 thanks for the context. A section of your debug.log file could be helpful. It will give us some context. Preferably enough to show the events before the failure so that we can determine what the state of the program was before the crash. Debug.log contains information about your ip address. Feel free to edit that out.

[sugar84]

Hello my Pivx-qt wallet was working fine, after the time it's just crashed silently. Bin was executed from the console, when pivx-qt crashed i didnt get any output there.

This is last lines from the debug.log, after the Pivx-qt crashed:

2017-03-20 16:58:37 ERROR: GetTransaction : Deserialize or I/O error - ReadCompactSize() : size too large
2017-03-20 16:58:37 ERROR: CheckProofOfStake() : INFO: read txPrev failed
2017-03-20 16:58:37 WARNING: ProcessBlock(): check proof-of-stake failed for block cd5ef43f5076288763cfe09619fbf9061bc0f1d9b0e204d6ddb810826e3c745b
2017-03-20 16:58:37 ERROR: ProcessNewBlock : AcceptBlock FAILED
2017-03-20 16:58:37 block time=1490022265 adjusted time=1490028533 is proof of stake=1
2017-03-20 16:58:37 ERROR: GetTransaction : Deserialize or I/O error - ReadCompactSize() : size too large
2017-03-20 16:58:37 ERROR: CheckProofOfStake() : INFO: read txPrev failed
2017-03-20 16:58:37 WARNING: ProcessBlock(): check proof-of-stake failed for block cd5ef43f5076288763cfe09619fbf9061bc0f1d9b0e204d6ddb810826e3c745b
2017-03-20 16:58:37 ERROR: ProcessNewBlock : AcceptBlock FAILED
2017-03-20 16:58:37 CMasternodeMan::AskForMN - Asking node for missing entry, vin: CTxIn(COutPoint(d754f7cd56dbe70f193eb63f7d008d87e88cb7019e03f529cc2f30510b8d0cae, 1),
 scriptSig=)
2017-03-20 16:58:37 block time=1490022265 adjusted time=1490028533 is proof of stake=1
2017-03-20 16:58:37 ERROR: GetTransaction : Deserialize or I/O error - ReadCompactSize() : size too large
2017-03-20 16:58:37 ERROR: CheckProofOfStake() : INFO: read txPrev failed
2017-03-20 16:58:37 WARNING: ProcessBlock(): check proof-of-stake failed for block cd5ef43f5076288763cfe09619fbf9061bc0f1d9b0e204d6ddb810826e3c745b
2017-03-20 16:58:37 ERROR: ProcessNewBlock : AcceptBlock FAILED

.... 
     a lot of same errors here
.....

2017-03-20 17:28:08 block time=1490022265 adjusted time=1490030304 is proof of stake=1
2017-03-20 17:28:08 ERROR: GetTransaction : Deserialize or I/O error - ReadCompactSize() : size too large
2017-03-20 17:28:08 ERROR: CheckProofOfStake() : INFO: read txPrev failed
2017-03-20 17:28:08 WARNING: ProcessBlock(): check proof-of-stake failed for block cd5ef43f5076288763cfe09619fbf9061bc0f1d9b0e204d6ddb810826e3c745b
2017-03-20 17:28:08 ERROR: ProcessNewBlock : AcceptBlock FAILED
2017-03-20 17:28:08 block time=1490022265 adjusted time=1490030304 is proof of stake=1
2017-03-20 17:28:08 ERROR: GetTransaction : Deserialize or I/O error - ReadCompactSize() : size too large
2017-03-20 17:28:08 ERROR: CheckProofOfStake() : INFO: read txPrev failed
2017-03-20 17:28:08 WARNING: ProcessBlock(): check proof-of-stake failed for block cd5ef43f5076288763cfe09619fbf9061bc0f1d9b0e204d6ddb810826e3c745b
2017-03-20 17:28:08 ERROR: ProcessNewBlock : AcceptBlock FAILED
2017-03-20 17:28:08 dumpaddr thread stop
2017-03-20 17:28:08 opencon thread interrupt
2017-03-20 17:28:08 keypool return 9
2017-03-20 17:28:08 ThreadStakeMinter() error 
2017-03-20 17:28:08 ThreadStakeMinter exiting,
2017-03-20 17:28:08 stakemint thread exit
2017-03-20 17:28:08 addcon thread interrupt
2017-03-20 17:28:08 net thread interrupt
2017-03-20 17:28:08 msghand thread interrupt
2017-03-20 17:28:08 PrepareShutdown: In progress...
2017-03-20 17:28:08 StopNode()
2017-03-20 17:28:09 Verifying mncache.dat format...
2017-03-20 17:28:09 ERROR: Read : Failed to open file /home/sugar/.pivx/mncache.dat
2017-03-20 17:28:09 Missing masternode cache file - mncache.dat, will try to recreate
2017-03-20 17:28:09 Writting info to mncache.dat...
2017-03-20 17:28:09 Written info to mncache.dat  112ms
2017-03-20 17:28:09   Masternodes: 1825, peers who asked us for Masternode list: 0, peers we asked for Masternode list: 0, entries in Masternode list we asked for: 2, nDsqCount: 0
2017-03-20 17:28:09 Masternode dump finished  113ms
2017-03-20 17:28:09 Verifying budget.dat format...
2017-03-20 17:28:09 ERROR: Read : Failed to open file /home/sugar/.pivx/budget.dat
2017-03-20 17:28:09 Missing budgets file - budget.dat, will try to recreate
2017-03-20 17:28:09 Writting info to budget.dat...
2017-03-20 17:28:09 Written info to budget.dat  41ms
2017-03-20 17:28:09 Budget dump finished  43ms
2017-03-20 17:28:09 Verifying mnpayments.dat format...
2017-03-20 17:28:09 ERROR: Read : Failed to open file /home/sugar/.pivx/mnpayments.dat
2017-03-20 17:28:09 Missing budgets file - mnpayments.dat, will try to recreate
2017-03-20 17:28:09 Writting info to mnpayments.dat...
2017-03-20 17:28:09 Written info to mnpayments.dat  39ms
2017-03-20 17:28:09 Budget dump finished  40ms
2017-03-20 17:28:09 Shutdown: done
2017-03-20 17:28:23 AppInit2 : parameter interaction: -listen=0 -> setting -discover=0

And this last lines after my try to restart the wallet with corrupted blockchain:

2017-03-20 17:29:06 block time=1490016199 adjusted time=1490030946 is proof of stake=1
2017-03-20 17:29:06 block time=1490016149 adjusted time=1490030946 is proof of stake=1
2017-03-20 17:29:06 block time=1490016055 adjusted time=1490030946 is proof of stake=1
2017-03-20 17:29:06 ERROR: ReadBlockFromDisk : Deserialize or I/O error - ReadCompactSize() : size too large
2017-03-20 17:29:06 ERROR: VerifyDB() : *** ReadBlockFromDisk failed at 563819, hash=8b6485ae4638c0bfd3faefdc3e6bdd28b72b595b5180f508131fb40bdd9272ad
2017-03-20 17:30:41 init message: Loading block index...
2017-03-20 17:30:41 GUI: QXcbConnection: XCB error: 3 (BadWindow), sequence: 668, resource id: 35105670, major code: 40 (TranslateCoords), minor code: 0
2017-03-20 17:30:41 Wiping LevelDB in /home/sugar/.pivx/blocks/index
2017-03-20 17:30:41 Opening LevelDB in /home/sugar/.pivx/blocks/index
2017-03-20 17:30:41 Opened LevelDB successfully
2017-03-20 17:30:41 Wiping LevelDB in /home/sugar/.pivx/chainstate
2017-03-20 17:30:41 Opening LevelDB in /home/sugar/.pivx/chainstate
2017-03-20 17:30:41 Opened LevelDB successfully
2017-03-20 17:30:41 Initializing databases...
2017-03-20 17:30:41 init message: Verifying blocks...
2017-03-20 17:30:41  block index             733ms
2017-03-20 17:30:41 init message: Loading wallet...
2017-03-20 17:30:42 nFileVersion = 2010600
2017-03-20 17:30:42 Keys: 1015 plaintext, 0 encrypted, 1015 w/ metadata, 1015 total
2017-03-20 17:30:42  wallet                  193ms
2017-03-20 17:30:42 Waiting for genesis block to be imported...
2017-03-20 17:30:42 Reindexing block file blk00000.dat...
2017-03-20 17:30:42 block time=1454124731 adjusted time=1490031042 is proof of stake=0

Hope this will help!
If you need additional info for debugging feel free to ask.

[presstab]

@sugar84 can you provide 20 or 30 lines before the very first occurrence of the error?

[presstab]

I was able to reproduce this issue. After 4 or 5 kill -9's it corrupted the chain.

2017-03-20 22:26:07 ERROR: ReadBlockFromDisk : Deserialize or I/O error - ReadCompactSize() : size too large: iostream error
2017-03-20 22:26:07 ERROR: VerifyDB() : *** ReadBlockFromDisk failed at 33936, hash=00000000019fdecd00672a91f77b205efe353dcdc15e8c09662124f573a54534
2017-03-20 22:26:07 : Corrupted block database detected.

Do you want to rebuild the block database now?
2017-03-20 22:26:07 Aborted block database rebuild. Exiting.

By adding a few more logs in some areas I see that this is triggered from the deserialization of a block at inside of ReadBlockFromDisk() https://github.com/PIVX-Project/PIVX/blob/v2.1.6-stable/src/main.cpp#L1589

Adding some more logging, I see that the deserialization is erroring on block.vtx - the transaction vector held by the block.

I have also determined that the size that is attempting to be deserialized is 3713892242, and the max allowed size is 33554432.

2017-03-20 22:26:07 ReadCompactSize(): size=3713802242

This is most likely an issue with the block position(edit: actually not). I am able to see that my client is expecting block 33936 to be located at pos 27101828 and in file blk00000.dat

Adding additional information about the block position to getblock and using a data directory that is not corrupted, shows that the position is correct.

./src/pivx-cli getblock 00000000019fdecd00672a91f77b205efe353dcdc15e8c09662124f573a54534
{
    "hash" : "00000000019fdecd00672a91f77b205efe353dcdc15e8c09662124f573a54534",
    "confirmations" : 84960,
    "size" : 1333,
    "height" : 33936,
    "blockPoS" : 27101828,
    "blockFile" : 0,
}

[sugar84]

@presstab still you need those 20-30 lines of logs or not?
they are missed =(
but i still keep my wallet opened, and on crash can post here if needed

[Fuzzbawls]

I decided to follow @presstab's presstab's lead and purposely attempt a corruption state by killing the process a few times.

I'm testing with the Qt wallet, which prompts the user if they want to abort the initialization of the program or rebuild the index (aka, reindex). Currently reindexing is non-functional (see #70), however I am running with a build of #71, which DOES allow me to recover from this issue during initialization.

[toirl]

Linux v2.1.6.0-25bad68
Hi I think I am facing the same problem here. I am using SSD.

Here is the output from my debug.log including some some lines before the first error:

2017-03-21 06:50:04 ProcessNewBlock : ACCEPTED
2017-03-21 06:50:04 block time=1489928556 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 block time=1489928556 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 block time=1489928556 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 UpdateTip: new best=c6730208e5824e18cebe3253a657706fe37cca8a90af893ed78fe562a9defa01  height=562369  log2_work=67.483985  tx=990302  date=2017-03-19 13:02:36 progress=0.995025  cache=424
2017-03-21 06:50:04 ProcessNewBlock : ACCEPTED
2017-03-21 06:50:04 block time=1489928594 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 block time=1489928594 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 block time=1489928594 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 UpdateTip: new best=852e64e5f8704147bbeb8cdad8648ecc6d9bd40f584527a912702d8ef441d605  height=562370  log2_work=67.483988  tx=990305  date=2017-03-19 13:03:14 progress=0.995027  cache=430
2017-03-21 06:50:04 ProcessNewBlock : ACCEPTED
2017-03-21 06:50:04 block time=1489928792 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 block time=1489928792 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 block time=1489928792 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 UpdateTip: new best=c864ff76351869ceae9dadbd7d9aea93495814bc0f8f3696e6b5c664449d4983  height=562371  log2_work=67.483992  tx=990308  date=2017-03-19 13:06:32 progress=0.995033  cache=450
2017-03-21 06:50:04 ProcessNewBlock : ACCEPTED
2017-03-21 06:50:04 block time=1489928893 adjusted time=1490079004 is proof of stake=1
2017-03-21 06:50:04 ERROR: GetTransaction : Deserialize or I/O error - ReadCompactSize() : size too large
2017-03-21 06:50:04 ERROR: CheckProofOfStake() : INFO: read txPrev failed
2017-03-21 06:50:04 WARNING: ProcessBlock(): check proof-of-stake failed for block 94c84583b2e99dcc7de528787d76a554102f516e219c896056c10ec75447fa27
2017-03-21 06:50:04 ERROR: ProcessNewBlock : AcceptBlock FAILE

If there is any way I can help to provide more infos to solve this issue let me know.

[presstab]

I have been able to figure out that the client actually almost always corrupts on force kill. There just isn't the correct set of checks in place for some cases, and often times the corruption is deeper in the chain than the default 288 blocks that are checked.

So from what I have observed, the typical corruption would be caused by something similar to this:
Session 1 - Syncing the block chain, client force closed and does not have proper shutdown.
Session 2 - Client loads, corruption is deeper in the chain than what is checked in VerifyDB(), or in some cases VerifyDB() isn't checking all of the items that need to be asserted. Later in Session 2 or any later session when the corrupted block is read from disk (maybe for a transaction check) it results in the incorrect block being read or the incorrect block position being read.

[sugar84]

I found what the blockchain db sometimes corrupts after the sleep/awake PC
Or other case of corrupt is kill by OOM caused by memory leaks of pivx-qt

[presstab]

See #88

This will not fix a corrupted database that was corrupted using code prior to #88 . But it will prevent the majority of corruptions that I was able to reproduce, and correct corruptions that occur with that code.

[Fuzzbawls]

Since #88 has now been merged, going to close this for now.

If the problem persists, please comment further so the issue can be re-opened.