log: reduce excessive "rolling back/forward" messages during block replay

l0rinc commented at 5:56 am on September 20, 2025: contributor

Summary

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:

0[*] Rolling forward 000000002f4f55aecfccc911076dc3f73ac0288c83dc1d79db0a026441031d40 (46245)
1[*] Rolling forward 0000000017ffcf34c8eac010c529670ba6745ea59cf1edf7b820928e3b40acf6 (46246)

After the change it shows:

0Replaying blocks
1Rolling forward to 00000000000000001034012d7e4facaf16ca747ea94b8ea66743086cfe298ef8 (326223 to 340991)
2Rolling forward 00000000000000000faabab19f17c0178c754dbed023e6c871dcaf74159c5f02 (330000)
3Rolling forward 00000000000000000d9b2508615d569e18f00c034d71474fc44a43af8d4a5003 (340000)
4...
5Rolled forward to 00000000000000001034012d7e4facaf16ca747ea94b8ea66743086cfe298ef8

(similarly to rolling back)

DrahtBot added the label Utils/log/libs on Sep 20, 2025

DrahtBot commented at 5:56 am on September 20, 2025: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/33443.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	vasild, Crypt-iQ

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#30155 (validation: Make ReplayBlocks interruptible by mzumsande)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

LLM Linter (✨ experimental)

Possible typos and grammar issues:

block-to-be-disconnect -> block-to-be-disconnected [past participle needed for “the block to be disconnected” so the sentence is grammatically correct]

drahtbot_id_5_m

l0rinc marked this as ready for review on Sep 21, 2025

ajtowns commented at 7:42 am on September 21, 2025: contributor

Should call this LogEssential() or similar, rather than calling internal logging functions. cf https://github.com/ajtowns/bitcoin/commits/202509-logessential/

Is this information actually very useful though, or is it only relevant for debugging? There’s already the Replaying blocks... notification which should show progress. Would something like this make more sense?

 0     // Roll forward from the forking point to the new tip.
 1     int nForkHeight = pindexFork ? pindexFork->nHeight : 0;
 2+    LogInfo("Rolling forward to %s (%i to %i)\n", pindexNew->GetBlockHash().ToString(), nForkHeight, pindexNew->nHeight);
 3     for (int nHeight = nForkHeight + 1; nHeight <= pindexNew->nHeight; ++nHeight) {
 4         const CBlockIndex& pindex{*Assert(pindexNew->GetAncestor(nHeight))};
 5
 6-        LogEssential("Rolling forward %s (%i)", pindex.GetBlockHash().ToString(), nHeight);
 7+        LogDebug(BCLog::VALIDATION, "Rolling forward %s (%i)", pindex.GetBlockHash().ToString(), nHeight);
 8         m_chainman.GetNotifications().progress(_("Replaying blocks…"), (int)((nHeight - nForkHeight) * 100.0 / (pindexNew->nHeight - nForkHeight)), false);
 9         if (!RollforwardBlock(&pindex, cache)) return false;
10     }

l0rinc commented at 2:49 pm on September 21, 2025: contributor

I don’t think this info is essential (though I like your proposed solution in case it is). It’s extremely spammy currently (my guess is that the logging is more costly than the operation itself). Alternatively, we could show percentages only (as mentioned in the PR description), since we know how much work we need to do in advance. I will push a proposal for that as well.

Edit: added the changes that @ajtowns proposed, I also favor removing the excessive logging instead of removing rate limiting. Reviewers are welcome to opine on whether showing any progress during the rolling forward is welcome (since it can take hours to do this in the worst case).

l0rinc force-pushed on Sep 21, 2025

l0rinc renamed this:
~~log: don't rate limit "rolling forward" messages~~
log: reduce excessive "rolling forward" messages during block replay
on Sep 21, 2025

in src/validation.cpp:2941 in 4aa3fdb92d

2946-                   FormatISO8601DateTime(tip->GetBlockTime()),
2947-                   chainman.GuessVerificationProgress(tip),
2948-                   coins_tip.DynamicMemoryUsage() * (1.0 / (1 << 20)),
2949-                   coins_tip.GetCacheSize(),
2950-                   !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages) : "");
2951+    LogEssential("%s%s: new best=%s height=%d version=0x%08x log2_work=%f tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)%s\n",

Crypt-iQ commented at 3:41 pm on September 22, 2025:

A new macro was not introduced in the original PR / was an intentional change so that a developer would have to use the “private” macro LogPrintLevel_ with should_ratelimit=false in order to bypass rate limiting. This change is fine code-wise, but my concern is that it’s now easier for a developer to accidentally introduce a logging location that an attacker can trigger. Maybe the comment for the macro can be modified to “Same as LogInfo, but never rate limited. Should be used with extreme care.”

ajtowns commented at 6:31 am on September 23, 2025:

Perhaps also noting that rate limiting does not apply to LogDebug and LogTrace would help encourage people to use those macros for noisy logs, rather than sticking with INFO level but disabling rate limiting.

vasild commented at 11:19 am on September 23, 2025:

Not modifying the original LogPrintLevel_(rate-unlimited = true) would remove this discussion from this PR. I agree with the other changes in this PR, but am somewhat anxious about the new LogEssential() macro.

l0rinc commented at 5:11 pm on September 23, 2025:

Should be used with extreme care

Given that we didn’t even have any rate limiting so far and as far as I can tell it wasn’t weaponized so far I’m not sure this is an “extreme” danger. But I don’t mind removing the rate-limit related commit suggested by @ajtowns, since it seems to be more contentious than just reducing the rolling forward messages. And I have extended it for the rolling forward messages as well and limit the log info to every 10k blocks to be less spammy.

in src/logging.h:361 in 4aa3fdb92d

356@@ -357,6 +357,9 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::Log
357 #define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, /*should_ratelimit=*/true, __VA_ARGS__)
358 #define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, /*should_ratelimit=*/true, __VA_ARGS__)
359 
360+// Same as LogInfo, but never rate limited
361+#define LogEssential(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, __VA_ARGS__)

vasild commented at 11:11 am on September 23, 2025:

d541409a64c60d127ff912dad9dea949d45dbd8c introduced rate limiting. If we are going to introduce a function (macro) to ignore the rate limiting, then it is just a matter of time before some code that uses the new unlimited function triggers a disk-fill. It looks to me that introducing such a function defeats the purpose of rate-limiting.

Now, if we really want to have rate-unlimited logging function, then we can consider that d541409a64c60d127ff912dad9dea949d45dbd8c went a bit too far:

This change affects the public LogPrintLevel function if called with
a level >= BCLog::Level::Info.

and that log messages with too high severity are so important that they should not be subject to rate limiting. That said, it looks to me that either Error messages should be rate-unlimited or a new severity level should be introduced, higher than Error that is rate-unlimited, instead of introducing Info-level, rate-unlimited function.

syslog(3) has debug, info, notice, warning, err, crit, alert, emerg. Maybe introduce a new BCLog::Level::Crit and LogCrit() which is rate-unlimited?

Crypt-iQ commented at 12:47 pm on September 23, 2025:

I think Error and Warning should be rate limited as they currently are. I am ok with a critical level and macro, but I think it might need more conceptual review and feedback vs. what this PR aims to do?

maflcko commented at 1:05 pm on September 23, 2025:

I also agree that errors and warnings should be rate limited. Errors are fatal, so should only be printed once, before the program aborts. Warnings should be rare, unless there is a coding bug, in which case the rate limiting seems useful.

The only place where side-stepping the rate limiting makes sense is the info level. If LogEssential is named too harmless, it could be named LogInfoWithoutRateLimiting, so that the slightly verbose name discourages using it in places where it is not appropriate.

l0rinc commented at 5:11 pm on September 23, 2025:

Agree, pushed a better solution to rate limit existing message + announcement of work ahead (as suggested by @ajtowns). Rate limiting changes can be done in a separate PR now if needed.

l0rinc force-pushed on Sep 23, 2025

l0rinc renamed this:
~~log: reduce excessive "rolling forward" messages during block replay~~
log: reduce excessive "rolling back/forward" messages during block replay
on Sep 23, 2025

l0rinc force-pushed on Sep 23, 2025

in src/validation.cpp:4905 in ae26c59b92

4901                 return false;
4902             }
4903-            LogInfo("Rolling back %s (%i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight);
4904+            if (pindexOld->nHeight % 10'000 == 0) {
4905+                LogInfo("Rolling back %s (%i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight);
4906+            }

vasild commented at 7:15 am on September 24, 2025:

Previously every block would have been printed. Now the start will be printed and then every 10'000th, but not the end, e.g.:

0rolling back from 54321 to 29238
1rolling back 50000
2rolling back 40000
3rolling back 30000
4// and nothing more

Would it be useful to indicate that the process has completed? E.g. one more message “rolled back successfully to 29238” after the loop?

Same for the “rolling forward” case.

l0rinc commented at 3:27 am on September 25, 2025:

Indeed, pushed, added you as coauthor. I will try to add some tests for this either in this PR or in a follow-up since it doesn’t seem to have any coverage.

in src/validation.cpp:4897 in ae26c59b92

4888@@ -4889,14 +4889,20 @@ bool Chainstate::ReplayBlocks()
4889     }
4890 
4891     // Rollback along the old branch.
4892+    int nForkHeight{pindexFork ? pindexFork->nHeight : 0};
4893+    if (pindexOld && pindexOld != pindexFork) {
4894+        LogInfo("Rolling back from %s (%i to %i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight, nForkHeight);
4895+    }
4896     while (pindexOld != pindexFork) {
4897         if (pindexOld->nHeight > 0) { // Never disconnect the genesis block.

vasild commented at 7:17 am on September 24, 2025:

The while and the if just below it assume that if pindexOld != pindexFork is true, then pindexOld is not nullptr. So, pindexOld && can be removed from the newly added if.

l0rinc commented at 3:26 am on September 25, 2025:

Good point, thanks, fixed.

vasild approved

vasild commented at 7:22 am on September 24, 2025: contributor

ACK ae26c59b92b5fc082faaeafca576a9d9f7e4549f

l0rinc force-pushed on Sep 25, 2025

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 <aj@erisian.com.au>
Co-authored-by: Vasil Dimov <vd@freebsd.org>

1fc7a81f1f

l0rinc force-pushed on Sep 25, 2025

vasild approved

vasild commented at 10:28 am on September 25, 2025: contributor

ACK 1fc7a81f1f5f30ba3ebe305ac2a520c7b4afb596

Crypt-iQ commented at 2:59 pm on September 25, 2025: contributor