Merge bitcoin/bitcoin#25614: Severity-based logging, step 2

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

Pull request description:

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

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

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

  See the individual commit messages for details.

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

Tree-SHA512: 476a638e0581f40b5d058a9992691722e8b546471ec85e07cbc990798d1197fbffbd02e1b3d081b4978404e07a428378cdc8e159c0004b81f58be7fb01b7cba0

Author: achow101

doc/developer-notes.md

@@ -386,8 +386,10 @@ Run configure with the `--enable-gprof` option, then make.
 If the code is behaving strangely, take a look in the `debug.log` file in the data directory;
 error and debugging messages are written there.
 
-The `-debug=...` command-line option controls debugging; running with just `-debug` or `-debug=1` will turn
-on all categories (and give you a very large `debug.log` file).
+Debug logging can be enabled on startup with the `-debug` and `-loglevel`
+configuration options and toggled while bitcoind is running with the `logging`
+RPC.  For instance, launching bitcoind with `-debug` or `-debug=1` will turn on
+all log categories and `-loglevel=trace` will turn on all log severity levels.
 
 The Qt code routes `qDebug()` output to `debug.log` under category "qt": run with `-debug=qt`
 to see it.

src/init.cpp

@@ -915,6 +915,7 @@ bool AppInitParameterInteraction(const ArgsManager& args, bool use_syscall_sandb
 
     // ********************************************************* Step 3: parameter-to-internal-flags
     init::SetLoggingCategories(args);
+    init::SetLoggingLevel(args);
 
     fCheckBlockIndex = args.GetBoolArg("-checkblockindex", chainparams.DefaultConsistencyChecks());
     fCheckpointsEnabled = args.GetBoolArg("-checkpoints", DEFAULT_CHECKPOINTS_ENABLED);

src/init/common.cpp

@@ -11,6 +11,7 @@
 #include <logging.h>
 #include <node/interface_ui.h>
 #include <tinyformat.h>
+#include <util/string.h>
 #include <util/system.h>
 #include <util/time.h>
 #include <util/translation.h>
@@ -23,11 +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 | 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);
@@ -55,6 +57,26 @@ void SetLoggingOptions(const ArgsManager& args)
     fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
 }
 
+void SetLoggingLevel(const ArgsManager& args)
+{
+    if (args.IsArgSet("-loglevel")) {
+        for (const std::string& level_str : args.GetArgs("-loglevel")) {
+            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()));
+                }
+            } 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>. Valid categories: %s. Valid loglevels: %s."), level_str, LogInstance().LogCategoriesString(), LogInstance().LogLevelsString()));
+                }
+            }
+        }
+    }
+}
+
 void SetLoggingCategories(const ArgsManager& args)
 {
     if (args.IsArgSet("-debug")) {

src/init/common.h

@@ -14,6 +14,7 @@ namespace init {
 void AddLoggingArgs(ArgsManager& args);
 void SetLoggingOptions(const ArgsManager& args);
 void SetLoggingCategories(const ArgsManager& args);
+void SetLoggingLevel(const ArgsManager& args);
 bool StartLogging(const ArgsManager& args);
 void LogPackageVersion();
 } // namespace init

src/logging.cpp

@@ -5,15 +5,17 @@
 
 #include <fs.h>
 #include <logging.h>
-#include <util/threadnames.h>
 #include <util/string.h>
+#include <util/threadnames.h>
 #include <util/time.h>
 
 #include <algorithm>
 #include <array>
 #include <mutex>
+#include <optional>
 
 const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
+constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
 
 BCLog::Logger& LogInstance()
 {
@@ -122,6 +124,19 @@ bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
     return (m_categories.load(std::memory_order_relaxed) & category) != 0;
 }
 
+bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
+{
+    // Log messages at Warning and Error level unconditionally, so that
+    // important troubleshooting information doesn't get lost.
+    if (level >= BCLog::Level::Warning) return true;
+
+    if (!WillLogCategory(category)) return false;
+
+    StdLockGuard scoped_lock(m_cs);
+    const auto it{m_category_log_levels.find(category)};
+    return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
+}
+
 bool BCLog::Logger::DefaultShrinkDebugFile() const
 {
     return m_categories == BCLog::NONE;
@@ -135,7 +150,7 @@ struct CLogCategoryDesc {
 const CLogCategoryDesc LogCategories[] =
 {
     {BCLog::NONE, "0"},
-    {BCLog::NONE, "none"},
+    {BCLog::NONE, ""},
     {BCLog::NET, "net"},
     {BCLog::TOR, "tor"},
     {BCLog::MEMPOOL, "mempool"},
@@ -184,11 +199,11 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
     return false;
 }
 
-std::string LogLevelToStr(BCLog::Level level)
+std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const
 {
     switch (level) {
-    case BCLog::Level::None:
-        return "none";
+    case BCLog::Level::Trace:
+        return "trace";
     case BCLog::Level::Debug:
         return "debug";
     case BCLog::Level::Info:
@@ -197,6 +212,8 @@ std::string LogLevelToStr(BCLog::Level level)
         return "warning";
     case BCLog::Level::Error:
         return "error";
+    case BCLog::Level::None:
+        return "";
     }
     assert(false);
 }
@@ -206,7 +223,7 @@ std::string LogCategoryToStr(BCLog::LogFlags category)
     // Each log category string representation should sync with LogCategories
     switch (category) {
     case BCLog::LogFlags::NONE:
-        return "none";
+        return "";
     case BCLog::LogFlags::NET:
         return "net";
     case BCLog::LogFlags::TOR:
@@ -269,6 +286,25 @@ std::string LogCategoryToStr(BCLog::LogFlags category)
     assert(false);
 }
 
+static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
+{
+    if (level_str == "trace") {
+        return BCLog::Level::Trace;
+    } else if (level_str == "debug") {
+        return BCLog::Level::Debug;
+    } else if (level_str == "info") {
+        return BCLog::Level::Info;
+    } else if (level_str == "warning") {
+        return BCLog::Level::Warning;
+    } else if (level_str == "error") {
+        return BCLog::Level::Error;
+    } else if (level_str == "none") {
+        return BCLog::Level::None;
+    } else {
+        return std::nullopt;
+    }
+}
+
 std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
 {
     // Sort log categories by alphabetical order.
@@ -287,6 +323,18 @@ std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
     return ret;
 }
 
+/** Log severity levels that can be selected by the user. */
+static constexpr std::array<BCLog::Level, 3> LogLevelsList()
+{
+    return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
+}
+
+std::string BCLog::Logger::LogLevelsString() const
+{
+    const auto& levels = LogLevelsList();
+    return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [this](BCLog::Level level) { return LogLevelToStr(level); });
+}
+
 std::string BCLog::Logger::LogTimestampStr(const std::string& str)
 {
     std::string strStamped;
@@ -334,7 +382,7 @@ namespace BCLog {
     }
 } // namespace BCLog
 
-void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags category, const BCLog::Level level)
+void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
 {
     StdLockGuard scoped_lock(m_cs);
     std::string str_prefixed = LogEscapeMessage(str);
@@ -443,3 +491,24 @@ void BCLog::Logger::ShrinkDebugFile()
     else if (file != nullptr)
         fclose(file);
 }
+
+bool BCLog::Logger::SetLogLevel(const std::string& level_str)
+{
+    const auto level = GetLogLevel(level_str);
+    if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
+    m_log_level = level.value();
+    return true;
+}
+
+bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str)
+{
+    BCLog::LogFlags flag;
+    if (!GetLogCategory(flag, category_str)) return false;
+
+    const auto level = GetLogLevel(level_str);
+    if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
+
+    StdLockGuard scoped_lock(m_cs);
+    m_category_log_levels[flag] = level.value();
+    return true;
+}

src/logging.h

@@ -7,8 +7,8 @@
 #define BITCOIN_LOGGING_H
 
 #include <fs.h>
-#include <tinyformat.h>
 #include <threadsafety.h>
+#include <tinyformat.h>
 #include <util/string.h>
 
 #include <atomic>
@@ -17,6 +17,7 @@
 #include <list>
 #include <mutex>
 #include <string>
+#include <unordered_map>
 #include <vector>
 
 static const bool DEFAULT_LOGTIMEMICROS = false;
@@ -68,12 +69,14 @@ namespace BCLog {
         ALL         = ~(uint32_t)0,
     };
     enum class Level {
-        Debug = 0,
-        None = 1,
-        Info = 2,
-        Warning = 3,
-        Error = 4,
+        Trace = 0, // High-volume or detailed logging for development/debugging
+        Debug,     // Reasonably noisy logging, but still usable in production
+        Info,      // Default
+        Warning,
+        Error,
+        None, // Internal use only
     };
+    constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
 
     class Logger
     {
@@ -91,6 +94,13 @@ namespace BCLog {
          */
         std::atomic_bool m_started_new_line{true};
 
+        //! Category-specific log level. Overrides `m_log_level`.
+        std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
+
+        //! If there is no category-specific log level, all logs with a severity
+        //! level lower than `m_log_level` will be ignored.
+        std::atomic<Level> m_log_level{DEFAULT_LOG_LEVEL};
+
         /** Log categories bitfield. */
         std::atomic<uint32_t> m_categories{0};
 
@@ -112,7 +122,7 @@ namespace BCLog {
         std::atomic<bool> m_reopen_file{false};
 
         /** Send a string to the log output */
-        void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags category, const BCLog::Level level);
+        void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level);
 
         /** Returns whether logs will be written to any output */
         bool Enabled() const
@@ -143,6 +153,22 @@ namespace BCLog {
 
         void ShrinkDebugFile();
 
+        std::unordered_map<LogFlags, Level> CategoryLevels() const
+        {
+            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);
@@ -151,6 +177,8 @@ namespace BCLog {
         bool DisableCategory(const std::string& str);
 
         bool WillLogCategory(LogFlags category) const;
+        bool WillLogCategoryLevel(LogFlags category, Level level) const;
+
         /** Returns a vector of the log categories in alphabetical order. */
         std::vector<LogCategory> LogCategoriesList() const;
         /** Returns a string with the log categories in alphabetical order. */
@@ -159,6 +187,12 @@ namespace BCLog {
             return Join(LogCategoriesList(), ", ", [&](const LogCategory& i) { return i.category; });
         };
 
+        //! Returns a string with all user-selectable log levels.
+        std::string LogLevelsString() const;
+
+        //! Returns the string representation of a log level.
+        std::string LogLevelToStr(BCLog::Level level) const;
+
         bool DefaultShrinkDebugFile() const;
     };
 
@@ -169,12 +203,7 @@ BCLog::Logger& LogInstance();
 /** Return true if log accepts specified category, at the specified level. */
 static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level)
 {
-    // Log messages at Warning and Error level unconditionally, so that
-    // important troubleshooting information doesn't get lost.
-    if (level >= BCLog::Level::Warning) {
-        return true;
-    }
-    return LogInstance().WillLogCategory(category);
+    return LogInstance().WillLogCategoryLevel(category, level);
 }
 
 /** Return true if str parses as a log category and set the flag */

src/test/i2p_tests.cpp

@@ -3,6 +3,7 @@
 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
 
 #include <i2p.h>
+#include <logging.h>
 #include <netaddress.h>
 #include <test/util/logging.h>
 #include <test/util/net.h>
@@ -19,6 +20,8 @@ BOOST_FIXTURE_TEST_SUITE(i2p_tests, BasicTestingSetup)
 
 BOOST_AUTO_TEST_CASE(unlimited_recv)
 {
+    const auto prev_log_level{LogInstance().LogLevel()};
+    LogInstance().SetLogLevel(BCLog::Level::Trace);
     auto CreateSockOrig = CreateSock;
 
     // Mock CreateSock() to create MockSock.
@@ -39,6 +42,7 @@ BOOST_AUTO_TEST_CASE(unlimited_recv)
     }
 
     CreateSock = CreateSockOrig;
+    LogInstance().SetLogLevel(prev_log_level);
 }
 
 BOOST_AUTO_TEST_SUITE_END()