Skip to content

Conversation

@klementtan
Copy link
Contributor

@klementtan klementtan commented Jun 6, 2022

Overview: This PR allows logs below the threshold severity level to be ignored (a continuation of #24464).

Notable changes:

  • Deduplicate identical code in LogCategoryToStr and LogCategories (addresses logging: Add severity level to logs #24464 (comment))
  • Threshold log level:
    • Introduce a global threshold log level that will allow the logger to ignore logs that are below the threshold level (defaults to Levels::info)
      • User can configure this with -loglevel=<level> (ie: -loglevel=warning)
    • Introduce a category-specific threshold log level that overrides the global threshold log level. Category-specific log level will only apply to the category supplied in the configuration
      • User can configure this with -loglevel=<category>:<level> (ie: -loglevel=net:warning)

Testing:

Global log level:

# global log level = info (default)
$ ./src/bitcoind -signet
$ grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
0

# global log level = debug
$ ./src/bitcoind -signet -loglevel=debug
$ grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
4

@jonatack
Copy link
Member

jonatack commented Jun 6, 2022

Concept ACK. I'm glad to see a category-specific config option. These should probably be added to the logging RPC as well in a follow-up.

@klementtan klementtan marked this pull request as draft June 6, 2022 17:22
@klementtan klementtan force-pushed the threshold_log_level branch from e1ce4a9 to 2091d52 Compare June 6, 2022 17:40
@DrahtBot DrahtBot added the Tests label Jun 6, 2022
@DrahtBot
Copy link
Contributor

DrahtBot commented Jun 7, 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:

  • #25203 (logging: update to severity-based logging by jonatack)
  • #24950 (Add config option to set max debug log size by tehelsper)
  • #24897 ([Draft / POC] Silent Payments by w0xlt)
  • #23443 (p2p: Erlay support signaling by naumenkogs)

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.

@laanwj
Copy link
Member

laanwj commented Jun 8, 2022

Concept ACK, this is more or less what I had in mind.

These should probably be added to the logging RPC as well in a follow-up.

Yep!

src/logging.cpp Outdated
Copy link
Member

@jonatack jonatack Jun 9, 2022

Choose a reason for hiding this comment

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

In the first commit, find() on a std::unordered_set has constant-to-linear (size of the container) complexity, whereas if you build a std::array instead, access with [] or .at will be constant time (and the array can be constexpr; git grep the codebase for "constexpr std::array" for examples).


nit suggestion

-            if (it == LogCategoryToStr.end()) {
-                s += "unknown";
-            } else {
-                s += it->second;
-            }
+            s += it == LogCategoryToStr.end() ? "unknown" : it->second;

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I am not really sure how to do that.

LogCategory enum values are bit flags (ie 1 << i) with the exception of None (0) and All(~0) instead of the default enum values (ie 0,1,2,..,n-1) that easily correspond to indexes of an array.

Some solutions I can think of:

  • Refactor LogCategory use the default enum values (ie 0,1,...) and create another helper function (ie LogCategoryToFlag(flag){ return 1 << flag;}
  • Create a custom hash function for LogCategoryToStr unordered_map that returns a unique hash value for each enum value. This will guarantee that the find() will execute in constant time.
    • Hash function could possibly be flag % SOME_PRIME.

However, I am not too sure if this additional complexity is worth it as the size of LogCategoryToStr is bounded

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Resolved the nit 👍🏻

Copy link
Member

@jonatack jonatack Jun 13, 2022

Choose a reason for hiding this comment

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

Thanks for looking into it! I guess at some point this might be refactored but doesn't necessarily need to be done here.

src/logging.cpp Outdated
Copy link
Member

Choose a reason for hiding this comment

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

In the first commit, a few suggestions

@@ -138,7 +138,7 @@ struct CLogCategoryDesc {
     }
 };
 
-const CLogCategoryDesc LogCategories[]{
+static CLogCategoryDesc LogCategories[]{
     {BCLog::NONE, "none"},
     {BCLog::NET, "net"},
     {BCLog::TOR, "tor"},
@@ -174,10 +174,10 @@ const CLogCategoryDesc LogCategories[]{
     {BCLog::ALL, "1"},
 };
 
-// Ignore last 2 extra mappings of NONE and ALL.
-const std::unordered_map<BCLog::LogFlags, std::string> LogCategoryToStr{
+static std::unordered_map<BCLog::LogFlags, std::string> LogCategoryToStr{
     LogCategories,
-    LogCategories + std::size(LogCategories) - 2};
+    LogCategories + std::size(LogCategories) - 2 // ignore last 2 extra mappings of NONE and ALL
+};

Copy link
Member

Choose a reason for hiding this comment

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

Wouldn't it make sense to do it the other way around?

First build LogCategoryToStr, then build LogCategoryDesc from that, adding the ALL=1 and NONE=0 instead of cutting them off. I think that's neater and less error prone.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

In the first commit, a few suggestions

Done 👍🏻

First build LogCategoryToStr, then build LogCategoryDesc from that, adding the ALL=1 and NONE=0 instead of cutting them off. I think that's neater and less error prone.

Agreed, building LogCategories from LogCategoryToStr is definitely cleaner!

However, I am unable to think of a trivial method to implement it as currently both LogCategories and LogCategoryToStr are global variables where the values are added in its constructor. To build LogCategories from LogCategoryToStr, we will most probably need to change LogCategories type from an array to a class that allows us to add our own construction logic (build from LogCategoryToStr and add ALL=1 and NONE=0).

If changing LogCategories to a class is the desired approach, I will split the first commit into a separate PR.

src/logging.cpp Outdated
Copy link
Member

@jonatack jonatack Jun 9, 2022

Choose a reason for hiding this comment

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

Suggestions:

  • order the params by in-param, then out-param
  • pass the string in-param by reference to const rather than by value
  • return a std::optional here instead of bool with a level out-param
  • use a switch statement (with no default case, grep doc/developer-notes.md for "switch statement on an enumeration example")
  • function can be static and is missing a line break before

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done, went with the return std::optional suggestion.

use a switch statement (with no default case, grep doc/developer-notes.md for "switch statement on an enumeration example")

I am unable to use a switch statement with level_str. If I am not wrong, c++ only allows switch statements with integral types and enumerators.

Copy link
Member

Choose a reason for hiding this comment

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

Oops, yes, you're right about switch statements.

@jonatack
Copy link
Member

jonatack commented Jun 9, 2022

I tested these commits cherry-picked on top of #25203 and it seems to be working fine, modulo the comments above.

@klementtan klementtan force-pushed the threshold_log_level branch 2 times, most recently from a68df86 to 81715dd Compare June 12, 2022 14:21
- Ignore logs that have lower severity than the threshold level

- Allow users to specify the global level and category
specific level through bitcoind arguements
@klementtan klementtan force-pushed the threshold_log_level branch from 81715dd to 05ee8a9 Compare June 12, 2022 14:47
@klementtan
Copy link
Contributor Author

@jonatack thanks for the detailed review! Addressed your comments in the latest commit.

Copy link
Member

@jonatack jonatack left a comment

Choose a reason for hiding this comment

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

Tested, a few more suggestions.

Tools and Utilities
-------------------

- Allow configuration of global and category specific threshold log levels. (#25287)
Copy link
Member

@jonatack jonatack Jun 13, 2022

Choose a reason for hiding this comment

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

Suggestion:

-- Allow configuration of global and category specific threshold log levels. (#25287)
+- A new `-loglevel` configuration option allows setting global and per-category
+  log severity levels: error, warning, info, debug (default: info). (#25287)

(This entry doesn't seem likely to cause a merge conflict, so it can probably be added directly to doc/release-notes.md)

ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-debugexclude=<category>", "Exclude debugging information for a category. Can be used in conjunction with -debug=1 to output debug logs for all categories except the specified category. This option can be specified multiple times to exclude multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category logging severity level; log messages of lower severity will not be printed to the debug log (default=%s). If <category>:<level> is supplied, the setting will override the global one. <category> can be: %s, <level> can be: %s. This option may be specified multiple times to set multiple category-specific levels.", BCLog::LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString(), LogInstance().LogLevelsString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);
Copy link
Member

Choose a reason for hiding this comment

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

Second iteration on this to hopefully make it shorter and clearer while providing the log levels at the start

Suggested change
argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category logging severity level; log messages of lower severity will not be printed to the debug log (default=%s). If <category>:<level> is supplied, the setting will override the global one. <category> can be: %s, <level> can be: %s. This option may be specified multiple times to set multiple category-specific levels.", BCLog::LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString(), LogInstance().LogLevelsString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category logging severity level: %s (default=%s). If <category>:<level> is supplied, the setting will override the global one and may be specified multiple times to set multiple category-specific levels. <category> can be: %s.", LogInstance().LogLevelsString(), BCLog::LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);
$ ./src/bitcoind -h | grep -A9 loglevel
  -loglevel=<level>|<category>:<level>
       Set the global or per-category logging severity level: debug, none,
       info, warning, error (default=info). If <category>:<level> is
       supplied, the setting will override the global one and may be
       specified multiple times to set multiple category-specific
       levels. <category> can be: addrman, bench, blockstorage,
       cmpctblock, coindb, estimatefee, http, i2p, ipc, leveldb,
       libevent, lock, mempool, mempoolrej, net, proxy, prune, qt, rand,
       reindex, rpc, selectcoins, tor, util, validation, walletdb, zmq.

if (loglevel.find_first_of(':', 3) == std::string::npos) {
// user passed a global log level (-loglevel=<level>)
if (!LogInstance().SetLogLevel(loglevel)) {
InitWarning(strprintf(_("Unsupported global threshold logging level provided -loglevel=%s. Valid values: debug, none, info, warning, error."), loglevel));
Copy link
Member

Choose a reason for hiding this comment

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

Suggested change
InitWarning(strprintf(_("Unsupported global threshold logging level provided -loglevel=%s. Valid values: debug, none, info, warning, error."), loglevel));
InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s"), loglevel, LogInstance().LogLevelsString()));

// user passed a category-specific log level (-loglevel=<category>:<level>)
const auto toks = SplitString(loglevel, ':');
if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
InitWarning(strprintf(_("Unsupported category-specific logging level provided -loglevel=%s. Expected -loglevel=<category>:<loglevel>."), loglevel));
Copy link
Member

Choose a reason for hiding this comment

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

Suggested change
InitWarning(strprintf(_("Unsupported category-specific logging level provided -loglevel=%s. Expected -loglevel=<category>:<loglevel>."), loglevel));
InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>"), loglevel));


std::vector<BCLog::Level> BCLog::Logger::LogLevelsList() const
{
return {BCLog::Level::Debug, BCLog::Level::None, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error};
Copy link
Member

Choose a reason for hiding this comment

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

It might be better to construct this vector programmatically to have a single point of truth, i.e. BCLog::Level.

* If there is no category-specific threshold log level, all logs with severity level lower than
* m_threshold_level will be ignored.
*/
Level m_threshold_level{Level::Info};
Copy link
Member

Choose a reason for hiding this comment

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

I'd find this data member naming clearer as m_severity_level or m_log_level (I prefer the latter), maybe that is just me.

Copy link
Contributor

@mzumsande mzumsande left a comment

Choose a reason for hiding this comment

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

I didn't deeply review the code yet, but I tested this a little bit.

# global log level = debug
$ ./src/bitcoind -signet -loglevel=debug
$ grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
4
  • This didn't work for me; the new -loglevel option seems to be completely ineffective unless I also specify a category, e.g. -debug=all. Not sure if this is expected, but it's not clear to me from the -loglevel documentation.

  • Warnings are unconditionally logged, even if I specify -loglevel=error -debug=all. This is not what I would have expected from the documentation.
    More generally, it is a bit confusing that there is a global threshold >= warning that applies even if no -debug=XXX was specified, and in addition a default threshold >= info if -debug=XXX was specified. I guess it could make sense in order to have specialised logging that does not create huge logfiles, but it is a change from the old behavior that if a user chooses a category, everything from that is logged by default.

@jonatack
Copy link
Member

jonatack commented Jun 13, 2022

Thanks for looking @mzumsande. The discussion in #25306 might be helpful, as well as testing this on top of #25203.

FWIW I discussed this pull offline with @klementtan; he is busy right now with a new job and I'm continuing his work with a new pull.

@jonatack
Copy link
Member

jonatack commented Jul 1, 2022

Pulled the commits here into #25203, updated with review feedback, some clean-up, and moving the refactoring commits to after the functional ones. Will continue with sub-PRs from that parent.

@klementtan
Copy link
Contributor Author

Closing this PR in favor of #25203. @jonatack thanks for picking it up!

@klementtan klementtan closed this Jul 2, 2022
achow101 added a commit to bitcoin-core/gui that referenced this pull request Sep 1, 2022
9580480 Update debug logging section in the developer notes (Jon Atack)
1abaa31 Update -debug and -debugexclude help docs for severity level logging (Jon Atack)
45f9282 Create BCLog::Level::Trace log severity level (Jon Atack)
2a8712d Unit test coverage for -loglevel configuration option (klementtan)
eb7bee5 Create -loglevel configuration option (klementtan)
98a1f9c Unit test coverage for log severity levels (klementtan)
9c7507b Create BCLog::Logger::LogLevelsString() helper function (klementtan)
8fe3457 Update LogAcceptCategory() and unit tests with log severity levels (klementtan)
c2797cf Add BCLog::Logger::SetLogLevel()/SetCategoryLogLevel() for string inputs (klementtan)
f6c0cc0 Add BCLog::Logger::m_category_log_levels data member and getter/setter (Jon Atack)
2978b38 Add BCLog::Logger::m_log_level data member and getter/setter (Jon Atack)
f1379ae Simplify BCLog::Level enum class and LogLevelToStr() function (Jon Atack)

Pull request description:

  This is an updated version of bitcoin/bitcoin#25287 and the next steps in parent PR #25203 implementing, with Klement Tan, user-configurable, per-category severity log levels based on an idea by John Newbery and refined in GitHub discussions by Wladimir Van der Laan and Marco Falke.

  - simplify the `BCLog::Level` enum class and the `LogLevelToStr()` function and add documentation
  - update the logging logic to filter logs by log level both globally and per-category
  - add a hidden `-loglevel` help-debug config option to allow testing setting the global or per-category severity level on startup for logging categories enabled with the `-debug` configuration option or the logging RPC (Klement Tan)
  - add a `trace` log severity level selectable by the user; the plan is for the current debug messages to become trace, LogPrint ones to become debug, and LogPrintf ones to become info, warning, or error

  ```
  $ ./src/bitcoind -help-debug | grep -A10 loglevel
    -loglevel=<level>|<category>:<level>
         Set the global or per-category severity level for logging categories
         enabled with the -debug configuration option or the logging RPC:
         info, debug, trace (default=info); warning and error levels are
         always logged. If <category>:<level> is supplied, the setting
         will override the global one and may be specified multiple times
         to set multiple category-specific levels. <category> can be:
         addrman, bench, blockstorage, cmpctblock, coindb, estimatefee,
         http, i2p, ipc, leveldb, libevent, lock, mempool, mempoolrej,
         net, proxy, prune, qt, rand, reindex, rpc, selectcoins, tor,
         util, validation, walletdb, zmq.
  ```

  See the individual commit messages for details.

ACKs for top commit:
  jonatack:
    One final push per `git range-diff a5d5569 ce3c4c9 9580480` (should be trivial to re-ACK) to ensure this pull changes no default behavior in any way for users or the tests/CI in order to be completely v24 compatible, to update the unit test setup in general, and to update the debug logging section in the developer notes.
  klementtan:
    reACK bitcoin/bitcoin@9580480
  1440000bytes:
    reACK bitcoin/bitcoin@9580480
  vasild:
    ACK 9580480
  dunxen:
    reACK 9580480
  brunoerg:
    reACK 9580480

Tree-SHA512: 476a638e0581f40b5d058a9992691722e8b546471ec85e07cbc990798d1197fbffbd02e1b3d081b4978404e07a428378cdc8e159c0004b81f58be7fb01b7cba0
@klementtan klementtan deleted the threshold_log_level branch February 2, 2023 12:33
@bitcoin bitcoin locked and limited conversation to collaborators Feb 2, 2024
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.

5 participants