diff --git a/src/init.cpp b/src/init.cpp index 2c2e3b77d50..4813fe267b6 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1400,10 +1400,14 @@ 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)); + 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.cpp b/src/logging.cpp index a090803652c..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( @@ -384,10 +391,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; } @@ -455,24 +462,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) { @@ -549,18 +558,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", + 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(), - 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 c801e94e289..723aeb790fb 100644 --- a/src/logging.h +++ b/src/logging.h @@ -18,6 +18,7 @@ #include #include #include +#include #include #include #include @@ -46,10 +47,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()); } }; @@ -104,47 +105,34 @@ 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 + constexpr bool DEFAULT_LOGRATELIMIT{true}; - //! 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}; + LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window); public: using SchedulerFunction = std::function, std::chrono::milliseconds)>; @@ -154,9 +142,12 @@ 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); + 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. @@ -201,7 +192,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); @@ -270,7 +261,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); @@ -343,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::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; diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 62ed2dffebb..ad51de13ea8 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; @@ -47,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"}, @@ -56,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; @@ -68,7 +80,9 @@ struct LogSetup : public BasicTestingSetup { LogInstance().m_log_sourcelocations = false; LogInstance().SetLogLevel(BCLog::Level::Debug); + LogInstance().DisableCategory(BCLog::LogFlags::ALL); LogInstance().SetCategoryLogLevel({}); + LogInstance().SetRateLimiting(nullptr); } ~LogSetup() @@ -82,6 +96,9 @@ struct LogSetup : public BasicTestingSetup { LogInstance().m_log_sourcelocations = prev_log_sourcelocations; 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}); } }; @@ -118,27 +135,20 @@ 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()); } 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"); 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", @@ -151,16 +161,13 @@ 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"); 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", @@ -192,19 +199,13 @@ 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()); } 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 @@ -225,11 +226,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()); } @@ -294,22 +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); }; - BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window}; + 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()}; @@ -337,138 +352,137 @@ 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) { - 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) -{ +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); }; - auto limiter = std::make_unique(sched_func, 1024 * 1024, 20s); - LogInstance().SetRateLimiting(std::move(limiter)); + 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() 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(); } }; 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.