log, refactor: Allow log macros to accept context arguments #29256
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/29256. ReviewsSee the guideline for information on the review process.
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update. 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. |
|
Concept NACK from me, this seems much uglier and trickier to work with. I've already written in depth about why the current approach makes sense, so I'll be brief here.
Being able to avoid logging critical messages is adding a bug, not a feature.
"+841 -626" and adding a dummy parameter to most calls does not make things less verbose, and it's also much harder to search for net related logging when the individual log statements just say
The only thing needed here is renaming from |
|
Hi AJ, this is a draft, and there will be some more changes which may address your concerns.
Agree, but the idea here is not to discard log messages, the idea just is to attach meaningful metadata to log messages so they can be filtered by component.
I can probably make the description clearer, but the idea here is that this will make the code less noisy: -LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n");
+LogWarning(log, "getsockname failed\n");It is true this sacrifices ability to grep by category constants in the source code, and maybe in your judgement that is an unacceptable cost? But in my opinion, if we ever using same category constants in disparate parts of source code, or different category constants in the same part of the source code, it means source code is badly organized and we should fix that instead of resorting to a coping mechanism of searching for constants instead of searching by source path. In my experience, I've haven't used logging frameworks that have encouraged category constants to be scattered and mixed like this, and I don't think it is a good idea. The "+841 -626" refactoring is definitely 💩-y and I plan to drop it from this PR. The change to the log macros is meant to facilitate that refactoring, not the other way around. I do think we should stop relying on the global logging instance for libbitcoinkernel code, but probably can keep using it elsewhere.
Probably something is lost in communication here, but the idea is to let wallet code use same LogDebug(), LogTrace(), LogInfo(), LogWarning(), LogError() macros other code uses. It just adds a little formatting hook so the wallet name is automatically included when the log source is the wallet. This way full functionality of #29256 is available to the wallet and we can drop WalletLogPrintf and not have dedicated wallet logging functions. |
|
🚧 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. |
f929469 to
15c08bc
Compare
Filtering is discarding. If you just want to find log messages, that what's grep is for, and if you want to make it more fine-grained than "hey this is an important log message/warning/error", that's what If it's any help, I think it's better to think of the sections as not related to which section of the code they appear in so much (again, that's what
The current code there is noisy because it uses -LogWarning("getsockname failed\n");
+LogWarning(log, "getsockname failed\n");which is adding characters, without adding any information to the reader.
I think
That's something that already happens:
I don't think there is anything here "encouraging" these categories to be scattered or mixed; most of them are specific to a small set of related files: TOR:torcontrol, HTTP:httpserver, ZMQ:zmq/, WALLETDB:wallet/, ESTIMATEFEE:policy/fees.cpp, SELECTCOINS:wallet/coinselection, REINDEX:validation, CMPCTBLOCK:blockencodings, RAND:random.cpp, etc. And you obviously have worked with code designed this way: that's how
Updating
A +190 -109 diff because you don't like a one-line wrapper function seems crazy to me. Do you have some reason to think there's large amounts of additional wallet debug logs that would be introduced if it didn't involve writing |
Change was suggested by hodlinator in bitcoin#29256 (comment)
Change was suggested by hodlinator in bitcoin#29256 (comment)
Change was suggested by hodlinator in bitcoin#29256 (comment)
48b3c95 to
5db1958
Compare
|
Rebased 46f5e27 -> 48b3c95 ( If reviewers agree with previous feedback that allowing category arguments to be passed to LogError/LogWarning/LogInfo macros is dangerous because it encourages developers to add log spam and encourages users to ignore important messages, I can add commit 0b5cbf9 here so specifying categories will remain forbidden. Would prefer not to do this because providing a consistent API and providing context with log messages seem like tangible benefits to me, while the current restrictions seem like an indirect and ineffective solution to log spam, but I could live with the restrictions if having them unblocks #30342 and #30343. |
There was a problem hiding this comment.
Code reviewed 5db1958 + 0b5cbf9
PR style
I think it would be clearer to introduce the logging_source_args-test by itself in an initial commit without any behavioral changes to the logging system, to then have following commits demonstrate how the output changes.
Subjective title
The PR title (and commit messages) is/are misleading/heavily subjective:
"Improve new LogDebug/Trace/Info/Warning/Error Macros"
More objective:
"Make LogInfo/Warning/Error accept category and stop requiring it for LogDebug/Trace"
But that title doesn't manage to also squeeze in what I think is the undisputedly useful part here - the log-source concept (required by child PRs #30342 and #30343). I wish that would be introduced without the other API changes.
Suggested change
0b5cbf9 disallowing categories for high priority levels does not go far enough, it is even more important that categories still be required for Debug/Trace IMO, to prevent spamming across categories. Took a stab at implementing that in additional commit 86c7b57 cebc9e2. (It also resets the category for high priority levels).
With my change the PR title could more or less be changed to "Add log source and non-global logging support".
To me it still feels like we should live with the consciously made API decisions from #28318 a bit longer without having to change them.
Test will be extended in next commit to cover support for context objects.
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>
Needed to fix errors like: const Context &GetContext(const Context &)': expects 1 arguments - 3 provided due to a compiler bug: https://stackoverflow.com/questions/5134523/msvc-doesnt-expand-va-args-correctly/5134656#5134656 Example CI failure: https://github.com/bitcoin/bitcoin/actions/runs/8072891468/job/22055528830?pr=29256
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>
07295ff to
2ebcc54
Compare
|
🚧 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. |
There was a problem hiding this comment.
Rebased 5db1958 -> 07295ff (pr/bclog.22 -> pr/bclog.23, compare) with suggested changes adding back #28318 restrictions.
Updated 07295ff -> 2ebcc54 (pr/bclog.23 -> pr/bclog.24, compare) to fix CI "no return statement in function" errors from GCC
Updated 2ebcc54 -> 176ad35 (pr/bclog.24 -> pr/bclog.25, compare) to fix CI errors from older clang versions and add new unit test in separate commit as suggested.
Updated 176ad35 -> 093d58e (pr/bclog.25 -> pr/bclog.26, compare) with minor tweaks to declarations and commit messages.
re: #29256 (review)
Thanks @hodlinator. I really appreciate you figuring out how to implement the restrictions from #28318. Even though I don't like them, I don't think they add a very big cost, so I've incorporated them to help narrow the scope of this PR and unblock it.
I'm still unable to wrap my head around the appeal of a logging framework with an inconsistent API that yells at you if you supply too much context for important messages, and yells at you if you give too little context for less important messages. I can follow the logic which leads to the conclusion that the restrictions are good, but it's not compelling to me, and seems like it just makes the logging framework jankier for developers and users and different from logging frameworks that are well regarded anywhere else. But dropping the restrictions is not the main goal of this PR, so I'm ok with keeping them.
I think it would be clearer to introduce the logging_source_args-test by itself in an initial commit without any behavioral changes to the logging system, to then have following commits demonstrate how the output changes.
Missed this suggestion but will implement in the next push. Need to fix some issues happening in CI anyway. (UPDATE: Implemented this suggestion now).
176ad35 to
093d58e
Compare
There was a problem hiding this comment.
Code reviewed 093d58e
Thank you for changing the end result of this PR to abide by the API decisions of #28318!
(Still think it's a bit odd to open up the gates in eaac991 to then return to closer to master behavior in 093d58e. But no blocker).
While the API has been "reverted", I still think there's a shift in behavior (output) - see inline comments.
(Sorry I didn't get to this sooner, somehow only registered that you had rebased before looking back at this today).
| "[net:error] error arg\n", | ||
| "[net:warning] warning arg\n", | ||
| "[net:info] info arg\n", |
There was a problem hiding this comment.
-
This still goes against the intent of logging: Simplify API for level based logging #28318 in my opinion, by adding categories to output of
LogError/LogWarning/LogInfowhen used with context. -
This also changes behavior insofar as adding
[.*info]-prefixes for LogInfo(), which were intentionally avoided in logging: Simplify API for level based logging #28318:
bitcoin/src/test/logging_tests.cpp
Lines 139 to 149 in e60fc7d
See other comment about suggested change to LogPrint_() to address both above points.
- Especially
LogInfo()without any prefix would feel less "naked" if you were to import the test withCustomLogContextfrom fea5da1 (wallet, logging: Replace WalletLogPrintf() with LogInfo() #30343) into this PR to demonstrate usage. Doing so would also give a greater sense of completeness here IMO.
| logger.PushBackCallback([&](const std::string& s) { messages.push_back(s); }); | ||
|
|
||
| BCLog::Context log{logger, BCLog::NET}; | ||
| LogError(log, "error %s\n", "arg"); |
There was a problem hiding this comment.
nit: Superfluous newlines here and in the other new test case below:
| LogError(log, "error %s\n", "arg"); | |
| LogError(log, "error %s", "arg"); |
| const auto& func = __func__; \ | ||
| BCLog::detail::Format([&](auto&& message) { \ | ||
| ctx.logger.LogPrintStr(message, func, __FILE__, __LINE__, \ | ||
| ctx.category, (level)); \ |
There was a problem hiding this comment.
LogPrint_() - Highly suggest one remaining change to maintain output behavior for LogError/LogWarning/LogInfo when used with context:
| ctx.category, (level)); \ | |
| take_category ? ctx.category : BCLog::LogFlags::ALL, \ | |
| (level)); \ |
One can still use the escape hatch of LogPrintLevel() or LogPrintStr() if one wants things like [net:info] -prefixes.
Looking back, this is a reinvention of that part of my change in cebc9e2 from #29256 (review). Curious to at least hear your thoughts. Not a definite blocker as context-support is after all something new.
Allow
LogDebug(),LogTrace(),LogInfo(),LogWarning(), andLogError()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:
#30342 - To let libbitcoinkernel send output to specfic
BCLog::Loggerinstances instead of a global instance, so output can be disambiguated and applications can have more control over logging.#30343 - To replace custom
WalletLogPrintfcalls with standard logging calls that automatically include wallet names and don't log everything at info level.This PR does not change behavior of current log prints or require them to be updated. It includes tests and documentation covering the new functionality.
Note: Originally this PR also removed some restrictions around passing category constants to log macros to try to make them more consistent, but these changes were too controversial and have been dropped.