Improve new LogDebug/Trace/Info/Warning/Error Macros

ryanofsky commented at 10:09 pm on January 16, 2024: contributor

Improve new LogDebug, LogTrace, LogInfo, LogWarning, LogError macros 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:

0LogError(BCLog::NET, "Something failed and needs to be fixed.\n");
1LogWarning(BCLog::NET, "Something seems wrong and may need to be fixed.\n");
2LogInfo(BCLog::NET, "Something happened you may want to know about.\n");
3LogDebug(BCLog::NET, "Something happened that may help you debug a problem.\n");
4LogTrace(BCLog::NET, "A low level event happened.\n");

It also allows log “source” objects to be specified and used:

0const BCLog::Source m_log{BCLog::NET};
1...
2LogError(m_log, "Something failed and needs to be fixed.\n");
3LogWarning(m_log, "Something seems wrong and may need to be fixed.\n");
4LogInfo(m_log, "Something happened you may want to know about.\n");
5LogDebug(m_log, "Something happened that may help you debug a problem.\n");
6LogTrace(m_log, "A low level event happened.\n");

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::Logger instance 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:

0LogError("Something failed and needs to be fixed.\n");
1LogWarning("Something seems wrong and may need to be fixed.\n");
2LogInfo("Something happened you may want to know about.\n");
3LogDebug("Something happened that may help you debug a problem.\n");
4LogTrace("A low level event happened.\n");

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:

Consistent, now accepting the same parameters
Compatible with log categories, to make it possible to filter or highlight log messages from a particular component
Compatible with wallet logging, which includes the wallet name in log messages
Require less verbosity, by not needing category constants to be repeated in log prints from a common source.
Not tied to one hardcoded global Logger instance

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:

The new macros cannot be used conveniently in wallet code because wallet log prints are supposed to include wallet names in log messages. This PR allows adding a format hook, which #30343 uses to begin using the new macros in wallet code without boilerplate or nonstandard logging functions.
The new macros cannot be used in libbitcoinkernel code because they do not allow specifying a logger instance. This PR allows specifying a logger instance, which #30342 uses so kernel code can specify which objects to log to.

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 the m_log argument 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.

DrahtBot commented at 10:09 pm on January 16, 2024: 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/29256.

Reviews

See the guideline for information on the review process.

Type	Reviewers
Concept NACK	ajtowns, hodlinator
Concept ACK	TheCharlatan, jonatack

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:

#29641 (scripted-diff: Use LogInfo over LogPrintf [WIP, NOMERGE, DRAFT] by maflcko)

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 commented at 10:34 pm on January 16, 2024: contributor

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.

Make them always accept log categories to make it possible to only log messages from a particular component.

Being able to avoid logging critical messages is adding a bug, not a feature.

Make them less verbose by not requiring BCLog category constants to be specified in individual log prints

“+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 m_log rather than BCLog::NET.

Make them compatible with wallet logging, which includes the wallet name in log messages

The only thing needed here is renaming from Printf to Info…

DrahtBot added the label Needs rebase on Jan 16, 2024

ryanofsky commented at 4:41 am on January 17, 2024: contributor

Hi AJ, this is a draft, and there will be some more changes which may address your concerns.

Make them always accept log categories to make it possible to only log messages from a particular component.

Being able to avoid logging critical messages is adding a bug, not a feature.

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.

Make them less verbose by not requiring BCLog category constants to be specified in individual log prints

“+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 m_log rather than BCLog::NET.

I can probably make the description clearer, but the idea here is that this will make the code less noisy:

0-LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n");
1+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 :hankey:-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.

Make them compatible with wallet logging, which includes the wallet name in log messages

The only thing needed here is renaming from Printf to Info…

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.

ryanofsky force-pushed on Jan 17, 2024

DrahtBot removed the label Needs rebase on Jan 17, 2024

ryanofsky force-pushed on Jan 17, 2024

DrahtBot added the label CI failed on Jan 17, 2024

DrahtBot commented at 7:15 pm on January 17, 2024: 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/20586125687

ryanofsky force-pushed on Jan 17, 2024

DrahtBot removed the label CI failed on Jan 17, 2024

ryanofsky marked this as ready for review on Jan 17, 2024

ryanofsky force-pushed on Jan 18, 2024

ajtowns commented at 6:12 am on January 19, 2024: contributor

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.

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 -logsourcelocations is for.

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 -logsourcelocations is for), but as a subset of the “debug” part, in that they let you filter/discard various parts of the full debug log that you would get with -debug=1.

0-LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n");
1+LogWarning(log, "getsockname failed\n");

The current code there is noisy because it uses LogPrintLevel. The change you’re actually making is:

0-LogWarning("getsockname failed\n");
1+LogWarning(log, "getsockname failed\n");

which is adding characters, without adding any information to the reader.

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?

I think LogDebug(BCLog::NET, "oh no, it all went wrong\n") is better than LogDebug(m_log, "oh no, it all went wrong). All the characters in the former are doing something useful; m_log in the latter isn’t (if it weren’t for macro magic, we’d write m_log.Debug("...") instead, which would be okay at least). I don’t think moving the category away from the line of code it’s affecting is very useful; and if you want to group all the logs from an individual file together (the way putting m_log{BCLog::NET} at the top of the file/class does), then, again, that’s what logsourcelocations is for…

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.

That’s something that already happens: BCLog::NET is in timedata and headersync and banman and net and net_processing; BCLog::VALIDATION is in validation and validationinterface and flatfile (thought there was a pr to fix that one) and signet; BCLog::MEMPOOL is in txmempool, validation and net_processing. It doesn’t mean the source code is badly organised, it means different parts of the source are generating related log messages.

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.

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 LogPrint has worked in this codebase since it was implemented in #3009.

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.

Updating TraceSqlCallback to call LogTrace rather than LogPrintf would be an improvement as those messages would get categorised properly; but otherwise this seems like massive overkill just to avoid writing "[%s] ...", walletname, ....

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.

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 [%s], walletname or are there a bunch of the current unconditional WalletLogPrintf calls that should be silenced and only available when debugging is enabled?

DrahtBot added the label CI failed on Jan 19, 2024

DrahtBot removed the label CI failed on Jan 19, 2024

willcl-ark added the label Utils/log/libs on Jan 24, 2024

ryanofsky commented at 8:03 pm on January 25, 2024: contributor

@ajtowns, to try to steer this discussion in a more constructive direction, would it be possible for you to make a list of the biggest harms you believe this PR would cause if it were merged? And if you have ideas on how the harms you see could be avoided, while the problems I am trying to solve (see “Problems this PR attempts to solve” in the PR description) could be addressed, it would be really helpful to know about. Maybe the harms you see this PR causing and the problems this PR is trying to solve are in direct contradiction, but it’s not obvious to me that this is the case, so maybe there is a way out of our disagreement here. In the meantime, I responded to your last message below.

re: #29256 (comment)

Filtering is discarding.

It’s really not. You can view logs into a text editor or log viewer and highlight categories of messages you are interested in while not discarding other messages.

I am just trying to add some basic flexibility here. If you don’t want to attach categories to log messages, you don’t have to, you can write LogWarning({}, "uncategorizable warning"). The PR just makes the log macros consistently accept a source parameter, so code has flexibility to set a category, set a log destination, add metadata to log messages, control log formatting, do a combination of these things, or do none of these things.

0-LogWarning("getsockname failed\n");
1+LogWarning(log, "getsockname failed\n");
which is adding characters, without adding any information to the reader.

This adds 5 characters, but also adds category information that was previously absent to the output. You can find examples of where the API changes in this PR increase verbosity, and examples where they decrease it, and I think there should be less verbosity on net. I also think some of this discussion around verbosity misses the bigger picture, and is a distraction from the actual goal of the PR, which is to add context to log messages, and give code that needs it control over logging behavior. But if making the log parameter optional is a requirement for you, it should be possible to implement that here and never increase verbosity in any case.

All the characters in the former are doing something useful; m_log in the latter isn’t (if it weren’t for macro magic, we’d write m_log.Debug("...") instead, which would be okay at least).

I agree m_log.Debug("...") would be better than LogDebug(m_log, "...") but I don’t understand why the former would be ok, but the latter is unacceptable. You definitely have much stronger opinions about verbosity than me, so maybe we can try to engage more constructively on this. I think on net, this PR should reduce verbosity, but maybe more improvements are possible that could alleviate your concerns.

I don’t think moving the category away from the line of code it’s affecting is very useful

That’s ok, since allowing this was a side effect, not a major goal of this PR. But LogDebug(m_log, "debug message") can be easier to write and read than LogDebug(BCLog::TXRECONCILIATION, "debug message"), especially if the code has a lot of log prints and the category is repeated a lot. In any case, you aren’t forced to choose one approach or the other. The PR allows both.

It doesn’t mean the source code is badly organised, it means different parts of the source are generating related log messages.

Ok, we definitely disagree on how well the code is organized. IMO, validation.cpp doing BCLog::MEMPOOL prints is messed up. But this is a tangent. I think log sources should encourage better organization, but this PR does not force anything or break anything that works now.

I don’t think there is anything here “encouraging” these categories to be scattered or mixed

I don’t want to make a big deal out of this, but just to clarify, I think the status quo where trace and debug macros require BCLog::LogFlags arguments and can’t take source arguments makes it easier to mix up categories, intentionally and unintentionally. The alternative where source objects can be used for error/warning/info prints, not just debug/trace prints, and can tag everything with the same category should make it easier to be consistent if you want to be consistent (and not get in the way if you don’t want to).

Updating TraceSqlCallback to call LogTrace rather than LogPrintf would be an improvement as those messages would get categorised properly; but otherwise this seems like massive overkill just to avoid writing "[%s] ...", walletname, ....

I don’t see the massive overkill. This is a reasonable PR that adds documentation, tests, and doesn’t change very much code. We don’t want to require every individual wallet log print to include "[%s] ...", walletname, ... boilerplate for obvious reasons, I think. The problems with the WalletLogPrintf function are:

It is only capable of logging at info level, does not provide a way to log at higher or lower levels.
It evaluates its arguments unconditionally, so if it were extended to log at lower levels, it would either be inefficient or need to duplicate preprocessor code from logging.h to be as efficient.
It is inconsistent with the rest of the codebase. It is nice if the same logging macros can be used everywhere, and the same features can be used everywhere. It also ensures logging is consistent within the wallet and only one logging API is used there.

DrahtBot added the label CI failed on Jan 25, 2024

ryanofsky commented at 3:45 am on January 29, 2024: contributor

re: #29256 (comment)

But if making the log parameter optional is a requirement for you, it should be possible to implement that here and never increase verbosity in any case.

It turns out making the category argument completely optional is not too hard to implement: 69e69b2a82c95f8040be093a29e5f84c37641f3a. So you could write:

0LogWarning("uncategorizable warning")

instead of

0LogWarning({}, "uncategorizable warning")

if that is the blocker here.

ajtowns commented at 5:32 am on January 29, 2024: contributor

And if you have ideas on how the harms you see could be avoided, while the problems I am trying to solve (see “Problems this PR attempts to solve” in the PR description) could be addressed,

I think the problem you are actually attempting to solve is “I, ryanofsky, find this weird and I don’t like it”, and I don’t think code changes are the way of solving that, any more than code changes are the right way to solve the problem “Bitcoin is weird and I don’t like it”. I think you’re wrong, but you seem unwilling to consider changing your opinion, so I’m pretty doubtful this is going to be productive. However, in case I’m wrong:

These macros cannot be used directly in wallet code because wallet log prints are supposed to automatically attach wallet names to log messages.

The only cases where wallet names are automatically attached to log messages are in info level calls, which can be trivially dealt with by changing the existing wrapper to call LogInfo, and with an optional scripted diff renaming the wrapper as well.

These macros cannot be used at all in libbitcoinkernel code because they do not allow specifying a logger instance.

This, also, is not true: the assumption of these macros is that there is a global BCLog::Logger instance, which is already provided by LogInstance(). If we want to allow apps to configure libbitcoinkernel’s logging in future, we could allow them to setup that global instance, or provide their own callbacks for it to use, in much the same way libevent allows you to setup callbacks. That’s not something that needs changing.

Filtering is discarding.

It’s really not. You can view logs into a text editor or log viewer and highlight categories of messages you are interested in while not discarding other messages.

That’s not filtering, that’s ‘grepping’. If you don’t want to filter, but just want to highlight, then, as I’ve said repeatedly, logsourcelocations is what you want; the only benefit categories have compared to that is that categories can be (and by default are) filtered/discarded. logsourcelocations gives you much more exact information, is precisely separated by source file as you want, works with every level of log message, and requires no code changes or ongoing development effort to support.

I am just trying to add some basic flexibility here. If you don’t want to attach categories to log messages, you don’t have to, you can write LogWarning({}, "uncategorizable warning").

In that case you will not be able to use your log viewer to highlight that message when you’re looking for it, which defeats your claimed goal. (Except, of course, you can select it for highlight, by looking for [warning] markers)

The PR just makes the log macros consistently accept a source parameter,

Can you please try using the logsourcelocations option before replying again? I really don’t see how it doesn’t already do everything you want, but you’ve ignored it every time I’ve mentioned it.

0-LogWarning("getsockname failed\n");
1+LogWarning(log, "getsockname failed\n");
which is adding characters, without adding any information to the reader.

The reader of the source code, is who I’m referring to here.

All the characters in the former are doing something useful; m_log in the latter isn’t (if it weren’t for macro magic, we’d write m_log.Debug("...") instead, which would be okay at least).

I agree m_log.Debug("...") would be better than LogDebug(m_log, "...")

I don’t think m_log.Debug() would be better than LogDebug – in my opinion having a global log instance is the right thing here, and both having multiple references to a global log instance or having multiple log instances that all then coordinate writing to a single log would be worse.

As I’ve already said, I think m_log.SetCategory(NET); m_log.Debug("connected to foo") is much worse than LogDebug(NET, "connected to foo"). Having to keep more context/state in your head when you’re looking at code makes things harder, and it tends to make tool use go from “usually works” to “never works” (eg, grep -RIl 'Log.*NET').

It doesn’t mean the source code is badly organised, it means different parts of the source are generating related log messages.

Ok, we definitely disagree on how well the code is organized. IMO, validation.cpp doing BCLog::MEMPOOL prints is messed up. But this is a tangent. I think log sources should encourage better organization, but this PR does not force anything or break anything that works now.

validation.cpp is where we have the code for “is this valid for the mempool”, because we thought the word “valid” was more important than the word “mempool” in that sentence. BCLog::VALIDATION on the other hand is limited to blocks and headers, allowing it to be much less noisy than anything that triggers for every transaction, like BCLog::MEMPOOL. None of that is any indication of whether the code is well or badly organised.

I don’t think there is anything here “encouraging” these categories to be scattered or mixed

I don’t want to make a big deal out of this, but just to clarify, I think the status quo where trace and debug macros require BCLog::LogFlags arguments and can’t take source arguments makes it easier to mix up categories, intentionally and unintentionally.

I think by “source arguments” you mean “a context argument”, and there’s no reason they couldn’t – you can write LogDebug(m_log_category, "stuff"); right now just as easily as you could LogDebug(m_log, "stuff"); after this PR. That would still be a bad idea, though, as having the name of the log category obvious in the code is helpful.

Updating TraceSqlCallback to call LogTrace rather than LogPrintf would be an improvement as those messages would get categorised properly; but otherwise this seems like massive overkill just to avoid writing "[%s] ...", walletname, ....

I don’t see the massive overkill.

If there’s a way of getting 99% of the benefits with a +1-1 change, then a +300-200 change is overkill in general.

This is a reasonable PR that adds documentation, tests, and doesn’t change very much code. We don’t want to require every individual wallet log print to include "[%s] ...", walletname, ... boilerplate for obvious reasons, I think. The problems with the WalletLogPrintf function are:
1. It is only capable of logging at info level, does not provide a way to log at higher or lower levels.

Why do you think that is a problem? None of the other existing cases need to add walletname boilerplate. What wallet-specific event (if it’s not wallet specific, it doesn’t need to be tagged with a wallet name) shouldn’t be unconditionally logged (if an event is affecting the thing that holds all your funds, isn’t that one of the most important things to log)?

2. It evaluates its arguments unconditionally, so if it were extended to log at lower levels, it would either be inefficient or need to duplicate preprocessor code from logging.h to be as efficient.

That it only logs at info level means it is unconditionally logged, so all the arguments are naturally unconditionally evaluated.

3. It is inconsistent with the rest of the codebase.

It’s inconsistent with your idea of how the codebase should be, but it’s completely consistent with how the codebase actually is. Which is fine: changing the codebase to match better ideas is how you improve it. But things aren’t going to improve if we can’t recognise how things actually are in the first place.

DrahtBot removed the label CI failed on Jan 30, 2024

DrahtBot commented at 12:18 pm on February 10, 2024: 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/20597453668

DrahtBot added the label CI failed on Feb 10, 2024

vasild commented at 9:00 am on February 16, 2024: contributor

Make them all accept log categories, to make it possible to filter or highlight log messages from a particular component.

This seems like a step in the right direction. Currently we log messages unconditionally that don’t have a category. But this is mixing two separate things - facility and severity. I have always found this confusing.

They got it right decades ago with syslog(3). Every log message has a facility and a severity. Because we don’t want users to configure their systems in such a way as to dangerously omit important messages, then we don’t provide a way to omit messages with higher severity than e.g. “info” or “notice”. This is unrelated to the facility.

If some parts of this PR cause controversy, could it be reduced to the non-controversial things?

ryanofsky force-pushed on Feb 27, 2024

ryanofsky commented at 11:05 pm on February 27, 2024: contributor

Updated 99feed7350b5fc3ae3157dd395ae6260c5bfc092 -> 0cd1616d47e61e125eb3e573573c0c56fba6b775 (pr/bclog.12 -> pr/bclog.13, compare) making the log macros backwards compatible to avoid any controversial changes. Rebased 0cd1616d47e61e125eb3e573573c0c56fba6b775 -> 93d37f7d655409e6830475a10f4c9f16e35c76cd (pr/bclog.13 -> pr/bclog.14, compare) due to silent conflicts with #26836. Updated 93d37f7d655409e6830475a10f4c9f16e35c76cd -> a91fbbd61551702f26f734f3cdd1c080f9d51628 (pr/bclog.14 -> pr/bclog.15, compare) to fix tidy failure https://cirrus-ci.com/task/6362757050662912, and try to work around MSVC compiler bug https://github.com/bitcoin/bitcoin/actions/runs/8072891468/job/22055528830?pr=29256, and clean up some documentation.

If some parts of this PR cause controversy, could it be reduced to the non-controversial things?

I made a try at this in the latest push. I think most of the criticism of this PR from AJ is saying that the changes here are unnecessary, not really that they are harmful, so I made the logging macros completely backwards compatible using the approach I mentioned #29256 (comment), and only kept the changes I think are essential. I think this should help.

ryanofsky force-pushed on Feb 27, 2024

ryanofsky force-pushed on Feb 28, 2024

DrahtBot removed the label CI failed on Feb 28, 2024

DrahtBot added the label Needs rebase on Mar 12, 2024

ryanofsky force-pushed on Mar 28, 2024

DrahtBot removed the label Needs rebase on Mar 28, 2024

DrahtBot added the label CI failed on Apr 20, 2024

DrahtBot removed the label CI failed on Apr 23, 2024

ajtowns commented at 12:05 pm on April 30, 2024: contributor

I think most of the criticism of this PR from AJ is saying that the changes here are unnecessary, not really that they are harmful,

I said “As I’ve already said, I think m_log.SetCategory(NET); m_log.Debug("connected to foo") is much worse than LogDebug(NET, "connected to foo").” Does that really not come across as me saying they’re harmful? I really don’t think I’m being that unclear. Anyway, I’ll bow out, I’m already sorry for touching this.

ryanofsky commented at 1:06 pm on April 30, 2024: contributor

I think most of the criticism of this PR from AJ is saying that the changes here are unnecessary, not really that they are harmful,

I said “As I’ve already said, I think m_log.SetCategory(NET); m_log.Debug("connected to foo") is much worse than LogDebug(NET, "connected to foo").” Does that really not come across as me saying they’re harmful? I really don’t think I’m being that unclear. Anyway, I’ll bow out, I’m already sorry for touching this.

I think it’s possible you might be referring to some changes in an earlier version of this PR. The PR allows the syntax you like and support it as a first-class usage! It does change wallet code, however to look like LogDebug(m_log, "debug message") to include wallet filenames in log messages. So if that is the harm which this PR causes, I want to acknowledge it, and I will update the PR description. @ajtowns we’ve definitely had difficulty communicating here and in some other issues, and I’m sorry for the dismissive comments I initially left on #28318, which on the whole I think is actually a good PR. I especially regret it you are “sorry for touching this”, because #28318 is a real improvement, and your comments on this PR have made it better too, and motivated all the work and simplifications I’ve made to it since it was opened.

ajtowns commented at 3:05 pm on April 30, 2024: contributor

I think most of the criticism of this PR from AJ is saying that the changes here are unnecessary, not really that they are harmful,

I said “As I’ve already said, I think m_log.SetCategory(NET); m_log.Debug("connected to foo") is much worse than LogDebug(NET, "connected to foo").” Does that really not come across as me saying they’re harmful? I really don’t think I’m being that unclear. Anyway, I’ll bow out, I’m already sorry for touching this.

I think it’s possible you might be referring to some changes in an earlier version of this PR.

That was the clearest example of saying that something was harmful, as evidence that I don’t think you summarised my criticism accurately. English is my first language, so it’s not like I can switch to another one to try to get my point across better… My main criticism of what remains is:

Can you please try using the logsourcelocations option before replying again? I really don’t see how it doesn’t already do everything you want, but you’ve ignored it every time I’ve mentioned it.

I’ll rephrase how I see things again for whatever that’s worth:

being able to match a log entry with where it came from in the source is super valuable
-logsourcelocations does that automatically for us, which is far less effort than manually specifying a category, and by giving a specific filename and line number, does a far better job of it as well
the only reason to keep the manual categories around at all is for selectively enabling/disabling noisy logs
the only noisy logs we have are those in the debug and trace levels (anything else would be a bug)
having those be manually specified rather than automatic is a win, as it allows us to rearrange our source code without accidentally breaking the configs of users who’ve enabled some noisy logs
adding those categories for non-noisy log messages is just busy work: it doesn’t make it easier to find the source location of the debug message than -logsourcelocations does, and it doesn’t help reduce log noise because those log messages aren’t noisy in the first place

The macros in #28318 pretty much fall out from that. I suppose an alternative would be to have Log(INFO, "foo") and LogNoisy(DEBUG, NET, "bar") or so.

There are probably things logsourcelocations is bad at; if so, why not improve it so the benefits hit everywhere automatically?

The PR allows the syntax you like and support it as a first-class usage!

I think specifying a category sometimes and not others depending on who happened to author that section of the code is a terrible idea. But I mean, it’s not any more terrible than having “LogPrint” and “LogPrintf” having significantly different behaviour, so it’s not like it’s a disaster. Anyway, it’s certainly not worth 15+ months of time/energy.

ryanofsky commented at 4:33 pm on April 30, 2024: contributor

Thanks, I added a link directly to this comment in the summary so those who are interested can follow the chain of reasoning.

To reiterate my own point of view, -logsourcelocation does not solve the same problem this PR solves because it does not (1) let libitcoinkernel applications call validation functions and control which Logger object they write to, and (2) allow code like wallet code and index code to easily include additional metadata in log messages (wallet names and index names) while using convenient LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() macros.

ajtowns commented at 10:06 am on May 2, 2024: contributor

To reiterate my own point of view, -logsourcelocation does not solve the same problem this PR solves because it does not

That ignores bullets (1), (2) and (5) from your OP (as it stands today).

It also ignores comments like vasild’s, jamesob’s, luke-jr’s, jonatack’s, laanwj’s or your own. There’s a valid disagreement there, isn’t there? Can’t we discuss it like engineers and work out what actual tradeoffs are lurking behind the intuition/gut feels? I’ve tried to spell out my reasoning both before and after the PR got merged as well as having brought it up at the irc meeting to try to trigger discussion, but the response has just to reiterate the disagreement without any analysis or engagement with the reasoning that I’ve offered for doing it this way? Why? That makes no sense to me. I’m willing to be convinced I’ve made a mistake; but someone has to show me where I made the mistake, or at least do a show of hands that the majority prefers something else.

I mean, am I incorrect in reading the previous two comments as “here are the reasons I think this solution make sense: A, B, C, D, E, F” and “okay, that’s nice, I’m going to completely ignore them, besides, X and Y are still important”? Other than “uh, okay, I guess I know when I’m not wanted”, how else am I meant to take it? What’s the chance a response addressing X and Y will just also get equally ignored?

(FWIW, I’d strongly contend that just declaring things should be such-and-such a way without being willing either talk through the tradeoffs and maybe find some mutually preferable solution, or to happily say “oh well, not what I’d consider perfect, but not so bad, let’s press on!” is a pretty major contributor to things not progressing very fast. I can understand that habit in bitcoin broadly – you explain why BTC is great and people shrug or call it a ponzi, and the only thing you can do is wait to be proven right, so you start just skipping straight to the final step – but I don’t understand it in the context of code changes at all…)

Anyway, on to X and Y:

(1) let libitcoinkernel applications call validation functions and control which Logger object they write to,

Doing that meaningfully means changing all the logging in all the bitcoin-kernel related modules (eg validation, mempool, blockstorage, scheduler, …) to explicitly specify a logger rather than using the global functions, which seems like a lot of pointless busy work? I can’t imagine why we’d want to support having multiple bitcoin-kernel instances in a single executable logging to different loggers; if someone wants to do that, it seems easy enough to just launch two separate processes.

The alternative would be to just have applications manipulate the global logger directly, which is how things already work, perhaps turning it into an atomic unique_ptr or similar and making many of its function virtual to allow overriding?. I’m just not really sure what the problem here is that’s worth fixing; we already buffer log messages until StartLogging is called, and libbitcoin-kernel continuing to have a global logger instance seems simple and efficient for both us and any potential users of the library.

(If we did want to do that anyway for some reason, then waiting until std::source_location is available would let us use log.Debug(...) syntax via template functions rather than having to use a macro and writing LogDebug(log, ...). So rushing this change now seems bad even if the goal makes sense in some way I don’t see)

(The phrasing in the OP is currently “The new macros cannot be used in libbitcoinkernel code because they do not allow specifying a logger instance.” but that seems just false – there’s a bunch of LogInfo() calls in kernel/*.cpp already, and all the LogPrintf and LogPrint calls in validation are just aliases of LogInfo and LogDebug)

and (2) allow code like wallet code and index code to easily include additional metadata in log messages (wallet names and index names) while using convenient LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() macros.

We could do that simply by renaming WalletLogPrintf to WalletLogInfo, with behaviour no worse than today. There just isn’t currently a need for non-info-level logs that report the wallet’s name (which makes sense: in general ops on a wallet are important enough to be an “INFO” event).

Having WalletLogPrintf (or whatever) wrap around LogInfo sucks a bit, because it means -logsourcelocations reports the wrapper location rather than the caller. But a fix for that will be easy “real-soon-now” (#29077) when we can use std::source_location.

Changing wallet/sqlite’s TraceSqlCallback to use LogTrace instead of LogPrintf is something we could do today that would improve things by making the output correctly indicate that it’s trace-level rather than info-level, and be correctly annotated with the debug category that enables it to be logged. Again, that only needs a few characters changed, not a fundamental revamp.

Here’s a patchset that does those wallet changes: it’s a one line change for the trace logging, and two scripted diffs. Easy to do, easy to review, and “allows the wallet code to easily include its metadata in log messages while using convenient LogInfo macros/functions”. If we want to improve things further (like using std::source_location when it’s available or introducing some wallet-specific warnings or debug messages) we could still easily do that in the future.

TheCharlatan commented at 7:26 pm on June 25, 2024: contributor

Concept ACK

Re #29256 (comment)

Doing that meaningfully means changing all the logging in all the bitcoin-kernel related modules (eg validation, mempool, blockstorage, scheduler, …) to explicitly specify a logger rather than using the global functions, which seems like a lot of pointless busy work? I can’t imagine why we’d want to support having multiple bitcoin-kernel instances in a single executable logging to different loggers; if someone wants to do that, it seems easy enough to just launch two separate processes.

There are use cases for having e.g. two chainstate managers running in parallel. Take a block file linearizer replacing the scripts in contrib/linearize as an example; you have one that reads blocks in their indexed order and another that writes blocks and their index back to another location on disk. Having something to distinguishing logs issued between the two sounds useful. In my eyes an important utility of the library is exactly that, you don’t have to use multiple processes or go through the rpc to interact with Bitcoin Core’s data structures and validation rules.

ryanofsky commented at 8:55 pm on June 25, 2024: contributor

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 log.Debug(...) syntax while disliking LogDebug(log, ...) syntax. I personally don’t see much distinction between the two syntaxes, other than that latter allows arguments to be conditionally evaluated. But not evaluating arguments seems less important to me than being able to log in a consistent way across the codebase, so this offers hope for compromise.

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.

ajtowns commented at 8:05 am on June 26, 2024: contributor

Take a block file linearizer replacing the scripts in contrib/linearize as an example; you have one that reads blocks in their indexed order and another that writes blocks and their index back to another location on disk.

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.

Having something to distinguishing logs issued between the two sounds useful

To me, this suggests that a “context” parameter would be more appropriate than an “instance” one – eg LogInfo(walletctx, "opened wallet, and sent all your funds to the genesis address, haha\n"); where the logging system would automatically invoke msg = walletctx(msg) when provided, in order to prefix the wallet name to the message or similar, but only after verifying logging is actually enabled. That’s much more constrained behaviour than an instance parameter – it just adds context information to a log message rather than allowing you to change the priority/category, or have completely different logging parameters (log file location, log to stdout, display source location, etc). The difference between LogInfo(m_wallet_ctx, "...") and the existing WalletLogPrintf("...") seems pretty minor to me.

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 ctx variable is established within the module and is private/local to that module. In that case, a similar approach to the one here would make sense – have it be an optional parameter that the wallet module uses.

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.

ryanofsky force-pushed on Jun 26, 2024

ryanofsky commented at 6:19 pm on June 26, 2024: contributor

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 ce0004e42d37786f98cdf9d55b976b935dcf1ba1 -> 5f64eab013a58967af37a59c863c2ab6d45ba6e8 (pr/bclog.16 -> pr/bclog.17, compare) updating the PR as described.

in doc/developer-notes.md:1 in 5f64eab013

hodlinator commented at 9:09 pm on June 26, 2024:

source feels a bit abstract and special case, it would be good to keep LogDebug(BCLog::CATEGORY, ... examples as the most prominent as they are the common case.

ryanofsky commented at 3:11 am on June 27, 2024:

re: #29256 (review)

source feels a bit abstract and special case, it would be good to keep LogDebug(BCLog::CATEGORY, ... examples as the most prominent as they are the common case.

Great point, reverted this. There’s no need to change this document anymore since the current version of this PR is backwards compatible (unlike the original version) so the original recommendations are still good. There’s more complete reference documentation in the logging header.

hodlinator commented at 8:29 pm on December 14, 2024:

If we were to go ahead with something close to what this PR is, I think it would be good to mention in developer-notes.md that LogInfo/Warning/Error take an optional category or source. - Or at the very least hint at there being more flexibility which is documented together with the macro implementations.

in src/logging.h:248 in 5f64eab013 outdated

213+    //! formatting hook.
214+    struct Source {
215+        LogFlags category;
216+        Logger& logger;
217+
218+        Source(LogFlags category = LogFlags::ALL, Logger& logger = LogInstance()) : category{category}, logger{logger} {}

hodlinator commented at 9:13 pm on June 26, 2024:

Could do with a comment such as // Implicitly constructible from a LogFlags value in order to be created by LogDebug(BCLog::NET, ...) etc. if the current approach is kept.

ryanofsky commented at 3:11 am on June 27, 2024:

re: #29256 (review)

Could do with a comment such as // Implicitly constructible from a LogFlags value in order to be created by LogDebug(BCLog::NET, ...) etc. if the current approach is kept.

Thank you! Added.

in src/logging.h:244 in 5f64eab013 outdated

207@@ -201,9 +208,36 @@ namespace BCLog {
208         bool DefaultShrinkDebugFile() const;
209     };
210 
211+    //! Object representing a particular source of log messages. Holds a logging
212+    //! category, a reference to the logger object to output to, and a
213+    //! formatting hook.
214+    struct Source {
215+        LogFlags category;

hodlinator commented at 9:13 pm on June 26, 2024:

0        const LogFlags category;

ryanofsky commented at 3:11 am on June 27, 2024:

re: #29256 (review)

Thanks again, but for now I did not take this suggestion. I think making individual struct members const can unnecessarily restrict the ways the struct can be initialized. I think the safety benefits of making the category member const are better enforced and more explicit when the entire struct is const, which should be best practice and already the case everywhere.

in src/test/logging_tests.cpp:98 in 5f64eab013 outdated

93+    LogWarning(log, "warning %s\n", "arg");
94+    LogInfo(log, "info %s\n", "arg");
95+    LogDebug(log, "debug %s\n", "arg");
96+    LogTrace(log, "trace %s\n", "arg");
97+
98+    std::vector<std::string> expected = {

hodlinator commented at 9:21 pm on June 26, 2024:

Could be made constexpr here and in other places:

0    constexpr auto EXPECTED = std::to_array({

ryanofsky commented at 3:11 am on June 27, 2024:

re: #29256 (review)

Could be made constexpr here and in other places:

Thanks! I don’t think there’s an obvious way to make these constexpr, but they should be const, so changed the declarations here, below, and in the next PR.

hodlinator commented at 1:29 pm on June 27, 2024:

I suggested constexpr auto EXPECTED = std::to_array({ above but maybe it doesn’t work for you? Should support constexpr that way under C++20 as far as I can tell. Are you using some fancy interface to GitHub that doesn’t yet show suggestion-embeds?

hodlinator commented at 1:51 pm on June 27, 2024:

Could go even more old-school and do:

0    constexpr const char* EXPECTED[]{
1        ...
2    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), std::cbegin(EXPECTED), std::cend(EXPECTED));

ryanofsky commented at 2:08 pm on June 28, 2024:

re: #29256 (review)

I suggested constexpr auto EXPECTED = std::to_array({ above but maybe it doesn’t work for you? Should support constexpr that way under C++20 as far as I can tell. Are you using some fancy interface to GitHub that doesn’t yet show suggestion-embeds?

No sorry, that works perfectly. I was just careless and only noticed constexpr without seeing the rest of it. Added your suggestion to this PR and followup PR #30343.

in src/test/logging_tests.cpp:208 in 5f64eab013 outdated

202@@ -86,6 +203,9 @@ BOOST_AUTO_TEST_CASE(logging_timer)
203 BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)
204 {
205     LogInstance().m_log_sourcelocations = true;
206+    auto LogPrintf_ = [](const std::string&fun, const std::string&file, int line, BCLog::LogFlags category, BCLog::Level level, const auto&... args) {
207+        LogInstance().LogPrintStr(strprintf(args...), fun, file, line, category, level);
208+    };

hodlinator commented at 9:48 pm on June 26, 2024:

Feels like a half-baked workaround for having removed the global LogPrintf_.

ryanofsky commented at 3:11 am on June 27, 2024:

re: #29256 (review)

Feels like a half-baked workaround for having removed the global LogPrintf_.

Yes, good catch. I wanted to leave the test case below unchanged in the main commit to check (and let it be obvious) that the new logging features do not change any current behavior. But it’s not good to leave behind a reference to an old function with a confusing name, so I added a new commit afterwards to modernize the test.

hodlinator changes_requested

hodlinator commented at 10:02 pm on June 26, 2024: contributor

NACK 5f64eab013a58967af37a59c863c2ab6d45ba6e8

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.

ryanofsky referenced this in commit 38d3298ea7 on Jun 27, 2024

ryanofsky force-pushed on Jun 27, 2024

ryanofsky commented at 3:42 am on June 27, 2024: contributor

Updated 5f64eab013a58967af37a59c863c2ab6d45ba6e8 -> 38d3298ea7e547797871140a02df3e7d60d34d36 (pr/bclog.17 -> pr/bclog.18, compare) with suggested changes.

re: #29256#pullrequestreview-2142978382

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 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. (EDIT: Rereading AJ’s comments, I’m not sure this paragraph actually represents what he thinks, so striking it out.)

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.

ajtowns commented at 2:47 pm on June 27, 2024: contributor

Rereading AJ’s comments, I’m not sure this paragraph actually represents what he thinks, so striking it out.

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.

logging options (before and after this PR) actually do not support filtering out Info/Warning/Error messages at all, by category or otherwise

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 https://github.com/bitcoin/bitcoin/pull/28318/commits/ab34dc6012351e7b8aab871dd9d2b38ade1cd9bc .

I’ll have another go at explaining my point of view:

But doing this would not be my starting point because I think generally category information is useful,

I don’t think category information is useful except for enabling log message filtering. It’s not useful otherwise, because -logsourcelocations is strictly superior in multiple ways (it’s automatic, it doesn’t need to be updated if we refactor things, and it gives more detailed information). For messages we don’t want users to filter, we shouldn’t provide a category, as that would provide no benefit at all.

hodlinator commented at 8:40 pm on June 27, 2024: contributor

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.

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.

Cool! Hoping that’s something @ajtowns could agree to allowing something like an optional source being passed to LogInfo etc to make the wallet code and other exceptions nicer without suddenly also accepting category everywhere.

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

ryanofsky referenced this in commit 681b21f7ca on Jun 28, 2024

ryanofsky force-pushed on Jun 28, 2024

ryanofsky commented at 2:23 pm on June 28, 2024: contributor

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 44afae705a12252149adbe7ac6d3646052b8bf3b 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 44afae705a12252149adbe7ac6d3646052b8bf3b 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 38d3298ea7e547797871140a02df3e7d60d34d36 -> 681b21f7ca07f0e1411354baa01649e7b1f30e8c (pr/bclog.18 -> pr/bclog.19, compare) with suggested constexpr change (thank you for the suggestion!)

jonatack commented at 4:58 pm on June 28, 2024: member

All consistent, now accepting the same parameters All compatible with log categories, to make it possible to filter or highlight log messages from a particular component All compatible with wallet logging, which includes the wallet name in log messages Require less verbosity, by not needing category constants to be repeated in log prints from a common source. Not tied to one hardcoded global Logger instance

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.

ryanofsky commented at 5:22 pm on June 28, 2024: contributor

re: #29256 (comment)

We’ve just over-complicated everything when it could be simple and open. I know a number of other developers think the same but don’t speak up much because it seems pointless to do so.

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.

ajtowns commented at 6:49 pm on June 28, 2024: contributor

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.

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.

jonatack commented at 6:52 pm on June 28, 2024: member

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?

All of these, I think. The idea was:

one Log(level, cat, msg) macro with a consistent API replace the current macros
the -debug and -loglevel config options and logging RPC soft-aligned into a single user-facing logging API
the printed logs to be the same format for each Log call, apart from custom options
developer documentation in the Log macro and the level/category enums, where grepping would lead you directly

Instead (from memory, I’m maybe not up to date), we now have:

a larger slew of macros
an inconsistent API and printed log that vary depending on which of the new level macros is called
various restrictions on calls and usage
documentation in various places
all these ducks to keep in a row

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.

ryanofsky commented at 7:54 pm on June 28, 2024: contributor

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.

hodlinator commented at 10:25 pm on June 28, 2024: contributor

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

I implemented that restriction in 44afae705a12252149adbe7ac6d3646052b8bf3b 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.

The API feels good to me, nice touch with the static_assert! Wish the implementation of the combined functionality were simpler, but don’t have the throughput to attempt boiling it down right now.

Side note: LogPrintfCategory surprised me in that it is logging with categories at Info-level. Seems to be only used by tests and benchmarks.. maybe uses of it could be removed as it was deprecated in the last release, or changed to use LogDebug?

DrahtBot added the label Needs rebase on Jul 26, 2024

ryanofsky referenced this in commit db2e3ff6fe on Aug 7, 2024

ryanofsky referenced this in commit 46f5e27e86 on Aug 7, 2024

ryanofsky force-pushed on Aug 7, 2024

DrahtBot removed the label Needs rebase on Aug 7, 2024

DrahtBot added the label Needs rebase on Sep 2, 2024

logging: Improve new LogDebug/Trace/Info/Warning/Error Macros

Improve new LogDebug(), LogTrace(), LogInfo(),  LogWarning(), LogError() macros
introduced in #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

12d97dbdcb

logging: Add preprocessor workaround for MSVC

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

5db1958e60

ryanofsky referenced this in commit 117de1cc26 on Dec 9, 2024

ryanofsky force-pushed on Dec 9, 2024

DrahtBot removed the label Needs rebase on Dec 9, 2024

ryanofsky commented at 2:00 pm on December 10, 2024: contributor

Rebased 46f5e27e86f9bd2c88df86f0d652fedab1bd0f21 -> 48b3c951aa256c6be0cc50461de00f758d92dcb4 (pr/bclog.20 -> pr/bclog.21, compare) due to conflicts with with #31174 and other PRs. Updated 48b3c951aa256c6be0cc50461de00f758d92dcb4 -> 5db1958e60aef9d3604448c21e1f397e561480ee (pr/bclog.21 -> pr/bclog.22, compare) to fix MSVC error C3495 https://github.com/bitcoin/bitcoin/actions/runs/12242607762/job/34150305407?pr=29256

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

in src/logging.h:306 in 5db1958e60

334-        }                                                 \
335+//! Internal helper to return first arg in a __VA_ARGS__ pack. This could be
336+//! simplified to `#define _FirstArg(arg, ...) arg` if not for a preprocessor
337+//! bug in Visual C++.
338+#define _FirstArgImpl(arg, ...) arg
339+#define _FirstArg(args) _FirstArgImpl args

hodlinator commented at 11:21 pm on December 13, 2024:

This looks less weird, would it be equivalent in this case or defeat the purpose?

0#define _FirstArg(args) _FirstArgImpl(args)

in src/logging.h:283 in 5db1958e60

301-#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, __VA_ARGS__)
302-#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, __VA_ARGS__)
303+//! Internal helper to get log source object from macro argument, if argument is
304+//! BCLog::Source object or a category constant that BCLog::Source can be
305+//! constructed from.
306+static inline const BCLog::Source& _LogSource(const BCLog::Source& source LIFETIMEBOUND) { return source; }

hodlinator commented at 11:33 pm on December 13, 2024:

Maybe best to avoid introducing identifiers starting with underscore, especially if followed by uppercase?

https://stackoverflow.com/a/228848

in src/logging.h:317 in 5db1958e60

345+            const auto& func = __func__;                                  \
346+            _LogFormat([&](auto&& source, auto&& message) {               \
347+                source.logger.LogPrintStr(message, func, __FILE__,        \
348+                    __LINE__, source.category, (level));                  \
349+            }, _LogSource(_FirstArg((__VA_ARGS__))), __VA_ARGS__);        \
350+        }                                                                 \

hodlinator commented at 11:37 pm on December 13, 2024:

nit: Could potentially avoid repeated Source construction:

0        auto log_source = _LogSource(_FirstArg((__VA_ARGS__)));           \
1        if (LogEnabled(log_source, (level))) {                            \
2            const auto& func = __func__;                                  \
3            _LogFormat([&](auto&& source, auto&& message) {               \
4                source.logger.LogPrintStr(message, func, __FILE__,        \
5                    __LINE__, source.category, (level));                  \
6            }, log_source, __VA_ARGS__);                                  \
7        }                                                                 \

hodlinator changes_requested

hodlinator commented at 10:11 pm on December 14, 2024: contributor

Code reviewed 5db1958e60aef9d3604448c21e1f397e561480ee + 0b5cbf9ee8ca39b91c6c635d27df94ec618be5cb

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

0b5cbf9ee8ca39b91c6c635d27df94ec618be5cb 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 ~~86c7b578cb4563a09783d95e95adc437c04447bc~~ cebc9e2a22892abf70f16f08a0cbfb12a98291b5. (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.

Improve new LogDebug/Trace/Info/Warning/Error Macros #29256

Problems this PR attempts to solve

Note to reviewers

Code Coverage & Benchmarks

Reviews

Conflicts

PR style

Subjective title

Suggested change