From 1fc7a81f1f5f30ba3ebe305ac2a520c7b4afb596 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C5=91rinc?= Date: Fri, 19 Sep 2025 22:53:37 -0700 Subject: [PATCH] log: reduce excessive messages during block replay After an incomplete reindex the blocks will need to be replayed. This results in excessive `Rolling back` and `Rolling forward` messages which quickly triggers the recently introduced log rate limiter. Change the logging strategy to: - Add single `LogInfo` messages showing the full range being replayed for both rollback and roll forward; - Log progress at `LogInfo` level only every 10,000 blocks to track the long operations. Reproducer: * Start a normal IBD, stop after some progress * Do a reindex, stop before it finishes * Restart the node normally without specifying the reindex parameter It should start rolling the blocks forward. Before this change the excessive logging would show: ``` [*] Rolling forward 000000002f4f55aecfccc911076dc3f73ac0288c83dc1d79db0a026441031d40 (46245) [*] Rolling forward 0000000017ffcf34c8eac010c529670ba6745ea59cf1edf7b820928e3b40acf6 (46246) ``` After the change it shows: ``` Replaying blocks Rolling forward to 00000000000000001034012d7e4facaf16ca747ea94b8ea66743086cfe298ef8 (326223 to 340991) Rolling forward 00000000000000000faabab19f17c0178c754dbed023e6c871dcaf74159c5f02 (330000) Rolling forward 00000000000000000d9b2508615d569e18f00c034d71474fc44a43af8d4a5003 (340000) ... Rolled forward to 00000000000000001034012d7e4facaf16ca747ea94b8ea66743086cfe298ef8 ``` (similarly to rolling back) Co-authored-by: Anthony Towns Co-authored-by: Vasil Dimov --- src/validation.cpp | 58 ++++++++++++++++++++++++++++------------------ 1 file changed, 35 insertions(+), 23 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index 8fcc719a684..deba0711b99 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -4889,35 +4889,47 @@ bool Chainstate::ReplayBlocks() } // Rollback along the old branch. - while (pindexOld != pindexFork) { - if (pindexOld->nHeight > 0) { // Never disconnect the genesis block. - CBlock block; - if (!m_blockman.ReadBlock(block, *pindexOld)) { - LogError("RollbackBlock(): ReadBlock() failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString()); - return false; + const int nForkHeight{pindexFork ? pindexFork->nHeight : 0}; + if (pindexOld != pindexFork) { + LogInfo("Rolling back from %s (%i to %i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight, nForkHeight); + while (pindexOld != pindexFork) { + if (pindexOld->nHeight > 0) { // Never disconnect the genesis block. + CBlock block; + if (!m_blockman.ReadBlock(block, *pindexOld)) { + LogError("RollbackBlock(): ReadBlock() failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString()); + return false; + } + if (pindexOld->nHeight % 10'000 == 0) { + LogInfo("Rolling back %s (%i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight); + } + DisconnectResult res = DisconnectBlock(block, pindexOld, cache); + if (res == DISCONNECT_FAILED) { + LogError("RollbackBlock(): DisconnectBlock failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString()); + return false; + } + // If DISCONNECT_UNCLEAN is returned, it means a non-existing UTXO was deleted, or an existing UTXO was + // overwritten. It corresponds to cases where the block-to-be-disconnect never had all its operations + // applied to the UTXO set. However, as both writing a UTXO and deleting a UTXO are idempotent operations, + // the result is still a version of the UTXO set with the effects of that block undone. } - LogInfo("Rolling back %s (%i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight); - DisconnectResult res = DisconnectBlock(block, pindexOld, cache); - if (res == DISCONNECT_FAILED) { - LogError("RollbackBlock(): DisconnectBlock failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString()); - return false; - } - // If DISCONNECT_UNCLEAN is returned, it means a non-existing UTXO was deleted, or an existing UTXO was - // overwritten. It corresponds to cases where the block-to-be-disconnect never had all its operations - // applied to the UTXO set. However, as both writing a UTXO and deleting a UTXO are idempotent operations, - // the result is still a version of the UTXO set with the effects of that block undone. + pindexOld = pindexOld->pprev; } - pindexOld = pindexOld->pprev; + LogInfo("Rolled back to %s", pindexFork->GetBlockHash().ToString()); } // Roll forward from the forking point to the new tip. - int nForkHeight = pindexFork ? pindexFork->nHeight : 0; - for (int nHeight = nForkHeight + 1; nHeight <= pindexNew->nHeight; ++nHeight) { - const CBlockIndex& pindex{*Assert(pindexNew->GetAncestor(nHeight))}; + if (nForkHeight < pindexNew->nHeight) { + LogInfo("Rolling forward to %s (%i to %i)", pindexNew->GetBlockHash().ToString(), nForkHeight, pindexNew->nHeight); + for (int nHeight = nForkHeight + 1; nHeight <= pindexNew->nHeight; ++nHeight) { + const CBlockIndex& pindex{*Assert(pindexNew->GetAncestor(nHeight))}; - LogInfo("Rolling forward %s (%i)", pindex.GetBlockHash().ToString(), nHeight); - m_chainman.GetNotifications().progress(_("Replaying blocks…"), (int)((nHeight - nForkHeight) * 100.0 / (pindexNew->nHeight - nForkHeight)), false); - if (!RollforwardBlock(&pindex, cache)) return false; + if (nHeight % 10'000 == 0) { + LogInfo("Rolling forward %s (%i)", pindex.GetBlockHash().ToString(), nHeight); + } + m_chainman.GetNotifications().progress(_("Replaying blocks…"), (int)((nHeight - nForkHeight) * 100.0 / (pindexNew->nHeight - nForkHeight)), false); + if (!RollforwardBlock(&pindex, cache)) return false; + } + LogInfo("Rolled forward to %s", pindexNew->GetBlockHash().ToString()); } cache.SetBestBlock(pindexNew->GetBlockHash());