logging: Simplify API for level based logging #28318

ajtowns · 2023-08-22T04:46:11Z

Replace LogPrint* functions with severity based logging functions:

LogInfo(...), LogWarning(...), LogError(...) for unconditional (uncategorised) logging (replaces LogPrintf)
LogDebug(CATEGORY, ...) and LogTrace(CATEGORY, ...) for conditional logging (replaces LogPrint)
LogPrintLevel(CATEGORY, LEVEL, ...) for when the level isn't known in advance, or a category needs to be added for an info/warning/error log message (mostly unchanged, but rarely needed)

Logs look roughly as they do now with LogInfo not having an [info] prefix, and LogDebug having a [cat] prefix, rather than a [cat:debug] prefix. This removes BCLog::Level::None entirely -- for LogFlags::NONE just use Level::Info, for any actual category, use Level::Debug.

Adds docs to developer-notes about when to use which level.

Adds -loglevelalways=1 option so that you get [net:debug], [all:info], [all:warning] etc, which might be helpful for automated parsing, or just if you like everything to be consistent. Defaults to off to reduce noise in the default config, and to avoid unnecessary changes on upgrades.

Changes the behaviour of LogPrintLevel(CATEGORY, BCLog::Level::Info, ...) to be logged unconditionally, rather than only being an additional optional logging level in addition to trace and debug. Does not change the behaviour of LogPrintLevel(NONE, Debug, ...) and LogPrintLevel(NONE, Trace, ...) being no-ops.

DrahtBot · 2023-08-22T04:46:14Z

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

Code Coverage

For detailed information about the code coverage, see the test coverage report.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	maflcko, stickies-v, jamesob, achow101
Concept ACK	jonatack, mzumsande, glozow

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:

#27826 (validation: log which peer sent us a header by Sjors)
#27231 (Fix logging RPC and -debugexclude with 0/none values, add test coverage, improve docs by jonatack)

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.

ajtowns · 2023-08-22T04:51:18Z

This implements ~~most of~~ ~~all of~~ most of my comment #25203 (comment)

I figure the main benefit of categories is to be able to selectively turn logging on/off -- but for unconditional logging, you don't have that benefit, so might as well just drop the category entirely, and just have the message be descriptive enough directly. Note that this effectively reverts #25306.

It should be compatible with other in-progress PRs -- it only deprecates the LogPrint* functions, it doesn't break them. And it should be easy to finish the conversion with a scripted-diff replacing LogPrintf/LogPrint across the codebase.

This seems like a straightforward way of getting the logging stuff finished up.

cc @jonatack

ajtowns · 2023-08-31T14:34:06Z

sample scripted diff code:

sed -i 's/LogPrintLevel(\(BCLog::[^,]*\), BCLog::Level::Debug,/LogDebug(\1,/' net_processing.cpp dbwrapper.cpp net.cpp node/txreconciliation.cpp validation.cpp

sed -i 's/LogPrintLevel(\(BCLog::[^,]*\), BCLog::Level::Error, */LogError(/' net.cpp txmempool.cpp

sed -i 's/LogPrintLevel(\(BCLog::[^,]*\), BCLog::Level::Warning, */LogWarning(/' net.cpp

sed -i 's/LogPrintf(/LogInfo(/' net.cpp
sed -i 's/LogPrint(\(BCLog::[^,]*\),/LogDebug(\1,/' net.cpp

stickies-v · 2023-08-31T14:35:24Z

Concept ACK

maflcko

Approach ACK. Makes sense to keep heavily used code snippets short.

This should also fix the issue of Info/Warning/Error messages not having a clear category and forcing the dev to somehow come up with one (or explicitly having to pick None)

maflcko · 2023-08-31T14:47:53Z

Is this ready for review, or any reason why this is still in draft?

ajtowns · 2023-08-31T14:58:17Z

Is this ready for review, or any reason why this is still in draft?

I was hoping for early feedback from @jonatack and initially wasn't happy with the original "break the -loglevel command line, do stuff, then replace it" commit order (that's now fixed). But no reason it can't be reviewed now. It could also be split up to separate out the -loglevel vs -trace change, or to defer the map to atomic change -- ie, I guess if later commits don't feel worth the review effort, feel free to stop early?

jonatack · 2023-08-31T16:20:29Z

I'll have a look later today but my initial read, to be confirmed, was Approach NACK in the direction, which I'll detail more on, and that this would hinder progress more than help.

I've been waiting for the merge of the bug fix, tests and updated docs in #27231 to continue on the next steps, as I thought it would be merged quickly (as bugfixes normally would be) and which is still waiting on re-ACKs after taking everyone's feedback. ISTM this conflicts with it, which doesn't help either. It doesn't make sense to conflict with that PR for this one IMO.

ajtowns · 2023-08-31T16:29:17Z

Is this ready for review, or any reason why this is still in draft?

Err, perhaps it was because I made some more changes and didn't push them? [EDIT: Oh, was just some additional lint things]

ajtowns · 2023-08-31T16:38:42Z

ISTM this conflicts with it, which doesn't help either. It doesn't make sense to conflict with that PR for this one IMO.

The first 6 commits apply cleanly on top of it; though LogPrintLevel(BCLog::NONE, BCLog::Level::Info, "foo9: %s\n", "bar9"); // no-op is no-longer a no-op, so the tests need modifying.

jonatack · 2023-08-31T16:41:12Z

The first 6 commits apply cleanly on top of it

Thanks, will review properly asap.

maflcko · 2023-08-31T16:49:07Z

Absent the behavior changes, assuming they are controversial, you could also just split out the naming stuff.

I don't see the benefit of making the code overly verbose and typing LogPrintLevel(BCLog::Level::Warning for every log when it is trivial to add an alias like LogWarning( and using it in new code should be uncontroversial.

I don't have an opinion on the category and I think anything is probably fine there.

jonatack

Some thoughts, commit-by-commit.

068de7a The idea behind the severity level logging is to ultimately have only one macro like Log(category, level) with one consistent, simple interface for everyone -- both developers updating logging in the code and people who read the logs -- and remove all the other macros when we're ready, simplifying the logging macros, tests, and benchmarks. This commit not only would add several more macros, but also with different interfaces for developers to remember or look up, rather than just one.

94e1b46 This would move the category from the prefix back into the log message string on an ad hoc basis, would be less consistent, and IMO a step backward.

f20bfc3 Non-urgent approach ACK, I can pull it into the parent in #25203 if you like.

b3bf2fa This would be a step back, I think, away from consistent explicit logging, to requiring remembering more implicit mental context baggage ("why do I see categories for these logs and not for those?") Also, the prefix allows not needing to put the category manually into the log strings.

53a7f76 Much of the value from severity level logging will come from making some of the noisy categories (net in particular, and maybe validation and mempool) much more useful by selecting which LogPrints become debug vs trace, and in general, by selecting which LogPrintfs become info, warning, or error.

4906f49 is an incomplete version of 118c756 (#25203) in the parent pull.

99ac8b1 As discussed in #27231 (comment), it seems to make sense to drop the NONE category and level enums from logging.{h,cpp} when we remove the deprecated macros (as opposed to 0/none values that are still needed at the init and rpc layers, cf #27231).

cb58059 I agree the config option interface is WIP; Klement Tan who was working on it took a job that diverted him from contributing. It seems incongruent to have -debug and -trace options but only -debugexclude. The plan discussed in one of the step PRs is to combine the functionality of the -debug and (help-debug) -loglevel options (perhaps to a renamed -log config option, which would be more consistent naming-wise with the logging RPC), and add log level functionality to that RPC. I haven't done that in the parent PR yet, so it's available to be done!

451f2e7 Ok for avoiding a mutex. I have had the nagging thought for a long time that it may not be inconceivable for some users to prefer logging only errors and warnings, thus to avoid coding ourselves into a corner regarding info always being logged (which might apply to the preceding commit as well).

logging: Improve new LogDebug/Trace/Info/Warning/Error Macros Improve new LogDebug(), LogTrace(), LogInfo(), LogWarning(), LogError() macros introduced in bitcoin#28318: - Make them always accept log categories to make it possible to only log messages from a particular component. - Make them not rely on a global LogInstance, to provide better control of logging in controlled environments, such as unit tests that want to selectively capture log output, or libbitcoinkernel applications that want to have multiple instances of validation objects without mixing their log output. - Make them consistent, now all accepting the same parameters. - Make them less verbose by not requiring BCLog category constants to be specified in individual log prints

logging: Make new logging macros compatible with wallet code New logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), LogError() macros introduced in bitcoin#28318 aren't really useful in wallet code because wallet code because wallet code prefixes most log messages wi 8000 th the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in bitcoin#28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages

Improve new LogDebug(), LogTrace(), LogInfo(), LogWarning(), LogError() macros introduced in bitcoin#28318: - Make them always accept log categories to make it possible to only log messages from a particular component. - Make them not rely on a global LogInstance, to provide better control of logging in controlled environments, such as unit tests that want to selectively capture log output, or libbitcoinkernel applications that want to have multiple instances of validation objects without mixing their log output. - Make them consistent, now all accepting the same parameters. - Make them less verbose by not requiring BCLog category constants to be specified in individual log prints

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in bitcoin#28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages

Improve new LogDebug(), LogTrace(), LogInfo(), LogWarning(), LogError() macros introduced in bitcoin#28318: - Make them always accept log categories to make it possible to only log messages from a particular component. - Make them not rely on a global LogInstance, to provide better control of logging in controlled environments, such as unit tests that want to selectively capture log output, or libbitcoinkernel applications that want to have multiple instances of validation objects without mixing their log output. - Make them consistent, now all accepting the same parameters. - Make them less verbose by not requiring BCLog category constants to be specified in individual log prints

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in bitcoin#28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages

…always logged levels ec779a2 doc: add unconditional info loglevel following merge of PR 28318 (Jon Atack) Pull request description: Commit ab34dc6 of bitcoin#28318 was an incomplete version of [`118c756` (bitcoin#25203)](bitcoin@118c756) from the `Severity-based logging` parent PR. Add the missing text to update the `-loglevel` help doc. While here, make the help text a little easier to understand. Can be tested by running: ``` ./src/bitcoind -regtest -help-debug | grep -A12 loglevel= ``` before ``` -loglevel=<level>|<category>:<level> Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC: info, debug, trace (default=debug); warning and error levels are always logged. ``` after ``` -loglevel=<level>|<category>:<level> Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC. Possible values are info, debug, trace (default=debug). The following levels are always logged: error, warning, info. ``` ACKs for top commit: stickies-v: ACK ec779a2 Tree-SHA512: 0c375e30a5a4c168ca7d97720e8c287f598216767afedae329824e09a480830faf8537b792c5c4bb647c68681c287fe3005c62093708ce85624e9a71c8245e42

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in bitcoin#28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages

Improve new LogDebug(), LogTrace(), LogInfo(), LogWarning(), LogError() macros introduced in bitcoin#28318: - Make them always accept log categories to make it possible to only log messages from a particular component. - Make them not rely on a global LogInstance, to provide better control of logging in controlled environments, such as unit tests that want to selectively capture log output, or libbitcoinkernel applications that want to have multiple instances of validation objects without mixing their log output. - Make them consistent, now all accepting the same parameters. - Make them less verbose by not requiring BCLog category constants to be specified in individual log prints

Disallow passing BCLog category constants to LogInfo(), LogWarning(), and LogError() macros, and disallow omitting BCLog categories when calling LogDebug() and LogTrace() macros. These restrictions have existed since the logging macros were added in bitcoin#28318 and not technically neccessary, but are believed to be useful to prevent log spam and prevent users from filtering out important messages based on category.

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in bitcoin#28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogContext class inheriting from BCLog::Context which can include the wallet name in log messages

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in bitcoin#28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages

Disallow passing BCLog category constants to LogInfo(), LogWarning(), and LogError() macros, and disallow omitting BCLog categories when calling LogDebug() and LogTrace() macros. These restrictions have existed since the logging macros were added in bitcoin#28318 and not technically neccessary, but are believed to be useful to prevent log spam and prevent users from filtering out important messages based on category.

Disallow passing BCLog category constants to LogInfo(), LogWarning(), and LogError() macros, and disallow omitting BCLog categories when calling LogDebug() and LogTrace() macros. These restrictions have existed since the logging macros were added in bitcoin#28318 and not technically neccessary, but are believed to be useful to prevent log spam and prevent users from filtering out important messages based on category. Co-Authored-By: Hodlinator <172445034+hodlinator@users.noreply.github.com>

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in bitcoin#28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogContext class inheriting from BCLog::Context which can include the wallet name in log messages

…always logged levels ec779a2 doc: add unconditional info loglevel following merge of PR 28318 (Jon Atack) Pull request description: Commit ab34dc6 of bitcoin#28318 was an incomplete version of [`118c756` (bitcoin#25203)](bitcoin@118c756) from the `Severity-based logging` parent PR. Add the missing text to update the `-loglevel` help doc. While here, make the help text a little easier to understand. Can be tested by running: ``` ./src/bitcoind -regtest -help-debug | grep -A12 loglevel= ``` before ``` -loglevel=<level>|<category>:<level> Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC: info, debug, trace (default=debug); warning and error levels are always logged. ``` after ``` -loglevel=<level>|<category>:<level> Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC. Possible values are info, debug, trace (default=debug). The following levels are always logged: error, warning, info. ``` ACKs for top commit: stickies-v: ACK ec779a2 Tree-SHA512: 0c375e30a5a4c168ca7d97720e8c287f598216767afedae329824e09a480830faf8537b792c5c4bb647c68681c287fe3005c62093708ce85624e9a71c8245e42

This was referenced Aug 22, 2023

validation: log which peer sent us a header #27826

Merged

Fix logging RPC and -debugexclude with 0/none values, add test coverage, improve docs #27231

Closed

ajtowns marked this pull request as draft August 23, 2023 02:44

ajtowns force-pushed the 202308-logdebug branch from 8d527cc to cc56df3 Compare August 23, 2023 03:11

DrahtBot added the CI failed label Aug 23, 2023

ajtowns mentioned this pull request Aug 23, 2023

Move log messages: tx enqueue to mempool, allocation to blockstorage #27277

Closed

DrahtBot removed the CI failed label Aug 23, 2023

maflcko added the Utils/log/libs label Aug 23, 2023

ajtowns force-pushed the 202308-logdebug branch from cc56df3 to f732efb Compare August 29, 2023 07:54

maflcko approved these changes Aug 31, 2023

View reviewed changes

ajtowns marked this pull request as ready for review August 31, 2023 14:55

ajtowns marked this pull request as draft August 31, 2023 16:28

ajtowns force-pushed the 202308-logdebug branch from f732efb to 451f2e7 Compare August 31, 2023 16:30

ajtowns marked this pull request as ready for review August 31, 2023 16:30

jonatack reviewed Sep 1, 2023

View reviewed changes

kwvg mentioned this pull request Feb 20, 2025

backport: trivial 2025 02 12 dashpay/dash#6582

Merged

5 tasks

bitcoin locked and limited conversation to collaborators Apr 30, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

logging: Simplify API for level based logging #28318

logging: Simplify API for level based logging #28318

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

logging: Simplify API for level based logging #28318

logging: Simplify API for level based logging #28318

Uh oh!

Conversation

Uh oh!

Uh oh!

Uh oh!

Code Coverage

Reviews

Conflicts

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!