diff --git a/src/logging.h b/src/logging.h index fdc12c79b32..7e8bd3b7bf6 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,81 @@ 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 Context { + Logger& logger; + LogFlags category; + + explicit Context(Logger& logger, LogFlags category = LogFlags::ALL) : logger{logger}, category{category} {} + + 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 detail { +//! Internal helper to get log context object from the first macro argument. +template +static const Context& GetContext(const Context& ctx LIFETIMEBOUND) { return ctx; } + +template +static Context GetContext(LogFlags category) +{ + //! Trigger a compile error if a caller tries to pass a category constant as + //! a source argument to a logging macro that specifies take_category == + //! false. There is no technical reason why all logging macros cannot accept + //! category arguments, but for various reasons, such as (1) not wanting to + //! allow users filter by category at high priority levels, and (2) wanting + //! to incentivize developers to use lower log levels to avoid log spam, + //! passing category constants at higher levels is forbidden. + static_assert(take_category, "Cannot pass BCLog::LogFlags category argument to high level Info/Warning/Error logging macros. Please use lower level Debug/Trace macro, or drop the category argument!"); + return Context{LogInstance(), category}; +} + +template +static Context GetContext(std::string_view fmt) +{ + //! Trigger a compile error if a caller forgets to pass a category constant + //! as a source argument to a logging macro that specifies take_category == + //! true. There is no technical reason why all logging macros could not + //! allow the category argument to be optional, but low priority level + //! macros should specify category in order to only be visible when the + //! selected category is enabled. This helps reduce log spam. + static_assert(!take_category, "Must pass category to Debug/Trace logging macros."); + return Context{LogInstance()}; +} + +//! Internal helper to format log arguments and call a logging function. +template +requires (!std::is_convertible_v) +void Format(LogFn&& log, Context&& ctx, ContextArg&&, util::ConstevalFormatString fmt, const Args&... args) +{ + log(ctx.Format(fmt, args...)); +} +template +void Format(LogFn&& log, Context&& ctx, util::ConstevalFormatString fmt, const Args&... args) +{ + log(ctx.Format(fmt, args...)); +} +} // namespace detail } // namespace BCLog -BCLog::Logger& LogInstance(); +//! Determine whether logging is enabled in a context at the specified level. +template +static inline bool LogEnabled(const Context& ctx, BCLog::Level level) +{ + return ctx.logger.WillLogCategoryLevel(ctx.category, level) && ctx.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 +322,65 @@ 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) -{ - 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); - } -} -#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) +//! Internal helper to return first arg in a __VA_ARGS__ pack. This could be +//! simplified to `#define FirstArg_(arg, ...) arg` if not for a preprocessor +//! bug in Visual C++. +#define FirstArg_Impl(arg, ...) arg +#define FirstArg_(args) FirstArg_Impl args -// 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 conditionally log. Only evaluates arguments when needed. +#define LogPrint_(level, take_category, ...) \ + do { \ + const auto& ctx{BCLog::detail::GetContext(FirstArg_((__VA_ARGS__)))}; \ + if (LogEnabled(ctx, (level))) { \ + const auto& func = __func__; \ + BCLog::detail::Format([&](auto&& message) { \ + ctx.logger.LogPrintStr(message, func, __FILE__, __LINE__, \ + ctx.category, (level)); \ + }, ctx, __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 context 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. +//! +//! `LogDebug` and `LogTrace` macros take an initial category argument, so +//! messages can be filtered by category, but categories should be omitted at +//! higher levels: +// +//! LogDebug(BCLog::TXRECONCILIATION, "Forget txreconciliation state of peer=%d\n", peer_id); +//! LogInfo("Important information, no category.\n"); +//! +//! Context arguments can also be passed to control log output (see class definition). +//! +//! const BCLog::Context m_log{BCLog::TXRECONCILIATION}; +//! ... +//! LogDebug(m_log, "Forget txreconciliation state of peer=%d\n", peer_id); +//! +#define LogError(...) LogPrint_(BCLog::Level::Error, false, __VA_ARGS__) +#define LogWarning(...) LogPrint_(BCLog::Level::Warning, false, __VA_ARGS__) +#define LogInfo(...) LogPrint_(BCLog::Level::Info, false, __VA_ARGS__) +#define LogDebug(...) LogPrint_(BCLog::Level::Debug, true, __VA_ARGS__) +#define LogTrace(...) LogPrint_(BCLog::Level::Trace, true, __VA_ARGS__) +#define LogPrintLevel(ctx, level, ...) LogPrint_(level, true, ctx, __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..cb6016e5ca3 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -76,6 +76,113 @@ 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::Context log{logger, BCLog::NET}; + 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 context arguments. +BOOST_FIXTURE_TEST_CASE(logging_context_args, LogSetup) +{ + LogInstance().EnableCategory(BCLog::LogFlags::ALL); + LogInstance().SetLogLevel(BCLog::Level::Trace); + + // Test logging with no context arguments. + LogError("error\n"); + LogWarning("warning\n"); + LogInfo("info\n"); + // LogDebug("debug\n"); // Not allowed because category is required! + // LogTrace("trace\n"); // Not allowed because category is required! + LogError("error %s\n", "arg"); + LogWarning("warning %s\n", "arg"); + LogInfo("info %s\n", "arg"); + // LogDebug("debug %s\n", "arg"); // Not allowed because category is required! + // LogTrace("trace %s\n", "arg"); // Not allowed because category is required! + + // Test logging with category constant arguments. + // LogError(BCLog::NET, "error\n"); // Not allowed because category is forbidden! + // LogWarning(BCLog::NET, "warning\n"); // Not allowed because category is forbidden! + // LogInfo(BCLog::NET, "info\n"); // Not allowed because category is forbidden! + LogDebug(BCLog::NET, "debug\n"); + LogTrace(BCLog::NET, "trace\n"); + // LogError(BCLog::NET, "error %s\n", "arg"); // Not allowed because category is forbidden! + // LogWarning(BCLog::NET, "warning %s\n", "arg"); // Not allowed because category is forbidden! + // LogInfo(BCLog::NET, "info %s\n", "arg"); // Not allowed because category is forbidden! + LogDebug(BCLog::NET, "debug %s\n", "arg"); + LogTrace(BCLog::NET, "trace %s\n", "arg"); + + // Test logging with context object. + BCLog::Context log{LogInstance(), 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", + + "[error] error arg", + "[warning] warning arg", + "info arg", + + "[net] debug", + "[net:trace] trace", + + "[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");