From 4987c035318536a76f3f5dd00beb417d8fb4b24c Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Thu, 5 Jun 2025 13:47:49 -0400 Subject: [PATCH 01/17] test: Mark ~DebugLogHelper as noexcept(false) We mark ~DebugLogHelper as noexcept(false) to be able to catch the exception it throws. This lets us use it in test in combination with BOOST_CHECK_THROW and BOOST_CHECK_NO_THROW to check that certain log messages are (not) logged. Co-Authored-By: Niklas Gogge Github-Pull: #32604 Rebased-From: df7972a6cfd919b972bcbba07de85f7797898529 --- src/test/util/logging.h | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/test/util/logging.h b/src/test/util/logging.h index 73ac23825f..5d7e4f91e0 100644 --- a/src/test/util/logging.h +++ b/src/test/util/logging.h @@ -33,7 +33,9 @@ class DebugLogHelper public: explicit DebugLogHelper(std::string message, MatchFn match = [](const std::string*){ return true; }); - ~DebugLogHelper() { check_found(); } + + //! Mark as noexcept(false) to catch any thrown exceptions. + ~DebugLogHelper() noexcept(false) { check_found(); } }; #define ASSERT_DEBUG_LOG(message) DebugLogHelper UNIQUE_NAME(debugloghelper)(message) From 41262cc4d53389ddadc59573e4eb246e085268ce Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Thu, 5 Jun 2025 12:19:28 -0400 Subject: [PATCH 02/17] log: introduce LogRateLimiter, LogLimitStats, Status LogRateLimiter will be used to keep track of source locations and our current time-based logging window. It contains an unordered_map and a m_suppressions_active bool to track source locations. The map is keyed by std::source_location, so a custom Hash function (SourceLocationHasher) and custom KeyEqual function (SourceLocationEqual) is provided. SourceLocationHasher uses CSipHasher(0,0) under the hood to get a uniform distribution. A public Reset method is provided so that a scheduler (e.g. the "b-scheduler" thread) can periodically reset LogRateLimiter's state when the time window has elapsed. The LogRateLimiter::Consume method checks if we have enough available bytes in our rate limiting budget to log an additional string. It returns a Status enum that denotes the rate limiting status and can be used by the caller to emit a warning, skip logging, etc. The Status enum has three states: - UNSUPPRESSED (logging was successful) - NEWLY_SUPPRESSED (logging was succcesful, next log will be suppressed) - STILL_SUPPRESSED (logging was unsuccessful) LogLimitStats counts the available bytes left for logging per source location for the current logging window. It does not track actual source locations; it is used as a value in m_source_locations. Also exposes a SuppressionsActive() method so the logger can use that in a later commit to prefix [*] to logs whenenever suppressions are active. Co-Authored-By: Niklas Gogge Co-Authored-By: stickies-v Github-Pull: #32604 Rebased-From: afb9e39ec5552e598a5febaa81820d5509b7c5d2 --- src/logging.cpp | 55 ++++++++++++++++++++++ src/logging.h | 95 ++++++++++++++++++++++++++++++++++++++ src/test/logging_tests.cpp | 77 ++++++++++++++++++++++++++++++ 3 files changed, 227 insertions(+) diff --git a/src/logging.cpp b/src/logging.cpp index 5f055566ef..eca6eac672 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -367,6 +367,30 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog) return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node)); } +BCLog::LogRateLimiter::LogRateLimiter( + SchedulerFunction scheduler_func, + uint64_t max_bytes, + std::chrono::seconds reset_window) : m_max_bytes{max_bytes}, m_reset_window{reset_window} +{ + scheduler_func([this] { Reset(); }, reset_window); +} + +BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume( + const std::source_location& source_loc, + const std::string& str) +{ + StdLockGuard scoped_lock(m_mutex); + auto& counter{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second}; + Status status{counter.GetDroppedBytes() > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED}; + + if (!counter.Consume(str.size()) && status == Status::UNSUPPRESSED) { + status = Status::NEWLY_SUPPRESSED; + m_suppression_active = true; + } + + return status; +} + void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const { if (!str.ends_with('\n')) str.push_back('\n'); @@ -492,6 +516,37 @@ void BCLog::Logger::ShrinkDebugFile() fclose(file); } +void BCLog::LogRateLimiter::Reset() +{ + decltype(m_source_locations) source_locations; + { + StdLockGuard scoped_lock(m_mutex); + source_locations.swap(m_source_locations); + m_suppression_active = false; + } + for (const auto& [source_loc, counter] : source_locations) { + uint64_t dropped_bytes{counter.GetDroppedBytes()}; + if (dropped_bytes == 0) continue; + LogPrintLevel_( + LogFlags::ALL, Level::Info, + "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.\n", + source_loc.file_name(), source_loc.line(), source_loc.function_name(), + dropped_bytes, Ticks(m_reset_window)); + } +} + +bool BCLog::LogLimitStats::Consume(uint64_t bytes) +{ + if (bytes > m_available_bytes) { + m_dropped_bytes += bytes; + m_available_bytes = 0; + return false; + } + + m_available_bytes -= bytes; + return true; +} + bool BCLog::Logger::SetLogLevel(std::string_view level_str) { const auto level = GetLogLevel(level_str); diff --git a/src/logging.h b/src/logging.h index fdc12c79b3..7411d33f5f 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 @@ -14,11 +15,14 @@ #include #include +#include #include #include #include +#include #include #include +#include #include static const bool DEFAULT_LOGTIMEMICROS = false; @@ -31,6 +35,24 @@ extern const char * const DEFAULT_DEBUGLOGFILE; extern bool fLogIPs; +struct SourceLocationEqual { + bool operator()(const std::source_location& lhs, const std::source_location& rhs) const noexcept + { + return lhs.line() == rhs.line() && std::string_view(lhs.file_name()) == std::string_view(rhs.file_name()); + } +}; + +struct SourceLocationHasher { + size_t operator()(const std::source_location& s) const noexcept + { + // Use CSipHasher(0, 0) as a simple way to get uniform distribution. + return static_cast(CSipHasher(0, 0) + .Write(std::hash{}(s.file_name())) + .Write(s.line()) + .Finalize()); + } +}; + struct LogCategory { std::string category; bool active; @@ -82,6 +104,79 @@ namespace BCLog { }; constexpr auto DEFAULT_LOG_LEVEL{Level::Debug}; constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging + constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes that can be logged within one window + + //! Keeps track of an individual source location and how many available bytes are left for logging from it. + class LogLimitStats + { + private: + //! Remaining bytes in the current window interval. + uint64_t m_available_bytes; + //! Number of bytes that were not consumed within the current window. + uint64_t m_dropped_bytes{0}; + + public: + LogLimitStats(uint64_t max_bytes) : m_available_bytes{max_bytes} {} + //! Consume bytes from the window if enough bytes are available. + //! + //! Returns whether enough bytes were available. + bool Consume(uint64_t bytes); + + uint64_t GetAvailableBytes() const + { + return m_available_bytes; + } + + uint64_t GetDroppedBytes() const + { + return m_dropped_bytes; + } + }; + + /** + * Fixed window rate limiter for logging. + */ + class LogRateLimiter + { + private: + mutable StdMutex m_mutex; + + //! Counters for each source location that has attempted to log something. + std::unordered_map m_source_locations GUARDED_BY(m_mutex); + //! True if at least one log location is suppressed. Cached view on m_source_locations for performance reasons. + std::atomic m_suppression_active{false}; + + public: + using SchedulerFunction = std::function, std::chrono::milliseconds)>; + /** + * @param scheduler_func Callable object used to schedule resetting the window. The first + * parameter is the function to be executed, and the second is the + * reset_window interval. + * @param max_bytes Maximum number of bytes that can be logged for each source + * location. + * @param reset_window Time window after which the byte counters are reset. + */ + LogRateLimiter(SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window); + //! Maximum number of bytes logged per location per window. + const uint64_t m_max_bytes; + //! Interval after which the window is reset. + const std::chrono::seconds m_reset_window; + //! Suppression status of a source log location. + enum class Status { + UNSUPPRESSED, // string fits within the limit + NEWLY_SUPPRESSED, // suppression has started since this string + STILL_SUPPRESSED, // suppression is still ongoing + }; + //! Consumes `source_loc`'s available bytes corresponding to the size of the (formatted) + //! `str` and returns its status. + [[nodiscard]] Status Consume( + const std::source_location& source_loc, + const std::string& str) EXCLUSIVE_LOCKS_REQUIRED(!m_mutex); + //! Resets all usage to zero. Called periodically by the scheduler. + void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex); + //! Returns true if any log locations are currently being suppressed. + bool SuppressionsActive() const { return m_suppression_active; } + }; class Logger { diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 77ec81e597..5d24ad771c 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -5,11 +5,13 @@ #include #include #include +#include #include #include #include #include +#include #include #include #include @@ -276,4 +278,79 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) } } +void MockForwardAndSync(CScheduler& scheduler, std::chrono::seconds duration) +{ + scheduler.MockForward(duration); + std::promise promise; + scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms); + promise.get_future().wait(); +} + +BOOST_AUTO_TEST_CASE(logging_log_rate_limiter) +{ + CScheduler scheduler{}; + scheduler.m_service_thread = std::thread([&scheduler] { scheduler.serviceQueue(); }); + uint64_t max_bytes{1024}; + auto reset_window{1min}; + auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }; + BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window}; + + using Status = BCLog::LogRateLimiter::Status; + auto source_loc_1{std::source_location::current()}; + auto source_loc_2{std::source_location::current()}; + + // A fresh limiter should not have any suppressions + BOOST_CHECK(!limiter.SuppressionsActive()); + + // Resetting an unused limiter is fine + limiter.Reset(); + BOOST_CHECK(!limiter.SuppressionsActive()); + + // No suppression should happen until more than max_bytes have been consumed + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes - 1, 'a')), Status::UNSUPPRESSED); + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::UNSUPPRESSED); + BOOST_CHECK(!limiter.SuppressionsActive()); + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::NEWLY_SUPPRESSED); + BOOST_CHECK(limiter.SuppressionsActive()); + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::STILL_SUPPRESSED); + BOOST_CHECK(limiter.SuppressionsActive()); + + // Location 2 should not be affected by location 1's suppression + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED); + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, "a"), Status::NEWLY_SUPPRESSED); + BOOST_CHECK(limiter.SuppressionsActive()); + + // After reset_window time has passed, all suppressions should be cleared. + MockForwardAndSync(scheduler, reset_window); + + BOOST_CHECK(!limiter.SuppressionsActive()); + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes, 'a')), Status::UNSUPPRESSED); + BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED); + + scheduler.stop(); +} + +BOOST_AUTO_TEST_CASE(logging_log_limit_stats) +{ + BCLog::LogLimitStats counter{BCLog::RATELIMIT_MAX_BYTES}; + + // Check that counter gets initialized correctly. + BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES); + BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull); + + const uint64_t MESSAGE_SIZE{512 * 1024}; + BOOST_CHECK(counter.Consume(MESSAGE_SIZE)); + BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE); + BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull); + + BOOST_CHECK(counter.Consume(MESSAGE_SIZE)); + BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2); + BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull); + + // Consuming more bytes after already having consumed 1MB should fail. + BOOST_CHECK(!counter.Consume(500)); + BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), 0ull); + BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 500ull); +} + BOOST_AUTO_TEST_SUITE_END() From a0992a842ed098ebcd5f955b232b9abb154d6f6e Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Thu, 5 Jun 2025 13:37:27 -0400 Subject: [PATCH 03/17] log: use std::source_location in place of __func__, __FILE__, __LINE__ The std::source_location conveniently stores the file name, line number, and function name of a source code location. We switch to using it instead of the __func__ identifier and the __FILE__ and __LINE__ macros. BufferedLog is changed to have a std::source_location member, replacing the source_file, source_line, and logging_function members. As a result, MemUsage no longer explicitly counts source_file or logging_function as the std::source_location memory usage is included in the MallocUsage call. This also changes the behavior of -logsourcelocations as std::source_location includes the entire function signature. Because of this, the functional test feature_config_args.py must be changed to no longer include the function signature as the function signature can differ across platforms. Co-Authored-By: Niklas Gogge Co-Authored-By: stickies-v Github-Pull: #32604 Rebased-From: a6a35cc0c23d0d529bfeb2f40d83d61f15ca7b40 --- src/logging.cpp | 38 +++++++++++++----------- src/logging.h | 16 +++++----- src/test/logging_tests.cpp | 41 +++++++++++++++++--------- test/functional/feature_config_args.py | 2 +- 4 files changed, 56 insertions(+), 41 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index eca6eac672..65cd993d7d 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -12,8 +12,10 @@ #include #include +#include #include #include +#include using util::Join; using util::RemovePrefixView; @@ -73,12 +75,12 @@ bool BCLog::Logger::StartLogging() // dump buffered messages from before we opened the log m_buffering = false; if (m_buffer_lines_discarded > 0) { - LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), __func__, __FILE__, __LINE__, BCLog::ALL, Level::Info); + LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info); } while (!m_msgs_before_open.empty()) { const auto& buflog = m_msgs_before_open.front(); std::string s{buflog.str}; - FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_file, buflog.source_line, buflog.logging_function, buflog.threadname, buflog.now, buflog.mocktime); + FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_loc, buflog.threadname, buflog.now, buflog.mocktime); m_msgs_before_open.pop_front(); if (m_print_to_file) FileWriteStr(s, m_fileout); @@ -364,7 +366,9 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog) { - return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node)); + return memusage::DynamicUsage(buflog.str) + + memusage::DynamicUsage(buflog.threadname) + + memusage::MallocUsage(sizeof(memusage::list_node)); } BCLog::LogRateLimiter::LogRateLimiter( @@ -391,14 +395,14 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume( return status; } -void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const +void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, const std::source_location& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const { if (!str.ends_with('\n')) str.push_back('\n'); str.insert(0, GetLogPrefix(category, level)); if (m_log_sourcelocations) { - str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_file, "./"), source_line, logging_function)); + str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name())); } if (m_log_threadnames) { @@ -408,28 +412,26 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego str.insert(0, LogTimestampStr(now, mocktime)); } -void BCLog::Logger::LogPrintStr(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) +void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) { StdLockGuard scoped_lock(m_cs); - return LogPrintStr_(str, logging_function, source_file, source_line, category, level); + return LogPrintStr_(str, std::move(source_loc), category, level); } -void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) +void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) { std::string str_prefixed = LogEscapeMessage(str); if (m_buffering) { { BufferedLog buf{ - .now=SystemClock::now(), - .mocktime=GetMockTime(), - .str=str_prefixed, - .logging_function=std::string(logging_function), - .source_file=std::string(source_file), - .threadname=util::ThreadGetInternalName(), - .source_line=source_line, - .category=category, - .level=level, + .now = SystemClock::now(), + .mocktime = GetMockTime(), + .str = str_prefixed, + .threadname = util::ThreadGetInternalName(), + .source_loc = std::move(source_loc), + .category = category, + .level = level, }; m_cur_buffer_memusage += MemUsage(buf); m_msgs_before_open.push_back(std::move(buf)); @@ -448,7 +450,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_ return; } - FormatLogStrInPlace(str_prefixed, category, level, source_file, source_line, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); + FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); if (m_print_to_console) { // print to console diff --git a/src/logging.h b/src/logging.h index 7411d33f5f..6ad6739adf 100644 --- a/src/logging.h +++ b/src/logging.h @@ -184,8 +184,8 @@ namespace BCLog { struct BufferedLog { SystemClock::time_point now; std::chrono::seconds mocktime; - std::string str, logging_function, source_file, threadname; - int source_line; + std::string str, threadname; + std::source_location source_loc; LogFlags category; Level level; }; @@ -210,7 +210,7 @@ namespace BCLog { /** Log categories bitfield. */ std::atomic m_categories{BCLog::NONE}; - void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const; + void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, const std::source_location& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const; std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const; @@ -218,7 +218,7 @@ namespace BCLog { std::list> m_print_callbacks GUARDED_BY(m_cs) {}; /** Send a string to the log output (internal) */ - void LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) EXCLUSIVE_LOCKS_REQUIRED(m_cs); std::string GetLogPrefix(LogFlags category, Level level) const; @@ -237,7 +237,7 @@ namespace BCLog { std::atomic m_reopen_file{false}; /** Send a string to the log output */ - void LogPrintStr(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns whether logs will be written to any output */ @@ -334,7 +334,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve 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) +inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; @@ -343,11 +343,11 @@ inline void LogPrintFormatInternal(std::string_view logging_function, std::strin } 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); + LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level); } } -#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) +#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(std::source_location::current(), category, level, __VA_ARGS__) // Log unconditionally. // Be conservative when using functions that unconditionally log to debug.log! diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 5d24ad771c..8cf0735b08 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -7,12 +7,16 @@ #include #include #include +#include +#include +#include #include #include #include #include #include +#include #include #include #include @@ -88,25 +92,34 @@ BOOST_AUTO_TEST_CASE(logging_timer) BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) { LogInstance().m_log_sourcelocations = true; - LogInstance().LogPrintStr("foo1: bar1", "fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug); - LogInstance().LogPrintStr("foo2: bar2", "fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info); - LogInstance().LogPrintStr("foo3: bar3", "fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug); - LogInstance().LogPrintStr("foo4: bar4", "fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info); - LogInstance().LogPrintStr("foo5: bar5", "fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug); - LogInstance().LogPrintStr("foo6: bar6", "fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info); + + struct Case { + std::string msg; + BCLog::LogFlags category; + BCLog::Level level; + std::string prefix; + std::source_location loc; + }; + + std::vector cases = { + {"foo1: bar1", BCLog::NET, BCLog::Level::Debug, "[net] ", std::source_location::current()}, + {"foo2: bar2", BCLog::NET, BCLog::Level::Info, "[net:info] ", std::source_location::current()}, + {"foo3: bar3", BCLog::ALL, BCLog::Level::Debug, "[debug] ", std::source_location::current()}, + {"foo4: bar4", BCLog::ALL, BCLog::Level::Info, "", std::source_location::current()}, + {"foo5: bar5", BCLog::NONE, BCLog::Level::Debug, "[debug] ", std::source_location::current()}, + {"foo6: bar6", BCLog::NONE, BCLog::Level::Info, "", std::source_location::current()}, + }; + + std::vector expected; + for (auto& [msg, category, level, prefix, loc] : cases) { + expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg)); + LogInstance().LogPrintStr(msg, std::move(loc), category, level); + } std::ifstream file{tmp_log_path}; std::vector log_lines; for (std::string log; std::getline(file, log);) { log_lines.push_back(log); } - std::vector expected = { - "[src1:1] [fn1] [net] foo1: bar1", - "[src2:2] [fn2] [net:info] foo2: bar2", - "[src3:3] [fn3] [debug] foo3: bar3", - "[src4:4] [fn4] foo4: bar4", - "[src5:5] [fn5] [debug] foo5: bar5", - "[src6:6] [fn6] foo6: bar6", - }; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py index c5e3c33b14..12a82ced9c 100755 --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -84,7 +84,7 @@ class ConfArgsTest(BitcoinTestFramework): self.log.debug('Verifying that disabling of the config file means garbage inside of it does ' \ 'not prevent the node from starting, and message about existing config file is logged') - ignored_file_message = [f'[InitConfig] Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.'] + ignored_file_message = [f'Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.'] with self.nodes[0].assert_debug_log(timeout=60, expected_msgs=ignored_file_message): self.start_node(0, extra_args=settings + ['-noconf']) self.stop_node(0) From 0b6b096421ac9d1c7b0542ea147562269e1c5bec Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Thu, 5 Jun 2025 13:42:03 -0400 Subject: [PATCH 04/17] log: Add rate limiting to LogPrintf, LogInfo, LogWarning, LogError, LogPrintLevel To mitigate disk-filling attacks caused by unsafe usages of LogPrintf and friends, we rate-limit them by passing a should_ratelimit bool that eventually makes its way to LogPrintStr which may call LogRateLimiter::Consume. The rate limiting is accomplished by adding a LogRateLimiter member to BCLog::Logger which tracks source code locations for the given logging window. Every hour, a source location can log up to 1MiB of data. Source locations that exceed the limit will have their logs suppressed for the rest of the window determined by m_limiter. This change affects the public LogPrintLevel function if called with a level >= BCLog::Level::Info. The UpdateTipLog function has been changed to use the private LogPrintLevel_ macro with should_ratelimit set to false. This allows UpdateTipLog to log during IBD without hitting the rate limit. Note that on restart, a source location that was rate limited before the restart will be able to log until it hits the rate limit again. Co-Authored-By: Niklas Gogge Co-Authored-By: stickies-v Github-Pull: #32604 Rebased-From: d541409a64c60d127ff912dad9dea949d45dbd8c --- src/init.cpp | 5 ++ src/logging.cpp | 35 +++++++++--- src/logging.h | 45 ++++++++++------ src/test/logging_tests.cpp | 107 ++++++++++++++++++++++++++++++++++++- src/validation.cpp | 20 +++---- 5 files changed, 181 insertions(+), 31 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index 7fdbf75dc6..0127fa3b45 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1384,6 +1384,11 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info) } }, std::chrono::minutes{5}); + LogInstance().SetRateLimiting(std::make_unique( + [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }, + BCLog::RATELIMIT_MAX_BYTES, + 1h)); + assert(!node.validation_signals); node.validation_signals = std::make_unique(std::make_unique(scheduler)); auto& validation_signals = *node.validation_signals; diff --git a/src/logging.cpp b/src/logging.cpp index 65cd993d7d..a090803652 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -75,7 +75,7 @@ bool BCLog::Logger::StartLogging() // dump buffered messages from before we opened the log m_buffering = false; if (m_buffer_lines_discarded > 0) { - LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info); + LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info, /*should_ratelimit=*/false); } while (!m_msgs_before_open.empty()) { const auto& buflog = m_msgs_before_open.front(); @@ -412,13 +412,14 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego str.insert(0, LogTimestampStr(now, mocktime)); } -void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) +void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) { StdLockGuard scoped_lock(m_cs); - return LogPrintStr_(str, std::move(source_loc), category, level); + return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit); } -void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) +// NOLINTNEXTLINE(misc-no-recursion) +void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) { std::string str_prefixed = LogEscapeMessage(str); @@ -451,6 +452,28 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so } FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); + bool ratelimit{false}; + if (should_ratelimit && m_limiter) { + auto status{m_limiter->Consume(source_loc, str_prefixed)}; + if (status == BCLog::LogRateLimiter::Status::NEWLY_SUPPRESSED) { + // NOLINTNEXTLINE(misc-no-recursion) + LogPrintStr_(strprintf( + "Excessive logging detected from %s:%d (%s): >%d bytes logged during " + "the last time window of %is. Suppressing logging to disk from this " + "source location until time window resets. Console logging " + "unaffected. Last log entry.\n", + source_loc.file_name(), source_loc.line(), source_loc.function_name(), + m_limiter->m_max_bytes, + Ticks(m_limiter->m_reset_window)), + std::source_location::current(), LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion + } + ratelimit = status == BCLog::LogRateLimiter::Status::STILL_SUPPRESSED; + // To avoid confusion caused by dropped log messages when debugging an issue, + // we prefix log lines with "[*]" when there are any suppressed source locations. + if (m_limiter->SuppressionsActive()) { + str_prefixed.insert(0, "[*] "); + } + } if (m_print_to_console) { // print to console @@ -460,7 +483,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so for (const auto& cb : m_print_callbacks) { cb(str_prefixed); } - if (m_print_to_file) { + if (m_print_to_file && !ratelimit) { assert(m_fileout != nullptr); // reopen the log file, if requested @@ -530,7 +553,7 @@ void BCLog::LogRateLimiter::Reset() uint64_t dropped_bytes{counter.GetDroppedBytes()}; if (dropped_bytes == 0) continue; LogPrintLevel_( - LogFlags::ALL, Level::Info, + LogFlags::ALL, Level::Info, /*should_ratelimit=*/false, "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.\n", source_loc.file_name(), source_loc.line(), source_loc.function_name(), dropped_bytes, Ticks(m_reset_window)); diff --git a/src/logging.h b/src/logging.h index 6ad6739adf..c801e94e28 100644 --- a/src/logging.h +++ b/src/logging.h @@ -200,6 +200,9 @@ namespace BCLog { size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0}; size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0}; + //! Manages the rate limiting of each log location. + std::unique_ptr m_limiter GUARDED_BY(m_cs); + //! Category-specific log level. Overrides `m_log_level`. std::unordered_map m_category_log_levels GUARDED_BY(m_cs); @@ -218,7 +221,7 @@ namespace BCLog { std::list> m_print_callbacks GUARDED_BY(m_cs) {}; /** Send a string to the log output (internal) */ - void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) EXCLUSIVE_LOCKS_REQUIRED(m_cs); std::string GetLogPrefix(LogFlags category, Level level) const; @@ -237,7 +240,7 @@ namespace BCLog { std::atomic m_reopen_file{false}; /** Send a string to the log output */ - void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns whether logs will be written to any output */ @@ -267,6 +270,12 @@ namespace BCLog { /** Only for testing */ void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); + void SetRateLimiting(std::unique_ptr&& limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) + { + StdLockGuard scoped_lock(m_cs); + m_limiter = std::move(limiter); + } + /** Disable logging * This offers a slight speedup and slightly smaller memory usage * compared to leaving the logging system in its default state. @@ -334,7 +343,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); template -inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString fmt, const Args&... args) +inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, const bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; @@ -343,19 +352,19 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLo } catch (tinyformat::format_error& fmterr) { log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt; } - LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level); + LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level, should_ratelimit); } } -#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(std::source_location::current(), category, level, __VA_ARGS__) +#define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) -// Log unconditionally. +// 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, __VA_ARGS__) -#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, __VA_ARGS__) -#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, __VA_ARGS__) +#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__) // Deprecated unconditional logging. #define LogPrintf(...) LogInfo(__VA_ARGS__) @@ -363,12 +372,18 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLo // 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__); \ - } \ +// Log by prefixing the output with the passed category name and severity level. This can either +// log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info +// is passed. If this function logs unconditionally, logging to disk is rate-limited. This is +// important so that callers don't need to worry about accidentally introducing a disk-fill +// vulnerability if level >= Info is used. Additionally, users specifying -debug are assumed to be +// developers or power users who are aware that -debug may cause excessive disk usage due to logging. +#define LogPrintLevel(category, level, ...) \ + do { \ + if (LogAcceptCategory((category), (level))) { \ + bool rate_limit{level >= BCLog::Level::Info}; \ + LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \ + } \ } while (0) // Log conditionally, prefixing the output with the passed category name. diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 8cf0735b08..f7f9ea175a 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include @@ -15,8 +16,10 @@ #include #include #include +#include #include #include +#include #include #include #include @@ -113,7 +116,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) std::vector expected; for (auto& [msg, category, level, prefix, loc] : cases) { expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg)); - LogInstance().LogPrintStr(msg, std::move(loc), category, level); + LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false); } std::ifstream file{tmp_log_path}; std::vector log_lines; @@ -366,4 +369,106 @@ BOOST_AUTO_TEST_CASE(logging_log_limit_stats) BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 500ull); } +void LogFromLocation(int location, std::string message) +{ + switch (location) { + case 0: + LogInfo("%s\n", message); + break; + case 1: + LogInfo("%s\n", message); + break; + case 2: + LogPrintLevel(BCLog::LogFlags::NONE, BCLog::Level::Info, "%s\n", message); + break; + case 3: + LogPrintLevel(BCLog::LogFlags::ALL, BCLog::Level::Info, "%s\n", message); + break; + } +} + +void LogFromLocationAndExpect(int location, std::string message, std::string expect) +{ + ASSERT_DEBUG_LOG(expect); + LogFromLocation(location, message); +} + +BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup) +{ + bool prev_log_timestamps = LogInstance().m_log_timestamps; + LogInstance().m_log_timestamps = false; + bool prev_log_sourcelocations = LogInstance().m_log_sourcelocations; + LogInstance().m_log_sourcelocations = false; + bool prev_log_threadnames = LogInstance().m_log_threadnames; + LogInstance().m_log_threadnames = false; + + CScheduler scheduler{}; + scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); }); + auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }; + auto limiter = std::make_unique(sched_func, 1024 * 1024, 20s); + LogInstance().SetRateLimiting(std::move(limiter)); + + // Log 1024-character lines (1023 plus newline) to make the math simple. + std::string log_message(1023, 'a'); + + std::string utf8_path{LogInstance().m_file_path.utf8string()}; + const char* log_path{utf8_path.c_str()}; + + // Use GetFileSize because fs::file_size may require a flush to be accurate. + std::streamsize log_file_size{static_cast(GetFileSize(log_path))}; + + // Logging 1 MiB should be allowed. + for (int i = 0; i < 1024; ++i) { + LogFromLocation(0, log_message); + } + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "should be able to log 1 MiB from location 0"); + + log_file_size = GetFileSize(log_path); + + BOOST_CHECK_NO_THROW(LogFromLocationAndExpect(0, log_message, "Excessive logging detected")); + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the start of the suppression period should be logged"); + + log_file_size = GetFileSize(log_path); + for (int i = 0; i < 1024; ++i) { + LogFromLocation(0, log_message); + } + + BOOST_CHECK_MESSAGE(log_file_size == GetFileSize(log_path), "all further logs from location 0 should be dropped"); + + BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Excessive logging detected"), std::runtime_error); + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 1 should be unaffected by other locations"); + + log_file_size = GetFileSize(log_path); + { + ASSERT_DEBUG_LOG("Restarting logging"); + MockForwardAndSync(scheduler, 1min); + } + + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the end of the suppression period should be logged"); + + BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Restarting logging"), std::runtime_error); + + // Attempt to log 1MiB from location 2 and 1MiB from location 3. These exempt locations should be allowed to log + // without limit. + log_file_size = GetFileSize(log_path); + for (int i = 0; i < 1024; ++i) { + BOOST_CHECK_THROW(LogFromLocationAndExpect(2, log_message, "Excessive logging detected"), std::runtime_error); + } + + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 2 should be exempt from rate limiting"); + + log_file_size = GetFileSize(log_path); + for (int i = 0; i < 1024; ++i) { + BOOST_CHECK_THROW(LogFromLocationAndExpect(3, log_message, "Excessive logging detected"), std::runtime_error); + } + + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 3 should be exempt from rate limiting"); + + LogInstance().m_log_timestamps = prev_log_timestamps; + LogInstance().m_log_sourcelocations = prev_log_sourcelocations; + LogInstance().m_log_threadnames = prev_log_threadnames; + scheduler.stop(); + LogInstance().SetRateLimiting(nullptr); +} + BOOST_AUTO_TEST_SUITE_END() diff --git a/src/validation.cpp b/src/validation.cpp index a1ac4e1e14..fde064458d 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2995,15 +2995,17 @@ static void UpdateTipLog( { AssertLockHeld(::cs_main); - LogPrintf("%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, - FormatISO8601DateTime(tip->GetBlockTime()), - chainman.GuessVerificationProgress(tip), - coins_tip.DynamicMemoryUsage() * (1.0 / (1 << 20)), - coins_tip.GetCacheSize(), - !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages) : ""); + + // Disable rate limiting in LogPrintLevel_ so this source location may log during IBD. + LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::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", + prefix, func_name, + tip->GetBlockHash().ToString(), tip->nHeight, tip->nVersion, + log(tip->nChainWork.getdouble()) / log(2.0), tip->m_chain_tx_count, + FormatISO8601DateTime(tip->GetBlockTime()), + chainman.GuessVerificationProgress(tip), + coins_tip.DynamicMemoryUsage() * (1.0 / (1 << 20)), + coins_tip.GetCacheSize(), + !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages) : ""); } void Chainstate::UpdateTip(const CBlockIndex* pindexNew) From 24c793d06c93768be88e9f8d0bb62936e199f68c Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Mon, 23 Jun 2025 15:57:44 -0400 Subject: [PATCH 05/17] doc: add release notes for new rate limiting logging behavior Github-Pull: #32604 Rebased-From: 4c772cbd83e502a1339e8993d192ea6416ecd45c --- doc/release-notes.md | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/doc/release-notes.md b/doc/release-notes.md index e4cf2f0b50..b384763e15 100644 --- a/doc/release-notes.md +++ b/doc/release-notes.md @@ -48,6 +48,17 @@ Notable changes - #32521 policy: make pathological transactions packed with legacy sigops non-standard +### Logging + +Unconditional logging to disk is now rate limited by giving each source location +a quota of 1MiB per hour. Unconditional logging is any logging with a log level +higher than debug, that is `info`, `warning`, and `error`. All logs will be +prefixed with `[*]` if there is at least one source location that is currently +being suppressed. (#32604) + +When `-logsourcelocations` is enabled, the log output now contains the entire +function signature instead of just the function name. (#32604) + ### RPC - The `dumptxoutset` RPC now requires a `type` parameter to be specified. To maintain pre @@ -163,6 +174,7 @@ Thanks to everyone who directly contributed to this release: - brunoerg - Bufo - Christewart +- Crypt-iQ - davidgumberg - deadmanoz - dergoegge From 25f975b8df8ac4692cdfe9c423f2903e97f34a2c Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 09:27:50 -0400 Subject: [PATCH 06/17] test: remove noexcept(false) comment in ~DebugLogHelper Github-Pull: #33011 Rebased-From: 616bc22f131132b9239ef362dca8c6bce000a539 --- src/test/util/logging.h | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/test/util/logging.h b/src/test/util/logging.h index 5d7e4f91e0..62b11c2841 100644 --- a/src/test/util/logging.h +++ b/src/test/util/logging.h @@ -33,8 +33,6 @@ class DebugLogHelper public: explicit DebugLogHelper(std::string message, MatchFn match = [](const std::string*){ return true; }); - - //! Mark as noexcept(false) to catch any thrown exceptions. ~DebugLogHelper() noexcept(false) { check_found(); } }; From 9cde68fa984571d68177152af0a029b43fef7bab Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 25 Jul 2025 16:39:33 -0400 Subject: [PATCH 07/17] log: avoid double hashing in SourceLocationHasher Co-Authored-By: l0rinc Github-Pull: #33011 Rebased-From: b8e92fb3d4137f91fe6a54829867fc54357da648 --- src/logging.h | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/logging.h b/src/logging.h index c801e94e28..33742dcbe6 100644 --- a/src/logging.h +++ b/src/logging.h @@ -46,10 +46,10 @@ struct SourceLocationHasher { size_t operator()(const std::source_location& s) const noexcept { // Use CSipHasher(0, 0) as a simple way to get uniform distribution. - return static_cast(CSipHasher(0, 0) - .Write(std::hash{}(s.file_name())) - .Write(s.line()) - .Finalize()); + return size_t(CSipHasher(0, 0) + .Write(s.line()) + .Write(MakeUCharSpan(std::string_view{s.file_name()})) + .Finalize()); } }; From 273ffda2c878954f30554bb88d286896d1177add Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 09:43:43 -0400 Subject: [PATCH 08/17] log: remove const qualifier from arguments in LogPrintFormatInternal Co-Authored-By: l0rinc Github-Pull: #33011 Rebased-From: 5f70bc80df06ca85d44e8201d47e7086e971fdea --- src/logging.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/logging.h b/src/logging.h index 33742dcbe6..c753172545 100644 --- a/src/logging.h +++ b/src/logging.h @@ -343,7 +343,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); template -inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, const bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) +inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; From dfe4e19f66e0acd4f14f726f29aeb6ef7d8506c4 Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 10:04:35 -0400 Subject: [PATCH 09/17] log: clarify RATELIMIT_MAX_BYTES comment, use RATELIMIT_WINDOW Co-Authored-By: stickies-v Github-Pull: #33011 Rebased-From: 8319a134684df2240057a5e8afaa6ae441fb8a58 --- src/init.cpp | 2 +- src/logging.h | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index 0127fa3b45..9e9cb5d732 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1387,7 +1387,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info) LogInstance().SetRateLimiting(std::make_unique( [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }, BCLog::RATELIMIT_MAX_BYTES, - 1h)); + BCLog::RATELIMIT_WINDOW)); assert(!node.validation_signals); node.validation_signals = std::make_unique(std::make_unique(scheduler)); diff --git a/src/logging.h b/src/logging.h index c753172545..106de1f8d3 100644 --- a/src/logging.h +++ b/src/logging.h @@ -104,7 +104,8 @@ namespace BCLog { }; constexpr auto DEFAULT_LOG_LEVEL{Level::Debug}; constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging - constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes that can be logged within one window + constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW + constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset //! Keeps track of an individual source location and how many available bytes are left for logging from it. class LogLimitStats From 7c3820ff63d91c9f5173e514d74814a34e647bdb Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 10:18:59 -0400 Subject: [PATCH 10/17] log: change LogLimitStats to struct LogRateLimiter::Stats Clean up the noisy LogLimitStats and remove references to the time window. Co-Authored-By: stickies-v Github-Pull: #33011 Rebased-From: 3c7cae49b692bb6bf5cae5ee23479091bed0b8be --- src/logging.cpp | 15 +++++------ src/logging.h | 52 +++++++++++++------------------------- src/test/logging_tests.cpp | 30 +++++++++++----------- 3 files changed, 40 insertions(+), 57 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index a090803652..befac8a03f 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -384,10 +384,10 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume( const std::string& str) { StdLockGuard scoped_lock(m_mutex); - auto& counter{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second}; - Status status{counter.GetDroppedBytes() > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED}; + auto& stats{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second}; + Status status{stats.m_dropped_bytes > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED}; - if (!counter.Consume(str.size()) && status == Status::UNSUPPRESSED) { + if (!stats.Consume(str.size()) && status == Status::UNSUPPRESSED) { status = Status::NEWLY_SUPPRESSED; m_suppression_active = true; } @@ -549,18 +549,17 @@ void BCLog::LogRateLimiter::Reset() source_locations.swap(m_source_locations); m_suppression_active = false; } - for (const auto& [source_loc, counter] : source_locations) { - uint64_t dropped_bytes{counter.GetDroppedBytes()}; - if (dropped_bytes == 0) continue; + for (const auto& [source_loc, stats] : source_locations) { + if (stats.m_dropped_bytes == 0) continue; LogPrintLevel_( LogFlags::ALL, Level::Info, /*should_ratelimit=*/false, "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.\n", source_loc.file_name(), source_loc.line(), source_loc.function_name(), - dropped_bytes, Ticks(m_reset_window)); + stats.m_dropped_bytes, Ticks(m_reset_window)); } } -bool BCLog::LogLimitStats::Consume(uint64_t bytes) +bool BCLog::LogRateLimiter::Stats::Consume(uint64_t bytes) { if (bytes > m_available_bytes) { m_dropped_bytes += bytes; diff --git a/src/logging.h b/src/logging.h index 106de1f8d3..04e6e0974c 100644 --- a/src/logging.h +++ b/src/logging.h @@ -107,44 +107,28 @@ namespace BCLog { constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset - //! Keeps track of an individual source location and how many available bytes are left for logging from it. - class LogLimitStats - { - private: - //! Remaining bytes in the current window interval. - uint64_t m_available_bytes; - //! Number of bytes that were not consumed within the current window. - uint64_t m_dropped_bytes{0}; - - public: - LogLimitStats(uint64_t max_bytes) : m_available_bytes{max_bytes} {} - //! Consume bytes from the window if enough bytes are available. - //! - //! Returns whether enough bytes were available. - bool Consume(uint64_t bytes); - - uint64_t GetAvailableBytes() const - { - return m_available_bytes; - } - - uint64_t GetDroppedBytes() const - { - return m_dropped_bytes; - } - }; - - /** - * Fixed window rate limiter for logging. - */ + //! Fixed window rate limiter for logging. class LogRateLimiter { + public: + //! Keeps track of an individual source location and how many available bytes are left for logging from it. + struct Stats { + //! Remaining bytes + uint64_t m_available_bytes; + //! Number of bytes that were consumed but didn't fit in the available bytes. + uint64_t m_dropped_bytes{0}; + + Stats(uint64_t max_bytes) : m_available_bytes{max_bytes} {} + //! Updates internal accounting and returns true if enough available_bytes were remaining + bool Consume(uint64_t bytes); + }; + private: mutable StdMutex m_mutex; - //! Counters for each source location that has attempted to log something. - std::unordered_map m_source_locations GUARDED_BY(m_mutex); - //! True if at least one log location is suppressed. Cached view on m_source_locations for performance reasons. + //! Stats for each source location that has attempted to log something. + std::unordered_map m_source_locations GUARDED_BY(m_mutex); + //! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons. std::atomic m_suppression_active{false}; public: @@ -155,7 +139,7 @@ namespace BCLog { * reset_window interval. * @param max_bytes Maximum number of bytes that can be logged for each source * location. - * @param reset_window Time window after which the byte counters are reset. + * @param reset_window Time window after which the stats are reset. */ LogRateLimiter(SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window); //! Maximum number of bytes logged per location per window. diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index f7f9ea175a..3fd6647024 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -348,25 +348,25 @@ BOOST_AUTO_TEST_CASE(logging_log_rate_limiter) BOOST_AUTO_TEST_CASE(logging_log_limit_stats) { - BCLog::LogLimitStats counter{BCLog::RATELIMIT_MAX_BYTES}; + BCLog::LogRateLimiter::Stats stats(BCLog::RATELIMIT_MAX_BYTES); - // Check that counter gets initialized correctly. - BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES); - BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull); + // Check that stats gets initialized correctly. + BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES); + BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0}); - const uint64_t MESSAGE_SIZE{512 * 1024}; - BOOST_CHECK(counter.Consume(MESSAGE_SIZE)); - BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE); - BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull); + const uint64_t MESSAGE_SIZE{BCLog::RATELIMIT_MAX_BYTES / 2}; + BOOST_CHECK(stats.Consume(MESSAGE_SIZE)); + BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE); + BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0}); - BOOST_CHECK(counter.Consume(MESSAGE_SIZE)); - BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2); - BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull); + BOOST_CHECK(stats.Consume(MESSAGE_SIZE)); + BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2); + BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0}); - // Consuming more bytes after already having consumed 1MB should fail. - BOOST_CHECK(!counter.Consume(500)); - BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), 0ull); - BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 500ull); + // Consuming more bytes after already having consumed RATELIMIT_MAX_BYTES should fail. + BOOST_CHECK(!stats.Consume(500)); + BOOST_CHECK_EQUAL(stats.m_available_bytes, uint64_t{0}); + BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{500}); } void LogFromLocation(int location, std::string message) From 81751341e9b5582fc5645ff88c5dd67cbd09cf43 Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 10:39:45 -0400 Subject: [PATCH 11/17] log: clean up LogPrintStr_ and Reset, prefix all logs with "[*]" when there are suppressions In LogPrintStr_: - remove an unnecessary BCLog since we are in the BCLog namespace. - remove an unnecessary \n when rate limiting is triggered since FormatLogStrInPlace will add it. - move the ratelimit bool into an else if block. - prefix all log lines with [*] when suppressions exist. Previously this was only done if should_ratelimit was true. In Reset: - remove an unnecessary \n since FormatLogStrInPlace will add it. - Change Level::Info to Level::Warning. Github-Pull: #33011 Rebased-From: e8f9c37a3b4c9c88baddb556c4b33a4cbba1f614 --- src/logging.cpp | 22 ++++++++++++---------- 1 file changed, 12 insertions(+), 10 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index befac8a03f..0cad290504 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -455,24 +455,26 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so bool ratelimit{false}; if (should_ratelimit && m_limiter) { auto status{m_limiter->Consume(source_loc, str_prefixed)}; - if (status == BCLog::LogRateLimiter::Status::NEWLY_SUPPRESSED) { + if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) { // NOLINTNEXTLINE(misc-no-recursion) LogPrintStr_(strprintf( "Excessive logging detected from %s:%d (%s): >%d bytes logged during " "the last time window of %is. Suppressing logging to disk from this " "source location until time window resets. Console logging " - "unaffected. Last log entry.\n", + "unaffected. Last log entry.", source_loc.file_name(), source_loc.line(), source_loc.function_name(), m_limiter->m_max_bytes, Ticks(m_limiter->m_reset_window)), std::source_location::current(), LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion + } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) { + ratelimit = true; } - ratelimit = status == BCLog::LogRateLimiter::Status::STILL_SUPPRESSED; - // To avoid confusion caused by dropped log messages when debugging an issue, - // we prefix log lines with "[*]" when there are any suppressed source locations. - if (m_limiter->SuppressionsActive()) { - str_prefixed.insert(0, "[*] "); - } + } + + // To avoid confusion caused by dropped log messages when debugging an issue, + // we prefix log lines with "[*]" when there are any suppressed source locations. + if (m_limiter && m_limiter->SuppressionsActive()) { + str_prefixed.insert(0, "[*] "); } if (m_print_to_console) { @@ -552,8 +554,8 @@ void BCLog::LogRateLimiter::Reset() for (const auto& [source_loc, stats] : source_locations) { if (stats.m_dropped_bytes == 0) continue; LogPrintLevel_( - LogFlags::ALL, Level::Info, /*should_ratelimit=*/false, - "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.\n", + LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false, + "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(), stats.m_dropped_bytes, Ticks(m_reset_window)); } From acfa83d9d000abd263d8cb5ac3355cfd8cf49ec0 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Wed, 23 Jul 2025 22:06:37 +0100 Subject: [PATCH 12/17] log: make m_limiter a shared_ptr This allows us to safely and explicitly manage the dual dependency on the limiter: one for the Logger, and one for the CScheduler. Github-Pull: #33011 Rebased-From: 3d630c2544e19480268426cda245796d4ce34ac3 --- src/init.cpp | 2 +- src/logging.cpp | 17 ++++++++++++----- src/logging.h | 11 ++++++++--- src/test/logging_tests.cpp | 8 +++++--- 4 files changed, 26 insertions(+), 12 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index 9e9cb5d732..fa7ac6077d 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1384,7 +1384,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info) } }, std::chrono::minutes{5}); - LogInstance().SetRateLimiting(std::make_unique( + LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create( [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }, BCLog::RATELIMIT_MAX_BYTES, BCLog::RATELIMIT_WINDOW)); diff --git a/src/logging.cpp b/src/logging.cpp index 0cad290504..2ed6835197 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -371,12 +371,19 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog) memusage::MallocUsage(sizeof(memusage::list_node)); } -BCLog::LogRateLimiter::LogRateLimiter( - SchedulerFunction scheduler_func, - uint64_t max_bytes, - std::chrono::seconds reset_window) : m_max_bytes{max_bytes}, m_reset_window{reset_window} +BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window) + : m_max_bytes{max_bytes}, m_reset_window{reset_window} {} + +std::shared_ptr BCLog::LogRateLimiter::Create( + SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window) { - scheduler_func([this] { Reset(); }, reset_window); + auto limiter{std::shared_ptr(new LogRateLimiter(max_bytes, reset_window))}; + std::weak_ptr weak_limiter{limiter}; + auto reset = [weak_limiter] { + if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset(); + }; + scheduler_func(reset, limiter->m_reset_window); + return limiter; } BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume( diff --git a/src/logging.h b/src/logging.h index 04e6e0974c..9419e245bd 100644 --- a/src/logging.h +++ b/src/logging.h @@ -18,6 +18,7 @@ #include #include #include +#include #include #include #include @@ -130,6 +131,7 @@ namespace BCLog { std::unordered_map m_source_locations GUARDED_BY(m_mutex); //! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons. std::atomic m_suppression_active{false}; + LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window); public: using SchedulerFunction = std::function, std::chrono::milliseconds)>; @@ -141,7 +143,10 @@ namespace BCLog { * location. * @param reset_window Time window after which the stats are reset. */ - LogRateLimiter(SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window); + static std::shared_ptr Create( + SchedulerFunction&& scheduler_func, + uint64_t max_bytes, + std::chrono::seconds reset_window); //! Maximum number of bytes logged per location per window. const uint64_t m_max_bytes; //! Interval after which the window is reset. @@ -186,7 +191,7 @@ namespace BCLog { size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0}; //! Manages the rate limiting of each log location. - std::unique_ptr m_limiter GUARDED_BY(m_cs); + std::shared_ptr m_limiter GUARDED_BY(m_cs); //! Category-specific log level. Overrides `m_log_level`. std::unordered_map m_category_log_levels GUARDED_BY(m_cs); @@ -255,7 +260,7 @@ namespace BCLog { /** Only for testing */ void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); - void SetRateLimiting(std::unique_ptr&& limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) + void SetRateLimiting(std::shared_ptr limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) { StdLockGuard scoped_lock(m_cs); m_limiter = std::move(limiter); diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 3fd6647024..41c0b1dd32 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -69,6 +69,7 @@ struct LogSetup : public BasicTestingSetup { LogInstance().SetLogLevel(BCLog::Level::Debug); LogInstance().SetCategoryLogLevel({}); + LogInstance().SetRateLimiting(nullptr); } ~LogSetup() @@ -82,6 +83,7 @@ struct LogSetup : public BasicTestingSetup { LogInstance().m_log_sourcelocations = prev_log_sourcelocations; LogInstance().SetLogLevel(prev_log_level); LogInstance().SetCategoryLogLevel(prev_category_levels); + LogInstance().SetRateLimiting(nullptr); } }; @@ -309,7 +311,8 @@ BOOST_AUTO_TEST_CASE(logging_log_rate_limiter) uint64_t max_bytes{1024}; auto reset_window{1min}; auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }; - BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window}; + auto limiter_{BCLog::LogRateLimiter::Create(sched_func, max_bytes, reset_window)}; + auto& limiter{*limiter_}; using Status = BCLog::LogRateLimiter::Status; auto source_loc_1{std::source_location::current()}; @@ -405,8 +408,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup) CScheduler scheduler{}; scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); }); auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }; - auto limiter = std::make_unique(sched_func, 1024 * 1024, 20s); - LogInstance().SetRateLimiting(std::move(limiter)); + LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(sched_func, 1024 * 1024, 20s)); // Log 1024-character lines (1023 plus newline) to make the math simple. std::string log_message(1023, 'a'); From 4ed7a51642dfa83159be7207c158dc7544d35f65 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Wed, 23 Jul 2025 22:29:01 +0100 Subject: [PATCH 13/17] test: add ReadDebugLogLines helper function Deduplicates repeated usage of the same functionality. Github-Pull: #33011 Rebased-From: 05d7c22479bf96bab9f8c8b8fa90368429ad2c88 --- src/test/logging_tests.cpp | 40 ++++++++++++++------------------------ 1 file changed, 15 insertions(+), 25 deletions(-) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 41c0b1dd32..bb898eb141 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -37,6 +37,16 @@ static void ResetLogger() LogInstance().SetCategoryLogLevel({}); } +static std::vector ReadDebugLogLines() +{ + std::vector lines; + std::ifstream ifs{LogInstance().m_file_path}; + for (std::string line; std::getline(ifs, line);) { + lines.push_back(std::move(line)); + } + return lines; +} + struct LogSetup : public BasicTestingSetup { fs::path prev_log_path; fs::path tmp_log_path; @@ -120,11 +130,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg)); LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false); } - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{ReadDebugLogLines()}; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } @@ -136,11 +142,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup) LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8"); LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9"); LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10"); - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{ReadDebugLogLines()}; std::vector expected = { "foo5: bar5", "[net] foo7: bar7", @@ -158,11 +160,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) LogInfo("foo8: %s", "bar8"); LogWarning("foo9: %s", "bar9"); LogError("foo10: %s", "bar10"); - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{ReadDebugLogLines()}; std::vector expected = { "[net] foo7: bar7", "foo8: bar8", @@ -194,11 +192,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) expected.push_back(expected_log); } - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{ReadDebugLogLines()}; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } @@ -227,11 +221,7 @@ BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup) "[net:warning] foo5: bar5", "[net:error] foo7: bar7", }; - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{ReadDebugLogLines()}; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } From 11538160b3d9a44990ac2c3a766764198a7e9127 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Thu, 31 Jul 2025 12:18:06 +0100 Subject: [PATCH 14/17] test: don't leak log category mask across tests This ensures log tests behave consistently when other tests modify the log category mask. Github-Pull: #33011 Rebased-From: 350193e5e2efabb3eb66197b91869b946ec5428c --- src/test/logging_tests.cpp | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index bb898eb141..f3100dac9b 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -57,6 +57,7 @@ struct LogSetup : public BasicTestingSetup { bool prev_log_sourcelocations; std::unordered_map prev_category_levels; BCLog::Level prev_log_level; + BCLog::CategoryMask prev_category_mask; LogSetup() : prev_log_path{LogInstance().m_file_path}, tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"}, @@ -66,7 +67,8 @@ struct LogSetup : public BasicTestingSetup { prev_log_threadnames{LogInstance().m_log_threadnames}, prev_log_sourcelocations{LogInstance().m_log_sourcelocations}, prev_category_levels{LogInstance().CategoryLevels()}, - prev_log_level{LogInstance().LogLevel()} + prev_log_level{LogInstance().LogLevel()}, + prev_category_mask{LogInstance().GetCategoryMask()} { LogInstance().m_file_path = tmp_log_path; LogInstance().m_reopen_file = true; @@ -78,6 +80,7 @@ struct LogSetup : public BasicTestingSetup { LogInstance().m_log_sourcelocations = false; LogInstance().SetLogLevel(BCLog::Level::Debug); + LogInstance().DisableCategory(BCLog::LogFlags::ALL); LogInstance().SetCategoryLogLevel({}); LogInstance().SetRateLimiting(nullptr); } @@ -94,6 +97,8 @@ struct LogSetup : public BasicTestingSetup { LogInstance().SetLogLevel(prev_log_level); LogInstance().SetCategoryLogLevel(prev_category_levels); LogInstance().SetRateLimiting(nullptr); + LogInstance().DisableCategory(BCLog::LogFlags::ALL); + LogInstance().EnableCategory(BCLog::LogFlags{prev_category_mask}); } }; @@ -136,6 +141,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup) { + LogInstance().EnableCategory(BCLog::NET); LogPrintf("foo5: %s\n", "bar5"); LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo4: %s\n", "bar4"); // not logged LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7"); @@ -155,6 +161,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) { + LogInstance().EnableCategory(BCLog::NET); LogTrace(BCLog::NET, "foo6: %s", "bar6"); // not logged LogDebug(BCLog::NET, "foo7: %s", "bar7"); LogInfo("foo8: %s", "bar8"); @@ -199,8 +206,6 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup) { LogInstance().EnableCategory(BCLog::LogFlags::ALL); - - LogInstance().SetLogLevel(BCLog::Level::Debug); LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info"); // Global log level From dfdd407c428030171213496c0cc2f30517bb86a1 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Wed, 23 Jul 2025 22:30:07 +0100 Subject: [PATCH 15/17] test: logging_filesize_rate_limit improvements - Add helper functions and structs to improve readability and reusability of test code - Make tests more specific by comparing all produced log lines with expected log lines instead of relying on approximations or proxies. Github-Pull: #33011 Rebased-From: 9f3b017bcc067bba1d1682a5d4e65b5450dc10c4 --- src/test/logging_tests.cpp | 205 ++++++++++++++++++++----------------- 1 file changed, 111 insertions(+), 94 deletions(-) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index f3100dac9b..e208ea4692 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -291,23 +291,40 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) } } -void MockForwardAndSync(CScheduler& scheduler, std::chrono::seconds duration) -{ - scheduler.MockForward(duration); - std::promise promise; - scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms); - promise.get_future().wait(); -} +struct ScopedScheduler { + CScheduler scheduler{}; + + ScopedScheduler() + { + scheduler.m_service_thread = std::thread([this] { scheduler.serviceQueue(); }); + } + ~ScopedScheduler() + { + scheduler.stop(); + } + void MockForwardAndSync(std::chrono::seconds duration) + { + scheduler.MockForward(duration); + std::promise promise; + scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms); + promise.get_future().wait(); + } + std::shared_ptr GetLimiter(size_t max_bytes, std::chrono::seconds window) + { + auto sched_func = [this](auto func, auto w) { + scheduler.scheduleEvery(std::move(func), w); + }; + return BCLog::LogRateLimiter::Create(sched_func, max_bytes, window); + } +}; BOOST_AUTO_TEST_CASE(logging_log_rate_limiter) { - CScheduler scheduler{}; - scheduler.m_service_thread = std::thread([&scheduler] { scheduler.serviceQueue(); }); uint64_t max_bytes{1024}; auto reset_window{1min}; - auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }; - auto limiter_{BCLog::LogRateLimiter::Create(sched_func, max_bytes, reset_window)}; - auto& limiter{*limiter_}; + ScopedScheduler scheduler{}; + auto limiter_{scheduler.GetLimiter(max_bytes, reset_window)}; + auto& limiter{*Assert(limiter_)}; using Status = BCLog::LogRateLimiter::Status; auto source_loc_1{std::source_location::current()}; @@ -335,13 +352,11 @@ BOOST_AUTO_TEST_CASE(logging_log_rate_limiter) BOOST_CHECK(limiter.SuppressionsActive()); // After reset_window time has passed, all suppressions should be cleared. - MockForwardAndSync(scheduler, reset_window); + scheduler.MockForwardAndSync(reset_window); BOOST_CHECK(!limiter.SuppressionsActive()); BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes, 'a')), Status::UNSUPPRESSED); BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED); - - scheduler.stop(); } BOOST_AUTO_TEST_CASE(logging_log_limit_stats) @@ -367,105 +382,107 @@ BOOST_AUTO_TEST_CASE(logging_log_limit_stats) BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{500}); } -void LogFromLocation(int location, std::string message) -{ +namespace { + +enum class Location { + INFO_1, + INFO_2, + DEBUG_LOG, + INFO_NOLIMIT, +}; + +void LogFromLocation(Location location, const std::string& message) { switch (location) { - case 0: + case Location::INFO_1: LogInfo("%s\n", message); - break; - case 1: + return; + case Location::INFO_2: LogInfo("%s\n", message); - break; - case 2: - LogPrintLevel(BCLog::LogFlags::NONE, BCLog::Level::Info, "%s\n", message); - break; - case 3: - LogPrintLevel(BCLog::LogFlags::ALL, BCLog::Level::Info, "%s\n", message); - break; + return; + case Location::DEBUG_LOG: + 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); + return; + } // no default case, so the compiler can warn about missing cases + assert(false); +} + +/** + * For a given `location` and `message`, ensure that the on-disk debug log behaviour resembles what + * we'd expect it to be for `status` and `suppressions_active`. + */ +void TestLogFromLocation(Location location, const std::string& message, + BCLog::LogRateLimiter::Status status, bool suppressions_active, + std::source_location source = std::source_location::current()) +{ + using Status = BCLog::LogRateLimiter::Status; + if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error + + std::ofstream ofs(LogInstance().m_file_path, std::ios::out | std::ios::trunc); // clear debug log + LogFromLocation(location, message); + auto log_lines{ReadDebugLogLines()}; + + BOOST_TEST_CONTEXT("TestLogFromLocation failed from " << source.file_name() << ":" << source.line()) + { + if (status == Status::STILL_SUPPRESSED) { + BOOST_CHECK_EQUAL(log_lines.size(), 0); + return; + } + + if (status == Status::NEWLY_SUPPRESSED) { + BOOST_REQUIRE_EQUAL(log_lines.size(), 2); + BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected")); + log_lines.erase(log_lines.begin()); + } + BOOST_REQUIRE_EQUAL(log_lines.size(), 1); + auto& payload{log_lines.back()}; + BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]")); + BOOST_CHECK(payload.ends_with(message)); } } -void LogFromLocationAndExpect(int location, std::string message, std::string expect) -{ - ASSERT_DEBUG_LOG(expect); - LogFromLocation(location, message); -} +} // namespace BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup) { - bool prev_log_timestamps = LogInstance().m_log_timestamps; + using Status = BCLog::LogRateLimiter::Status; LogInstance().m_log_timestamps = false; - bool prev_log_sourcelocations = LogInstance().m_log_sourcelocations; LogInstance().m_log_sourcelocations = false; - bool prev_log_threadnames = LogInstance().m_log_threadnames; LogInstance().m_log_threadnames = false; + LogInstance().EnableCategory(BCLog::LogFlags::HTTP); - CScheduler scheduler{}; - scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); }); - auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }; - LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(sched_func, 1024 * 1024, 20s)); + constexpr int64_t line_length{1024}; + constexpr int64_t num_lines{1024}; + constexpr int64_t bytes_quota{line_length * num_lines}; + constexpr auto time_window{20s}; - // Log 1024-character lines (1023 plus newline) to make the math simple. - std::string log_message(1023, 'a'); + ScopedScheduler scheduler{}; + auto limiter{scheduler.GetLimiter(bytes_quota, time_window)}; + LogInstance().SetRateLimiting(limiter); - std::string utf8_path{LogInstance().m_file_path.utf8string()}; - const char* log_path{utf8_path.c_str()}; + const std::string log_message(line_length - 1, 'a'); // subtract one for newline - // Use GetFileSize because fs::file_size may require a flush to be accurate. - std::streamsize log_file_size{static_cast(GetFileSize(log_path))}; - - // Logging 1 MiB should be allowed. - for (int i = 0; i < 1024; ++i) { - LogFromLocation(0, log_message); + for (int i = 0; i < num_lines; ++i) { + TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false); } - BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "should be able to log 1 MiB from location 0"); - - log_file_size = GetFileSize(log_path); - - BOOST_CHECK_NO_THROW(LogFromLocationAndExpect(0, log_message, "Excessive logging detected")); - BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the start of the suppression period should be logged"); - - log_file_size = GetFileSize(log_path); - for (int i = 0; i < 1024; ++i) { - LogFromLocation(0, log_message); - } - - BOOST_CHECK_MESSAGE(log_file_size == GetFileSize(log_path), "all further logs from location 0 should be dropped"); - - BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Excessive logging detected"), std::runtime_error); - BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 1 should be unaffected by other locations"); - - log_file_size = GetFileSize(log_path); + TestLogFromLocation(Location::INFO_1, "a", Status::NEWLY_SUPPRESSED, /*suppressions_active=*/true); + TestLogFromLocation(Location::INFO_1, "b", Status::STILL_SUPPRESSED, /*suppressions_active=*/true); + TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true); { - ASSERT_DEBUG_LOG("Restarting logging"); - MockForwardAndSync(scheduler, 1min); + scheduler.MockForwardAndSync(time_window); + BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging")); } - - BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the end of the suppression period should be logged"); - - BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Restarting logging"), std::runtime_error); - - // Attempt to log 1MiB from location 2 and 1MiB from location 3. These exempt locations should be allowed to log - // without limit. - log_file_size = GetFileSize(log_path); - for (int i = 0; i < 1024; ++i) { - BOOST_CHECK_THROW(LogFromLocationAndExpect(2, log_message, "Excessive logging detected"), std::runtime_error); + // Check that logging from previously suppressed location is unsuppressed again. + TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false); + // Check that conditional logging, and unconditional logging with should_ratelimit=false is + // not being ratelimited. + for (Location location : {Location::DEBUG_LOG, Location::INFO_NOLIMIT}) { + for (int i = 0; i < num_lines + 2; ++i) { + TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false); + } } - - BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 2 should be exempt from rate limiting"); - - log_file_size = GetFileSize(log_path); - for (int i = 0; i < 1024; ++i) { - BOOST_CHECK_THROW(LogFromLocationAndExpect(3, log_message, "Excessive logging detected"), std::runtime_error); - } - - BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 3 should be exempt from rate limiting"); - - LogInstance().m_log_timestamps = prev_log_timestamps; - LogInstance().m_log_sourcelocations = prev_log_sourcelocations; - LogInstance().m_log_threadnames = prev_log_threadnames; - scheduler.stop(); - LogInstance().SetRateLimiting(nullptr); } BOOST_AUTO_TEST_SUITE_END() From 206f5902db5c5b0a08f0575b5ba6007730011e5f Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 1 Aug 2025 11:13:10 -0400 Subject: [PATCH 16/17] config: add DEBUG_ONLY -logratelimit Use -nologratelimit by default in functional tests if the bitcoind version supports it. Co-Authored-By: stickies-v Github-Pull: #33011 Rebased-From: 5c74a0b397cb3db94761bad78801eed4544155b9 --- src/init.cpp | 12 ++++++++---- src/init/common.cpp | 1 + src/logging.h | 1 + test/functional/test_framework/test_node.py | 2 ++ 4 files changed, 12 insertions(+), 4 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index fa7ac6077d..70615a191b 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1384,10 +1384,14 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info) } }, std::chrono::minutes{5}); - LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create( - [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }, - BCLog::RATELIMIT_MAX_BYTES, - BCLog::RATELIMIT_WINDOW)); + if (args.GetBoolArg("-logratelimit", BCLog::DEFAULT_LOGRATELIMIT)) { + LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create( + [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }, + BCLog::RATELIMIT_MAX_BYTES, + BCLog::RATELIMIT_WINDOW)); + } else { + LogInfo("Log rate limiting disabled"); + } assert(!node.validation_signals); node.validation_signals = std::make_unique(std::make_unique(scheduler)); diff --git a/src/init/common.cpp b/src/init/common.cpp index 7191854c74..362db9d40d 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -38,6 +38,7 @@ void AddLoggingArgs(ArgsManager& argsman) argsman.AddArg("-logsourcelocations", strprintf("Prepend debug output with name of the originating source location (source file, line number and function name) (default: %u)", DEFAULT_LOGSOURCELOCATIONS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-loglevelalways", strprintf("Always prepend a category and level (default: %u)", DEFAULT_LOGLEVELALWAYS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); + argsman.AddArg("-logratelimit", strprintf("Apply rate limiting to unconditional logging to mitigate disk-filling attacks (default: %u)", BCLog::DEFAULT_LOGRATELIMIT), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-printtoconsole", "Send trace/debug info to console (default: 1 when no -daemon. To disable logging to file, set -nodebuglogfile)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); } diff --git a/src/logging.h b/src/logging.h index 9419e245bd..723aeb790f 100644 --- a/src/logging.h +++ b/src/logging.h @@ -107,6 +107,7 @@ namespace BCLog { constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset + constexpr bool DEFAULT_LOGRATELIMIT{true}; //! Fixed window rate limiter for logging. class LogRateLimiter diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index abca2b559b..47ae2cc22d 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -137,6 +137,8 @@ class TestNode(): self.args.append("-logsourcelocations") if self.version_is_at_least(239000): self.args.append("-loglevel=trace") + if self.version_is_at_least(299900): + self.args.append("-nologratelimit") # Default behavior from global -v2transport flag is added to args to persist it over restarts. # May be overwritten in individual tests, using extra_args. From 0022e25333a8eabf79c0341f94cf06db36e32f4f Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Mon, 18 Aug 2025 14:23:04 -0400 Subject: [PATCH 17/17] test: modify logging_filesize_rate_limit params Change time_window from 20s to 1h so Reset is not accidentally called if the test takes a while. Change num_lines from 1024 to 10 since LogRateLimiter is parameterized and does not require logging 1MiB of data. Co-Authored-By: stickies-v Github-Pull: #33211 Rebased-From: 5dda364c4b1965da586db7b81de8be90b6919414 --- src/test/logging_tests.cpp | 35 +++++++++++++++++------------------ 1 file changed, 17 insertions(+), 18 deletions(-) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index e208ea4692..a2ccb5fdb1 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -417,30 +417,29 @@ void TestLogFromLocation(Location location, const std::string& message, BCLog::LogRateLimiter::Status status, bool suppressions_active, std::source_location source = std::source_location::current()) { + BOOST_TEST_INFO_SCOPE("TestLogFromLocation called from " << source.file_name() << ":" << source.line()); using Status = BCLog::LogRateLimiter::Status; if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error std::ofstream ofs(LogInstance().m_file_path, std::ios::out | std::ios::trunc); // clear debug log LogFromLocation(location, message); auto log_lines{ReadDebugLogLines()}; + BOOST_TEST_INFO_SCOPE(log_lines.size() << " log_lines read: \n" << util::Join(log_lines, "\n")); - BOOST_TEST_CONTEXT("TestLogFromLocation failed from " << source.file_name() << ":" << source.line()) - { - if (status == Status::STILL_SUPPRESSED) { - BOOST_CHECK_EQUAL(log_lines.size(), 0); - return; - } - - if (status == Status::NEWLY_SUPPRESSED) { - BOOST_REQUIRE_EQUAL(log_lines.size(), 2); - BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected")); - log_lines.erase(log_lines.begin()); - } - BOOST_REQUIRE_EQUAL(log_lines.size(), 1); - auto& payload{log_lines.back()}; - BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]")); - BOOST_CHECK(payload.ends_with(message)); + if (status == Status::STILL_SUPPRESSED) { + BOOST_CHECK_EQUAL(log_lines.size(), 0); + return; } + + if (status == Status::NEWLY_SUPPRESSED) { + BOOST_REQUIRE_EQUAL(log_lines.size(), 2); + BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected")); + log_lines.erase(log_lines.begin()); + } + BOOST_REQUIRE_EQUAL(log_lines.size(), 1); + auto& payload{log_lines.back()}; + BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]")); + BOOST_CHECK(payload.ends_with(message)); } } // namespace @@ -454,9 +453,9 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup) LogInstance().EnableCategory(BCLog::LogFlags::HTTP); constexpr int64_t line_length{1024}; - constexpr int64_t num_lines{1024}; + constexpr int64_t num_lines{10}; constexpr int64_t bytes_quota{line_length * num_lines}; - constexpr auto time_window{20s}; + constexpr auto time_window{1h}; ScopedScheduler scheduler{}; auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};