Skip to content

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

Draft
ryanofsky wants to merge 18 commits into
bitcoin:masterfrom
ryanofsky:pr/gklog
Draft

kernel, logging: Pass Logger instances to kernel objects#30342
ryanofsky wants to merge 18 commits into
bitcoin:masterfrom
ryanofsky:pr/gklog

Conversation

@ryanofsky

@ryanofsky ryanofsky commented Jun 26, 2024

Copy link
Copy Markdown
Contributor

Pass Logger instances to BlockManager, CCoinsViewDB, CDBWrapper, Chainstate, ChainstateManager, CoinsViews, and CTxMemPool classes 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:

@DrahtBot

DrahtBot commented Jun 26, 2024

Copy link
Copy Markdown
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/30342.

Reviews

See the guideline and AI policy for information on the review process.

Type Reviewers
Concept ACK sedited
Approach NACK stickies-v

If your review is incorrectly listed, please copy-paste <!--meta-tag:bot-skip--> into the comment that the bot should ignore.

Conflicts

Reviewers, this pull request conflicts with the following ones:

  • #35744 (coins: prevent DB resize from invalidating cursors by l0rinc)
  • #35731 (Indexes: Harden the flush-error notification invariant by arejula27)
  • #35714 (validation: stop writes after flush failure by l0rinc)
  • #35675 (mining: add block template manager by ismaelsadeeq)
  • #35646 (RFC: Separate out runtime errors from BlockValidationState using util::Expected by yuvicc)
  • #35641 (kernel: Add script evaluation tracer by sedited)
  • #35581 (node: add block template manager and track waitNext fee inflow by ismaelsadeeq)
  • #35570 (refactor: Change some validation.cpp methods to return BlockValidationState by optout21)
  • #35557 (kernel, validation: Add btck_chainstate_manager_set_clock_time by ryanofsky)
  • #35496 (kernel: add btck_set_mock_time for testing time-dependent paths by stringintech)
  • #35322 (logging: streamline Logger state and drop redundant methods by ryanofsky)
  • #35307 (blockstorage: keep snapshot base in normal blockfile range by shuv-amp)
  • #35071 (Reindex: save progress to continue after interruption by pinheadmz)
  • #34864 (coins: tighten cache entry state invariants by l0rinc)
  • #34778 (logging: rewrite macros to enforce restrictions at compile-time, improve efficiency and usability by ryanofsky)
  • #34775 (kernel: make logging callback global by stickies-v)
  • #34729 (Reduce log noise by ajtowns)
  • #34320 (coins: delegate CCoinsViewDB::HaveCoin to GetCoin by l0rinc)
  • #34132 (coins: drop error catcher, centralize fatal read handling by l0rinc)
  • #33922 (mining: add getMemoryLoad() and track template non-mempool memory footprint by Sjors)
  • #33847 (kernel: Improve logging API by ryanofsky)
  • #33646 (log: check fclose() results and report safely in logging.cpp by cedwies)
  • #33324 (blocks: add -reobfuscate-blocks argument to enable (de)obfuscating existing blocks by l0rinc)
  • #30343 (wallet, logging: Replace WalletLogPrintf() with LogInfo() by ryanofsky)
  • #29700 (kernel, refactor: return error status on all fatal errors by ryanofsky)
  • #29256 (log, refactor: Allow log macros to accept context arguments by ryanofsky)
  • #26022 (Add util::ResultPtr class by ryanofsky)
  • #25722 (refactor: Use util::Result class for wallet loading by ryanofsky)
  • #25665 (refactor: Add util::Result failure types and ability to merge result values by ryanofsky)
  • #24230 (indexes: Stop using node internal types and locking cs_main, improve sync logic by ryanofsky)
  • #19461 (multiprocess: Add bitcoin-gui -ipcconnect option by ryanofsky)
  • #19460 (multiprocess: Add bitcoin-wallet -ipcconnect option by ryanofsky)
  • #10102 (Multiprocess bitcoin by ryanofsky)

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.

@sedited

sedited commented Jun 26, 2024

Copy link
Copy Markdown
Contributor

Concept ACK.

@DrahtBot

Copy link
Copy Markdown
Contributor

🚧 At least one of the CI tasks failed. Make sure to run all tests locally, according to the
documentation.

Possibly this is due to a silent merge conflict (the changes in this pull request being
incompatible with the current code in the target branch). If so, make sure to rebase on the latest
commit of the target branch.

Leave a comment here, if you need help tracking down a confusing failure.

Debug: https://github.com/bitcoin/bitcoin/runs/26722091796

@ryanofsky

Copy link
Copy Markdown
Contributor Author

Updated 4542335 -> db1b9f7 (pr/gklog.1 -> pr/gklog.2, compare) moving code to an earlier commit to fix a "test-each-commit" test failure https://github.com/bitcoin/bitcoin/actions/runs/9684398780/job/26722073921?pr=30342, and cleaning up code to fix a clang-tidy warning https://cirrus-ci.com/task/5893151045451776

ryanofsky added a commit to ryanofsky/bitcoin that referenced this pull request Jul 3, 2024
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.
stickies-v and others added 11 commits July 13, 2026 20:29
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>
Co-authored-by: Ryan Ofsky <ryan@ofsky.org>
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: unnecessary strprintf
calls during fuzzing, confusing error messages when macros are called
with the wrong arguments, duplicated code with unexplained differences
and undocumented assumptions.

Since this is a rewrite, reading the new code in log.h first should be clearer
than starting from the diff.

Specific benefits of the new implementation are:

- Functionality is implemented once in a single `LOG_EMIT` macro instead of
  multiple times in different macros with diverging code paths and unexplained
  differences.

- Unnecessary `strprintf` calls are now skipped when logging is disabled (in
  bitcoind when `-noprinttoconsole -nodebuglogfile` options are used, and in
  tests and kernel applications when DisableLogging is called). This change
  should not affect bitcoind noticeably, but could speed up fuzz tests calling
  functions which log.

- Clearer error messages: 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 direct message telling you to add or remove the category instead
  of expanded macro syntax errors.

- Previously it was possible to call `detail_LogWithSrcLoc` with
  inconsistent or invalid arguments, for example bypassing ratelimiting
  without it being explicit. New `LOG_EMIT` macro is compile-time safe
  and enforces the exact same restrictions as other macros.

- 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.

- `NO_RATE_LIMIT` special case used to bypass rate limiting is dropped.
  The `LOG_EMIT` macro can control rate limiting (and other options if
  they are added in the future) while still using the same ratelimiting
  defaults as other macros.

Co-Authored-By: Hodlinator <172445034+hodlinator@users.noreply.github.com>
Co-Authored-By: stickies-v <stickies-v@protonmail.com>
Drop Entry::should_ratelimit field in favor of Options::ratelimit field.

Dropping the Entry::should_ratelimit field makes buffered log messages
in m_msgs_before_open smaller, and avoids potential confusion because
the field is stored after rate limiting has been applied, so just gets
ignored. Conceptually it also makes sense to treat the ratelimit option
as an input to the logger rather than as an attribute of the message
being logged.
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 <172445034+hodlinator@users.noreply.github.com>
Co-Authored-By: stickies-v <stickies-v@protonmail.com>
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.
Current kernel logging API is too complicated and too restrictive. This PR
tries to improves it.

I'd expect an API that supported logging to allow creating log streams with
different options and providing some way to specify which library operations
should be logged to which streams.

By contrast, the current API allows creating multiple log streams, but all the
streams receive the same messages because options can only be set globally and
the stream objects can't be passed to any kernel API functions. They are not
even referenced by the `btck_Context` struct which holds other shared state. If
no log streams are created, log messages are generated anyway, but they are
stored in a 1MB buffer and not sent anywhere, unless a log stream is created
later, at which point they are sent in bulk to that stream. More log streams
can be created after that, but they only receive new messages, not the buffered
ones. If log output is not needed, a btck_logging_disable() call is required to
prevent log messages from accumulating in the 1MB buffer. Calling this will
abort the program if any log streams were created before it was called, and
also abort the program if any new log streams are created later.

None of these behaviors seem necessary or ideal, and it would be better to
provide a simpler logging API that allows creating a log stream, setting
options on it, registering it with the `btck_Context` instance and receiving
log messages from it. Another advantage of this approach is that it could allow
(with bitcoin#30342) different log streams to be used for different purposes, which
would be not be possible with the current interface.
@DrahtBot

Copy link
Copy Markdown
Contributor

🚧 At least one of the CI tasks failed.
Task No wallet: https://github.com/bitcoin/bitcoin/actions/runs/29337611210/job/87100747364
LLM reason (✨ experimental): CI failed during CMake configuration because Clang 17 rejected the warning flag -Wunique-object-duplication (treated as an error via -Werror).

Hints

Try to run the tests locally, according to the documentation. However, a CI failure may still
happen due to a number of reasons, for example:

  • Possibly due to a silent merge conflict (the changes in this pull request being
    incompatible with the current code in the target branch). If so, make sure to rebase on the latest
    commit of the target branch.

  • A sanitizer issue, which can only be found by compiling with the sanitizer and running the
    affected test.

  • An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

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.
Needed due to base PR, can be dropped before merge
@DrahtBot

Copy link
Copy Markdown
Contributor

🚧 At least one of the CI tasks failed.
Task NetBSD Cross: https://github.com/bitcoin/bitcoin/actions/runs/29372633900/job/87219192123
LLM reason (✨ experimental): CI failed because the fuzz test build for coins_view.cpp did not compile (g_thread_pool_mutex undeclared / thread-safety attribute errors, treated as -Werror).

Hints

Try to run the tests locally, according to the documentation. However, a CI failure may still
happen due to a number of reasons, for example:

  • Possibly due to a silent merge conflict (the changes in this pull request being
    incompatible with the current code in the target branch). If so, make sure to rebase on the latest
    commit of the target branch.

  • A sanitizer issue, which can only be found by compiling with the sanitizer and running the
    affected test.

  • An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants