merge bitcoin#25614: Severity-based logging, step 2

doc/developer-notes.md

@@ -390,8 +390,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 dashd is running with the `logging`
+RPC.  For instance, launching dashd 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

@@ -1212,6 +1212,7 @@ bool AppInitParameterInteraction(const ArgsManager& args)
 
     // ********************************************************* 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

@@ -13,6 +13,7 @@
 #include <logging.h>
 #include <node/ui_interface.h>
 #include <random.h>
+#include <util/string.h>
 #include <util/system.h>
 #include <util/time.h>
 #include <util/translation.h>
@@ -57,11 +58,12 @@ bool SanityChecks()
 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 | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
@@ -89,6 +91,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

@@ -21,6 +21,7 @@ bool SanityChecks();
 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/string.h>
 #include <util/system.h>
 #include <util/threadnames.h>
-#include <util/string.h>
 #include <util/time.h>
 
 #include <algorithm>
 #include <array>
+#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"},
@@ -201,11 +216,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:
@@ -214,6 +229,8 @@ std::string LogLevelToStr(BCLog::Level level)
         return "warning";
     case BCLog::Level::Error:
         return "error";
+    case BCLog::Level::None:
+        return "";
     }
     assert(false);
 }
@@ -223,7 +240,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:
@@ -318,6 +335,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(bool enabled_only) const
 {
     // Sort log categories by alphabetical order.
@@ -338,6 +374,18 @@ std::vector<LogCategory> BCLog::Logger::LogCategoriesList(bool enabled_only) con
     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;
@@ -385,7 +433,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);
@@ -494,3 +542,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;
@@ -92,12 +93,14 @@ namespace BCLog {
         ALL         = ~(uint64_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
     {
@@ -115,6 +118,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<uint64_t> m_categories{0};
 
@@ -137,7 +147,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
@@ -168,6 +178,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);
+
         uint64_t GetCategoryMask() const { return m_categories.load(); }
 
         void EnableCategory(LogFlags flag);
@@ -176,6 +202,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(bool enabled_only = false) const;
         /** Returns a string with the log categories in alphabetical order. */
@@ -184,6 +212,12 @@ namespace BCLog {
             return Join(LogCategoriesList(enabled_only), ", ", [&](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;
     };
 
@@ -194,12 +228,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 <netbase.h>
 #include <test/util/logging.h>
@@ -20,6 +21,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.
@@ -40,6 +43,7 @@ BOOST_AUTO_TEST_CASE(unlimited_recv)
     }
 
     CreateSock = CreateSockOrig;
+    LogInstance().SetLogLevel(prev_log_level);
 }
 
 BOOST_AUTO_TEST_SUITE_END()