diff --git a/doc/release-notes-32604.md b/doc/release-notes-32604.md new file mode 100644 index 00000000000..d4d3726e86e --- /dev/null +++ b/doc/release-notes-32604.md @@ -0,0 +1,10 @@ +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) diff --git a/src/init.cpp b/src/init.cpp index 1f72c22ec2f..a741a669b06 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1378,6 +1378,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 5f055566ef5..a090803652c 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, /*should_ratelimit=*/false); } 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,17 +366,43 @@ 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)); } -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 +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, 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) { @@ -384,28 +412,27 @@ 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, bool should_ratelimit) { 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, should_ratelimit); } -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) +// 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); 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)); @@ -424,7 +451,29 @@ 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()); + 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 @@ -434,7 +483,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_ 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 @@ -492,6 +541,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, /*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)); + } +} + +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 fdc12c79b32..c801e94e289 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 { @@ -89,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; }; @@ -105,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); @@ -115,7 +213,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; @@ -123,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::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, bool should_ratelimit) EXCLUSIVE_LOCKS_REQUIRED(m_cs); std::string GetLogPrefix(LogFlags category, Level level) const; @@ -142,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::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, bool should_ratelimit) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns whether logs will be written to any output */ @@ -172,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. @@ -239,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::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, const bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; @@ -248,19 +352,19 @@ 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, should_ratelimit); } } -#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, 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__) @@ -268,12 +372,18 @@ inline void LogPrintFormatInternal(std::string_view logging_function, std::strin // 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 77ec81e5977..f7f9ea175a0 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -5,12 +5,21 @@ #include #include #include +#include +#include #include +#include +#include +#include #include #include #include +#include +#include #include +#include +#include #include #include #include @@ -86,25 +95,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, /*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 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()); } @@ -276,4 +294,181 @@ 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); +} + +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/test/util/logging.h b/src/test/util/logging.h index 73ac23825f9..5d7e4f91e0f 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) diff --git a/src/validation.cpp b/src/validation.cpp index eb8bd2b57ce..88180caca90 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2976,15 +2976,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) diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py index 8bbada3af62..441c21f03a3 100755 --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -82,7 +82,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)