From f69d1ae56dbdf062ea7a39d6788378c77b621013 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Mon, 8 Dec 2025 22:29:39 +1000 Subject: [PATCH] util/log: Provide util::log::NO_RATE_LIMIT to avoid rate limits --- doc/developer-notes.md | 14 +++++++---- src/logging.cpp | 3 +-- src/logging.h | 1 - src/test/logging_tests.cpp | 2 +- src/util/log.h | 49 +++++++++++++++++++++++++------------- src/validation.cpp | 4 ++-- 6 files changed, 47 insertions(+), 26 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 18691811aa4..4738148d914 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -736,13 +736,12 @@ logging messages. They should be used as follows: most of the time, and it should be used for log messages that are useful for debugging and can reasonably be enabled on a production system (that has sufficient free storage space). They will be logged - if the program is started with `-debug=category` or `-debug=1`. + if the program is started with `-debug=category` or `-debug=1`, or + the category is enabled through the `logging` RPC. - `LogInfo(fmt, params...)` should only be used rarely, e.g. for startup messages or for infrequent and important events such as a new block tip - being found or a new outbound connection being made. These log messages - are unconditional, so care must be taken that they can't be used by an - attacker to fill up storage. + being found or a new outbound connection being made. - `LogError(fmt, params...)` should be used in place of `LogInfo` for severe problems that require the node (or a subsystem) to shut down @@ -764,6 +763,13 @@ Note that the format strings and parameters of `LogDebug` and `LogTrace` are only evaluated if the logging category is enabled, so you must be careful to avoid side-effects in those expressions. +While `LogInfo`, `LogWarning` and `LogError` messages should be rare, +in case there are circumstances where they are not, those messages +are automatically rate-limited to prevent potential disk-filling +attacks. For the cases where this protection is undesirable, +rate-limiting can be avoided with the `util::log::NO_RATE_LIMIT` tag, eg +`LogInfo(util::log::NO_RATE_LIMIT, "UpdateTip: new best=%s ...",...)`. + ## General C++ For general C++ guidelines, you may refer to the [C++ Core diff --git a/src/logging.cpp b/src/logging.cpp index 8f52312819c..0edc970df67 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -572,8 +572,7 @@ void BCLog::LogRateLimiter::Reset() } for (const auto& [source_loc, stats] : source_locations) { if (stats.m_dropped_bytes == 0) continue; - LogPrintLevel_( - LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false, + LogWarning(util::log::NO_RATE_LIMIT, "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.", source_loc.file_name(), source_loc.line(), source_loc.function_name_short(), stats.m_dropped_bytes, Ticks(m_reset_window)); diff --git a/src/logging.h b/src/logging.h index 4d40694278b..9ff1c7ea4d2 100644 --- a/src/logging.h +++ b/src/logging.h @@ -276,7 +276,6 @@ namespace BCLog { bool DefaultShrinkDebugFile() const; }; - } // namespace BCLog BCLog::Logger& LogInstance(); diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 37a43e9740c..550ef85cc4a 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -382,7 +382,7 @@ void LogFromLocation(Location location, const std::string& message) { LogDebug(BCLog::LogFlags::HTTP, "%s\n", message); return; case Location::INFO_NOLIMIT: - LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, "%s\n", message); + LogInfo(util::log::NO_RATE_LIMIT, "%s\n", message); return; } // no default case, so the compiler can warn about missing cases assert(false); diff --git a/src/util/log.h b/src/util/log.h index 9394161f61d..64df6373380 100644 --- a/src/util/log.h +++ b/src/util/log.h @@ -43,6 +43,12 @@ namespace util::log { /** Opaque to util::log; interpreted by consumers (e.g., BCLog::LogFlags). */ using Category = uint64_t; +//! Structure and constant for tagging not to rate limit. +struct NoRateLimitTag { + explicit NoRateLimitTag() = default; +}; +inline constexpr NoRateLimitTag NO_RATE_LIMIT{}; + enum class Level { Trace = 0, // High-volume or detailed logging for development/debugging Debug, // Reasonably noisy logging, but still usable in production @@ -68,15 +74,9 @@ bool ShouldLog(Category category, Level level); /** Send message to be logged. Applications using the logging library need to provide this. */ void Log(Entry entry); -} // namespace util::log - -namespace BCLog { -//! Alias for compatibility. Prefer util::log::Level over BCLog::Level in new code. -using Level = util::log::Level; -} // namespace BCLog template -inline void LogPrintFormatInternal(SourceLocation&& source_loc, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) +inline void LogPrintFormatInternal_(SourceLocation&& source_loc, BCLog::LogFlags flag, util::log::Level level, bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) { std::string log_msg; try { @@ -92,17 +92,35 @@ inline void LogPrintFormatInternal(SourceLocation&& source_loc, BCLog::LogFlags .message = std::move(log_msg)}); } +template +inline void LogPrintFormatInternal(SourceLocation&& source_loc, BCLog::LogFlags flag, util::log::Level level, util::ConstevalFormatString fmt, const Args&... args) +{ + return LogPrintFormatInternal_(std::move(source_loc), flag, level, /*should_ratelimit=*/true, fmt, args...); +} + +template +inline void LogPrintFormatInternal(SourceLocation&& source_loc, BCLog::LogFlags flag, util::log::Level level, util::log::NoRateLimitTag, util::ConstevalFormatString fmt, const Args&... args) +{ + return LogPrintFormatInternal_(std::move(source_loc), flag, level, /*should_ratelimit=*/false, fmt, args...); +} +} // namespace util::log + +namespace BCLog { +//! Alias for compatibility. Prefer util::log::Level over BCLog::Level in new code. +using Level = util::log::Level; +} // namespace BCLog + // Allow __func__ to be used in any context without warnings: // NOLINTNEXTLINE(bugprone-lambda-function-name) -#define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(SourceLocation{__func__}, category, level, should_ratelimit, __VA_ARGS__) +#define LogPrintLevel_(category, level, ...) util::log::LogPrintFormatInternal(SourceLocation{__func__}, category, level, __VA_ARGS__) // Log unconditionally. Uses basic rate limiting to mitigate disk filling attacks. // 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, /*should_ratelimit=*/true, __VA_ARGS__) -#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, /*should_ratelimit=*/true, __VA_ARGS__) -#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, /*should_ratelimit=*/true, __VA_ARGS__) +#define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, util::log::Level::Info, __VA_ARGS__) +#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, util::log::Level::Warning, __VA_ARGS__) +#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, util::log::Level::Error, __VA_ARGS__) // Use a macro instead of a function for conditional logging to prevent // evaluating arguments when logging for the category is not enabled. @@ -113,14 +131,13 @@ inline void LogPrintFormatInternal(SourceLocation&& source_loc, BCLog::LogFlags #define detail_LogIfCategoryAndLevelEnabled(category, level, ...) \ do { \ if (util::log::ShouldLog((category), (level))) { \ - bool rate_limit{level >= BCLog::Level::Info}; \ - Assume(!rate_limit); /*Only called with the levels below*/ \ - LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \ + Assume((level) < util::log::Level::Info); /*Only called with the levels below*/ \ + LogPrintLevel_((category), (level), util::log::NO_RATE_LIMIT, __VA_ARGS__); \ } \ } while (0) // Log conditionally, prefixing the output with the passed category name. -#define LogDebug(category, ...) detail_LogIfCategoryAndLevelEnabled(category, BCLog::Level::Debug, __VA_ARGS__) -#define LogTrace(category, ...) detail_LogIfCategoryAndLevelEnabled(category, BCLog::Level::Trace, __VA_ARGS__) +#define LogDebug(category, ...) detail_LogIfCategoryAndLevelEnabled(category, util::log::Level::Debug, __VA_ARGS__) +#define LogTrace(category, ...) detail_LogIfCategoryAndLevelEnabled(category, util::log::Level::Trace, __VA_ARGS__) #endif // BITCOIN_UTIL_LOG_H diff --git a/src/validation.cpp b/src/validation.cpp index f85a834f2a4..f7a4c87766e 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2864,8 +2864,8 @@ static void UpdateTipLog( AssertLockHeld(::cs_main); - // Disable rate limiting in LogPrintLevel_ so this source location may log during IBD. - LogPrintLevel_(BCLog::LogFlags::ALL, util::log::Level::Info, /*should_ratelimit=*/false, "%s%s: new best=%s height=%d version=0x%08x log2_work=%f tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)%s\n", + // Disable rate limiting as this may log frequently during IBD. + LogInfo(util::log::NO_RATE_LIMIT, "%s%s: new best=%s height=%d version=0x%08x log2_work=%f tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)%s\n", prefix, func_name, tip->GetBlockHash().ToString(), tip->nHeight, tip->nVersion, log(tip->nChainWork.getdouble()) / log(2.0), tip->m_chain_tx_count,