Improve new LogDebug/Trace/Info/Warning/Error Macros #29256
Conversation
|
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers. Code CoverageFor detailed information about the code coverage, see the test coverage report. 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. |
ryanofsky
force-pushed
the
pr/bclog
branch
3 times, most recently
from
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 |
|
re: #29256 (comment) AJ, thanks for the response. I want to let your comment stand, and not reply in detail right away to wait for input on this PR from other potential reviewers. I think your views on importance of hardcoding category constants in certain log statements, and on not allowing categories to be specified in other log statements are atypical, or at least will not be as strongly felt by other reviewers. But your response does help me understand your concerns better, and your preferred solution of letting wallet code use its own logging functions, and having kernel code continue to use a global logger. It is also maybe a sign of hope to me that you seem to like I also want to say again that I respect your opinions and appreciate you paying attention to this PR. Your earlier comments directly led to a number of improvements in the PR since it was opened. |
I don't think we should be reworking logging in our entire codebase in order to have a slight improvement in the hypothetical case where we replace some python scripts in contrib with C++ code? If this is worth doing, surely there is a much better example of why.
To me, this suggests that a "context" parameter would be more appropriate than an "instance" one -- eg There are two different ways you might want to add context information: internally to a module, in the way that the wallet does, which would imply the The other way is to have the context be provided externally to a module, so that you can create two instances of the module with different logging contexts that the caller controls. The latter seems like what you're imagining for the contrib/linearize example; but in that case, every module needs to pull in a context from its caller, much more like #30338. I don't see how the latter would mesh well with modules like wallet that also want to add internal context (would we have chained contexts? would the context object manage that?), and it seems like unnecessary complexity to me. |
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
Needed to fix errors like: const Source &_LogSource(const Source &)': expects 1 arguments - 3 provided const Source &_LogSource(const Source &)': 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
|
With the latest push, this PR is now much smaller, and now mostly consists of documentation and test changes. I wanted to split this up in order to be able to base #30342 on a smaller changeset. The wallet changes that were previously part of this PR were moved to #30343. Rebased ce0004e -> 5f64eab ( |
There was a problem hiding this comment.
NACK 5f64eab
At first glance it seems good to be able to specify an optional category to LogInfo, but it risks encouraging inflating LogInfo usage over LogDebug. This could open up future arguments like "you can just filter out the whole category if you don't like my added LogInfo". How about disallowing category for LogInfo like we currently do, but optionally accept something like source for the occasional exception like wallet code in #30343?
It's better to keep requiring either a category (or a source) for LogDebug & LogTrace as they are many and it makes them easier to filter.
Change was suggested by hodlinator in bitcoin#29256 (comment)
Change was suggested by hodlinator in bitcoin#29256 (comment)
There was a problem hiding this comment.
Updated 5f64eab -> 38d3298 (pr/bclog.17 -> pr/bclog.18, compare) with suggested changes.
re: #29256 (review)
Thank you for the close review!
On disallowing category arguments in LogInfo, that is an interesting line of reasoning that would not have occurred to me. Your suggestion to only accept source arguments not category arguments for LogInfo would probably be ok and is something I can implement.
If I understand correctly, you are worried that if it is possible to specify categories in LogInfo, then developers will be tempted to add spammy LogInfo prints that will drown out useful information, when they should be using LogDebug instead, because developers will assume that users can filter out categories they are not interested in. I think this is something worth thinking about, but I'm not sure if you know that logging options (before and after this PR) actually do not support filtering out Info/Warning/Error messages at all, by category or otherwise. These are considered unconditional logging levels, so users would need to write scripts or use external software to filter these. I'm not sure if that fact might change your opinion, but it should be concrete rationale that would push back against developers adding spammy LogInfo prints.
It's also interesting that your reason for not wanting to allow category arguments in (EDIT: Rereading AJ's comments, I'm not sure this paragraph actually represents what he thinks, so striking it out.)LogInfo is sort of the opposite of AJ's reason for not wanting to allow categories in LogInfo (though the reasons are technically compatible). AJ believes it is unsafe to allow specify category arguments in LogInfo and LogWarning and LogError statements because it creates the risk that users will write external scripts or filters that drop entire categories and leave themselves unaware of important log information.
I do think there are plausible reasons to want to disallow attaching categories to certain log statements. If the only way I can make progress on this PR is to refuse to allow categories to be specified, I can make changes implementing that. But doing this would not be my starting point because I think generally category information is useful, and as long as we don't add unsafe options to our own software to filter out entire categories, I think we should try to provide users with category information and let them decide how to use it.
Thanks for that, it was bumming me out thinking about how to try and clarify it. I really prefer your approach in #30348 and #30347 where you identify a specific objective problem and separately propose a targeted fix for exactly that problem.
Note that filtering out Info messages was previously a feature the logging system (and in particular, Info messages with a category would be filtered out by default). That feature was removed in ab34dc6 . I'll have another go at explaining my point of view:
I don't think category information is useful except for enabling log message filtering. It's not useful otherwise, because |
Cool! Hoping that's something @ajtowns could agree to allowing something like an optional The fact that there's something behind the immediate macro level preventing |
There was a problem hiding this comment.
re: #29256 (comment)
The fact that there's something behind the immediate macro level preventing LogInfo/LogError/LogWarning from being filtered is a weaker argument to use in pushing against added logging outside of LogDebug/LogTrace statements, than them not even accepting a category to potentially filter on. Gotta respect an opinionated API. :)
Understood. If the current restrictions which prevent categories from being filtered out are not enough, a developer restriction to prevent categories constants from being specified could be a stronger tool to do the things you and maybe AJ are trying to accomplish. I implemented that restriction in 44afae7 and would be ok with adding it this PR if it solves problems for you and AJ, even if I don't personally see a need for the API to be so restrictive.
I will say one nice thing about the approach in 44afae7 is that someone tries to write a LogInfo statement that includes a category they will get a clear static_assert error explaining that they need to drop the category argument or reduce the log level, instead of just seeing preprocessor and strprintf errors which are harder to decipher.
Updated 38d3298 -> 681b21f (pr/bclog.18 -> pr/bclog.19, compare) with suggested constexpr change (thank you for the suggestion!)
I think I'd be Concept ACK on these, though I've somewhat tuned out since the unfortunate deviation the severity-based logging has taken since #28318 for the reasons I've stated there and in other PRs. We've just over-wrought everything when it could be simple and open. A number of other developers think the same but don't speak up much because it seems pointless to do so. Aside, and unsure it is an issue of discussion: Unless proven otherwise in practice later on, I do not think we need to be overly paranoid and helicopter parenting yet with respect to node operators footgunning themselves en masse with custom log level settings. Only developers and more technically aware users are likely to use them. |
|
re: #29256 (comment)
Curious, when you say "over-complicated", are you referring to the implementation of the logging code, or to the usage of the logging API? Or to effects of logging settings? I don't think the logging API is too complicated. I think #28318 made it more self documenting and simpler. On the other hand, I would say that the macro definitions used to implement the logging API are pretty complicated. This PR does try to improve them by making the implementation sequential and documenting every part of it. But I think it is ok for the implementation to be complicated if the interface is simple, and if there are legitimate reasons to make it complicated, like not evaluating arguments when debug logging is turned off. I'm not sure about interpretation of logging settings, but I haven't been involved in those PRs. |
That comment had already stood for eight weeks, and included an example patchset of changes that could improve things with regards to your complaints about wallet logging, while discussion continued on this. Instead we've had no progress and no discussion, which seems to me to be pretty counter productive. I've opened up what I assume is the least controversial of those as #30355 if you have any interest. |
All of these, I think. The idea was:
Instead (from memory, I'm maybe not up to date), we now have:
None of that seems necessary (unless there is a technical obstacle?) I suggest doing the simplest consistent implementation and API we can come up. Easier for both users and developers. Those seem more valuable than e.g. saving characters that developers might copy/paste when adding new logging. |
|
re: #29256 (comment) Thanks I appreciate the clarification, and I agree with most of those points, except I genuinely do think having one convenience macro for each log level is nice. And LogPrintLevel exists so it is even possible to ignore the convenience macros if you want to do that. Just as an observation, I get the sense that I am not the only one who likes the convenience macros, and that when other people read your comments complaining about the existence of these macros, it might make them discount the value of other things you are saying. So I don't know if it would help, but it might be better if you could come to a grudging acceptance of the macros, and think about not bringing them up if they aren't essential to points you are making. It might help other points be better received and understood. |
|
(For what it is worth, I'm used to thin convenience macros for logging from other codebases. In the ecosystem we also have https://github.com/ElementsProject/lightning/blob/master/lightningd/log.h which follows the same pattern).
The API feels good to me, nice touch with the Side note: |
|
🐙 This pull request conflicts with the target branch and needs rebase. |
Improve new
LogDebug,LogTrace,LogInfo,LogWarning,LogErrormacros introduced in #28318 by allowing metadata and log instances to be specified.This allows categories to be specified at all log levels, not just debug and trace levels:
It also allows log "source" objects to be specified and used:
The advantage of source objects is that they allow more metadata, not just categories, to be attached to log messages, such as wallet names, index names, chainstate names, RPC request ids, and other information to provide more context. Source objects also allow controlling which
BCLog::Loggerinstance is logged to, so unit tests and libbitcoinkernel applications can direct log output from different sources to different places, and not have log output from all sources combined into one stream.The macros also support log statements with no sources or categories for convenience:
The PR is fully backward compatible and does not change any current behavior or require switching to any new syntax. Existing log prints continue to work exactly the same as before.
A new overview of the macros can be found in the logging header. To summarize, the changes in this PR make the macros:
Problems this PR attempts to solve
The new log macros introduced in #28318 are generally great. They allow writing code that is succinct and clear, and make it a lot easier to figure out what log levels are being used. Unfortunately, the new macros are slightly less general than than needed to be used throughout the codebase. Particularly:
Without changing the new macros, the only alternative approach to solving these problems would be to reimplement the macros outside the logging framework so they could be used by wallet and validation code. This PR just takes the approach of slightly generalizing these macros so they work everywhere.
Note to reviewers
I'd encourage first looking at the actual logging API changes in the PR to evaluate it and try to come an independent judgement before looking at the discussion history. Unfortunately and regrettably, I made some dismissive comments on the previous PR, so the discussion here starts out immediately heated.
A summary of the disagreement is that ajtowns believes allowing log syntax
LogDebug(m_log, "debug message\n")is harmful if log category is part of them_logargument instead of being an explicit category constant, because the codebase will be harder to grep. I think being able to log with source objects instead of category constants is a benefit not just for reducing verbosity, but also for outputting categories consistently instead of haphazardly, for outputting other contextual information like wallet names, index names, and chainstate names, and for being able to log to different instances and not hardcode logging macros to use one global logger.