logging: threshold log level

klementtan commented at 5:01 pm on June 6, 2022: contributor

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 #24464 (review))
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:

0# global log level = info (default)
1$ ./src/bitcoind -signet
2$ grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
30
4
5# global log level = debug
6$ ./src/bitcoind -signet -loglevel=debug
7$ grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
84

logging: deduplicate LogCategory code 8e16e52771

jonatack commented at 5:12 pm on June 6, 2022: contributor

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 marked this as a draft on Jun 6, 2022

klementtan force-pushed on Jun 6, 2022

DrahtBot added the label Tests on Jun 6, 2022

DrahtBot commented at 8:49 am on June 7, 2022: contributor

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 added the label Utils/log/libs on Jun 7, 2022

klementtan force-pushed on Jun 8, 2022

klementtan marked this as ready for review on Jun 8, 2022

klementtan force-pushed on Jun 8, 2022

laanwj commented at 5:44 pm on June 8, 2022: member

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!

in src/logging.cpp:333 in 63f6957f08 outdated

319@@ -343,7 +320,12 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi
320         std::string s{"["};
321 
322         if (category != LogFlags::NONE) {
323-            s += LogCategoryToStr(category);
324+            auto it = LogCategoryToStr.find(category);

jonatack commented at 2:07 pm on June 9, 2022:

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

0-            if (it == LogCategoryToStr.end()) {
1-                s += "unknown";
2-            } else {
3-                s += it->second;
4-            }
5+            s += it == LogCategoryToStr.end() ? "unknown" : it->second;

klementtan commented at 2:43 pm on June 12, 2022:

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

klementtan commented at 2:44 pm on June 12, 2022:

Resolved the nit 👍🏻

jonatack commented at 9:09 am on June 13, 2022:

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

in src/test/logging_tests.cpp:141 in 63f6957f08 outdated

136@@ -120,8 +137,6 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
137 
138 BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
139 {
140-    // Prevent tests from failing when the line number of the following log calls changes.
141-    LogInstance().m_log_sourcelocations = false;
142     LogInstance().EnableCategory(BCLog::LogFlags::ALL);
143     const auto concated_categery_names = LogInstance().LogCategoriesString();

jonatack commented at 2:27 pm on June 9, 2022:

nit, maybe touch this up while touching the test file

0-    const auto concated_categery_names = LogInstance().LogCategoriesString();
1+    const auto concated_category_names = LogInstance().LogCategoriesString();
2     std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
3-    const auto category_names = SplitString(concated_categery_names, ',');
4+    const auto category_names = SplitString(concated_category_names, ',');

klementtan commented at 2:04 pm on June 12, 2022:

Done, good catch 👍🏻

in src/logging.cpp:200 in 63f6957f08 outdated

195 
196+// Ignore last 2 extra mappings of NONE and ALL.
197+const std::unordered_map<BCLog::LogFlags, std::string> LogCategoryToStr{
198+    LogCategories,
199+    LogCategories + std::size(LogCategories) - 2};
200+

jonatack commented at 2:29 pm on June 9, 2022:

In the first commit, a few suggestions

 0@@ -138,7 +138,7 @@ struct CLogCategoryDesc {
 1     }
 2 };
 3 
 4-const CLogCategoryDesc LogCategories[]{
 5+static CLogCategoryDesc LogCategories[]{
 6     {BCLog::NONE, "none"},
 7     {BCLog::NET, "net"},
 8     {BCLog::TOR, "tor"},
 9@@ -174,10 +174,10 @@ const CLogCategoryDesc LogCategories[]{
10     {BCLog::ALL, "1"},
11 };
12 
13-// Ignore last 2 extra mappings of NONE and ALL.
14-const std::unordered_map<BCLog::LogFlags, std::string> LogCategoryToStr{
15+static std::unordered_map<BCLog::LogFlags, std::string> LogCategoryToStr{
16     LogCategories,
17-    LogCategories + std::size(LogCategories) - 2};
18+    LogCategories + std::size(LogCategories) - 2 // ignore last 2 extra mappings of NONE and ALL
19+};

laanwj commented at 2:59 pm on June 9, 2022:

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.

klementtan commented at 3:12 pm on June 12, 2022:

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.

in src/init/common.cpp:81 in 63f6957f08 outdated

77@@ -77,6 +78,7 @@ void AddLoggingArgs(ArgsManager& argsman)
78     argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
79     argsman.AddArg("-printtoconsole", "Send trace/debug info to console (default: 1 when no -daemon. To disable logging to file, set -nodebuglogfile)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
80     argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
81+    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Sets the threshold log level and any logs with severity lower than the threshold level will be ignored (default -loglevel=info). -loglevel=<level> sets the global threshold log level and will be applied to all categories. If <category>:<level> is supplied, the threshold level overrides the global threshold level and will only be applied to <category>. <category> can be: %s, <level> can be: debug, info, warning, error. This option can be specified multiple times to set multiple category specific threshold level.", LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);

jonatack commented at 2:57 pm on June 9, 2022:

0    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=info). If <category>:<level> is supplied, the setting will override the global one. <category> can be: %s, <level> can be: debug, info, warning, error. This option may be specified multiple times to set multiple category-specific levels.", LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);

also suggest:

moving this line to just after -logips
using a constexpr for the default level and using it here and elsewhere where needed
writing a method like LogCategoriesString() to output the log levels debug, none, info, warning, error here, in SetLoggingLevel(), and in the future update to the logging RPC

klementtan commented at 2:23 pm on June 12, 2022:

Done 👍🏻. Moved the line to after -logips, used constexpr for default level and added a LogCategoriesString

in src/init/common.cpp:112 in 63f6957f08 outdated

107+                    InitWarning(strprintf(_("Unsupported global threshold logging level provided -loglevel=%s. Valid values: debug, none, info, warning, error."), loglevel));
108+                };
109+            } else {
110+                const auto toks = SplitString(loglevel, ':');
111+                if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
112+                    InitWarning(strprintf(_("Unsupported category specific threshold logging level provided -loglevel=%s. Expected -loglevel=<category>:<loglevel>."), loglevel));

jonatack commented at 3:06 pm on June 9, 2022:

here and elsewhere, missing hyphen s/category specific/category-specific/ and “threshold” seems unneeded, could be omitted

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

klementtan commented at 2:23 pm on June 12, 2022:

Done 👍🏻

in src/logging.cpp:231 in 63f6957f08 outdated

227@@ -200,73 +228,22 @@ std::string LogLevelToStr(BCLog::Level level)
228     }
229     assert(false);
230 }
231-
232-std::string LogCategoryToStr(BCLog::LogFlags category)
233+bool GetLogLevel(BCLog::Level& level, std::string level_str)

jonatack commented at 3:43 pm on June 9, 2022:

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

klementtan commented at 2:51 pm on June 12, 2022:

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.

jonatack commented at 2:54 pm on June 12, 2022:

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

in src/init/common.cpp:104 in 63f6957f08 outdated

 95@@ -94,6 +96,26 @@ void SetLoggingOptions(const ArgsManager& args)
 96     fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
 97 }
 98 
 99+void SetLoggingLevel(const ArgsManager& args)
100+{
101+    if (args.IsArgSet("-loglevel")) {
102+        const auto loglevels = args.GetArgs("-loglevel");
103+        for (const auto& loglevel : loglevels) {
104+            const auto is_global = loglevel.find(':') == std::string::npos;

jonatack commented at 3:43 pm on June 9, 2022:

(this is very low-level so feel free to ignore) perhaps avoid creating an unneeded temporary in the loop, use find_first_of and maybe even pass in a pos argument

0-            const auto is_global = loglevel.find(':') == std::string::npos;
1-            if (is_global) {
2+            if (loglevel.find_first_of(':', 3) == std::string::npos) {

or

 0     if (args.IsArgSet("-loglevel")) {
 1         const auto loglevels = args.GetArgs("-loglevel");
 2         for (const auto& loglevel : loglevels) {
 3-            const auto is_global = loglevel.find(':') == std::string::npos;
 4-            if (is_global) {
 5+            if (loglevel.find_first_of(':', 3) == std::string::npos) {
 6+                // user passed a global log level (-loglevel=level)
 7                 if (!LogInstance().SetLogLevel(loglevel)) {
 8                     InitWarning(strprintf(_("Unsupported global threshold logging level provided -loglevel=%s. Valid values: debug, none, info, warning, error."), loglevel));
 9                 };
10             } else {
11+                // user passed a category-specific log level (-loglevel=category:level)
12                 const auto toks = SplitString(loglevel, ':');

klementtan commented at 2:23 pm on June 12, 2022:

Done 👍🏻

jonatack commented at 4:00 pm on June 9, 2022: contributor

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

klementtan force-pushed on Jun 12, 2022

logging: Add -loglevel configuration option.

- Ignore logs that have lower severity than the threshold level

- Allow users to specify the global level and category
specific level through bitcoind arguements

20c6e4d6a3

docs: Add threshold log level to release notes. 05ee8a9ba0

klementtan force-pushed on Jun 12, 2022

klementtan commented at 0:06 am on June 13, 2022: contributor

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

in doc/release-notes-25287.md:4 in 05ee8a9ba0

0@@ -0,0 +1,4 @@
1+Tools and Utilities
2+-------------------
3+
4+- Allow configuration of global and category specific threshold log levels. (#25287)

jonatack commented at 7:28 am on June 13, 2022:

Suggestion:

0-- Allow configuration of global and category specific threshold log levels. (#25287)
1+- A new `-loglevel` configuration option allows setting global and per-category
2+  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)

in src/init/common.cpp:71 in 05ee8a9ba0

67@@ -67,6 +68,7 @@ void AddLoggingArgs(ArgsManager& argsman)
68         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
69     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);
70     argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
71+    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);

jonatack commented at 8:01 am on June 13, 2022:

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

0    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);

0$ ./src/bitcoind -h | grep -A9 loglevel
1  -loglevel=<level>|<category>:<level>
2       Set the global or per-category logging severity level: debug, none,
3       info, warning, error (default=info). If <category>:<level> is
4       supplied, the setting will override the global one and may be
5       specified multiple times to set multiple category-specific
6       levels. <category> can be: addrman, bench, blockstorage,
7       cmpctblock, coindb, estimatefee, http, i2p, ipc, leveldb,
8       libevent, lock, mempool, mempoolrej, net, proxy, prune, qt, rand,
9       reindex, rpc, selectcoins, tor, util, validation, walletdb, zmq.

in src/init/common.cpp:107 in 05ee8a9ba0

102+        const auto loglevels = args.GetArgs("-loglevel");
103+        for (const auto& loglevel : loglevels) {
104+            if (loglevel.find_first_of(':', 3) == std::string::npos) {
105+                // user passed a global log level (-loglevel=<level>)
106+                if (!LogInstance().SetLogLevel(loglevel)) {
107+                    InitWarning(strprintf(_("Unsupported global threshold logging level provided -loglevel=%s. Valid values: debug, none, info, warning, error."), loglevel));

jonatack commented at 8:18 am on June 13, 2022:

0                    InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s"), loglevel, LogInstance().LogLevelsString()));

in src/init/common.cpp:113 in 05ee8a9ba0

108+                }
109+            } else {
110+                // user passed a category-specific log level (-loglevel=<category>:<level>)
111+                const auto toks = SplitString(loglevel, ':');
112+                if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
113+                    InitWarning(strprintf(_("Unsupported category-specific logging level provided -loglevel=%s. Expected -loglevel=<category>:<loglevel>."), loglevel));

jonatack commented at 8:19 am on June 13, 2022:

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

in src/logging.cpp:270 in 05ee8a9ba0

264@@ -287,6 +265,15 @@ std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
265     return ret;
266 }
267 
268+std::vector<BCLog::Level> BCLog::Logger::LogLevelsList() const
269+{
270+    return {BCLog::Level::Debug, BCLog::Level::None, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error};

jonatack commented at 8:25 am on June 13, 2022:

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

in src/logging.h:108 in 05ee8a9ba0

103+
104+        /**
105+         * If there is no category-specific threshold log level, all logs with severity level lower than
106+         * m_threshold_level will be ignored.
107+         */
108+        Level m_threshold_level{Level::Info};

jonatack commented at 9:04 am on June 13, 2022:

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.

jonatack commented at 9:07 am on June 13, 2022: contributor

Tested, a few more suggestions.

mzumsande commented at 6:35 pm on June 13, 2022: contributor

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

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

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 commented at 6:40 pm on June 13, 2022: contributor

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 commented at 1:41 pm on July 1, 2022: contributor

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 commented at 5:10 am on July 2, 2022: contributor

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

klementtan closed this on Jul 2, 2022

achow101 referenced this in commit 7281fac2e0 on Sep 1, 2022

klementtan deleted the branch on Feb 2, 2023

bitcoin locked this on Feb 2, 2024

logging: threshold log level #25287

Conflicts