Repository: bitcoin/bitcoin (language: cpp)

Issue:
Reindex subtly corrupts blknnnnn.dat files and causes subsequent deserialization errors
**Summary** 
When block downloads restart after a reindex of block files, spurious bytes are inserted in the blk.dat file.  A subsequent reindex will show a deserialization error in the log file.

**Test system** 
CentOS 7, Bitcoin Core v0.21.0 pre-built binaries and reproduced going back to 0.10.3!

**Problem Description**
Performing a reindex of the block files reliably introduces spurious bytes, resulting in subsequent deserialization errors.  

At the point where block downloads resume and are added to the blk.dat file, 8 extra bytes are introduced in front of the first new data block.  Depending on the scenario, these 8 bytes are either all 0's, or a valid message start string (0xf9beb4d9 "magic" sequence) followed by 4 more bytes.  Normal blocks of \<magic> \<length> \<raw block> resume after these 8 bytes.

Investigation revealed that the 4 bytes after the magic were actually the length of a previously existing block in the blk.dat file that had been overwritten.

It appears what is happening is that after reindexing, a file position is calculated for adding newly downloaded blocks, and this position is incorrectly computed to be 8 bytes beyond the proper place.  If the insert position is at the end of the file, the intervening 8 bytes are zero filled.  If the insert position overwrites pre-existing blocks, the first 8 bytes of the overwritten block(s) are left behind.

It appears the problem results from an inconsistency in the operation of FindBlockPos during reindexing, when it returns file positions at the beginning of the raw block, as opposed to the end of previous block/beginning of the magic.

The block reading algorithm is apparently able to recover and continue, so this problem is not fatal.  Inspection of the debug.log shows "LoadExternalBlockFile: Deserialize or I/O error" when it occurs.  To be clear, the first reindex doesn't show this error, but causes the problem such that a subsequent reindex will generate it.

Researching old issues, I suspect this problem contributed to symptoms observed in issues #6492 and #14933.  It also looks like like #5864 might have been an attempt to address this or a similar problem.

**Reproduction Scenarios**
These scenarios are rather contrived, but are the simplest ones I could come up with to quickly and reliably demonstrate the issue.

**Scenario 1**
To create a deterministic scenario, this example uses what I'll refer to as "canonical" block files.  That is, block files where the chain blocks are stored in-order up to the file size limit of 128M.  Thus, the canonical blk00000.dat file has the following properties:

size: 134214363
blocks: 119965 (up to height 119964)
SHA-256: fe4b764e0ce523cfce6d9e4f326e0d0977ee317a51b4a129cda707cfa4699dd7  

1) Start with a "canonical" blk00000.dat as the only file in a new data dir
2) Start up bitcoin-qt with -reindex.  
3) Once the reindex completes and block downloads resume over the network, terminate the process.

In the debug.log, you should see:
2021-03-06T21:41:52Z Leaving block file 0: CBlockFileInfo(blocks=119965, size=134214371, heights=0...119964, time=2009-01-03...2011-04-24)

Note that the size has grown by 8 bytes.  Inspection of hexdumps show 8 extra zero bytes at the end of the file.

Before reindex:
```
07fff2c0  14 9f ce 4e af a6 17 17  d9 24 b1 d0 9b 30 28 3d  |...N.....$...0(=|
07fff2d0  ee a3 f1 e3 fd 88 ac 00  00 00 00                 |...........|
```

After reindex:
```
07fff2c0  14 9f ce 4e af a6 17 17  d9 24 b1 d0 9b 30 28 3d  |...N.....$...0(=|
07fff2d0  ee a3 f1 e3 fd 88 ac 00  00 00 00 00 00 00 00 00  |................|
07fff2e0  00 00 00                                          |...|
```
In this scenario, blk00000.dat is "full", so the new block will go in blk00001.dat.  But, in the process of testing blk00000.dat to see if the new block can be appended, it appears an incorrect file pointer offset winds up adding 8 bytes to the file.

**Scenario 2 part 1**
The results of this scenario are more variable due to the random ordering of blocks resulting from parallel block downloads.

1) Start with a blk00000.dat and blk00001.dat containing out-of-order blocks from a parallel block download.
2) Perform a reindex on these block files.  
3) Wait past header synchronization until new block downloads resume over the network (blk00002.dat is created), then shut the process down.

What you should discover upon inspection of blk00001.dat is that the file has been changed, and at the point where the content changes, the spurious magic and length bytes will appear.  This will be somewhere near but not at the end of the file.  (It appears that the insert point is after the last block that could be verified to be part of the main chain; because of parallel block downloads, some remaining blocks that couldn't be attached are overwritten.)  An example from my run:

Before reindex:
```
07f788d0  88 ac 00 00 00 00 f9 be  b4 d9 ad bf 00 00 01 00  |................|
07f788e0  00 00 ea 8d fd 5c 0e 23  08 c8 b3 a6 73 61 5d fa  |.....\.#....sa].|
```
Note magic at offset 0x07f788d6, block length of 0x0000bfad, version 0x01 byte from raw block

After reindex:
```
07f788d0  88 ac 00 00 00 00 f9 be  b4 d9 ad bf 00 00 f9 be  |................|
07f788e0  b4 d9 61 bf 00 00 01 00  00 00 c3 70 ca 79 eb ed  |..a........p.y..|
```
Note magic at offset 0x07f788d6, length of 0x0000bfad as before, but now followed by another magic and a length 0x0000bf61 before getting to the version 0x01.


**Scenario 2 part 2**
1) Save a copy of the block files resulting from the end of the previous scenario.
2) Start another reindex using those files.  Again, wait until new block downloads resume, then shut down.

In the debug.log, you should find the following where the corrupted block file was processed:
2021-03-06T22:19:55Z LoadExternalBlockFile: Deserialize or I/O error - ReadCompactSize(): size too large: iostream error

Depending on exactly how things go off the rails, the error could appear as:
2021-03-06T23:07:48Z LoadExternalBlockFile: Deserialize or I/O error - Read attempted past buffer limit: iostream error

If you inspect your last block file from the first reindex and compare it to its state after the second reindex, you should find a second instance of the spurious magic+length bytes.

If you perform another reindex with the block files as they stand now, you'll get two deserialize errors in the debug log.  Each additional reindex will add another instance.


Reindex subtly corrupts blknnnnn.dat files and causes subsequent deserialization errors
**Summary** 
When block downloads restart after a reindex of block files, spurious bytes are inserted in the blk.dat file.  A subsequent reindex will show a deserialization error in the log file.

**Test system** 
CentOS 7, Bitcoin Core v0.21.0 pre-built binaries and reproduced going back to 0.10.3!

**Problem Description**
Performing a reindex of the block files reliably introduces spurious bytes, resulting in subsequent deserialization errors.  

At the point where block downloads resume and are added to the blk.dat file, 8 extra bytes are introduced in front of the first new data block.  Depending on the scenario, these 8 bytes are either all 0's, or a valid message start string (0xf9beb4d9 "magic" sequence) followed by 4 more bytes.  Normal blocks of \<magic> \<length> \<raw block> resume after these 8 bytes.

Investigation revealed that the 4 bytes after the magic were actually the length of a previously existing block in the blk.dat file that had been overwritten.

It appears what is happening is that after reindexing, a file position is calculated for adding newly downloaded blocks, and this position is incorrectly computed to be 8 bytes beyond the proper place.  If the insert position is at the end of the file, the intervening 8 bytes are zero filled.  If the insert position overwrites pre-existing blocks, the first 8 bytes of the overwritten block(s) are left behind.

It appears the problem results from an inconsistency in the operation of FindBlockPos during reindexing, when it returns file positions at the beginning of the raw block, as opposed to the end of previous block/beginning of the magic.

The block reading algorithm is apparently able to recover and continue, so this problem is not fatal.  Inspection of the debug.log shows "LoadExternalBlockFile: Deserialize or I/O error" when it occurs.  To be clear, the first reindex doesn't show this error, but causes the problem such that a subsequent reindex will generate it.

Researching old issues, I suspect this problem contributed to symptoms observed in issues #6492 and #14933.  It also looks like like #5864 might have been an attempt to address this or a similar problem.

**Reproduction Scenarios**
These scenarios are rather contrived, but are the simplest ones I could come up with to quickly and reliably demonstrate the issue.

**Scenario 1**
To create a deterministic scenario, this example uses what I'll refer to as "canonical" block files.  That is, block files where the chain blocks are stored in-order up to the file size limit of 128M.  Thus, the canonical blk00000.dat file has the following properties:

size: 134214363
blocks: 119965 (up to height 119964)
SHA-256: fe4b764e0ce523cfce6d9e4f326e0d0977ee317a51b4a129cda707cfa4699dd7  

1) Start with a "canonical" blk00000.dat as the only file in a new data dir
2) Start up bitcoin-qt with -reindex.  
3) Once the reindex completes and block downloads resume over the network, terminate the process.

In the debug.log, you should see:
2021-03-06T21:41:52Z Leaving block file 0: CBlockFileInfo(blocks=119965, size=134214371, heights=0...119964, time=2009-01-03...2011-04-24)

Note that the size has grown by 8 bytes.  Inspection of hexdumps show 8 extra zero bytes at the end of the file.

Before reindex:
```
07fff2c0  14 9f ce 4e af a6 17 17  d9 24 b1 d0 9b 30 28 3d  |...N.....$...0(=|
07fff2d0  ee a3 f1 e3 fd 88 ac 00  00 00 00                 |...........|
```

After reindex:
```
07fff2c0  14 9f ce 4e af a6 17 17  d9 24 b1 d0 9b 30 28 3d  |...N.....$...0(=|
07fff2d0  ee a3 f1 e3 fd 88 ac 00  00 00 00 00 00 00 00 00  |................|
07fff2e0  00 00 00                                          |...|
```
In this scenario, blk00000.dat is "full", so the new block will go in blk00001.dat.  But, in the process of testing blk00000.dat to see if the new block can be appended, it appears an incorrect file pointer offset winds up adding 8 bytes to the file.

**Scenario 2 part 1**
The results of this scenario are more variable due to the random ordering of blocks resulting from parallel block downloads.

1) Start with a blk00000.dat and blk00001.dat containing out-of-order blocks from a parallel block download.
2) Perform a reindex on these block files.  
3) Wait past header synchronization until new block downloads resume over the network (blk00002.dat is created), then shut the process down.

What you should discover upon inspection of blk00001.dat is that the file has been changed, and at the point where the content changes, the spurious magic and length bytes will appear.  This will be somewhere near but not at the end of the file.  (It appears that the insert point is after the last block that could be verified to be part of the main chain; because of parallel block downloads, some remaining blocks that couldn't be attached are overwritten.)  An example from my run:

Before reindex:
```
07f788d0  88 ac 00 00 00 00 f9 be  b4 d9 ad bf 00 00 01 00  |................|
07f788e0  00 00 ea 8d fd 5c 0e 23  08 c8 b3 a6 73 61 5d fa  |.....\.#....sa].|
```
Note magic at offset 0x07f788d6, block length of 0x0000bfad, version 0x01 byte from raw block

After reindex:
```
07f788d0  88 ac 00 00 00 00 f9 be  b4 d9 ad bf 00 00 f9 be  |................|
07f788e0  b4 d9 61 bf 00 00 01 00  00 00 c3 70 ca 79 eb ed  |..a........p.y..|
```
Note magic at offset 0x07f788d6, length of 0x0000bfad as before, but now followed by another magic and a length 0x0000bf61 before getting to the version 0x01.


**Scenario 2 part 2**
1) Save a copy of the block files resulting from the end of the previous scenario.
2) Start another reindex using those files.  Again, wait until new block downloads resume, then shut down.

In the debug.log, you should find the following where the corrupted block file was processed:
2021-03-06T22:19:55Z LoadExternalBlockFile: Deserialize or I/O error - ReadCompactSize(): size too large: iostream error

Depending on exactly how things go off the rails, the error could appear as:
2021-03-06T23:07:48Z LoadExternalBlockFile: Deserialize or I/O error - Read attempted past buffer limit: iostream error

If you inspect your last block file from the first reindex and compare it to its state after the second reindex, you should find a second instance of the spurious magic+length bytes.

If you perform another reindex with the block files as they stand now, you'll get two deserialize errors in the debug log.  Each additional reindex will add another instance.




Discussion / hints:
@prairiefalcon Thanks for this great detailed bug report. I have reproduced your given scenarios and can confirm that the bug still exists in the current master branch as of at least 2b5a741e98f186e50d9fbe1ceadcc8b8c91547f7. I have a fix to avoid adding the invalid data to the block files. I will look into creating a way to automatically clean up affected blk files, and will also look into updating the automated tests to catch this going forward.
@prairiefalcon Thanks for this great detailed bug report. I have reproduced your given scenarios and can confirm that the bug still exists in the current master branch as of at least 2b5a741e98f186e50d9fbe1ceadcc8b8c91547f7. I have a fix to avoid adding the invalid data to the block files. I will look into creating a way to automatically clean up affected blk files, and will also look into updating the automated tests to catch this going forward.

Fix patch:
diff --git a/src/node/blockstorage.cpp b/src/node/blockstorage.cpp
index 17ab226a30d38..826e4150fe126 100644
--- a/src/node/blockstorage.cpp
+++ b/src/node/blockstorage.cpp
@@ -788,19 +788,24 @@ bool ReadRawBlockFromDisk(std::vector<uint8_t>& block, const FlatFilePos& pos, c
     return true;
 }
 
-/** Store block on disk. If dbp is non-nullptr, the file is known to already reside on disk */
 FlatFilePos BlockManager::SaveBlockToDisk(const CBlock& block, int nHeight, CChain& active_chain, const CChainParams& chainparams, const FlatFilePos* dbp)
 {
     unsigned int nBlockSize = ::GetSerializeSize(block, CLIENT_VERSION);
     FlatFilePos blockPos;
-    if (dbp != nullptr) {
+    const auto position_known {dbp != nullptr};
+    if (position_known) {
         blockPos = *dbp;
+    } else {
+        // when known, blockPos.nPos points at the offset of the block data in the blk file. that already accounts for
+        // the serialization header present in the file (the 4 magic message start bytes + the 4 length bytes = 8 bytes = BLOCK_SERIALIZATION_HEADER_SIZE).
+        // we add BLOCK_SERIALIZATION_HEADER_SIZE only for new blocks since they will have the serialization header added when written to disk.
+        nBlockSize += static_cast<unsigned int>(BLOCK_SERIALIZATION_HEADER_SIZE);
     }
-    if (!FindBlockPos(blockPos, nBlockSize + 8, nHeight, active_chain, block.GetBlockTime(), dbp != nullptr)) {
+    if (!FindBlockPos(blockPos, nBlockSize, nHeight, active_chain, block.GetBlockTime(), position_known)) {
         error("%s: FindBlockPos failed", __func__);
         return FlatFilePos();
     }
-    if (dbp == nullptr) {
+    if (!position_known) {
         if (!WriteBlockToDisk(block, blockPos, chainparams.MessageStart())) {
             AbortNode("Failed to write block");
             return FlatFilePos();
diff --git a/src/node/blockstorage.h b/src/node/blockstorage.h
index 488713dbd8c1c..8e49254e76cec 100644
--- a/src/node/blockstorage.h
+++ b/src/node/blockstorage.h
@@ -44,6 +44,9 @@ static const unsigned int UNDOFILE_CHUNK_SIZE = 0x100000; // 1 MiB
 /** The maximum size of a blk?????.dat file (since 0.8) */
 static const unsigned int MAX_BLOCKFILE_SIZE = 0x8000000; // 128 MiB
 
+/** Size of header written by WriteBlockToDisk before a serialized CBlock */
+static constexpr size_t BLOCK_SERIALIZATION_HEADER_SIZE = CMessageHeader::MESSAGE_START_SIZE + sizeof(unsigned int);
+
 extern std::atomic_bool fImporting;
 extern std::atomic_bool fReindex;
 /** Pruning-related variables and constants */
@@ -171,6 +174,7 @@ class BlockManager
     bool WriteUndoDataForBlock(const CBlockUndo& blockundo, BlockValidationState& state, CBlockIndex* pindex, const CChainParams& chainparams)
         EXCLUSIVE_LOCKS_REQUIRED(::cs_main);
 
+    /** Store block on disk. If dbp is not nullptr, then it provides the known position of the block within a block file on disk. */
     FlatFilePos SaveBlockToDisk(const CBlock& block, int nHeight, CChain& active_chain, const CChainParams& chainparams, const FlatFilePos* dbp);
 
     /** Calculate the amount of disk space the block & undo files currently use */
diff --git a/src/validation.cpp b/src/validation.cpp
index b5d6a660886fe..e8cb92a1f1a7b 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -4378,7 +4378,18 @@ void CChainState::LoadExternalBlockFile(FILE* fileIn, FlatFilePos* dbp)
                     }
                 }
             } catch (const std::exception& e) {
-                LogPrintf("%s: Deserialize or I/O error - %s\n", __func__, e.what());
+                // historical bugs added extra data to the block files that does not deserialize cleanly.
+                // commonly this data is between readable blocks, but it does not really matter. such data is not fatal to the import process.
+                // the code that reads the block files deals with invalid data by simply ignoring it.
+                // it continues to search for the next {4 byte magic message start bytes + 4 byte length + block} that does deserialize cleanly
+                // and passes all of the other block validation checks dealing with POW and the merkle root, etc...
+                // we merely note with this informational log message when unexpected data is encountered.
+                // we could also be experiencing a storage system read error, or a read of a previous bad write. these are possible, but
+                // less likely scenarios. we don't have enough information to tell a difference here.
+                // the reindex process is not the place to attempt to clean and/or compact the block files. if so desired, a studious node operator
+                // may use knowledge of the fact that the block files are not entirely pristine in order to prepare a set of pristine, and
+                // perhaps ordered, block files for later reindexing.
+                LogPrint(BCLog::REINDEX, "%s: unexpected data at file offset 0x%x - %s. continuing\n", __func__, (nRewind - 1), e.what());
             }
         }
     } catch (const std::runtime_error& e) {


Test patch:
diff --git a/src/Makefile.test.include b/src/Makefile.test.include
index 02a3f9ae7db9a..09148f9d36a6f 100644
--- a/src/Makefile.test.include
+++ b/src/Makefile.test.include
@@ -77,6 +77,7 @@ BITCOIN_TESTS =\
   test/blockencodings_tests.cpp \
   test/blockfilter_index_tests.cpp \
   test/blockfilter_tests.cpp \
+  test/blockmanager_tests.cpp \
   test/bloom_tests.cpp \
   test/bswap_tests.cpp \
   test/checkqueue_tests.cpp \
diff --git a/src/test/blockmanager_tests.cpp b/src/test/blockmanager_tests.cpp
new file mode 100644
index 0000000000000..dd7c32cc46c0e
--- /dev/null
+++ b/src/test/blockmanager_tests.cpp
@@ -0,0 +1,42 @@
+// Copyright (c) 2022 The Bitcoin Core developers
+// Distributed under the MIT software license, see the accompanying
+// file COPYING or http://www.opensource.org/licenses/mit-license.php.
+
+#include <chainparams.h>
+#include <node/blockstorage.h>
+#include <node/context.h>
+#include <validation.h>
+
+#include <boost/test/unit_test.hpp>
+#include <test/util/setup_common.h>
+
+using node::BlockManager;
+using node::BLOCK_SERIALIZATION_HEADER_SIZE;
+
+// use BasicTestingSetup here for the data directory configuration, setup, and cleanup
+BOOST_FIXTURE_TEST_SUITE(blockmanager_tests, BasicTestingSetup)
+
+BOOST_AUTO_TEST_CASE(blockmanager_find_block_pos)
+{
+    const auto params {CreateChainParams(ArgsManager{}, CBaseChainParams::MAIN)};
+    BlockManager blockman {};
+    CChain chain {};
+    // simulate adding a genesis block normally
+    BOOST_CHECK_EQUAL(blockman.SaveBlockToDisk(params->GenesisBlock(), 0, chain, *params, nullptr).nPos, BLOCK_SERIALIZATION_HEADER_SIZE);
+    // simulate what happens during reindex
+    // simulate a well-formed genesis block being found at offset 8 in the blk00000.dat file
+    // the block is found at offset 8 because there is an 8 byte serialization header
+    // consisting of 4 magic bytes + 4 length bytes before each block in a well-formed blk file.
+    FlatFilePos pos{0, BLOCK_SERIALIZATION_HEADER_SIZE};
+    BOOST_CHECK_EQUAL(blockman.SaveBlockToDisk(params->GenesisBlock(), 0, chain, *params, &pos).nPos, BLOCK_SERIALIZATION_HEADER_SIZE);
+    // now simulate what happens after reindex for the first new block processed
+    // the actual block contents don't matter, just that it's a block.
+    // verify that the write position is at offset 0x12d.
+    // this is a check to make sure that https://github.com/bitcoin/bitcoin/issues/21379 does not recur
+    // 8 bytes (for serialization header) + 285 (for serialized genesis block) = 293
+    // add another 8 bytes for the second block's serialization header and we get 293 + 8 = 301
+    FlatFilePos actual{blockman.SaveBlockToDisk(params->GenesisBlock(), 1, chain, *params, nullptr)};
+    BOOST_CHECK_EQUAL(actual.nPos, BLOCK_SERIALIZATION_HEADER_SIZE + ::GetSerializeSize(params->GenesisBlock(), CLIENT_VERSION) + BLOCK_SERIALIZATION_HEADER_SIZE);
+}
+
+BOOST_AUTO_TEST_SUITE_END()