Severity-based logging, step 2 #25614

pull jonatack wants to merge 12 commits into bitcoin:master from jonatack:loglevel-config-option changing 10 files +270 −36
  1. 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
    $ ./src/bitcoind -help-debug | grep -A10 loglevel
  -loglevel=<level>|<category>:<level>
       Set the global or per-category severity level for logging categories
       enabled with the -debug configuration option or the logging RPC:
       info, debug, trace (default=info); warning and error levels are
       always logged. If <category>:<level> is supplied, the setting
       will override the global one and may be specified multiple times
       to set multiple category-specific levels. <category> can be:
       addrman, bench, blockstorage, cmpctblock, coindb, estimatefee,
       http, i2p, ipc, leveldb, libevent, lock, mempool, mempoolrej,
       net, proxy, prune, qt, rand, reindex, rpc, selectcoins, tor,
       util, validation, walletdb, zmq.

    See the individual commit messages for details.

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

    <!--4a62be1de6b64f3ed646cdc7932c8cf5-->

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

  3. DrahtBot commented at 7:00 PM on July 14, 2022: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->

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

    <!--174a7506f384e20aa4161008e828411d-->

    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.

  4. laanwj added the label Utils/log/libs on Jul 14, 2022
  5. 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:

    constexpr std::array<BCLog::Level, static_cast<size_t>(BCLog::Level::None) + 1> BCLog::Logger::LogLevelsList() const
{
    return {BCLog::Level::Trace, BCLog::Level::Debug, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error, BCLog::Level::None};
}
    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!

  6. 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: 
        const auto levels = LogLevelsList();
    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!

  7. klementtan commented at 4:35 PM on July 17, 2022: contributor

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

  8. 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: 
        const auto level = GetLogLevel(level_str);
    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.

  9. 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

  10. jonatack force-pushed on Jul 20, 2022
  11. 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

  12. jonatack force-pushed on Jul 20, 2022
  13. klementtan commented at 4:05 PM on July 25, 2022: contributor

    Code review ACK and tested ACK 706805d

    Testing:

    # Absence of debug log when loglevel=INFO
$  ./src/bitcoind -signet -loglevel=info
$  grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
      0

# Debug log present when loglevel=DEBUG
$ ./src/bitcoind -signet -loglevel=debug
$  grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
       2

# Category-specific log level. loglevel=net:info
$ ./src/bitcoind -signet -loglevel=net:info
Bitcoin Core starting
$  grep -o "net:debug" ~/.bitcoin/signet/debug.log | wc -l
       0
  14. 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.

                    if (!LogInstance().SetLogLevel(level_str)) {
                    InitError(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s"), level_str, LogInstance().LogLevelsString()));
                }
                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>.

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

      log severity levels. (#25614)
    jonatack commented at 12:40 PM on August 11, 2022:

    done

  16. w0xlt approved
  17. 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.

  18. 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.

  19. 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.

  20. jonatack force-pushed on Aug 11, 2022
  21. jonatack force-pushed on Aug 11, 2022
  22. 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!)

    <details><summary><code>git diff 706805d 63215dd</code></summary><p>

    diff --git a/doc/release-notes.md b/doc/release-notes.md
index 4680731280..9585144ce5 100644
--- a/doc/release-notes.md
+++ b/doc/release-notes.md
@@ -94,7 +94,7 @@ Tools and Utilities
 -------------------
 
 - A new `-loglevel` configuration option allows setting global and per-category
-  log severity levels. (#25203)
+  log severity levels. (#25614)
 
 Wallet
 ------
diff --git a/src/init/common.cpp b/src/init/common.cpp
index a0f5cb2a6e..a22d921b21 100644
--- a/src/init/common.cpp
+++ b/src/init/common.cpp
@@ -29,7 +29,7 @@ void AddLoggingArgs(ArgsManager& argsman)
         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-debugexclude=<category>", "Exclude debugging information for a category. Can be used in conjunction with -debug=1 to output debug logs for all categories except the specified category. This option can be specified multiple times to exclude multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
-    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category 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);
+    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);
     argsman.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 #ifdef HAVE_THREAD_LOCAL
     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);
@@ -64,13 +64,13 @@ void SetLoggingLevel(const ArgsManager& args)
             if (level_str.find_first_of(':', 3) == std::string::npos) {
                 // user passed a global log level, i.e. -loglevel=<level>
                 if (!LogInstance().SetLogLevel(level_str)) {
-                    InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s"), level_str, LogInstance().LogLevelsString()));
+                    InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s."), level_str, LogInstance().LogLevelsString()));
                 }
             } else {
                 // user passed a category-specific log level, i.e. -loglevel=<category>:<level>
                 const auto& toks = SplitString(level_str, ':');
                 if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
-                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>"), level_str));
+                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>. Valid loglevel values: %s."), level_str, LogInstance().LogLevelsString()));
                 }
             }
         }
diff --git a/src/logging.cpp b/src/logging.cpp
index 3891be1cdc..964eb57eb8 100644
--- a/src/logging.cpp
+++ b/src/logging.cpp
@@ -321,9 +321,10 @@ std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
     return ret;
 }
 
-static constexpr std::array<BCLog::Level, static_cast<size_t>(BCLog::Level::None)> LogLevelsList()
+/** Log severity levels that can be selected by the user. */
+static constexpr std::array<BCLog::Level, 3> LogLevelsList()
 {
-    return {BCLog::Level::Trace, BCLog::Level::Debug, BCLog::Level::Info, BCLog::Level::Warning, BCLog::Level::Error};
+    return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
 }
 
 std::string BCLog::Logger::LogLevelsString() const
@@ -492,7 +493,7 @@ void BCLog::Logger::ShrinkDebugFile()
 bool BCLog::Logger::SetLogLevel(const std::string& level_str)
 {
     const auto level = GetLogLevel(level_str);
-    if (!level) return false;
+    if (!level || level > BCLog::Level::Info) return false;
     m_log_level = level.value();
     return true;
 }
@@ -503,7 +504,7 @@ bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const s
     if (!GetLogCategory(flag, category_str)) return false;
 
     const auto level = GetLogLevel(level_str);
-    if (!level) return false;
+    if (!level || level > BCLog::Level::Info) return false;
     m_category_log_levels[flag] = level.value();
     return true;
 }
diff --git a/src/logging.h b/src/logging.h
index 88e5486545..6d4661792b 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -7,8 +7,8 @@
 #define BITCOIN_LOGGING_H
 
 #include <fs.h>
-#include <tinyformat.h>
 #include <threadsafety.h>
+#include <tinyformat.h>
 #include <unordered_map>
 #include <util/string.h>
 
@@ -191,7 +191,7 @@ namespace BCLog {
         std::string LogLevelsString() const;
 
         //! Returns the string representation of a log level.
-        std::string LogLevelToStr(BCLog::Level level = DEFAULT_LOG_LEVEL) const;
+        std::string LogLevelToStr(BCLog::Level level) const;
 
         bool DefaultShrinkDebugFile() const;
     };
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index c3b4a8a8c1..87bd4ef114 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -171,18 +171,18 @@ BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
 {
     LogInstance().EnableCategory(BCLog::LogFlags::ALL);
 
-    LogInstance().SetLogLevel(BCLog::Level::Info);
-    LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"debug");
+    LogInstance().SetLogLevel(BCLog::Level::Debug);
+    LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
 
     // Global log level
     LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
-    LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Debug, "foo2: %s. This log level is lower than the global one.\n", "bar2");
+    LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
     LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
     LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
 
     // Category-specific log level
     LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
-    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");
+    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");
     LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
 
     std::vector<std::string> expected = {
@@ -207,11 +207,11 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
         ResetLogger();
         ArgsManager args;
         args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
-        const char* argv_test[] = {"bitcoind", "-loglevel=warning"};
+        const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
         std::string err;
         BOOST_CHECK(args.ParseParameters(2, argv_test, err));
         init::SetLoggingLevel(args);
-        BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Warning);
+        BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
     }
 
     // Set category-specific log level
@@ -219,7 +219,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
         ResetLogger();
         ArgsManager args;
         args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
-        const char* argv_test[] = {"bitcoind", "-loglevel=net:warning"};
+        const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
         std::string err;
         BOOST_CHECK(args.ParseParameters(2, argv_test, err));
         init::SetLoggingLevel(args);
@@ -228,7 +228,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
         const auto& category_levels{LogInstance().CategoryLevels()};
         const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
         BOOST_CHECK(net_it != category_levels.end());
-        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Warning);
+        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
     }
 
     // Set both global log level and category-specific log level
@@ -236,7 +236,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
         ResetLogger();
         ArgsManager args;
         args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
-        const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:warning", "-loglevel=http:error"};
+        const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
         std::string err;
         BOOST_CHECK(args.ParseParameters(4, argv_test, err));
         init::SetLoggingLevel(args);
@@ -247,11 +247,11 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
 
         const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
         BOOST_CHECK(net_it != category_levels.end());
-        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Warning);
+        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
 
         const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
         BOOST_CHECK(http_it != category_levels.end());
-        BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Error);
+        BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
     }
 }

    </p></details>

  23. jonatack force-pushed on Aug 11, 2022
  24. 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".

                        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.

  25. unknown approved
  27. dunxen approved
  28. 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.

  29. brunoerg approved
  30. brunoerg commented at 12:37 PM on August 15, 2022: contributor

    crACK 63215dd36c46b1b68ce2e2133ec1d21c044cf055

  31. jarolrod approved
  32. jarolrod commented at 7:43 PM on August 15, 2022: member

    tACK 63215dd36c46b1b68ce2e2133ec1d21c044cf055

    LGTM

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

        } else if (level_str == "none") {
        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

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

    if (!LogInstance().EnableCategory(toks[0])) {
    InitWarning(strprintf(_("Unsupported logging category: %s. Valid categories: %s."), toks[0], LogInstance().LogCategoriesString()));
}
    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).

  35. 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.

  36. 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"

    -        //! Category-specific log level. Overrides the global `m_log_level`.
+        //! Category-specific log level. Overrides `m_log_level`.
  37. 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?

            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.

  38. 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.

  39. 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?

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

    Thanks. Indeed, "reached!" is printed:

    -        BOOST_TEST(GetLogCategory(category, trimmed_category_name));
+        BOOST_TEST(false);
+        BOOST_TEST_MESSAGE("reached!");
    jonatack commented at 10:15 AM on August 16, 2022:

    Done

  40. 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

  41. 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

  42. 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

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

    Release notes should be added to a PR-specific release note file at
`/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.

    - Release notes should be added to a PR-specific release note file at
- `/doc/release-notes-<PR number>.md` to avoid conflicts between multiple PRs.
- All `release-notes*` files are merged into a single
+ When it seems likely to cause a merge conflict, a release note should be added
+ in a PR-specific file named `/doc/release-notes-<PR number>.md`.  These
+ `release-notes*` files are merged into a single
[/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.)

  44. 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?

  45. 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.

  46. 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.

  47. jonatack force-pushed on Aug 16, 2022
  48. 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.

  49. klementtan commented at 4:58 PM on August 16, 2022: contributor

    crACK b99dc23c94d802cea94127f2eb376f90aef33a05

  50. klementtan approved
  51. dunxen approved
  52. dunxen commented at 6:39 PM on August 16, 2022: contributor

    reACK b99dc23

  53. unknown approved
  55. brunoerg approved
  56. brunoerg commented at 9:45 PM on August 16, 2022: contributor

    crACK b99dc23c94d802cea94127f2eb376f90aef33a05

  57. 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.

  58. vasild approved
  59. 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.
  60. 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.)

  61. 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.

  62. 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.

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

  64. 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
  65. w0xlt approved
  66. w0xlt commented at 10:43 PM on August 18, 2022: contributor

    reACK b99dc23c94d802cea94127f2eb376f90aef33a05

  67. jonatack force-pushed on Aug 19, 2022
  68. 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.

    <details><summary><code>git diff b99dc23 ce3c4c9</code></summary><p>

    diff --git a/doc/release-notes.md b/doc/release-notes.md
index 9585144ce5..444926087b 100644
--- a/doc/release-notes.md
+++ b/doc/release-notes.md
@@ -93,9 +93,6 @@ New settings
 Tools and Utilities
 -------------------
 
-- A new `-loglevel` configuration option allows setting global and per-category
-  log severity levels. (#25614)
-
 Wallet
 ------
 
diff --git a/src/init/common.cpp b/src/init/common.cpp
index 840cb57eaa..f2d2c5640a 100644
--- a/src/init/common.cpp
+++ b/src/init/common.cpp
@@ -24,12 +24,12 @@ namespace init {
 void AddLoggingArgs(ArgsManager& argsman)
 {
     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);
-    argsman.AddArg("-debug=<category>", "Output debugging information (default: -nodebug, supplying <category> is optional). "
-        "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.",
+    argsman.AddArg("-debug=<category>", "Output debug and trace logging (default: -nodebug, supplying <category> is optional). "
+        "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.",
         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
-    argsman.AddArg("-debugexclude=<category>", "Exclude debugging information for a category. Can be used in conjunction with -debug=1 to output debug logs for all categories except the specified category. This option can be specified multiple times to exclude multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+    argsman.AddArg("-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);
     argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
-    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category 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);
+    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);
     argsman.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 #ifdef HAVE_THREAD_LOCAL
     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);
diff --git a/src/logging.h b/src/logging.h
index 27e00a4466..4d13ea0d80 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -9,7 +9,6 @@
 #include <fs.h>
 #include <threadsafety.h>
 #include <tinyformat.h>
-#include <unordered_map>
 #include <util/string.h>
 
 #include <atomic>
@@ -18,6 +17,7 @@
 #include <list>
 #include <mutex>
 #include <string>
+#include <unordered_map>
 #include <vector>
 
 static const bool DEFAULT_LOGTIMEMICROS = false;
@@ -158,7 +158,17 @@ namespace BCLog {
             StdLockGuard scoped_lock(m_cs);
             return m_category_log_levels;
         }
+        void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels)
+        {
+            StdLockGuard scoped_lock(m_cs);
+            m_category_log_levels = levels;
+        }
+        bool SetCategoryLogLevel(const std::string& category_str, const std::string& level_str);
+
         Level LogLevel() const { return m_log_level.load(); }
+        void SetLogLevel(Level level) { m_log_level = level; }
+        bool SetLogLevel(const std::string& level);
+
         uint32_t GetCategoryMask() const { return m_categories.load(); }
 
         void EnableCategory(LogFlags flag);
@@ -166,16 +176,6 @@ namespace BCLog {
         void DisableCategory(LogFlags flag);
         bool DisableCategory(const std::string& str);
 
-        bool SetLogLevel(const std::string& level);
-        void SetLogLevel(Level level) { m_log_level = level; }
-
-        bool SetCategoryLogLevel(const std::string& category_str, const std::string& level_str);
-        void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels)
-        {
-            StdLockGuard scoped_lock(m_cs);
-            m_category_log_levels = levels;
-        }
-
         bool WillLogCategory(LogFlags category) const;
         bool WillLogCategoryLevel(LogFlags category, Level level) const;
 
@@ -187,7 +187,7 @@ namespace BCLog {
             return Join(LogCategoriesList(), ", ", [&](const LogCategory& i) { return i.category; });
         };
 
-        //! Returns a string with the log levels in increasing order of severity.
+        //! Returns a string with all user-selectable log levels.
         std::string LogLevelsString() const;
 
         //! Returns the string representation of a log level.
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index cc2194bb78..a6f3a62c71 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -11,6 +11,7 @@
 #include <chrono>
 #include <fstream>
 #include <iostream>
+#include <unordered_map>
 #include <utility>
 #include <vector>
 
@@ -255,5 +256,4 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
     }
 }
 
-
 BOOST_AUTO_TEST_SUITE_END()

    </p></details>

  69. dunxen approved
  70. dunxen commented at 10:23 AM on August 19, 2022: contributor

    reACK ce3c4c9

    Changes since last ACK LGTM

  71. 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

  72. vasild approved
  73. 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!

  74. unknown approved
  76. Add BCLog::Logger::m_log_level data member and getter/setter
    Co-authored-by: "klementtan <klementtan@gmail.com>"
    2978b387bf
  77. Add BCLog::Logger::m_category_log_levels data member and getter/setter
    Co-authored-by: "klementtan <klementtan@gmail.com>"
    f6c0cc0350
  78. Add BCLog::Logger::SetLogLevel()/SetCategoryLogLevel() for string inputs
    and remove unnecessary param constness in LogPrintStr()

Co-authored-by: jonatack <jon@atack.com>
    c2797cfc60
  79. Update LogAcceptCategory() and unit tests with log severity levels
    Co-authored-by: "Jon Atack <jon@atack.com>"
    8fe3457dbb
  80. Create BCLog::Logger::LogLevelsString() helper function
    Co-authored-by: "Jon Atack <jon@atack.com>"
    9c7507bf76
  81. Unit test coverage for log severity levels
    Co-authored-by: "Jon Atack <jon@atack.com>"
    98a1f9c687
  82. 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
  83. Unit test coverage for -loglevel configuration option
    Co-authored-by: "Jon Atack <jon@atack.com>"
    2a8712db4f
  84. 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
  85. Update -debug and -debugexclude help docs for severity level logging 1abaa31aa3
  86. jonatack force-pushed on Aug 20, 2022
  87. 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.

  88. Update debug logging section in the developer notes 9580480570
  89. jonatack force-pushed on Aug 20, 2022
  90. unknown approved
  92. jonatack commented at 9:42 AM on August 22, 2022: contributor

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

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

  94. 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.

  95. 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.

  96. jonatack commented at 10:31 AM on August 22, 2022: contributor

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

  97. jonatack closed this on Aug 22, 2022
  98. 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

  99. 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.

  100. 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.

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

  102. 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.

  103. vasild commented at 1:35 PM on August 22, 2022: contributor

    ACK 958048057087e6562b474f9028316c00ec03c2e4

    (in case this gets reopened)

  105. dunxen commented at 6:11 PM on August 22, 2022: contributor

    reACK 9580480

  106. jonatack deleted the branch on Aug 22, 2022
  107. brunoerg commented at 1:53 PM on August 24, 2022: contributor

    reACK 958048057087e6562b474f9028316c00ec03c2e4

  108. jonatack renamed this:
    logging: add `-loglevel` configuration option and a `trace` log level
    Severity-based logging, step 2
    on Aug 29, 2022
  109. jonatack restored the branch on Aug 29, 2022
  110. 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).

  111. jonatack reopened this on Aug 29, 2022
  112. 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).

  113. achow101 merged this on Sep 1, 2022
  114. achow101 closed this on Sep 1, 2022
  115. jonatack deleted the branch on Sep 1, 2022
  116. sidhujag referenced this in commit e4a0e1e73a on Sep 1, 2022
  117. 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?

  118. 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.

  119. 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.

  120. MarcoFalke commented at 10:12 AM on September 2, 2022: member

    some questions

  121. bitcoin locked this on Sep 6, 2023
Contributors
jonatackDrahtBotklementtanw0xltfjahrbrunoergvasilddunxenjarolrodfanquakeMarcoFalkemzumsande
Labels
Utils/log/libs
Linked (view graph)
#25203 Severity-based logging -- parent PR#25287 logging: threshold log level
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-05-02 18:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me