reindex, log, test: fixes #21379

mruddy · mruddy · commit 66b8d3c23d99 · 2022-04-18T21:54:09.000-04:00
This fixes a blk file size calculation made during reindex that results in increased blk file malformedness.
The fix is to avoid double counting the size of the serialization header during reindex.
This adds a unit test to reproduce the bug before the fix and to ensure that it does not recur.
These changes include a log message change also so as to not be as alarming. This is a common and recoverable
data corruption. These messages can now be filtered by the debug log reindex category.
diff --git a/src/Makefile.test.include b/src/Makefile.test.include
@@ -78,6 +78,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/node/blockstorage.cpp b/src/node/blockstorage.cpp
@@ -785,19 +785,27 @@ 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 dbp is not nullptr, then the file and block within it are known to already reside on disk
+    if (position_known) {
         blockPos = *dbp;
-    }
-    if (!FindBlockPos(blockPos, nBlockSize + 8, nHeight, active_chain, block.GetBlockTime(), dbp != nullptr)) {
+    } 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).
+        // we add 8 only for new blocks since they will have the serialization header added when written to disk.
+        // this avoids over accounting for the serialization header on existing blocks. such over accounting was a long
+        // standing bug that added undesirable 8 byte gaps into blk data files following a -reindex operation.
+        // for more info, see https://github.com/bitcoin/bitcoin/issues/21379
+        nBlockSize += 8U;
+    }
+    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/test/blockmanager_tests.cpp b/src/test/blockmanager_tests.cpp
@@ -0,0 +1,40 @@
+// 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;
+
+// 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, 8U);
+    // 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, 8};
+    BOOST_CHECK_EQUAL(blockman.SaveBlockToDisk(params->GenesisBlock(), 0, chain, *params, &pos).nPos, 8U);
+    // 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
+    BOOST_CHECK_EQUAL(blockman.SaveBlockToDisk(params->GenesisBlock(), 1, chain, *params, nullptr).nPos, 301U);
+}
+
+BOOST_AUTO_TEST_SUITE_END()
diff --git a/src/validation.cpp b/src/validation.cpp
@@ -4356,7 +4356,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) {

Original file line number	Diff line number	Diff line change
`@@ -4356,7 +4356,18 @@ void CChainState::LoadExternalBlockFile(FILE* fileIn, FlatFilePos* dbp)`
`4356`	`4356`	`}`
`4357`	`4357`	`}`
`4358`	`4358`	`} catch (const std::exception& e) {`
`4359`		`- LogPrintf("%s: Deserialize or I/O error - %s\n", __func__, e.what());`
	`4359`	`+ // historical bugs added extra data to the block files that does not deserialize cleanly.`
	`4360`	`+ // commonly this data is between readable blocks, but it does not really matter. such data is not fatal to the import process.`
	`4361`	`+ // the code that reads the block files deals with invalid data by simply ignoring it.`
	`4362`	`+ // it continues to search for the next {4 byte magic message start bytes + 4 byte length + block} that does deserialize cleanly`
	`4363`	`+ // and passes all of the other block validation checks dealing with POW and the merkle root, etc...`
	`4364`	`+ // we merely note with this informational log message when unexpected data is encountered.`
	`4365`	`+ // we could also be experiencing a storage system read error, or a read of a previous bad write. these are possible, but`
	`4366`	`+ // less likely scenarios. we don't have enough information to tell a difference here.`
	`4367`	`+ // the reindex process is not the place to attempt to clean and/or compact the block files. if so desired, a studious node operator`
	`4368`	`+ // may use knowledge of the fact that the block files are not entirely pristine in order to prepare a set of pristine, and`
	`4369`	`+ // perhaps ordered, block files for later reindexing.`
	`4370`	`+ LogPrint(BCLog::REINDEX, "%s: unexpected data at file offset 0x%x - %s. continuing\n", __func__, (nRewind - 1), e.what());`
`4360`	`4371`	`}`
`4361`	`4372`	`}`
`4362`	`4373`	`} catch (const std::runtime_error& e) {`