From 616bc22f131132b9239ef362dca8c6bce000a539 Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 09:27:50 -0400 Subject: [PATCH 01/11] test: remove noexcept(false) comment in ~DebugLogHelper --- 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 5d7e4f91e0f..62b11c28410 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 b8e92fb3d4137f91fe6a54829867fc54357da648 Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 25 Jul 2025 16:39:33 -0400 Subject: [PATCH 02/11] log: avoid double hashing in SourceLocationHasher Co-Authored-By: l0rinc --- src/logging.h | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/logging.h b/src/logging.h index c801e94e289..33742dcbe68 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 5f70bc80df06ca85d44e8201d47e7086e971fdea Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 09:43:43 -0400 Subject: [PATCH 03/11] log: remove const qualifier from arguments in LogPrintFormatInternal Co-Authored-By: l0rinc --- src/logging.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/logging.h b/src/logging.h index 33742dcbe68..c753172545c 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 8319a134684df2240057a5e8afaa6ae441fb8a58 Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 10:04:35 -0400 Subject: [PATCH 04/11] log: clarify RATELIMIT_MAX_BYTES comment, use RATELIMIT_WINDOW Co-Authored-By: stickies-v --- 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 cc9f8160a3b..b48d3cc0710 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1384,7 +1384,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 c753172545c..106de1f8d30 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 3c7cae49b692bb6bf5cae5ee23479091bed0b8be Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 10:18:59 -0400 Subject: [PATCH 05/11] log: change LogLimitStats to struct LogRateLimiter::Stats Clean up the noisy LogLimitStats and remove references to the time window. Co-Authored-By: stickies-v --- 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 a090803652c..befac8a03f8 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 106de1f8d30..04e6e0974c4 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 62ed2dffebb..dbe13886af1 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 e8f9c37a3b4c9c88baddb556c4b33a4cbba1f614 Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 18 Jul 2025 10:39:45 -0400 Subject: [PATCH 06/11] 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. --- src/logging.cpp | 22 ++++++++++++---------- 1 file changed, 12 insertions(+), 10 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index befac8a03f8..0cad2905047 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 3d630c2544e19480268426cda245796d4ce34ac3 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Wed, 23 Jul 2025 22:06:37 +0100 Subject: [PATCH 07/11] 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. --- 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 b48d3cc0710..297910e2a26 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1381,7 +1381,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 0cad2905047..2ed6835197b 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 04e6e0974c4..9419e245bdf 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 dbe13886af1..4d4141c1a44 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 05d7c22479bf96bab9f8c8b8fa90368429ad2c88 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Wed, 23 Jul 2025 22:29:01 +0100 Subject: [PATCH 08/11] test: add ReadDebugLogLines helper function Deduplicates repeated usage of the same functionality. --- 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 4d4141c1a44..888e1119cd4 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 350193e5e2efabb3eb66197b91869b946ec5428c Mon Sep 17 00:00:00 2001 From: stickies-v Date: Thu, 31 Jul 2025 12:18:06 +0100 Subject: [PATCH 09/11] test: don't leak log category mask across tests This ensures log tests behave consistently when other tests modify the log category mask. --- 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 888e1119cd4..41d77328042 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 9f3b017bcc067bba1d1682a5d4e65b5450dc10c4 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Wed, 23 Jul 2025 22:30:07 +0100 Subject: [PATCH 10/11] 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. --- 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 41d77328042..ad51de13ea8 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 5c74a0b397cb3db94761bad78801eed4544155b9 Mon Sep 17 00:00:00 2001 From: Eugene Siegel Date: Fri, 1 Aug 2025 11:13:10 -0400 Subject: [PATCH 11/11] config: add DEBUG_ONLY -logratelimit Use -nologratelimit by default in functional tests if the bitcoind version supports it. Co-Authored-By: stickies-v --- 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 297910e2a26..b4119cb9a25 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1381,10 +1381,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 25121d74ed9..53f4215c3b6 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 9419e245bdf..723aeb790fb 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 57b4b8c3093..3b0814635aa 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -136,6 +136,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.