Merge bitcoin/bitcoin#24858: incorrect blk file size calculation during reindex results in recoverable blk file corruption

bcb0cacac28e98a39dc856c574a0872fe17059e9 reindex, log, test: fixes #21379 (mruddy)

Pull request description:

  Fixes #21379.

  The blocks/blk?????.dat files are mutated and become increasingly malformed, or corrupt, as a result of running the re-indexing process.
  The mutations occur after the re-indexing process has finished, as new blocks are appended, but are a result of a re-indexing process miscalculation that lingers in the block manager's `m_blockfile_info` `nSize` data until node restart.
  These additions to the blk files are non-fatal, but also not desirable.
  That is, this is a form of data corruption that the reading code is lenient enough to process (it skips the extra bytes), but it adds some scary looking log messages as it encounters them.

  The summary of the problem is that the re-index process double counts the size of the serialization header (magic message start bytes [4 bytes] + length [4 bytes] = 8 bytes) while calculating the blk data file size (both values already account for the serialization header's size, hence why it is over accounted).

  This bug manifests itself in a few different ways, after re-indexing, when a new block from a peer is processed:
  1. If the new block will not fit into the last blk file processed while re-indexing, while remaining under the 128MiB limit, then the blk file is flushed to disk and truncated to a size that is 8 greater than it should be. The truncation adds zero bytes (see `FlatFileSeq::Flush` and `TruncateFile`).
  1. If the last blk file processed while re-indexing has logical space for the new block under the 128 MiB limit:
      1. If the blk file was not already large enough to hold the new block, then the zeros are, in effect, added by `fseek` when the file is opened for writing. Eight zero bytes are added to the end of the last blk file just before the new block is written. This happens because the write offset is 8 too great due to the miscalculation. The result is 8 zero bytes between the end of the last block and the beginning of the next block's magic + length + block.
      1. If the blk file was already large enough to hold the new block, then the current existing file contents remain in the 8 byte gap between the end of the last block and the beginning of the next block's magic + length + block. Commonly, when this occcurs, it is due to the blk file containing blocks that are not connected to the block tree during reindex and are thus left behind by the reindex process and later overwritten when new blocks are added. The orphaned blocks can be valid blocks, but due to the nature of concurrent block download, the parent may not have been retrieved and written by the time the node was previously shutdown.

ACKs for top commit:
  LarryRuane:
    tested code-review ACK bcb0cacac28e98a39dc856c574a0872fe17059e9
  ryanofsky:
    Code review ACK bcb0cacac28e98a39dc856c574a0872fe17059e9. This is a disturbing bug with an easy fix which seems well-worth merging.
  mzumsande:
    ACK bcb0cacac28e98a39dc856c574a0872fe17059e9 (reviewed code and did some testing, I agree that it fixes the bug).
  w0xlt:
    tACK https://github.com/bitcoin/bitcoin/pull/24858/commits/bcb0cacac28e98a39dc856c574a0872fe17059e9

Tree-SHA512: acc97927ea712916506772550451136b0f1e5404e92df24cc05e405bb09eb6fe7c3011af3dd34a7723c3db17fda657ae85fa314387e43833791e9169c0febe51

5 files changed, 68 insertions, 5 deletions

diff --git a/src/Makefile.test.include b/src/Makefile.test.include
index 253f64d2c3..b21e9906a3 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/node/blockstorage.cpp b/src/node/blockstorage.cpp
index 57f81e6bb6..2d5c91bc5c 100644
--- a/src/node/blockstorage.cpp
+++ b/src/node/blockstorage.cpp
@@ -789,19 +789,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 37d74ed102..29501c1959 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 @@ public:
     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/test/blockmanager_tests.cpp b/src/test/blockmanager_tests.cpp
new file mode 100644
index 0000000000..dd7c32cc46
--- /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()
diff --git a/src/validation.cpp b/src/validation.cpp
index 514a528314..be2836e603 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -4476,7 +4476,18 @@ void Chainstate::LoadExternalBlockFile(
                     }
                 }
             } 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) {