diff --git a/doc/release-notes.md b/doc/release-notes.md index e4cf2f0b50..b384763e15 100644 --- a/doc/release-notes.md +++ b/doc/release-notes.md @@ -48,6 +48,17 @@ Notable changes - #32521 policy: make pathological transactions packed with legacy sigops non-standard +### Logging + +Unconditional logging to disk is now rate limited by giving each source location +a quota of 1MiB per hour. Unconditional logging is any logging with a log level +higher than debug, that is `info`, `warning`, and `error`. All logs will be +prefixed with `[*]` if there is at least one source location that is currently +being suppressed. (#32604) + +When `-logsourcelocations` is enabled, the log output now contains the entire +function signature instead of just the function name. (#32604) + ### RPC - The `dumptxoutset` RPC now requires a `type` parameter to be specified. To maintain pre @@ -163,6 +174,7 @@ Thanks to everyone who directly contributed to this release: - brunoerg - Bufo - Christewart +- Crypt-iQ - davidgumberg - deadmanoz - dergoegge diff --git a/src/init.cpp b/src/init.cpp index 7fdbf75dc6..70615a191b 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1384,6 +1384,15 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info) } }, std::chrono::minutes{5}); + 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)); auto& validation_signals = *node.validation_signals; diff --git a/src/init/common.cpp b/src/init/common.cpp index 7191854c74..362db9d40d 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -38,6 +38,7 @@ void AddLoggingArgs(ArgsManager& argsman) argsman.AddArg("-logsourcelocations", strprintf("Prepend debug output with name of the originating source location (source file, line number and function name) (default: %u)", DEFAULT_LOGSOURCELOCATIONS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-loglevelalways", strprintf("Always prepend a category and level (default: %u)", DEFAULT_LOGLEVELALWAYS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); + argsman.AddArg("-logratelimit", strprintf("Apply rate limiting to unconditional logging to mitigate disk-filling attacks (default: %u)", BCLog::DEFAULT_LOGRATELIMIT), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-printtoconsole", "Send trace/debug info to console (default: 1 when no -daemon. To disable logging to file, set -nodebuglogfile)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); } diff --git a/src/logging.cpp b/src/logging.cpp index 5f055566ef..2ed6835197 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,50 @@ 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(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) +{ + 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( + const std::source_location& source_loc, + const std::string& str) +{ + StdLockGuard scoped_lock(m_mutex); + 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 (!stats.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 +419,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 +458,31 @@ 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 == 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.", + 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; + } + } + + // 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) { // print to console @@ -434,7 +492,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 +550,36 @@ 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, stats] : source_locations) { + if (stats.m_dropped_bytes == 0) continue; + LogPrintLevel_( + 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)); + } +} + +bool BCLog::LogRateLimiter::Stats::Consume(uint64_t bytes) +{ + if (bytes > m_available_bytes) { + m_dropped_bytes += bytes; + m_available_bytes = 0; + return false; + } + + m_available_bytes -= bytes; + return true; +} + bool BCLog::Logger::SetLogLevel(std::string_view level_str) { const auto level = GetLogLevel(level_str); diff --git a/src/logging.h b/src/logging.h index fdc12c79b3..723aeb790f 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,15 @@ #include #include +#include #include #include +#include #include +#include #include #include +#include #include static const bool DEFAULT_LOGTIMEMICROS = false; @@ -31,6 +36,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 size_t(CSipHasher(0, 0) + .Write(s.line()) + .Write(MakeUCharSpan(std::string_view{s.file_name()})) + .Finalize()); + } +}; + struct LogCategory { std::string category; bool active; @@ -82,6 +105,69 @@ 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 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 + { + 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; + + //! 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)>; + /** + * @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 stats are reset. + */ + 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. + 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 +175,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 +191,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::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); @@ -115,7 +204,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 +212,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 +231,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 +261,12 @@ namespace BCLog { /** Only for testing */ void DisconnectTestLogger() 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); + } + /** Disable logging * This offers a slight speedup and slightly smaller memory usage * compared to leaving the logging system in its default state. @@ -239,7 +334,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); template -inline void LogPrintFormatInternal(std::string_view logging_function, std::string_view source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString fmt, const Args&... args) +inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; @@ -248,19 +343,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 +363,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 77ec81e597..a2ccb5fdb1 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 @@ -28,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; @@ -38,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"}, @@ -47,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; @@ -59,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() @@ -73,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}); } }; @@ -86,41 +112,43 @@ 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); - 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", + + 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::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", @@ -133,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", @@ -174,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 @@ -207,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()); } @@ -276,4 +291,197 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) } } +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) +{ + uint64_t max_bytes{1024}; + auto reset_window{1min}; + 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()}; + 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. + 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); +} + +BOOST_AUTO_TEST_CASE(logging_log_limit_stats) +{ + BCLog::LogRateLimiter::Stats stats(BCLog::RATELIMIT_MAX_BYTES); + + // 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{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(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 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}); +} + +namespace { + +enum class Location { + INFO_1, + INFO_2, + DEBUG_LOG, + INFO_NOLIMIT, +}; + +void LogFromLocation(Location location, const std::string& message) { + switch (location) { + case Location::INFO_1: + LogInfo("%s\n", message); + return; + case Location::INFO_2: + LogInfo("%s\n", message); + 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()) +{ + BOOST_TEST_INFO_SCOPE("TestLogFromLocation called from " << source.file_name() << ":" << source.line()); + using Status = BCLog::LogRateLimiter::Status; + if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error + + std::ofstream ofs(LogInstance().m_file_path, std::ios::out | std::ios::trunc); // clear debug log + LogFromLocation(location, message); + auto log_lines{ReadDebugLogLines()}; + BOOST_TEST_INFO_SCOPE(log_lines.size() << " log_lines read: \n" << util::Join(log_lines, "\n")); + + if (status == Status::STILL_SUPPRESSED) { + BOOST_CHECK_EQUAL(log_lines.size(), 0); + return; + } + + if (status == Status::NEWLY_SUPPRESSED) { + BOOST_REQUIRE_EQUAL(log_lines.size(), 2); + BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected")); + log_lines.erase(log_lines.begin()); + } + BOOST_REQUIRE_EQUAL(log_lines.size(), 1); + auto& payload{log_lines.back()}; + BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]")); + BOOST_CHECK(payload.ends_with(message)); +} + +} // namespace + +BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup) +{ + using Status = BCLog::LogRateLimiter::Status; + LogInstance().m_log_timestamps = false; + LogInstance().m_log_sourcelocations = false; + LogInstance().m_log_threadnames = false; + LogInstance().EnableCategory(BCLog::LogFlags::HTTP); + + constexpr int64_t line_length{1024}; + constexpr int64_t num_lines{10}; + constexpr int64_t bytes_quota{line_length * num_lines}; + constexpr auto time_window{1h}; + + ScopedScheduler scheduler{}; + auto limiter{scheduler.GetLimiter(bytes_quota, time_window)}; + LogInstance().SetRateLimiting(limiter); + + const std::string log_message(line_length - 1, 'a'); // subtract one for newline + + for (int i = 0; i < num_lines; ++i) { + TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false); + } + 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); + { + scheduler.MockForwardAndSync(time_window); + BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging")); + } + // 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_AUTO_TEST_SUITE_END() diff --git a/src/test/util/logging.h b/src/test/util/logging.h index 73ac23825f..62b11c2841 100644 --- a/src/test/util/logging.h +++ b/src/test/util/logging.h @@ -33,7 +33,7 @@ class DebugLogHelper public: explicit DebugLogHelper(std::string message, MatchFn match = [](const std::string*){ return true; }); - ~DebugLogHelper() { check_found(); } + ~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 a1ac4e1e14..fde064458d 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2995,15 +2995,17 @@ static void UpdateTipLog( { AssertLockHeld(::cs_main); - LogPrintf("%s%s: new best=%s height=%d version=0x%08x log2_work=%f tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)%s\n", - prefix, func_name, - tip->GetBlockHash().ToString(), tip->nHeight, tip->nVersion, - log(tip->nChainWork.getdouble()) / log(2.0), tip->m_chain_tx_count, - FormatISO8601DateTime(tip->GetBlockTime()), - chainman.GuessVerificationProgress(tip), - coins_tip.DynamicMemoryUsage() * (1.0 / (1 << 20)), - coins_tip.GetCacheSize(), - !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages) : ""); + + // Disable rate limiting in LogPrintLevel_ so this source location may log during IBD. + LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, "%s%s: new best=%s height=%d version=0x%08x log2_work=%f tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)%s\n", + prefix, func_name, + tip->GetBlockHash().ToString(), tip->nHeight, tip->nVersion, + log(tip->nChainWork.getdouble()) / log(2.0), tip->m_chain_tx_count, + FormatISO8601DateTime(tip->GetBlockTime()), + chainman.GuessVerificationProgress(tip), + coins_tip.DynamicMemoryUsage() * (1.0 / (1 << 20)), + coins_tip.GetCacheSize(), + !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages) : ""); } void Chainstate::UpdateTip(const CBlockIndex* pindexNew) diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py index c5e3c33b14..12a82ced9c 100755 --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -84,7 +84,7 @@ class ConfArgsTest(BitcoinTestFramework): self.log.debug('Verifying that disabling of the config file means garbage inside of it does ' \ 'not prevent the node from starting, and message about existing config file is logged') - ignored_file_message = [f'[InitConfig] Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.'] + ignored_file_message = [f'Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.'] with self.nodes[0].assert_debug_log(timeout=60, expected_msgs=ignored_file_message): self.start_node(0, extra_args=settings + ['-noconf']) self.stop_node(0) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index abca2b559b..47ae2cc22d 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -137,6 +137,8 @@ class TestNode(): self.args.append("-logsourcelocations") if self.version_is_at_least(239000): self.args.append("-loglevel=trace") + if self.version_is_at_least(299900): + self.args.append("-nologratelimit") # Default behavior from global -v2transport flag is added to args to persist it over restarts. # May be overwritten in individual tests, using extra_args.