kernel, logging: Pass Logger instances to kernel objects#30342
kernel, logging: Pass Logger instances to kernel objects#30342ryanofsky wants to merge 15 commits intobitcoin:masterfrom
Conversation
|
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers. Code Coverage & BenchmarksFor details see: https://corecheck.dev/bitcoin/bitcoin/pulls/30342. ReviewsSee the guideline for information on the review process.
If your review is incorrectly listed, please copy-paste ConflictsReviewers, this pull request conflicts with the following ones:
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:
2026-03-09 19:02:53 |
|
Concept ACK. |
|
🚧 At least one of the CI tasks failed. Make sure to run all tests locally, according to the Possibly this is due to a silent merge conflict (the changes in this pull request being Leave a comment here, if you need help tracking down a confusing failure. |
|
Updated 4542335 -> db1b9f7 ( |
Change LogInstance() function to no longer allocate (and leak) a BCLog::Logger instance. Instead allow kernel applications to initialize their own logging instances that can be returned by LogInstance(). This change is somewhat useful by itself, but more useful in combination with bitcoin#30342. By itself, it gives kernel applications control over when the Logger is created and destroyed and allows new instances to replace old ones. In combination with bitcoin#30342 it allows multiple log instances to exist at the same time, and different output to be sent to different instances. This commit is built on top of bitcoin#30141 since it simplifies the implementation somewhat.
|
🚧 At least one of the CI tasks failed. HintsTry to run the tests locally, according to the documentation. However, a CI failure may still
Leave a comment here, if you need help tracking down a confusing failure. |
stickies-v
left a comment
stickies-v
left a comment
There was a problem hiding this comment.
I've finally started reviewing this PR in more detail, after my recent related work on kernel logging. I'm currently leaning Concept ACK, Approach NACK.
Concept ACK because:
- a large part of the bitcoinkernel interface is contextualized, e.g.
btck_ChainstateManageris initialized with abtck_Context, so having contextualized logging seems like a natural fit - bitcoinkernel is a library, we should be minimally opinionated on how it's used, so long as it's safe. If users have good use cases for e.g. multiple
ChainstateManager's, being able to separate log streams would be good
Approach NACK because I think the below downsides are bigger than the above upsides:
- logging interface becomes more cumbersome, i.e. caller has to figure out if a logger is in scope and if it should be used. It is easy to misuse (e.g. forget to log to context when it exists, which seems hard to enforce.)
- non-trivial code change / review cost, lots of merge conflicts, ...
I think this change might become more desirable if/when we have more demand for this feature (i.e. more actual use cases for contextualized logging) or when it becomes a less invasive code change to do so (e.g. if/when kernel is a separate codebase, or when it becomes feasible to use an interface like m_log.info(...)).
I've asked the kernel working group for use cases and motivations for contextualized logging, and so far I've not heard much (but I hope people will chime in here rather than me speaking on their behalf). If you have any, perhaps opening a tracking issue for that might be useful so we can better decide when this feature becomes worth it given the complexity? I'm definitely not against the idea itself, I just pragmatically think it's not worth the current cost.
|
Thanks for the review!
I think it's straightforward to enforce if there are places where we want to require log contexts. For example if we want to enforce it in kernel files it could look like: diff
--- a/src/util/log.h
+++ b/src/util/log.h
@@ -156,11 +156,19 @@ void Log(Level level, bool should_ratelimit, SourceLocation&& source_loc, Contex
#define FirstArg_Impl(arg, ...) arg
#define FirstArg_(args) FirstArg_Impl args
+constexpr bool LOG_REQUIRE_CONTEXT = false;
+
+template <typename T>
+concept LogContext = requires {
+ requires std::remove_reference_t<T>::log_context;
+};
+
//! Internal helper to conditionally log. Only evaluates arguments when needed.
// Allow __func__ to be used in any context without warnings:
// NOLINTBEGIN(bugprone-lambda-function-name)
#define LogPrint_(level, should_ratelimit, take_category, ...) \
do { \
+ static_assert(!LOG_REQUIRE_CONTEXT || LogContext<decltype(FirstArg_((__VA_ARGS__)))>, "Log call must pass a log context as first argument"); \
auto&& _context{util::log::detail::GetContext<take_category>(FirstArg_((__VA_ARGS__)))}; \
if (util::log::ShouldLog(_context.logger, _context.category, (level))) { \
util::log::detail::Log((level), (should_ratelimit), SourceLocation{__func__}, \
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -76,6 +76,8 @@
#include <tuple>
#include <utility>
+#define LOG_REQUIRE_CONTEXT true
+
using kernel::CCoinsStats;
using kernel::ChainstateRole;
using kernel::CoinStatsHashType;Also note that without enforcement, the consequence of a missing context argument is just the log message going to the global logging stream, which already happens now.
I'd be interested to know more about what part of the code change seem difficult to review. The main change is adding a new parameter to a bunch of functions, which seems like the archetype of a change that is trivial to verify. I guess there are a lot of test updates too. Anyway, would like to know more about what specific difficulties you see here. |
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 <[email protected]>
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 <[email protected]> Co-Authored-By: stickies-v <[email protected]>
Allow LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() macros to accept context arguments to provide more information in log messages and more control over logging to callers. This functionality is used in followup PRs: - bitcoin#30342 - To let libbitcoinkernel send output to specfic `BCLog::Logger` instances instead of a global instance, so output can be disambiguated and applications can have more control over logging. - bitcoin#30343 - To replace custom `WalletLogPrintf` calls with standard logging calls that automatically include wallet names and don't log everything at info level. This commit does not change behavior of current log prints or require them to be updated. It includes tests and documentation covering the new functionality. Co-Authored-By: Hodlinator <[email protected]> Co-Authored-By: stickies-v <[email protected]>
Custom log contexts allow overridding log formatting and adding metadata, such as request ids or wallet names to log messages, while still using standard macros for logging. This is used to replace WalletLogPrintf() functions with LogInfo() calls in followup PR bitcoin#30343.
Pass Logger instances to BlockManager, CCoinsViewDB, CDBWrapper, ChainstateManager, and CoinsViews instances so libbitcoinkernel applications and test code have the option to control where log output goes instead of having all output sent to the global logger. This commit just passes the logger objects without using them. The next commit updates log print statements to use the new objects.
Add option to require context objects to be passed to log macros in a file or block of code, so new logging calls can't forget to specify them and accidentally log to the global logging stream.
This is a mechanical change updating kernel code that currently uses the global log instance to log to local instances instead.
Change LogInstance() function to no longer allocate (and leak) a BCLog::Logger instance. Instead allow kernel applications to initialize their own logging instances that can be returned by LogInstance(). The LogInstance() function is not actually used for the majority of logging in kernel code. Most kernel log output goes directly to BCLog::Logger instances specified when kernel objects like ChainstateManager and CTxMemPool are constructed, which allows applications to create multiple Logger instances and control which log output is sent to them. The only kernel code that does rely on LogInstance() is certain low level code in the util library, like the RNG seeder, that is not passed a specific instance and needs to rely on the global LogInstance() function. Other code outside the kernel library uses LogInstance() heavily, and may continue to do so. bitcoind and test code now just create a log instance before the first LogInstance() call, which it returns, so all behavior is the same as before.
Nice, I hadn't thought of a per-file approach, that seems elegant.
I don't think (and didn't say) that this PR is difficult to review. But I think "non-trivial code change / review cost, lots of merge conflicts, ..." is a reasonable statement for a cumulative diff of this size and 26 PR merge conflicts. Note: I do think this is an elegant implementation, and I am not necessarily opposed to the changes, I think it would be nice if kernel eventually has contextualized logging. I just don't think it's currently important as it seems users (incl myself) don't actually need this. Just making kernel logging explicitly global ( |
|
🐙 This pull request conflicts with the target branch and needs rebase. |
4 participants
Pass
Loggerinstances toBlockManager,CCoinsViewDB,CDBWrapper,Chainstate,ChainstateManager,CoinsViews, andCTxMemPoolclasses so libbitcoinkernel applications and tests have the option to control where log output goes instead of having all output sent to the global logger.This PR is an alternative to #30338. It is more limited because it only changes kernel code while leaving other parts of the codebase alone. It also takes the opportunity to migrate legacy LogPrint / LogPrintf calls to the new log macros introduced in #28318.
This is based on #34778 + #29256 + #33847. The non-base commits are:
4c740d3d458refactor: Pass Logger instances to kernel objects4ecb05a429blogging: Add LOG_REQUIRE_CONTEXT optionfbf6f92897drefactor: Log kernel output to local log instances71e2a726cb8kernel: Drop global Logger instance