From 12d97dbdcbb73cb4a68ca4b52591bc9c7649d3cf Mon Sep 17 00:00:00 2001 From: Ryan Ofsky Date: Fri, 12 Jan 2024 16:52:05 -0500 Subject: [PATCH] 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 | 148 ++++++++++++++++++++++++++++--------- src/test/logging_tests.cpp | 117 +++++++++++++++++++++++++++++ 2 files changed, 229 insertions(+), 36 deletions(-) diff --git a/src/logging.h b/src/logging.h index fdc12c79b32..07be8e23b6d 100644 --- a/src/logging.h +++ b/src/logging.h @@ -6,6 +6,7 @@ #ifndef BITCOIN_LOGGING_H #define BITCOIN_LOGGING_H +#include #include #include #include @@ -21,6 +22,12 @@ #include #include +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 + std::string Format(util::ConstevalFormatString 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 +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 -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 fmt, const Args&... args) +//! Internal helper to get log source object from macro argument, if argument is +//! 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 +requires (!std::is_convertible_v) +void _LogFormat(LogFn&& log, Source&& source, SourceArg&&, util::ConstevalFormatString fmt, const Args&... args) { - if (LogInstance().Enabled()) { - 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; - } - LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line, flag, level); - } + log(source, source.Format(fmt, args...)); +} +template +void _LogFormat(LogFn&& log, Source&& source, util::ConstevalFormatString fmt, const Args&... args) +{ + log(source, source.Format(fmt, args...)); } -#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. -// Be conservative when using functions that unconditionally log to debug.log! -// It should not be the case that an inbound peer can fill up a user's storage -// with debug.log entries. -#define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__) -#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, __VA_ARGS__) -#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, __VA_ARGS__) - -// Deprecated unconditional logging. -#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__); \ - } \ +//! Internal helper to check level and log. Avoids evaluating arguments if not logging. +#define _LogPrint(level, ...) \ + do { \ + if (LogEnabled(_LogSource(_FirstArg(__VA_ARGS__)), (level))) { \ + const auto& func = __func__; \ + _LogFormat([&](auto&& source, auto&& message) { \ + source.logger.LogPrintStr(message, func, __FILE__, \ + __LINE__, source.category, (level)); \ + }, _LogSource(_FirstArg(__VA_ARGS__)), __VA_ARGS__); \ + } \ } while (0) -// Log conditionally, prefixing the output with the passed category name. -#define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) -#define LogTrace(category, ...) LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__) +//! Logging macros which output log messages at the specified levels, and avoid +//! evaluating their arguments if logging is not enabled for the level. The +//! 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 diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 77ec81e5977..74a676a9e95 100644 --- a/src/test/logging_tests.cpp +++ b/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 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 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("tests", "end_msg");