logging: Improve new LogDebug/Trace/Info/Warning/Error Macros

Improve new LogDebug(), LogTrace(), LogInfo(),  LogWarning(), LogError() macros
introduced in #28318:

- Make them always accept log categories to make it possible to only log
  messages from a particular component.
- Make them not rely on a global LogInstance, to provide better control of
  logging in controlled environments, such as unit tests that want to
  selectively capture log output, or libbitcoinkernel applications that want to
  have multiple instances of validation objects without mixing their log output.
- Make them consistent, now all accepting the same parameters.
- Make them less verbose by not requiring BCLog category constants to be
  specified in individual log prints

src/logging.h

@@ -6,6 +6,7 @@
 #ifndef BITCOIN_LOGGING_H
 #define BITCOIN_LOGGING_H
 
+#include <attributes.h>
 #include <threadsafety.h>
 #include <tinyformat.h>
 #include <util/fs.h>
@@ -21,6 +22,12 @@
 #include <unordered_map>
 #include <vector>
 
+namespace BCLog {
+class Logger;
+} // namespace BCLog
+
+BCLog::Logger& LogInstance();
+
 static const bool DEFAULT_LOGTIMEMICROS = false;
 static const bool DEFAULT_LOGIPS        = false;
 static const bool DEFAULT_LOGTIMESTAMPS = true;
@@ -73,6 +80,11 @@ namespace BCLog {
         TXPACKAGES  = (CategoryMask{1} << 28),
         ALL         = ~NONE,
     };
+    //! Log level constants. Most code will not need to use these directly and
+    //! can use LogTrace, LogDebug, LogInfo, LogWarning, and LogError macros
+    //! defined below for less verbosity and more efficiency (by not evaluating
+    //! unused format arguments). See macro definitions below or "Logging"
+    //! section in developer-notes.md for more detailed information.
     enum class Level {
         Trace = 0, // High-volume or detailed logging for development/debugging
         Debug,     // Reasonably noisy logging, but still usable in production
@@ -225,9 +237,36 @@ namespace BCLog {
         bool DefaultShrinkDebugFile() const;
     };
 
+    //! Object representing a particular source of log messages. Holds a logging
+    //! category, a reference to the logger object to output to, and a
+    //! formatting hook.
+    struct Source {
+        LogFlags category;
+        Logger& logger;
+
+        //! Constructor. Implicit so can be constructed from category constants passed to Log macros below.
+        Source(LogFlags category = LogFlags::ALL, Logger& logger = LogInstance()) : category{category}, logger{logger} {}
+
+        template <typename... Args>
+        std::string Format(util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args) const
+        {
+            std::string log_msg;
+            try {
+                log_msg = tfm::format(fmt, args...);
+            } catch (tinyformat::format_error& fmterr) {
+                log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt;
+            }
+            return log_msg;
+        }
+    };
 } // namespace BCLog
 
-BCLog::Logger& LogInstance();
+//! Determine whether logging is enabled from a source at the specified level.
+template <typename Source>
+static inline bool LogEnabled(const Source& source, BCLog::Level level)
+{
+    return source.logger.WillLogCategoryLevel(source.category, level) && source.logger.Enabled();
+}
 
 /** Return true if log accepts specified category, at the specified level. */
 static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level)
@@ -238,46 +277,83 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve
 /** Return true if str parses as a log category and set the flag */
 bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str);
 
-template <typename... Args>
+//! Internal helper to get log source object from macro argument, if argument is
-inline void LogPrintFormatInternal(std::string_view logging_function, std::string_view source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
+//! BCLog::Source object or a category constant that BCLog::Source can be
+//! constructed from.
+static inline const BCLog::Source& _LogSource(const BCLog::Source& source LIFETIMEBOUND) { return source; }
+
+//! Internal helper to get log source object from macro argument, if argument is
+//! just a format string and no source or category was provided.
+static inline BCLog::Source _LogSource(std::string_view fmt) { return {}; }
+
+//! Internal helper to format log arguments and call a logging function.
+template <typename LogFn, typename Source, typename SourceArg, typename... Args>
+requires (!std::is_convertible_v<SourceArg, std::string_view>)
+void _LogFormat(LogFn&& log, Source&& source, SourceArg&&, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
 {
-    if (LogInstance().Enabled()) {
+    log(source, source.Format(fmt, args...));
-        std::string log_msg;
+}
-        try {
+template <typename LogFn, typename Source, typename... Args>
-            log_msg = tfm::format(fmt, args...);
+void _LogFormat(LogFn&& log, Source&& source, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
-        } catch (tinyformat::format_error& fmterr) {
+{
-            log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt;
+    log(source, source.Format(fmt, args...));
-        }
-        LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line, flag, level);
-    }
 }
 
-#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__)
+//! Internal helper to return first arg in a __VA_ARGS__ pack.
+#define _FirstArg(arg, ...) arg
 
-// Log unconditionally.
+//! Internal helper to check level and log. Avoids evaluating arguments if not logging.
-// Be conservative when using functions that unconditionally log to debug.log!
+#define _LogPrint(level, ...)                                             \
-// It should not be the case that an inbound peer can fill up a user's storage
+    do {                                                                  \
-// with debug.log entries.
+        if (LogEnabled(_LogSource(_FirstArg(__VA_ARGS__)), (level))) {    \
-#define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__)
+            const auto& func = __func__;                                  \
-#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, __VA_ARGS__)
+            _LogFormat([&](auto&& source, auto&& message) {               \
-#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, __VA_ARGS__)
+                source.logger.LogPrintStr(message, func, __FILE__,        \
-
+                    __LINE__, source.category, (level));                  \
-// Deprecated unconditional logging.
+            }, _LogSource(_FirstArg(__VA_ARGS__)), __VA_ARGS__);          \
-#define LogPrintf(...) LogInfo(__VA_ARGS__)
+        }                                                                 \
-
-// Use a macro instead of a function for conditional logging to prevent
-// evaluating arguments when logging for the category is not enabled.
-
-// Log conditionally, prefixing the output with the passed category name and severity level.
-#define LogPrintLevel(category, level, ...)               \
-    do {                                                  \
-        if (LogAcceptCategory((category), (level))) {     \
-            LogPrintLevel_(category, level, __VA_ARGS__); \
-        }                                                 \
     } while (0)
 
-// Log conditionally, prefixing the output with the passed category name.
+//! Logging macros which output log messages at the specified levels, and avoid
-#define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__)
+//! evaluating their arguments if logging is not enabled for the level. The
-#define LogTrace(category, ...) LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__)
+//! macros accept an optional log source parameter followed by a printf-style
+//! format string and arguments.
+//!
+//! - LogError(), LogWarning(), and LogInfo() are all enabled by default, so
+//!   they should be called infrequently, in cases where they will not spam the
+//!   log and take up disk space.
+//!
+//! - LogDebug() is enabled when debug logging is enabled, and should be used to
+//!   show messages that can help users troubleshoot issues.
+//!
+//! - LogTrace() is enabled when both debug logging AND tracing are enabled, and
+//!   should be used for fine-grained traces that will be helpful to developers.
+//!
+//! For more information about log levels, see the -debug and -loglevel
+//! documentation, or the "Logging" section of developer notes.
+//!
+//! A source argument specifying a category can be specified as a first argument to
+//! all log macros, but it is optional:
+//!
+//!   LogDebug(BCLog::TXRECONCILIATION, "Forget txreconciliation state of peer=%d\n", peer_id);
+//!   LogInfo("Uncategorizable log information.\n");
+//!
+//! Source objects can also be declared to avoid repeating category constants:
+//!
+//!   const BCLog::Source m_log{BCLog::TXRECONCILIATION};
+//!   ...
+//!   LogDebug(m_log, "Forget txreconciliation state of peer=%d\n", peer_id);
+//!
+//! Using source objects also allows diverting log messages to a local logger
+//! instead of the global logging instance.
+#define LogError(...) _LogPrint(BCLog::Level::Error, __VA_ARGS__)
+#define LogWarning(...) _LogPrint(BCLog::Level::Warning, __VA_ARGS__)
+#define LogInfo(...) _LogPrint(BCLog::Level::Info, __VA_ARGS__)
+#define LogDebug(...) _LogPrint(BCLog::Level::Debug, __VA_ARGS__)
+#define LogTrace(...) _LogPrint(BCLog::Level::Trace, __VA_ARGS__)
+#define LogPrintLevel(source, level, ...) _LogPrint(level, source, __VA_ARGS__)
+
+//! Deprecated macros.
+#define LogPrintf(...) LogInfo(__VA_ARGS__)
 
 #endif // BITCOIN_LOGGING_H

src/test/logging_tests.cpp

@@ -76,6 +76,123 @@ struct LogSetup : public BasicTestingSetup {
     }
 };
 
+//! Test logging to local logger.
+BOOST_AUTO_TEST_CASE(logging_local_logger)
+{
+    BCLog::Logger logger;
+    logger.m_log_timestamps = false;
+    logger.EnableCategory(BCLog::LogFlags::ALL);
+    logger.SetLogLevel(BCLog::Level::Trace);
+    logger.StartLogging();
+
+    std::vector<std::string> messages;
+    logger.PushBackCallback([&](const std::string& s) { messages.push_back(s); });
+
+    BCLog::Source log{BCLog::NET, logger};
+    LogError(log, "error %s\n", "arg");
+    LogWarning(log, "warning %s\n", "arg");
+    LogInfo(log, "info %s\n", "arg");
+    LogDebug(log, "debug %s\n", "arg");
+    LogTrace(log, "trace %s\n", "arg");
+
+    constexpr auto expected{std::to_array({
+        "[net:error] error arg\n",
+        "[net:warning] warning arg\n",
+        "[net:info] info arg\n",
+        "[net] debug arg\n",
+        "[net:trace] trace arg\n",
+    })};
+    BOOST_CHECK_EQUAL_COLLECTIONS(messages.begin(), messages.end(), expected.begin(), expected.end());
+}
+
+//! Test logging to global logger with different types of source arguments.
+BOOST_FIXTURE_TEST_CASE(logging_source_args, LogSetup)
+{
+    LogInstance().EnableCategory(BCLog::LogFlags::ALL);
+    LogInstance().SetLogLevel(BCLog::Level::Trace);
+
+    // Test logging with no source arguments.
+    LogError("error\n");
+    LogWarning("warning\n");
+    LogInfo("info\n");
+    LogDebug("debug\n");
+    LogTrace("trace\n");
+    LogError("error %s\n", "arg");
+    LogWarning("warning %s\n", "arg");
+    LogInfo("info %s\n", "arg");
+    LogDebug("debug %s\n", "arg");
+    LogTrace("trace %s\n", "arg");
+
+    // Test logging with category arguments.
+    LogError(BCLog::NET, "error\n");
+    LogWarning(BCLog::NET, "warning\n");
+    LogInfo(BCLog::NET, "info\n");
+    LogDebug(BCLog::NET, "debug\n");
+    LogTrace(BCLog::NET, "trace\n");
+    LogError(BCLog::NET, "error %s\n", "arg");
+    LogWarning(BCLog::NET, "warning %s\n", "arg");
+    LogInfo(BCLog::NET, "info %s\n", "arg");
+    LogDebug(BCLog::NET, "debug %s\n", "arg");
+    LogTrace(BCLog::NET, "trace %s\n", "arg");
+
+    // Test logging with source object.
+    BCLog::Source log{BCLog::TOR};
+    LogError(log, "error\n");
+    LogWarning(log, "warning\n");
+    LogInfo(log, "info\n");
+    LogDebug(log, "debug\n");
+    LogTrace(log, "trace\n");
+    LogError(log, "error %s\n", "arg");
+    LogWarning(log, "warning %s\n", "arg");
+    LogInfo(log, "info %s\n", "arg");
+    LogDebug(log, "debug %s\n", "arg");
+    LogTrace(log, "trace %s\n", "arg");
+
+    constexpr auto expected{std::to_array({
+        "[error] error",
+        "[warning] warning",
+        "info",
+        "[debug] debug",
+        "[trace] trace",
+
+        "[error] error arg",
+        "[warning] warning arg",
+        "info arg",
+        "[debug] debug arg",
+        "[trace] trace arg",
+
+        "[net:error] error",
+        "[net:warning] warning",
+        "[net:info] info",
+        "[net] debug",
+        "[net:trace] trace",
+
+        "[net:error] error arg",
+        "[net:warning] warning arg",
+        "[net:info] info arg",
+        "[net] debug arg",
+        "[net:trace] trace arg",
+
+        "[tor:error] error",
+        "[tor:warning] warning",
+        "[tor:info] info",
+        "[tor] debug",
+        "[tor:trace] trace",
+
+        "[tor:error] error arg",
+        "[tor:warning] warning arg",
+        "[tor:info] info arg",
+        "[tor] debug arg",
+        "[tor:trace] trace arg",
+    })};
+    std::ifstream file{tmp_log_path};
+    std::vector<std::string> log_lines;
+    for (std::string log; std::getline(file, log);) {
+        log_lines.push_back(log);
+    }
+    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+}
+
 BOOST_AUTO_TEST_CASE(logging_timer)
 {
     auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");