Severity-based logging, step 2

jonatack commented at 1:58 pm on July 14, 2022: contributor

This is an updated version of #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

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

See the individual commit messages for details.

DrahtBot commented at 2:25 pm on July 14, 2022: contributor

🕵️ @harding has been requested to review this pull request as specified in the REVIEWERS file.

DrahtBot commented at 7:00 pm on July 14, 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:

#24950 (Add config option to set max debug log size by tehelsper)
#16673 (Relog configuration args on debug.log rotation by LarryRuane)

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 Jul 14, 2022

in src/logging.cpp:326 in 5326f46bba outdated

320@@ -287,6 +321,16 @@ std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
321     return ret;
322 }
323 
324+std::vector<BCLog::Level> BCLog::Logger::LogLevelsList() const
325+{
326+    return {BCLog::Level::Debug, BCLog::Level::None, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error};

klementtan commented at 3:36 pm on July 17, 2022:

Should BCLog::Level::None be placed at the end of the vector so that the ordering will be similar to its enum value? Maybe we could remove BCLog::Level::None from this list entirely.
Should BCLog::Level::Trace be included in this list as well?

We could modify this function to be constexpr and return std::array instead. This will allow us to static assert the number of elements in the array at compile time. ie:

0constexpr std::array<BCLog::Level, static_cast<size_t>(BCLog::Level::None) + 1> BCLog::Logger::LogLevelsList() const
1{
2    return {BCLog::Level::Trace, BCLog::Level::Debug, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error, BCLog::Level::None};
3}

jonatack commented at 10:38 am on July 19, 2022:

I plan to replace this hardcoded data structure with an automated version in c57d6e7d449e14827528439537716bed6cbfc9fe but good ideas, done!

in src/logging.cpp:331 in 5326f46bba outdated

326+    return {BCLog::Level::Debug, BCLog::Level::None, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error};
327+}
328+
329+std::string BCLog::Logger::LogLevelsString() const
330+{
331+    return Join(LogLevelsList(), ", ", [this](BCLog::Level level) { return LogLevelToStr(level); });

klementtan commented at 3:55 pm on July 17, 2022:

0    const auto levels = LogLevelsList();
1    return Join(std::vector<BCLog::Level>{levels.begin(), levels.end() - 1}, ", ", [this](BCLog::Level level) { return LogLevelToStr(level); });

As LogLevelsString returns "" for BCLog::Level::None, this function will return , ,. Maybe remove BCLog::Level::None from the vector of levels? Alternatively, we could remove BCLog::Level::None from LogLevelsList completely

jonatack commented at 11:57 am on July 19, 2022:

Alternatively, we could remove BCLog::Level::None from LogLevelsList completely

Agree SGTM, thanks!

klementtan commented at 4:35 pm on July 17, 2022: contributor

Approach ACK and crACK 5326f46bba46bbd111c00c616e1362276d717e99 (except for some minor comments)

in src/logging.cpp:497 in 5326f46bba outdated

486@@ -443,3 +487,22 @@ void BCLog::Logger::ShrinkDebugFile()
487     else if (file != nullptr)
488         fclose(file);
489 }
490+
491+bool BCLog::Logger::SetLogLevel(const std::string& level_str)
492+{
493+    const auto level = GetLogLevel(level_str);

klementtan commented at 4:51 pm on July 17, 2022:

0    const auto level = GetLogLevel(level_str);
1    if (level > BCLog::Level::Warning) return false;

Suggestion ( feel free to ignore ):

Since we are unconditionally logging any logs >= BCLog::Level::Warning level, should we prevent users from setting any threshold level > BCLog::Level::Warning? This will prevent users from having the weird behavior of successfully setting the threshold log level to Error but still seeing Warning logs. (Same for SetCategoryLogLevel)

jonatack commented at 2:57 pm on August 11, 2022:

Suggestion ( feel free to ignore ):

Since we are unconditionally logging any logs >= BCLog::Level::Warning level, should we prevent users from setting any threshold level > BCLog::Level::Warning? This will prevent users from having the weird behavior of successfully setting the threshold log level to Error but still seeing Warning logs. (Same for SetCategoryLogLevel)

I updated your first commit here to do this.

in src/init/common.cpp:32 in 5326f46bba outdated

28@@ -28,6 +29,7 @@ void AddLoggingArgs(ArgsManager& argsman)
29         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
30     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);
31     argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
32+    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(), LogInstance().LogLevelToStr(), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);

klementtan commented at 4:52 pm on July 17, 2022:

It might be useful to state that all logs >= Warning will still be unconditionally logged.

jonatack commented at 11:08 am on July 20, 2022:

Done

jonatack force-pushed on Jul 20, 2022

jonatack commented at 11:27 am on July 20, 2022: contributor

Updated with review feedack by @klementtan (thanks!) per git range-diff 0897b18 5326f46 706805d

jonatack force-pushed on Jul 20, 2022

klementtan commented at 4:05 pm on July 25, 2022: contributor

Code review ACK and tested ACK 706805d

Testing:

 0# Absence of debug log when loglevel=INFO
 1$  ./src/bitcoind -signet -loglevel=info
 2$  grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
 3      0
 4
 5# Debug log present when loglevel=DEBUG
 6$ ./src/bitcoind -signet -loglevel=debug
 7$  grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
 8       2
 9
10# Category-specific log level. loglevel=net:info
11$ ./src/bitcoind -signet -loglevel=net:info
12Bitcoin Core starting
13$  grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
14       0

in src/init/common.cpp:68 in 706805d9ac outdated

63+        for (const std::string& level_str : args.GetArgs("-loglevel")) {
64+            if (level_str.find_first_of(':', 3) == std::string::npos) {
65+                // user passed a global log level, i.e. -loglevel=<level>
66+                if (!LogInstance().SetLogLevel(level_str)) {
67+                    InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s"), level_str, LogInstance().LogLevelsString()));
68+                }

w0xlt commented at 7:59 am on July 31, 2022:

nit: Feel free to ignore. Perhaps if the user enters an invalid value, initialization should not proceed. The log can also record the level.

For example, the user might type -loglevel=DEBUG and think logging is working while it is not a valid option.

0                if (!LogInstance().SetLogLevel(level_str)) {
1                    InitError(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s"), level_str, LogInstance().LogLevelsString()));
2                }
3                else LogPrintf("Using log level %s\n", level_str);

jonatack commented at 12:25 pm on August 11, 2022:

nit: Feel free to ignore. Perhaps if the user enters an invalid value, initialization should not proceed.

Thanks for the suggestion! However, updating from InitWarning to InitError would only change the first line of the debug log, and I think it makes more sense to log “Warning” than “Error” for this case. Also, the existing log init errors (for -debug=) are warnings as well.

The log can also record the level. For example, the user might type -loglevel=DEBUG and think logging is working while it is not a valid option.

It is already logged as either Command-line arg: loglevel=<setting> or Config file arg: loglevel=<setting>.

in doc/release-notes.md:97 in 706805d9ac outdated

92@@ -93,6 +93,9 @@ New settings
93 Tools and Utilities
94 -------------------
95 
96+- A new `-loglevel` configuration option allows setting global and per-category
97+  log severity levels. (#25203)

w0xlt commented at 8:00 am on July 31, 2022:

nit:

0  log severity levels. (#25614)

jonatack commented at 12:40 pm on August 11, 2022:

done

w0xlt approved

w0xlt commented at 8:04 am on July 31, 2022: contributor

Code Review and Tested ACK 706805d9ac98dc4fc0543108c0bf6d914b27bef1

These are 4 first commits from #25203. I understand they are the basis for the other changes in the log.

in src/logging.h:77 in e1513f25fa outdated

75-        Error = 4,
76+        Debug = 0, // High-volume or detailed logging for development/debugging
77+        Info,      // Default
78+        Warning,
79+        Error,
80+        None, // Internal use only

fjahr commented at 3:20 pm on August 7, 2022:

nit: Indentation of the comment doesn’t match the ones above

jonatack commented at 9:28 pm on August 7, 2022:

Thanks for the suggestion but this is what clang-format returns.

fjahr commented at 4:33 pm on August 7, 2022: contributor

Code looks good but I think this is missing some documentation on how -loglevel and -debug relate to each other. Otherwise I think some users may be confused.

jonatack force-pushed on Aug 11, 2022

jonatack commented at 3:07 pm on August 11, 2022: contributor

Updated to address @fjahr’s #25614#pullrequestreview-1064438055 suggestion in the -loglevel help with "Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC"), @w0xlt’s release note feedback, @klementtan’s suggestion in #25614 (review) (which required updating the unit tests a bit) and a couple other minor improvements. Mind re-revewing, please? (Thanks!)

  0diff --git a/doc/release-notes.md b/doc/release-notes.md
  1index 4680731280..9585144ce5 100644
  2--- a/doc/release-notes.md
  3+++ b/doc/release-notes.md
  4@@ -94,7 +94,7 @@ Tools and Utilities
  5 -------------------
  6 
  7 - A new `-loglevel` configuration option allows setting global and per-category
  8-  log severity levels. (#25203)
  9+  log severity levels. (#25614)
 10 
 11 Wallet
 12 ------
 13diff --git a/src/init/common.cpp b/src/init/common.cpp
 14index a0f5cb2a6e..a22d921b21 100644
 15--- a/src/init/common.cpp
 16+++ b/src/init/common.cpp
 17@@ -29,7 +29,7 @@ void AddLoggingArgs(ArgsManager& argsman)
 18         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 19     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);
 20     argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 21-    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category debug logging severity level: %s (default=%s). Error and warning levels are logged unconditionally.  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(), LogInstance().LogLevelToStr(), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);
 22+    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC: %s (default=%s); 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: %s.", LogInstance().LogLevelsString(), LogInstance().LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);
 23     argsman.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 24 #ifdef HAVE_THREAD_LOCAL
 25     argsman.AddArg("-logthreadnames", strprintf("Prepend debug output with name of the originating thread (only available on platforms supporting thread_local) (default: %u)", DEFAULT_LOGTHREADNAMES), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 26@@ -64,13 +64,13 @@ void SetLoggingLevel(const ArgsManager& args)
 27             if (level_str.find_first_of(':', 3) == std::string::npos) {
 28                 // user passed a global log level, i.e. -loglevel=<level>
 29                 if (!LogInstance().SetLogLevel(level_str)) {
 30-                    InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s"), level_str, LogInstance().LogLevelsString()));
 31+                    InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s."), level_str, LogInstance().LogLevelsString()));
 32                 }
 33             } else {
 34                 // user passed a category-specific log level, i.e. -loglevel=<category>:<level>
 35                 const auto& toks = SplitString(level_str, ':');
 36                 if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
 37-                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>"), level_str));
 38+                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>. Valid loglevel values: %s."), level_str, LogInstance().LogLevelsString()));
 39                 }
 40             }
 41         }
 42diff --git a/src/logging.cpp b/src/logging.cpp
 43index 3891be1cdc..964eb57eb8 100644
 44--- a/src/logging.cpp
 45+++ b/src/logging.cpp
 46@@ -321,9 +321,10 @@ std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
 47     return ret;
 48 }
 49 
 50-static constexpr std::array<BCLog::Level, static_cast<size_t>(BCLog::Level::None)> LogLevelsList()
 51+/** Log severity levels that can be selected by the user. */
 52+static constexpr std::array<BCLog::Level, 3> LogLevelsList()
 53 {
 54-    return {BCLog::Level::Trace, BCLog::Level::Debug, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error};
 55+    return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
 56 }
 57 
 58 std::string BCLog::Logger::LogLevelsString() const
 59@@ -492,7 +493,7 @@ void BCLog::Logger::ShrinkDebugFile()
 60 bool BCLog::Logger::SetLogLevel(const std::string& level_str)
 61 {
 62     const auto level = GetLogLevel(level_str);
 63-    if (!level) return false;
 64+    if (!level || level > BCLog::Level::Info) return false;
 65     m_log_level = level.value();
 66     return true;
 67 }
 68@@ -503,7 +504,7 @@ bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const s
 69     if (!GetLogCategory(flag, category_str)) return false;
 70 
 71     const auto level = GetLogLevel(level_str);
 72-    if (!level) return false;
 73+    if (!level || level > BCLog::Level::Info) return false;
 74     m_category_log_levels[flag] = level.value();
 75     return true;
 76 }
 77diff --git a/src/logging.h b/src/logging.h
 78index 88e5486545..6d4661792b 100644
 79--- a/src/logging.h
 80+++ b/src/logging.h
 81@@ -7,8 +7,8 @@
 82 #define BITCOIN_LOGGING_H
 83 
 84 #include <fs.h>
 85-#include <tinyformat.h>
 86 #include <threadsafety.h>
 87+#include <tinyformat.h>
 88 #include <unordered_map>
 89 #include <util/string.h>
 90 
 91@@ -191,7 +191,7 @@ namespace BCLog {
 92         std::string LogLevelsString() const;
 93 
 94         //! Returns the string representation of a log level.
 95-        std::string LogLevelToStr(BCLog::Level level = DEFAULT_LOG_LEVEL) const;
 96+        std::string LogLevelToStr(BCLog::Level level) const;
 97 
 98         bool DefaultShrinkDebugFile() const;
 99     };
100diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
101index c3b4a8a8c1..87bd4ef114 100644
102--- a/src/test/logging_tests.cpp
103+++ b/src/test/logging_tests.cpp
104@@ -171,18 +171,18 @@ BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
105 {
106     LogInstance().EnableCategory(BCLog::LogFlags::ALL);
107 
108-    LogInstance().SetLogLevel(BCLog::Level::Info);
109-    LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"debug");
110+    LogInstance().SetLogLevel(BCLog::Level::Debug);
111+    LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
112 
113     // Global log level
114     LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
115-    LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Debug, "foo2: %s. This log level is lower than the global one.\n", "bar2");
116+    LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
117     LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
118     LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
119 
120     // Category-specific log level
121     LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
122-    LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo6: %s. This log level is lower than the category-specific one but higher than the global one. \n", "bar6");
123+    LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo6: %s. This log level is the same as the global one but lower than the category-specific one, which takes precedence. \n", "bar6");
124     LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
125 
126     std::vector<std::string> expected = {
127@@ -207,11 +207,11 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
128         ResetLogger();
129         ArgsManager args;
130         args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
131-        const char* argv_test[] = {"bitcoind", "-loglevel=warning"};
132+        const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
133         std::string err;
134         BOOST_CHECK(args.ParseParameters(2, argv_test, err));
135         init::SetLoggingLevel(args);
136-        BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Warning);
137+        BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
138     }
139 
140     // Set category-specific log level
141@@ -219,7 +219,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
142         ResetLogger();
143         ArgsManager args;
144         args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
145-        const char* argv_test[] = {"bitcoind", "-loglevel=net:warning"};
146+        const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
147         std::string err;
148         BOOST_CHECK(args.ParseParameters(2, argv_test, err));
149         init::SetLoggingLevel(args);
150@@ -228,7 +228,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
151         const auto& category_levels{LogInstance().CategoryLevels()};
152         const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
153         BOOST_CHECK(net_it != category_levels.end());
154-        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Warning);
155+        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
156     }
157 
158     // Set both global log level and category-specific log level
159@@ -236,7 +236,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
160         ResetLogger();
161         ArgsManager args;
162         args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
163-        const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:warning", "-loglevel=http:error"};
164+        const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
165         std::string err;
166         BOOST_CHECK(args.ParseParameters(4, argv_test, err));
167         init::SetLoggingLevel(args);
168@@ -247,11 +247,11 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
169 
170         const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
171         BOOST_CHECK(net_it != category_levels.end());
172-        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Warning);
173+        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
174 
175         const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
176         BOOST_CHECK(http_it != category_levels.end());
177-        BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Error);
178+        BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
179     }
180 }

jonatack force-pushed on Aug 11, 2022

in src/init/common.cpp:73 in 6964e063b3 outdated

68+                }
69+            } else {
70+                // user passed a category-specific log level, i.e. -loglevel=<category>:<level>
71+                const auto& toks = SplitString(level_str, ':');
72+                if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
73+                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>. Valid loglevel values: %s."), level_str, LogInstance().LogLevelsString()));

brunoerg commented at 9:08 pm on August 12, 2022:

Just a doubt: Why here is an InitWarning instead of an InitError? Is it because we want to proceed even with an invalid loglevel?

jonatack commented at 9:31 pm on August 12, 2022:

Thanks for the question! See #25614 (review)

brunoerg commented at 10:40 pm on August 12, 2022:

Oh, nice! Sorry for not noticing that.

vasild commented at 7:50 am on August 16, 2022:

It would be useful to print the valid categories as well, e.g. if the user mistypes `-loglevel=network:debug", he would see that the correct one is “net”, instead of “network”.

0                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>. Valid categories: %s. Valid loglevel values: %s."), level_str, LogInstance().LogCategoriesString(), LogInstance().LogLevelsString()));

jonatack commented at 9:01 am on August 16, 2022:

I did this before the last repush, then stopped because the message would be very long, too long.

jonatack commented at 9:55 am on August 16, 2022:

Ok done. We’ll see what people say.

unknown approved

unknown commented at 10:47 pm on August 12, 2022: none

utACK https://github.com/bitcoin/bitcoin/pull/25614/commits/63215dd36c46b1b68ce2e2133ec1d21c044cf055

dunxen approved

dunxen commented at 2:20 pm on August 13, 2022: contributor

Code review and tested ACK 63215dd36c46b1b68ce2e2133ec1d21c044cf055

I tried a few categories and global log levels and saw expected output in logs.

brunoerg approved

brunoerg commented at 12:37 pm on August 15, 2022: contributor

crACK 63215dd36c46b1b68ce2e2133ec1d21c044cf055

jarolrod approved

jarolrod commented at 7:43 pm on August 15, 2022: member

tACK 63215dd36c46b1b68ce2e2133ec1d21c044cf055

LGTM

in src/logging.cpp:216 in 63215dd36c outdated

209@@ -197,6 +210,8 @@ std::string LogLevelToStr(BCLog::Level level)
210         return "warning";
211     case BCLog::Level::Error:
212         return "error";
213+    case BCLog::Level::None:
214+        return "";

vasild commented at 7:16 am on August 16, 2022:

The reverse of this - GetLogLevel() contains:

0    } else if (level_str == "none") {
1        return BCLog::Level::None;

It would be more consistent to use either "" or "none" in both places.

jonatack commented at 9:53 am on August 16, 2022:

Done

in src/init/common.cpp:74 in 63215dd36c outdated

69+            } else {
70+                // user passed a category-specific log level, i.e. -loglevel=<category>:<level>
71+                const auto& toks = SplitString(level_str, ':');
72+                if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
73+                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>. Valid loglevel values: %s."), level_str, LogInstance().LogLevelsString()));
74+                }

vasild commented at 7:45 am on August 16, 2022:

Shouldn’t -loglevel=category:info automatically enable -debug=category? If “yes”, then extend this with:

0if (!LogInstance().EnableCategory(toks[0])) {
1    InitWarning(strprintf(_("Unsupported logging category: %s. Valid categories: %s."), toks[0], LogInstance().LogCategoriesString()));
2}

jonatack commented at 9:04 am on August 16, 2022:

No, I don’t think it should.

vasild commented at 12:47 pm on August 16, 2022:

There is probably a counter-reason, but my thinking is that setting e.g. -loglevel=net:... alone, without -debug=net is pointless and probably a sign of misuse. You always want to set -debug=net too, if you ever set -loglevel=net:..., right? What about at least printing a warning at startup like:

You only set -loglevel=net:..., did you forget to set -debug=net?

jonatack commented at 1:21 pm on August 16, 2022:

You may want to toggle on/off the debug logging at runtime instead (e.g. for very verbose logging) with the logging RPC.

Out of the scope of this PR: -debug= should be renamed to -log=, I guess, because now it could be confusing with the exposed levels. E.g. -debug=net -loglevel=net:info looks self-contradictory to me - is it going to log >=debug (due to -debug=net) or >=info due to loglevel=net:info?

Once this migration happens (if it succeeds in doing so down the road), then in the parent PR I reckon it may be worth proposing to fold the -debug and -loglevel config options into a single -log or -logging one and try to combine the functionality of both into the logging RPC (ideally in a backward-compatible way).

in src/logging.cpp:507 in 63215dd36c outdated

502+{
503+    BCLog::LogFlags flag;
504+    if (!GetLogCategory(flag, category_str)) return false;
505+
506+    const auto level = GetLogLevel(level_str);
507+    if (!level || level > BCLog::Level::Info) return false;

vasild commented at 8:01 am on August 16, 2022:

Should this be DEFAULT_LOG_LEVEL instead of BCLog::Level::Info?

Right now they are the same, but if DEFAULT_LOG_LEVEL is changed, this should be changed too, right? If “yes”, then this should be DEFAULT_LOG_LEVEL.

jonatack commented at 9:03 am on August 16, 2022:

No, I considered this but they don’t share the exact same logic; the default level isn’t necessarily linked to the maximum user-setable severity level.

jonatack commented at 10:01 am on August 16, 2022:

Hoisted to a MAX_USER_SETABLE_SEVERITY_LEVEL constant.

in src/logging.h:100 in 63215dd36c outdated

 96@@ -94,6 +97,13 @@ namespace BCLog {
 97         /** Log categories bitfield. */
 98         std::atomic<uint32_t> m_categories{0};
 99 
100+        //! Category-specific log level. Overrides the global `m_log_level`.

vasild commented at 8:04 am on August 16, 2022:

nit: m_log_level is not global. s/the global//

jonatack commented at 10:08 am on August 16, 2022:

Removed “the global”

0-        //! Category-specific log level. Overrides the global `m_log_level`.
1+        //! Category-specific log level. Overrides `m_log_level`.

in src/logging.h:105 in 63215dd36c outdated

 96@@ -94,6 +97,13 @@ namespace BCLog {
 97         /** Log categories bitfield. */
 98         std::atomic<uint32_t> m_categories{0};
 99 
100+        //! Category-specific log level. Overrides the global `m_log_level`.
101+        std::unordered_map<LogFlags, Level> m_category_log_levels;
102+
103+        //! If there is no category-specific log level, all logs with a severity
104+        //! level lower than `m_log_level` will be ignored.
105+        Level m_log_level{Level::Info};

vasild commented at 8:09 am on August 16, 2022:

If the newly added m_category_log_levels and m_log_level can be accessed concurrently from multiple threads (I think they can), then they should be either atomic, const (and set in the constructor) or protected by a mutex. Similarly to the neighboring e.g. m_categories.

jonatack commented at 11:16 am on August 16, 2022:

Looking into this, m_log_level can be atomic, but since m_category_log_levels isn’t a trivially copyable type, I wonder if we can guard it with the existing Logger::m_cs.

vasild commented at 12:41 pm on August 16, 2022:

Yes, m_cs should work.

I looked into making these const and setting them from the constructor, but that seems nearly impossible with the current LogInstance() and g_logger (we don’t have the args at that time). Significant changes would be required to achieve that.

jonatack commented at 1:15 pm on August 16, 2022:

Done (I think).

vasild commented at 1:33 pm on August 16, 2022:

Should DEFAULT_LOG_LEVEL be used here?

0        Level m_log_level{DEFAULT_LOG_LEVEL};

jonatack commented at 1:37 pm on August 16, 2022:

SGTM, done

klementtan commented at 4:57 pm on August 16, 2022:

Suggestions feel free to ignore:

I think a std::shared_mutex will be a good candidate for this situation. It will allow us not to need to synchronize calls to LogPrint (Reader) and only synchronize calls when we occasionally modify (Writer) m_category_log_levels during initialization or runtime during modification (future plan).

However, this might very well be a premature optimization as m_cs is only held for a very short period in SetCategoryLogLevel and CategoryLevels.

in src/logging.h:207 in 63215dd36c outdated

208-    if (level >= BCLog::Level::Warning) {
209-        return true;
210-    }
211-    return LogInstance().WillLogCategory(category);
212+    return LogInstance().WillLogCategoryLevel(category, level);
213 }

vasild commented at 8:22 am on August 16, 2022:

LogAcceptCategory() is now the same as WillLogCategoryLevel() and thus looks unnecessary. It is used in just 6 places. Consider replacing all of those with LogInstance().WillLogCategoryLevel(category, level) and removing LogAcceptCategory().

jonatack commented at 9:22 am on August 16, 2022:

I plan to do this in the parent PR in the refactorings to come.

in src/test/logging_tests.cpp:151 in 63215dd36c outdated

151-        BCLog::LogFlags category = BCLog::NONE;
152-        const auto trimmed_category_name = TrimString(category_name);
153+        BCLog::LogFlags category;
154+        const auto& trimmed_category_name{TrimString(category_name)};
155         BOOST_TEST(GetLogCategory(category, trimmed_category_name));
156         expected_category_names.emplace_back(category, trimmed_category_name);

vasild commented at 8:29 am on August 16, 2022:

Execution will continue past a failed BOOST_TEST() if GetLogCategory() returns false and category will remain uninitialized. Thus we will read an uninitialized value in that case. Either restore the initialization to = BCLog::NONE or change BOOST_TEST() to BOOST_REQUIRE().

jonatack commented at 9:26 am on August 16, 2022:

If BOOST_TEST fails, doesn’t the test halt at that point and log a failure?

fanquake commented at 9:28 am on August 16, 2022:

No: https://www.boost.org/doc/libs/1_80_0/libs/test/doc/html/boost_test/testing_tools/tools_assertion_severity_level.html

jonatack commented at 9:44 am on August 16, 2022:

Thanks. Indeed, “reached!” is printed:

0-        BOOST_TEST(GetLogCategory(category, trimmed_category_name));
1+        BOOST_TEST(false);
2+        BOOST_TEST_MESSAGE("reached!");

jonatack commented at 10:15 am on August 16, 2022:

Done

in src/test/logging_tests.cpp:212 in 63215dd36c outdated

207+        ResetLogger();
208+        ArgsManager args;
209+        args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
210+        const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
211+        std::string err;
212+        BOOST_CHECK(args.ParseParameters(2, argv_test, err));

vasild commented at 8:39 am on August 16, 2022:

s/BOOST_CHECK/BOOST_REQUIRE/ since the checks that follow are meaningless if this fails.

jonatack commented at 10:15 am on August 16, 2022:

Done

in src/test/logging_tests.cpp:224 in 63215dd36c outdated

219+        ResetLogger();
220+        ArgsManager args;
221+        args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
222+        const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
223+        std::string err;
224+        BOOST_CHECK(args.ParseParameters(2, argv_test, err));

vasild commented at 8:40 am on August 16, 2022:

s/BOOST_CHECK/BOOST_REQUIRE/ since the checks that follow are meaningless if this fails.

jonatack commented at 10:18 am on August 16, 2022:

Done

in src/test/logging_tests.cpp:230 in 63215dd36c outdated

225+        init::SetLoggingLevel(args);
226+        BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::DEFAULT_LOG_LEVEL);
227+
228+        const auto& category_levels{LogInstance().CategoryLevels()};
229+        const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
230+        BOOST_CHECK(net_it != category_levels.end());

vasild commented at 8:41 am on August 16, 2022:

s/BOOST_CHECK/BOOST_REQUIRE/ since the line below is UB if this fails (dereference of the end() iterator).

(and similar in the next test below)

jonatack commented at 9:23 am on August 16, 2022:

I think the test halts in case of failure anyway.

fanquake commented at 9:39 am on August 16, 2022:

I think the test halts in case of failure anyway.

BOOST_CHECK continues after errors: https://www.boost.org/doc/libs/1_80_0/libs/test/doc/html/boost_test/testing_tools/tools_assertion_severity_level.html.

jonatack commented at 9:48 am on August 16, 2022:

Thanks. Indeed, verified.

jonatack commented at 10:19 am on August 16, 2022:

Done

in doc/release-notes.md:97 in 63215dd36c outdated

92@@ -93,6 +93,9 @@ New settings
93 Tools and Utilities
94 -------------------
95 
96+- A new `-loglevel` configuration option allows setting global and per-category
97+  log severity levels. (#25614)

vasild commented at 8:54 am on August 16, 2022:

Shouldn’t this be in a newly added file doc/release-notes-25614.md. From developer-notes:

0Release notes should be added to a PR-specific release note file at
1`/doc/release-notes-<PR number>.md` to avoid conflicts between multiple PRs.

jonatack commented at 9:07 am on August 16, 2022:

A merge conflict looks unlikely here (and this guideline seems rarely followed nowadays).

vasild commented at 9:12 am on August 16, 2022:

Ok, I am fine with this either way.

In general, if a guideline is rarely followed then it is better to remove it from the guidelines, rather than keep breaking it.

MarcoFalke commented at 9:48 am on August 22, 2022:

I am not sure what to do here myself, but maybe it is best to remove the doc/release-notes.md file from the repo to enforce the guideline? (There is still the doc/release-notes-empty-template.md file)

jonatack commented at 10:11 am on August 22, 2022:

IIRC the guideline was being followed but then it began being suggested to reviewers not to create a separate file when a merge conflict seemed unlikely. I have a WIP branch to update the release notes (https://github.com/jonatack/bitcoin/commits/2022-08-developer-notes-updates) that includes a change like this.

0- Release notes should be added to a PR-specific release note file at
1- `/doc/release-notes-<PR number>.md` to avoid conflicts between multiple PRs.
2- All `release-notes*` files are merged into a single
3+ When it seems likely to cause a merge conflict, a release note should be added
4+ in a PR-specific file named `/doc/release-notes-<PR number>.md`.  These
5+ `release-notes*` files are merged into a single
6[/doc/release-notes.md](/doc/release-notes.md) file prior to the release.

No strong opinion as to whether we want to continue in this direction, I haven’t merged the release notes yet so don’t know the pain level involved in doing that.

(This pull no longer has a release note.)

vasild commented at 8:59 am on August 16, 2022: contributor

Since the new log level Trace is unused outside of tests, is it assumed that some of the existent Debug log messages can/should be converted to Trace, or is it that just newly added logging will be using Trace?

Out of the scope of this PR: -debug= should be renamed to -log=, I guess, because now it could be confusing with the exposed levels. E.g. -debug=net -loglevel=net:info looks self-contradictory to me - is it going to log >=debug (due to -debug=net) or >=info due to loglevel=net:info?

in src/init/common.cpp:30 in 63215dd36c outdated

28@@ -28,6 +29,7 @@ void AddLoggingArgs(ArgsManager& argsman)
29         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
30     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);

vasild commented at 9:08 am on August 16, 2022:

The semantic of -debug and -debugexclude seem to have been changed in this PR which warrants an update of their help text.

Before -debug=net would enable debug log messages for net. Now -debug=net enables the net category for logging and the severity level is chosen separately via -loglevel=net:....

jonatack commented at 9:21 am on August 18, 2022:

The semantic of -debug and -debugexclude seem to have been changed in this PR which warrants an update of their help text.

Before -debug=net would enable debug log messages for net. Now -debug=net enables the net category for logging and the severity level is chosen separately via -loglevel=net:....

Good observation! This is only the case for LogPrintLevel messages with a severity level of debug or trace, of which there are only two currently that are debug and none that are trace. In other words, -loglevel doesn’t affect much of anything yet, but these helps should be updated before migrating further log messages to LogPrintLevel debug/trace. Done now here as I’m retouching.

jonatack commented at 9:28 am on August 16, 2022: contributor

Since the new log level Trace is unused outside of tests, is it assumed that some of the existent Debug log messages can/should be converted to Trace, or is it that just newly added logging will be using Trace?

Generally, the current debug messages become trace, LogPrint ones become debug, and LogPrintf ones become info, warning, or error (discussion in #25306). Edit: added this info to the pull description.

jonatack force-pushed on Aug 16, 2022

jonatack commented at 4:25 pm on August 16, 2022: contributor

Updated with @vasild’s review feedback per git range-diff a5d5569 63215dd b99dc23

Invalidates ACKs by @1440000bytes, @dunxen, @brunoerg and @jarolrod and previous ACKs by @klementtan and @w0xlt.

klementtan commented at 4:58 pm on August 16, 2022: contributor

crACK b99dc23c94d802cea94127f2eb376f90aef33a05

klementtan approved

dunxen approved

dunxen commented at 6:39 pm on August 16, 2022: contributor

reACK b99dc23

unknown approved

unknown commented at 8:12 pm on August 16, 2022: none

reACK https://github.com/bitcoin/bitcoin/pull/25614/commits/b99dc23c94d802cea94127f2eb376f90aef33a05

brunoerg approved

brunoerg commented at 9:45 pm on August 16, 2022: contributor

crACK b99dc23c94d802cea94127f2eb376f90aef33a05

in src/logging.h:98 in b99dc23c94 outdated

93@@ -91,6 +94,13 @@ namespace BCLog {
94          */
95         std::atomic_bool m_started_new_line{true};
96 
97+        //! Category-specific log level. Overrides `m_log_level`.
98+        std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);

vasild commented at 12:28 pm on August 17, 2022:

non-show-stopper nit: the m_category_log_levels and m_log_level are introduced in commit logging: add -loglevel configuration option and later made thread safe in another two commits: logging: make m_log_level data member in Logger class thread-safe and logging: make m_category_log_levels data member in Logger class thread-safe.

It would make sense to squash the two fixup commits into the first one that introduces the variables.

jonatack commented at 9:22 am on August 18, 2022:

Re-organized into logical steps.

vasild approved

vasild commented at 12:56 pm on August 17, 2022: contributor

ACK b99dc23c94d802cea94127f2eb376f90aef33a05

Is this planned for 24.0? I find the interaction between -debug and -loglevel confusing from user perspective after this PR. I agree with this comment that they should be just one, probably named -log, behaving as -loglevel from this PR, meaning that -debug gets deprecated and removed. So, one of the following will happen:

If this PR gets included in 24.0 as is, with -loglevel then we would be stuck with that name because it would be bad to introduce a new option -loglevel in 24.0 and rename it to -log in the next version (25.0).
We can rename -loglevel to -log either in this PR or in a quick followup that also gets included in 24.0.
Don’t include this PR in 24.0 and rename -loglevel to -log later, before 25.0.

jonatack commented at 2:39 pm on August 17, 2022: contributor

This PR doesn’t affect anything yet; leaving it unmerged would only be blocking progress as it is needed for testing the next steps in the parent PR (and the parent becomes increasingly difficult to maintain over time as it is affected by changes all over the codebase). As such, changing or removing the -loglevel config option wouldn’t break user space if we manage to do the steps I outlined. (Also, IIRC config options have been removed in the past without any particular process.)

mzumsande commented at 3:33 pm on August 17, 2022: contributor

This PR doesn’t affect anything yet;

In that case why not make -loglevel ArgsManager::DEBUG_ONLY for now (24.0) and only announce it in a release note once it does affect more things, the RPCs are final, and the log levels are actually used widely.

vasild commented at 5:35 pm on August 17, 2022: contributor

changing or removing the -loglevel config option wouldn’t break user space

I am only saying that it would be undesirable to introduce -loglevel and rename it in the next version (I am not saying that we will or want to rename it, but will loose the option to do so in case we decide we want). If we release it now as -loglevel we would “be stuck” with that name. I am ok with that, but just wanted to make it clear.

why not make -loglevel ArgsManager::DEBUG_ONLY for now (24.0)

Right! If -loglevel has very little to no impact now, then hiding it under ArgsManager::DEBUG_ONLY would give us the flexibility and plenty of time to discuss it and hopefully do the parent PR too prior to 25.0.

jonatack commented at 9:46 am on August 18, 2022: contributor

(I am not saying that we will or want to rename it, but will loose the option to do so in case we decide we want). If we release it now as -loglevel we would “be stuck” with that name. I am ok with that, but just wanted to make it clear.

Hypothetically, renaming an established config option like -debug= to, say, -log= would presumably be a higher hurdle than doing so for a new option. That said, I suspect neither is a high hurdle if reviewers agree, as these options are probably mainly used for development, as also implied by the name -debug. (There seems to be common agreement that a majority of users don’t change the default logging settings, which this informal small-sample twitter poll concords with; 2/3 of 208 responding don’t change the defaults, and the 60-some who do could likely be developers: https://twitter.com/jonatack/status/1534643109975449607).

In that case why not make -loglevel ArgsManager::DEBUG_ONLY for now (24.0) and only announce it in a release note once it does affect more things

SGTM, done (will re-push in a few hours, the time to reverify the build at each commit for the other changes).

Simplify BCLog::Level enum class and LogLevelToStr() function

- simplify the BCLog::Level enum class (and future changes to it) by
  only setting the value of the first enumerator

- move the BCLog::Level:None enumerator to the end of the BCLog::Level
  enum class and LogLevelToStr() member function, as the None enumerator
  is only used internally, and by being the highest BCLog::Level value it
  can be used to iterate over the enumerators

- replace the unused BCLog::Level:None string "none" with an empty string
  as the case will never be hit

- add documentation

f1379aeca9

w0xlt approved

w0xlt commented at 10:43 pm on August 18, 2022: contributor

reACK b99dc23c94d802cea94127f2eb376f90aef33a05

jonatack force-pushed on Aug 19, 2022

jonatack commented at 10:16 am on August 19, 2022: contributor

Updated per review feedback by @vasild and @mzumsande (make -loglevel a help-debug option, drop the release note, update the -debug and -debugexclude helps, reorganize commits logically). Verified that each commit is hygienic. Also grouped the new getter and setters together per data member and a couple minor fixups I noticed while re-reviewing and updated the PR description.

Invalidates 6 ACKs by @klementtan, @dunxen, @1440000bytes, @brunoerg, @vasild and @w0xlt,and a previous ACK by @jarolrod.

  0diff --git a/doc/release-notes.md b/doc/release-notes.md
  1index 9585144ce5..444926087b 100644
  2--- a/doc/release-notes.md
  3+++ b/doc/release-notes.md
  4@@ -93,9 +93,6 @@ New settings
  5 Tools and Utilities
  6 -------------------
  7 
  8-- A new `-loglevel` configuration option allows setting global and per-category
  9-  log severity levels. (#25614)
 10-
 11 Wallet
 12 ------
 13 
 14diff --git a/src/init/common.cpp b/src/init/common.cpp
 15index 840cb57eaa..f2d2c5640a 100644
 16--- a/src/init/common.cpp
 17+++ b/src/init/common.cpp
 18@@ -24,12 +24,12 @@ namespace init {
 19 void AddLoggingArgs(ArgsManager& argsman)
 20 {
 21     argsman.AddArg("-debuglogfile=<file>", strprintf("Specify location of debug log file. Relative paths will be prefixed by a net-specific datadir location. (-nodebuglogfile to disable; default: %s)", DEFAULT_DEBUGLOGFILE), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS);
 22-    argsman.AddArg("-debug=<category>", "Output debugging information (default: -nodebug, supplying <category> is optional). "
 23-        "If <category> is not supplied or if <category> = 1, output all debugging information. <category> can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.",
 24+    argsman.AddArg("-debug=<category>", "Output debug and trace logging (default: -nodebug, supplying <category> is optional). "
 25+        "If <category> is not supplied or if <category> = 1, output all debug and trace logging. <category> can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.",
 26         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 27-    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);
 28+    argsman.AddArg("-debugexclude=<category>", "Exclude debug and trace logging for a category. Can be used in conjunction with -debug=1 to output debug and trace logging for all categories except the specified category. This option can be specified multiple times to exclude multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 29     argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 30-    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC: %s (default=%s); 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: %s.", LogInstance().LogLevelsString(), LogInstance().LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION, OptionsCategory::DEBUG_TEST);
 31+    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC: %s (default=%s); 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: %s.", LogInstance().LogLevelsString(), LogInstance().LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
 32     argsman.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 33 #ifdef HAVE_THREAD_LOCAL
 34     argsman.AddArg("-logthreadnames", strprintf("Prepend debug output with name of the originating thread (only available on platforms supporting thread_local) (default: %u)", DEFAULT_LOGTHREADNAMES), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 35diff --git a/src/logging.h b/src/logging.h
 36index 27e00a4466..4d13ea0d80 100644
 37--- a/src/logging.h
 38+++ b/src/logging.h
 39@@ -9,7 +9,6 @@
 40 #include <fs.h>
 41 #include <threadsafety.h>
 42 #include <tinyformat.h>
 43-#include <unordered_map>
 44 #include <util/string.h>
 45 
 46 #include <atomic>
 47@@ -18,6 +17,7 @@
 48 #include <list>
 49 #include <mutex>
 50 #include <string>
 51+#include <unordered_map>
 52 #include <vector>
 53 
 54 static const bool DEFAULT_LOGTIMEMICROS = false;
 55@@ -158,7 +158,17 @@ namespace BCLog {
 56             StdLockGuard scoped_lock(m_cs);
 57             return m_category_log_levels;
 58         }
 59+        void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels)
 60+        {
 61+            StdLockGuard scoped_lock(m_cs);
 62+            m_category_log_levels = levels;
 63+        }
 64+        bool SetCategoryLogLevel(const std::string& category_str, const std::string& level_str);
 65+
 66         Level LogLevel() const { return m_log_level.load(); }
 67+        void SetLogLevel(Level level) { m_log_level = level; }
 68+        bool SetLogLevel(const std::string& level);
 69+
 70         uint32_t GetCategoryMask() const { return m_categories.load(); }
 71 
 72         void EnableCategory(LogFlags flag);
 73@@ -166,16 +176,6 @@ namespace BCLog {
 74         void DisableCategory(LogFlags flag);
 75         bool DisableCategory(const std::string& str);
 76 
 77-        bool SetLogLevel(const std::string& level);
 78-        void SetLogLevel(Level level) { m_log_level = level; }
 79-
 80-        bool SetCategoryLogLevel(const std::string& category_str, const std::string& level_str);
 81-        void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels)
 82-        {
 83-            StdLockGuard scoped_lock(m_cs);
 84-            m_category_log_levels = levels;
 85-        }
 86-
 87         bool WillLogCategory(LogFlags category) const;
 88         bool WillLogCategoryLevel(LogFlags category, Level level) const;
 89 
 90@@ -187,7 +187,7 @@ namespace BCLog {
 91             return Join(LogCategoriesList(), ", ", [&](const LogCategory& i) { return i.category; });
 92         };
 93 
 94-        //! Returns a string with the log levels in increasing order of severity.
 95+        //! Returns a string with all user-selectable log levels.
 96         std::string LogLevelsString() const;
 97 
 98         //! Returns the string representation of a log level.
 99diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
100index cc2194bb78..a6f3a62c71 100644
101--- a/src/test/logging_tests.cpp
102+++ b/src/test/logging_tests.cpp
103@@ -11,6 +11,7 @@
104 #include <chrono>
105 #include <fstream>
106 #include <iostream>
107+#include <unordered_map>
108 #include <utility>
109 #include <vector>
110 
111@@ -255,5 +256,4 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
112     }
113 }
114 
115-
116 BOOST_AUTO_TEST_SUITE_END()

dunxen approved

dunxen commented at 10:23 am on August 19, 2022: contributor

reACK ce3c4c9

Changes since last ACK LGTM

in src/init/common.cpp:26 in ce3c4c93a8 outdated

23@@ -23,11 +24,12 @@ namespace init {
24 void AddLoggingArgs(ArgsManager& argsman)
25 {
26     argsman.AddArg("-debuglogfile=<file>", strprintf("Specify location of debug log file. Relative paths will be prefixed by a net-specific datadir location. (-nodebuglogfile to disable; default: %s)", DEFAULT_DEBUGLOGFILE), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS);
27-    argsman.AddArg("-debug=<category>", "Output debugging information (default: -nodebug, supplying <category> is optional). "

vasild commented at 12:13 pm on August 19, 2022:

nit, please ignore: missing space in the commit log message: Update -debug and-debugexclude help docs for severity level logging

jonatack commented at 11:32 am on August 20, 2022:

done while repushing

vasild approved

vasild commented at 12:57 pm on August 19, 2022: contributor

ACK ce3c4c93a820fa918af4de545dbaffee9d0e1501 this looks good for 24.0 as well

Wish-list for the future:

Rename -loglevel to -log
Deprecate and remove -debug and -debugexclude in favor of -log
In the source code, we use “flag” and “category” interchangeably, but that is confusing as “flag” is too generic and I keep confusing it with “level”, use just “category”. Also, “level” and “severity” are used interchangeably, better use just “severity”.

Thank you!

unknown approved

unknown commented at 2:28 pm on August 19, 2022: none

reACK https://github.com/bitcoin/bitcoin/pull/25614/commits/ce3c4c93a820fa918af4de545dbaffee9d0e1501

Add BCLog::Logger::m_log_level data member and getter/setter

Co-authored-by: "klementtan <klementtan@gmail.com>"

2978b387bf

Add BCLog::Logger::m_category_log_levels data member and getter/setter

Co-authored-by: "klementtan <klementtan@gmail.com>"

f6c0cc0350

Add BCLog::Logger::SetLogLevel()/SetCategoryLogLevel() for string inputs

and remove unnecessary param constness in LogPrintStr()

Co-authored-by: jonatack <jon@atack.com>

c2797cfc60

Update LogAcceptCategory() and unit tests with log severity levels

Co-authored-by: "Jon Atack <jon@atack.com>"

8fe3457dbb

Create BCLog::Logger::LogLevelsString() helper function

Co-authored-by: "Jon Atack <jon@atack.com>"

9c7507bf76

Unit test coverage for log severity levels

Co-authored-by: "Jon Atack <jon@atack.com>"

98a1f9c687

Create -loglevel configuration option

- add a -loglevel=<level>|<category:level> config option to allow users
  to set a global -loglevel and category-specific log levels. LogPrintLevel
  messages with a higher severity level than -loglevel will not be printed
  in the debug log.

- for now, this config option is debug-only during the migration to
  severity-based logging

- update unit and functional tests

Co-authored-by: "Jon Atack <jon@atack.com>"

eb7bee5f84

Unit test coverage for -loglevel configuration option

Co-authored-by: "Jon Atack <jon@atack.com>"

2a8712db4f

Create BCLog::Level::Trace log severity level

for verbose log messages for development or debugging only, as bitcoind may run
more slowly, that are more granular/frequent than the Debug log level, i.e. for
very high-frequency, low-level messages to be logged distinctly from
higher-level, less-frequent debug logging that could still be usable in production.

An example would be to log higher-level peer events (connection, disconnection,
misbehavior, eviction) as Debug, versus Trace for low-level, high-volume p2p
messages in the BCLog::NET category. This will enable the user to log only the
former without the latter, in order to focus on high-level peer management events.

With respect to the name, "trace" is suggested as the most granular level
in resources like the following:
- https://sematext.com/blog/logging-levels
- https://howtodoinjava.com/log4j2/logging-levels

Update the test framework and add test coverage.

45f9282162

Update -debug and -debugexclude help docs for severity level logging 1abaa31aa3

jonatack force-pushed on Aug 20, 2022

jonatack commented at 11:36 am on August 20, 2022: contributor

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.

Update debug logging section in the developer notes 9580480570

jonatack force-pushed on Aug 20, 2022

unknown approved

unknown commented at 1:05 am on August 21, 2022: none

reACK https://github.com/bitcoin/bitcoin/pull/25614/commits/958048057087e6562b474f9028316c00ec03c2e4

jonatack commented at 9:42 am on August 22, 2022: contributor

@vasild, @dunxen, @brunoerg, @w0xlt, @jarolrod, @mzumsande, @klementtan mind having a last look here?

MarcoFalke commented at 10:06 am on August 22, 2022: member

Given that this is primarily for devs, is there a reason to ship this in 24.0 this late before the feature freeze? (Sorry if this has been discussed before, haven’t read the whole discussion)

jonatack commented at 10:19 am on August 22, 2022: contributor

Given that this is primarily for devs, is there a reason to ship this in 24.0 this late before the feature freeze? (Sorry if this has been discussed before, haven’t read the whole discussion)

The reason is to unblock the parent PR that has been stuck on this step for months, during which it becomes increasingly harder to maintain due to changes merged in the codebase since, as there is logging throughout the codebase. I also see refactoring PRs merged right now with much less accumulated review. This PR has been carefully reworked not to change behavior. Merging would allow review to begin on the next steps in the parent and signal that this migration may realistically happen, which would encourage continued work and review.

fanquake commented at 10:28 am on August 22, 2022: member

The reason is to unblock the parent PR that has been stuck on this step for months, during which it becomes increasingly harder to maintain due to changes merged in the codebase since. I also see refactoring PRs merged right now with much less accumulated review. As this PR has been carefully reworked not to change behavior, it is like a refactoring.

If the parent PR isn’t going into 24.0, it’s not clear why this change would need to be merged into 24.0 to unblock it. In fact, it would seem better, if this (broader) migration is going to happen, to perform all the refactoring/changes within the same release cycle (i.e 25.0), rather than shipping some small part of it now, which has been massaged to not actually change any behaviour.

jonatack commented at 10:31 am on August 22, 2022: contributor

15 accumulated ACKs but maintainers not in favor. Up for grabs.

jonatack closed this on Aug 22, 2022

MarcoFalke commented at 10:41 am on August 22, 2022: member

I am in favour of this configuration option, my question was solely about the milestone

jonatack commented at 10:52 am on August 22, 2022: contributor

Pushing this back needlessly only serves to stop momentum and discourage people from investing further time working on it or reviewing it. A lot of time and effort went into it to be ready for this release and unblock progress.

jonatack commented at 11:12 am on August 22, 2022: contributor

which has been massaged to not actually change any behaviour.

I think that was a needlessly negative comment. The changes were improvements, which is why I iterated on it, and there is no reason to change behavior yet for the few existing LogPrintLevel statements with a debug severity level.

fanquake commented at 11:43 am on August 22, 2022: member

I think that was a needlessly negative comment.

Apologies if you thought so. I was mostly referring to what you said here: “This PR has been carefully reworked not to change behavior.”.

The changes were improvements,

I never said they weren’t. My point was that this PR initially contained (iirc) more user-facing / behaviour changes; but was then altered to not change any behaviour (except for introducing a new option), seemingly so that it could be included for 24.0.

However it’s still not clear (to me) why this needs to go into 24.0, especially if it’s the first step in a larger (quite invasive) refactoring, which, as I mentioned above, I think if we are going to do, it would make more sense to do inside a single release cycle.

Also, there’s review suggestions above, such as “Rename -loglevel to -log”. If this is something we might do, then why rush to merge this now, only to have to change (and maybe go through deprecating) the option name again later, when we could instead just merge this change as -log for 25.0?

I understand that the parent PR might be unruly to maintain, but that’s also to be expected if it’s a major refactor, made up of a very large number of commits, that also touches many different areas of the codebase, including some of the most heavily trafficked (i.e p2p).

jonatack commented at 12:29 pm on August 22, 2022: contributor

Work began on this on March 2 with #24464 and the goal was to have it done for v24. After an initial flurry, progress has been blocked at this step (and #25586 went nowhere). If we couldn’t do it for v24 after an early start, the same will be given as a reason not to move forward with later steps 6 months from now for v25, and any progress would needlessly be pushed back and discouraged.

Also, there’s review suggestions above, such as #25614#pullrequestreview-1078726454. If this is something we might do, then why rush to merge this now, only to have to change (and maybe go through deprecating) the option name again later, when we could instead just merge this change as -log for 25.0?

It’s odd to read “rush to merge” for this pull along with its predecessor #25287, both opened in June and having quite a lot of review. Meanwhile, less-reviewed changes, often with fix-ups needed, are merged regularly without friction. The process looks arbitrary.

The suggestion you mention would only make sense if both (a) -debug were to be renamed to -log, and (b) the functionality of both -debug and -loglevel were to be combined. I am not sure there is consensus on doing both of those, nor on the resulting UX, and it’s way out of scope here. Furthermore, there would be no need to create a deprecation process for a debug-only -loglevel option that would also not apply to renaming the established -debug option, if such a deprecation process exists; I have not seen one in the past years. Using hypotheticals like that as arguments to gatekeep this, with the number of ACKs and amount of review over two PRs (here and #25287) it has seen, doesn’t make sense.

vasild commented at 1:35 pm on August 22, 2022: contributor

ACK 958048057087e6562b474f9028316c00ec03c2e4

(in case this gets reopened)

klementtan commented at 6:02 pm on August 22, 2022: contributor

reACK https://github.com/bitcoin/bitcoin/commit/958048057087e6562b474f9028316c00ec03c2e4

dunxen commented at 6:11 pm on August 22, 2022: contributor

reACK 9580480

jonatack deleted the branch on Aug 22, 2022

brunoerg commented at 1:53 pm on August 24, 2022: contributor

reACK 958048057087e6562b474f9028316c00ec03c2e4

jonatack renamed this:
~~logging: add `-loglevel` configuration option and a `trace` log level~~
Severity-based logging, step 2
on Aug 29, 2022

jonatack restored the branch on Aug 29, 2022

jonatack commented at 2:59 pm on August 29, 2022: contributor

Renamed and re-opened thanks to 5 re-ACKs (20 total), feature freeze postponed to Sept 1 per #24987 (comment), and numerous private messages of support (thank you).

jonatack reopened this on Aug 29, 2022

in src/logging.cpp:331 in 9c7507bf76 outdated

326+}
327+
328+std::string BCLog::Logger::LogLevelsString() const
329+{
330+    const auto& levels = LogLevelsList();
331+    return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [this](BCLog::Level level) { return LogLevelToStr(level); });

MarcoFalke commented at 3:08 pm on August 29, 2022:

nit in 9c7507bf76e79da99766a69df939520ea0a125d1 (only if you retouch and rebase for other reasons):

Can drop std::vector copy after https://github.com/bitcoin/bitcoin/commit/c89fabff3d17f23098d70c925fbdc98aca79fec6

jonatack commented at 10:19 am on September 2, 2022:

Thanks, will touch up in the parent (leaving unresolved until it’s done).

achow101 merged this on Sep 1, 2022

achow101 closed this on Sep 1, 2022

jonatack deleted the branch on Sep 1, 2022

sidhujag referenced this in commit e4a0e1e73a on Sep 1, 2022

in src/init/common.cpp:62 in 9580480570

56@@ -55,6 +57,26 @@ void SetLoggingOptions(const ArgsManager& args)
57     fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
58 }
59 
60+void SetLoggingLevel(const ArgsManager& args)
61+{
62+    if (args.IsArgSet("-loglevel")) {

MarcoFalke commented at 8:07 am on September 2, 2022:

Why is this check needed, given that you set DISALLOW_NEGATION and DISALLOW_ELISION?

vasild commented at 8:05 am on September 6, 2022:

It looks unnecessary to me, given that the entire body of the if is a for-loop that would iterate 0 times if this check is removed and -loglevel is not set, right? Is that true even if DISALLOW_ELISION is not used?

in src/init/common.cpp:64 in 9580480570

56@@ -55,6 +57,26 @@ void SetLoggingOptions(const ArgsManager& args)
57     fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
58 }
59 
60+void SetLoggingLevel(const ArgsManager& args)
61+{
62+    if (args.IsArgSet("-loglevel")) {
63+        for (const std::string& level_str : args.GetArgs("-loglevel")) {
64+            if (level_str.find_first_of(':', 3) == std::string::npos) {

MarcoFalke commented at 8:07 am on September 2, 2022:

Where does the 3 come from?

MarcoFalke commented at 8:11 am on September 2, 2022:

Also, if you ran SplitString first, this check could just be if (toks.size() == 1)?

jonatack commented at 10:21 am on September 2, 2022:

Also, if you ran SplitString first, this check could just be if (toks.size() == 1)?

Thanks, will touch up in the parent.

in src/logging.h:161 in 9580480570

152@@ -143,6 +153,22 @@ namespace BCLog {
153 
154         void ShrinkDebugFile();
155 
156+        std::unordered_map<LogFlags, Level> CategoryLevels() const
157+        {
158+            StdLockGuard scoped_lock(m_cs);
159+            return m_category_log_levels;
160+        }
161+        void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels)

MarcoFalke commented at 8:39 am on September 2, 2022:

I am not really a fan of adding test-only code to the core codebase. This may live in the unit tests or test library.

jonatack commented at 10:22 am on September 2, 2022:

Will move it to the tests.

MarcoFalke commented at 10:12 am on September 2, 2022: member

some questions

bitcoin locked this on Sep 6, 2023

Severity-based logging, step 2 #25614

Conflicts