logging: rewrite macros to add ratelimit option, avoid unused strprintf, clarify confusing errors by ryanofsky · Pull Request #34778 · bitcoin/bitcoin

ryanofsky · 2026-03-09T15:28:25Z

Rewrite log macros to fix a number of issues: lack of control over rate limiting, unnecessary strprintf calls during fuzzing, and confusing error messages when macros are called with the wrong arguments.

This PR is a refactoring and shouldn't change externally visible behavior. Changes are described in detail in commit messages. There are also some internal improvements making previously implicit behaviors (evaluating unused format arguments, not outputting categories at certain log levels) explicit and better enforced.

Some changes here were originally part of #29256, but they should make sense on their own and simplify both PRs.

Test that LogInfo/LogWarning/LogError always evaluate their arguments even when logging is disabled. ajtowns pointed out this behavior was important and could affect non-logging code if changed in bitcoin#34374 (comment) Co-authored-by: l0rinc <pap.lorinc@gmail.com>

Add new logging test to call macros with all allowed combinations of macro arguments. The new test replaces a less comprehensive test that doesn't cover log statements without format arguments. It's also moved to the top of the test suite because it's a good illustration of what typical log prints look like, what logging calls are allowed and disallowed, and what the resulting log output looks like.

Previously this used to be possible through the LogPrintLevel call but now that call is removed, this change is just an internal refactoring and has no visible effect except in tests.

Rewrite log macros to fix a number of issues: lack of control over rate limiting, unnecessary strprintf calls during fuzzing, confusing error messages when macros are called with the wrong arguments. More specifically, benefits are: - Control over rate limiting: `LogPrintLevel_` hack used to bypass rate limiting is dropped. A `LogPrint` macro is added that can control rate limiting (as well as other options if they are added in the future). - Unnecessary `strprintf` calls are now skipped in bitcoind when `-noprinttoconsole -nodebuglogfile` options are used, and skipped in tests and kernel applications when logging is disabled. This change should not affect bitcoind noticeably, but it could speed up fuzz tests calling functions that log. - Clearer error messages: Differences between macros accepting and not accepting category arguments has been a source of confusion. Now if you pass a category to a macro which does not accept it, or forget to pass a category to a macro which requires it, you will see a clear error message telling you to add or remove the category instead of more confusing macro errors. - Previously you could call `LogPrintLevel_` to bypass restrictions on passing category arguments. Now `LogPrint` enforces all requirements. - Previously "always evaluate arguments" behavior at Info and higher levels looked accidental and was undocumented (bitcoin#34374 (comment)). Now the behavior is documented and explicit. - There is now a single macro, `LogPrint` implementing all logging functionality and enforcing all restrictions, instead of different sets of macros with branching code paths and unexplained differences. Co-Authored-By: Hodlinator <172445034+hodlinator@users.noreply.github.com> Co-Authored-By: stickies-v <stickies-v@protonmail.com>

DrahtBot · 2026-03-09T15:29:06Z

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

Reviews

See the guideline for information on the review process.

Type	Reviewers
Concept NACK	ajtowns

If your review is incorrectly listed, please copy-paste  into the comment that the bot should ignore.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#34806 (refactor: logging: Various API improvements by ajtowns)
#34730 (util/log: Combine the warning/error log levels into a single alert level by ajtowns)
#34729 (Reduce log noise by ajtowns)
#34639 (iwyu: Document or remove some pragma: export and other improvements by hebasto)
#34514 (refactor: remove unnecessary std::move for trivially copyable types by l0rinc)
#33727 (zmq: Log bind error at Error level, abort startup on init error by isrod)

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:

testring -> testing [typo in "Include commented out calls ... for easy manual testring..."]
readble -> readable [typo in "these calls produce readble compile errors."]

^{2026-03-09 15:29:05}

ajtowns · 2026-03-10T10:46:49Z

Concept NACK to reintroducing a generic LogPrint. The NO_RATE_LIMIT commit from #34038 has been available for review for three months now, and has had a concept ack for that long.

ryanofsky · 2026-03-10T13:43:13Z

The NO_RATE_LIMIT commit from #34038 has been available for review for three months now, and has had a concept ack for that long.

That's interesting. #34038 is mostly a logging backend change, changing the RPC interface and command line options. It seems like the no-ratelimit change part of that PR might not be related to the other changes there? (I don't see the connection at least.)

To compare the two approaches, #34038 syntax looks like:

LogInfo(util::log::NO_RATE_LIMIT, "message");

while syntax here is:

LogPrint((.level = util::log::Level::Info, .ratelimit = false), "message"),

There is not much difference between the approaches externally, and they are compatible (this PR could easily support a NO_RATE_LIMIT flag if reviewers would prefer that.)

This bigger goal of this PR is to replace current implementation of the logging macros which is messy and inconsistent with a clean implementation. All preprocessor functionality is implemented in a single macro called LogPrint, getting rid of the branching code paths at different priority levels [1] [2] that have unexplained differences. The differences are all kept, they are just explicit rather than implicit, with better documentation and tests and stricter enforcement of restrictions.

The .ratelimit = true option is exposed as a side-effect of this refactoring, and the refactoring also allows other options to be implemented cleanly in the future. Examples could be .log_once=true .log_every=24h .log_every=60m .stack_trace=true .dedup = true etc. I was also thinking of an .impossible = true option that could be used to document preconditions & provide better bug reports and output from fuzz & unit test failures. The point is that I think we should make it easy to add logging options and try to implement most options with constexpr code instead of macros. And get rid of complication of different macros at different log levels having different implementations.

Anyway I'd be happy to review #34038 and I think the runtime changes there look nice. The NO_RATE_LIMIT flag idea there could be nice. If reviewers like it maybe I could support it here and #34038 could be simpler and only implement the logging backend improvements without making a unrelated change (it would seem) to the logging macros?

maflcko · 2026-03-10T14:30:13Z

src/validation.cpp

-    // Disable rate limiting in LogPrintLevel_ so this source location may log during IBD.
-    LogPrintLevel_(BCLog::LogFlags::ALL, util::log::Level::Info, /*should_ratelimit=*/false, "%s%s: new best=%s height=%d version=0x%08x log2_work=%f tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)%s\n",
+    // Disable rate limiting so this source location may log during IBD.
+    LogPrint((.level = util::log::Level::Info, .ratelimit = false),


not sure about using the internal/hidden macro here, after the changes. If someone wants to log at info level, it seems clearer to just call LogInfo, instead of using some internal macro with a bunch of options.

Also, supporting .ratelimit = false for other levels doesn't really make sense, and certainly isn't needed by current code at all, so supporting it seems odd.

edit: I see it is needed for one warning log as well. So I guess my main concern is that this will open the gates for the "wild west" that we were trying to fix: For example, this new macro may encourage to re-introduce helpers of the form: [](auto level, auto msg) { LogPrint((.level=level),"%s", msg); }, which will then work incorrectly with regard to rate-limiting (silently dropping warnings/errors, when info logs overflow)

re: #34778 (comment)

so supporting it seems odd.

When you say odd do you mean the code is doing something it should not do? Or not doing something it should do? For example, It would be easy to add a static assert to prevent ratelimiting being requested at certain levels if you feel that is important. Though I'm not sure why ratelimiting should not be available at different levels (I haven't looked into the rate limiting implementation).

Overall, the idea here is to accept options and pass them along the backend to implement. I imagine the bitcoinkernel backend probably won't support rate limiting at all for example (or at least it doesn't in #34374)

(I haven't looked into the rate limiting implementation).

I've edited my comment to explain one case that will make code more brittle.

I mostly think this should remain internal/hidden, maybe LogPrintInternalDetail(...). Otherwise, devs may think this is fine to use without thinking much about the implicit edges.

re: #34778 (comment)

For example, this new macro may encourage to re-introduce helpers of the form: [](auto level, auto msg) { LogPrint((.level=level),"%s", msg); }, which will then work incorrectly with regard to rate-limiting (silently dropping warnings/errors, when info logs overflow)

Hmm, I'm confused why someone would do what you are suggesting, but if they did it should be safe and work correctly. The ratelimit default value should be the same as before.

The point of adding LogPrint is to be a safe, single implementation of logging code that other macros can just forward to without their own bespoke logic and special cases.

Please let me know if I am missing something here. Like I said I haven't actually looked at the ratelimiting implementation. This PR is just forwarding the option. If any unsafe option values are currently accepted, we should definitely prohibit them with a static assert, but I'm not seeing where that could be happening.

Hmm, I'm confused why someone would do what you are suggesting,

Well, you can go back in the git history to find this exact pattern. See 2210feb.

but if they did it should be safe and work correctly.

No, see 2210feb, which fixed this. (You can refer to the commit messages for more details)

re: #34778 (comment)

Hmm, I'm confused why someone would do what you are suggesting,

Well, you can go back in the git history to find this exact pattern. See 2210feb.

Thanks for clarifying. For others who may be following, the pattern is shown specifically in f273167 and 94c51ae and it is not allowed by this PR. This PR enforces the same restrictions as current code.

E.g. if you try to revert f273167 and call LogPrint((.level = ConvertIPCLogLevel(message.level)) , "%s\n", message.message); you will see an error because the level is not a compile time constant.

(EDIT: I'd add that I don't see anything inherently wrong with the pattern used in those commits, and no reason it couldn't work well. The previous LogPrintLevel implemention just had a bug and was good candidate for removal for other reasons.)

and it is not allowed by this PR. This PR enforces the same restrictions as current code.

I don't think this is true. I am sure one can write a similar pattern deriving the level constexpr/consteval.

(EDIT: I'd add that I don't see anything inherently wrong with the pattern used in those commits, and no reason it couldn't work well.

logging takes the source location, which is then used for other stuff (such as rate limiting or -logsourcelocations). Using the same source location for different logs is brittle in itself. Though, using it for different log levels is doubly brittle. I don't see the need to regress here

re: #34778 (comment)

and it is not allowed by this PR. This PR enforces the same restrictions as current code.

I don't think this is true. I am sure one can write a similar pattern deriving the level constexpr/consteval.

Can we slow down and try to work through an example here? I would like to understand the problem you are concerned about and either confirm that it is not an issue here, or make some fix to solve it.

As far as I can tell, you did a little pattern matching like "this new function looks similar to that previously removed function" and assuming "therefore it has the same bugs and limitations of the previous function." This is a reasonable assumption, but it happens not to be true in this case!

(EDIT: I'd add that I don't see anything inherently wrong with the pattern used in those commits, and no reason it couldn't work well.

logging takes the source location, which is then used for other stuff (such as rate limiting or -logsourcelocations). Using the same source location for different logs is brittle in itself.

Sorry yes I should have clarified I only think the pattern is good for external code that does not include source locations. Internal logs should definitely have source locations! I don't think you will find any regressions on that front either implemented in this PR or enabled by it.

To the contrary, followup PR #30343 adds source locations to wallet code which is currently missing them.

example

Of course, this synthetic example is not found in the codebase as-is, but I don't see why it wouldn't compile with the changes in this pull

struct Module { std::string m_name; template<Level level> void ModuleLog(std::string m) { LogPrint((.level=level), "[%s] %s", m_name, m); } ... };

re: #34778 (comment)

Thanks for the concrete example. I am assuming based on your earlier comments that problem with this example is that it hides source locations, and I agree hiding source locations would be bad. I guess I just disagree with the realism of the example. You seem to be saying is that this PR could make developers more tempted to write bad per-module logging interfaces and add calls like:

my_module.ModuleLog<Level::Info>("message")

to the code, hiding source locations that would otherwise be available. Even though developers could implement literally the same bad interface today by calling the LogInfo/LogWarning/LogError macros with an if or switch statement? And even though we already have an existing WalletLogPrintf function today which has no problem hiding source locations with the current logging macros?

I just don't see this PR by itself having any real impact on support for source locations. But if that is the concern and I did not misunderstand something, thanks for clarifying.

stickies-v and others added 4 commits March 6, 2026 20:07

log refactor: Ensure categories are not logged at info and higher levels

8f3e279

Previously this used to be possible through the LogPrintLevel call but now that call is removed, this change is just an internal refactoring and has no visible effect except in tests.

This was referenced Mar 9, 2026

log, refactor: Allow log macros to accept context arguments #29256

Draft

wallet, logging: Replace WalletLogPrintf() with LogInfo() #30343

Draft

kernel, logging: Pass Logger instances to kernel objects #30342

Draft

DrahtBot mentioned this pull request Mar 10, 2026

zmq: Log bind error at Error level, abort startup on init error #33727

Draft

maflcko reviewed Mar 10, 2026

View reviewed changes

DrahtBot mentioned this pull request Mar 14, 2026

refactor: logging: Various API improvements #34806

Open

Conversation

ryanofsky commented Mar 9, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Mar 9, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Reviews

Conflicts

LLM Linter (✨ experimental)

Uh oh!

ajtowns commented Mar 10, 2026

Uh oh!

ryanofsky commented Mar 10, 2026

Uh oh!

maflcko Mar 10, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ryanofsky Mar 10, 2026

Choose a reason for hiding this comment

Uh oh!

maflcko Mar 10, 2026

Choose a reason for hiding this comment

Uh oh!

ryanofsky Mar 10, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

maflcko Mar 10, 2026

Choose a reason for hiding this comment

Uh oh!

ryanofsky Mar 10, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

maflcko Mar 10, 2026

Choose a reason for hiding this comment

Uh oh!

ryanofsky Mar 10, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

maflcko Mar 10, 2026

Choose a reason for hiding this comment

Uh oh!

ryanofsky Mar 10, 2026

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

ryanofsky commented Mar 9, 2026 •

edited

Loading

DrahtBot commented Mar 9, 2026 •

edited

Loading

maflcko Mar 10, 2026 •

edited

Loading

ryanofsky Mar 10, 2026 •

edited

Loading

ryanofsky Mar 10, 2026 •

edited

Loading

ryanofsky Mar 10, 2026 •

edited

Loading