Skip to content

logging: add LogPrintfCategory to log unconditionally with category #25306

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Jun 14, 2022

Conversation

jonatack
Copy link
Member

@jonatack jonatack commented Jun 8, 2022

These are the next two commits from #25203.

  • Add LogPrintfCategory to log unconditionally while prefixing the output with the passed category name. Add documentation and a unit test, and update the lint-logs.py and lint-format-strings.py scripts.

  • Replace the log messages that manually print a category, with LogPrintfCategory. In upcoming commits, it will likely be used in many other cases, such as to replace LogPrintf where it makes sense.

@jonatack jonatack force-pushed the 2022-06-logprintfcategory branch from cb9135d to 90787ff Compare June 8, 2022 11:51
Copy link
Member

@maflcko maflcko left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm

jonatack added 2 commits June 8, 2022 14:02
prefixing the output with the passed category name.

- add documentation
- add a unit test
- update lint-logs.py
- update lint-format-strings.py
Here we update only the log messages that manually print a category.

In upcoming commits, LogPrintCategory will likely be used in many
other cases, such as to replace `LogPrintf` where it makes sense.
@DrahtBot
Copy link
Contributor

DrahtBot commented Jun 8, 2022

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

  • #25308 (refactor: Reduce number of LoadChainstate parameters and return values by ryanofsky)
  • #25203 (logging: update to severity-based logging by jonatack)
  • #21603 (log: Mitigate disk filling attacks by rate limiting LogPrintf by dergoegge)

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.

@klementtan
Copy link
Contributor

Code Review ACK ecff20d

@laanwj
Copy link
Member

laanwj commented Jun 8, 2022

Concept ACK

I do think this is an intermediate state. I imagine at some point we'll want to have a category and log level for every message, so the need to log messages with just a category goes away again.

Copy link
Contributor

@brunoerg brunoerg left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK ecff20d

Just reviewed the code and it's good. I built and ran it (signet) and checked debug.log, lgtm.

Ex:

2022-06-08T17:03:23Z Script verification uses 7 additional threads
2022-06-08T17:03:23Z scheduler thread start
2022-06-08T17:03:23Z [http] creating work queue of depth 16
2022-06-08T17:03:23Z Using random cookie authentication.
2022-06-08T17:03:23Z Generated RPC authentication cookie /Users/brunogarcia/Library/Application Support/Bitcoin/signet/.cookie
2022-06-08T17:03:23Z [http] starting 4 worker threads
2022-06-08T17:03:23Z Using wallet directory /Users/brunogarcia/Library/Application Support/Bitcoin/signet/wallets

@jonatack
Copy link
Member Author

jonatack commented Jun 8, 2022

@laanwj No strong opinion but I thought the same, tried a version of it, and initially concluded that (a) [category:all] for unconditional logging might be unnecessarily verbose, and (b) all doesn't seem useful as a severity level that a user can set in our logging (it would do the same as setting debug currently), though I could be overlooking a use case.

@maflcko
Copy link
Member

maflcko commented Jun 8, 2022

I also was under the assumption that this is permanent. If it wasn't, we probably should not do it, but then I am also wondering if there is a better alternative.

@laanwj
Copy link
Member

laanwj commented Jun 8, 2022

Right, my understanding was that the None category and level would eventually go away, and it'd be more like logging systems in other applications. That it's an intermediate solution until the existing messages are "sorted out". And after threshold configuration (like #25287) was added. But I could be wrong.

In any case, permanent or not, I'm ok with this as intermediate solution.

@jonatack
Copy link
Member Author

jonatack commented Jun 8, 2022

I could imagine a scenario where LogPrintf and LogPrintfCategory might go away someday (along with None) if they are more or less converted to, say, Info level, and users setting the level to Warning or Error just wouldn't care to see those messages. But that seems a little radical for now (or not, IDK, Info will be the default and I would use that or a more detailed level myself).

@maflcko
Copy link
Member

maflcko commented Jun 8, 2022

I guess the statements under discussion are mostly:

  • Single logs (per process lifetime), for example init logs
  • Heartbeat logs (when a block came in)

I can see how they are useful unconditionally to make later debugging easier, which would be my reason to keep them unconditional.
However, I can also see how there might be a user only interested in Warning/Error logs, not in Info logs. So I guess one alternative is to change None to Info and make it the default severity. (That is probably also the way python does it)

@jonatack
Copy link
Member Author

jonatack commented Jun 8, 2022

For an idea, open https://github.com/bitcoin/bitcoin/pull/25203/files, click to load the files with a larger diff, and search for LogPrintfCategory. They probably could all be changed to Error, Warning, or Info. The default debug log would be shockingly quiet, though.

@laanwj
Copy link
Member

laanwj commented Jun 8, 2022

I can see how they are useful unconditionally to make later debugging easier, which would be my reason to keep them unconditional.

Yes, I don't disagree. It does feel somewhat strange to me to have log messages that figure higher than Error in severity, but aren't errors. But if used sparingly for this purpose it makes sense.

So I guess one alternative is to change None to Info and make it the default severity. (That is probably also the way python does it)

The default debug log would be shockingly quiet, though.

I think the default logging should remain the same. So if we use Info as default log level for what is now unconditional, for most categories we'd want to have the standard threshold at Info. For some (leveldb, qt) it could deviate, becuase they are spammy.

@jonatack
Copy link
Member Author

jonatack commented Jun 8, 2022

Users would currently need to turn on debug logging though, to see Info logging.

Edit: right, change Info to be unconditional. Hmm. That may need some shifting, though in the latest pass I moved most non-essential logging into debug anyway.

@laanwj
Copy link
Member

laanwj commented Jun 8, 2022

Users would currently need to turn on debug logging though, to see Info logging.

Yes. The current hardcoded LogAcceptCategory thresholding implementation is silly I temporarily added it for leveldb category, basically, until there's more fine-grained configuration possible. The default threshold for non-spammy cagtegories should probably be Info and higher.

I think the current LogPrint messages should be of level Debug, and current LogPrintf should be Info or higher. I'm fine with having an unconditional None level for marker messages as @MarcoFalke says.

@jonatack
Copy link
Member Author

jonatack commented Jun 8, 2022

In the parent PR I propose also a trace level, for the really verbose low-level messages.

@laanwj
Copy link
Member

laanwj commented Jun 8, 2022

Right, makes sense. Though we shouldn't go over the top with number of severity levels either. But trace sounds OK for some cases like low-level networking logging.

@laanwj
Copy link
Member

laanwj commented Jun 14, 2022

Code review ACK ecff20d

@laanwj laanwj merged commit 9e4fbeb into bitcoin:master Jun 14, 2022
@jonatack jonatack deleted the 2022-06-logprintfcategory branch June 14, 2022 17:11
sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Jun 15, 2022
…nally with category

ecff20d logging: use LogPrintfCategory rather than a manual category (Jon Atack)
eb8aab7 logging: add LogPrintfCategory to log unconditionally with category (Jon Atack)

Pull request description:

  These are the next two commits from bitcoin#25203.

  - Add `LogPrintfCategory` to log unconditionally while prefixing the output with the passed category name. Add documentation and a unit test, and update the `lint-logs.py` and `lint-format-strings.py` scripts.

  - Replace the log messages that manually print a category, with `LogPrintfCategory`. In upcoming commits, it will likely be used in many other cases, such as to replace `LogPrintf` where it makes sense.

ACKs for top commit:
  klementtan:
    Code Review ACK ecff20d
  laanwj:
    Code review ACK ecff20d
  brunoerg:
    ACK ecff20d

Tree-SHA512: ad3a82835254f7606efcd14b88f3d9072f1eb9b25db1321ed38ef6a4ec60efd555d78f5e19d93736f2f8500251d06f8beee9d694a153f24bf5cce3590a2a45a5
@bitcoin bitcoin locked and limited conversation to collaborators Jul 19, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants