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 65cd993d7d0..a090803652c 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -75,7 +75,7 @@ bool BCLog::Logger::StartLogging() // dump buffered messages from before we opened the log m_buffering = false; if (m_buffer_lines_discarded > 0) { - LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info); + LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info, /*should_ratelimit=*/false); } while (!m_msgs_before_open.empty()) { const auto& buflog = m_msgs_before_open.front(); @@ -412,13 +412,14 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego str.insert(0, LogTimestampStr(now, mocktime)); } -void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) +void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) { StdLockGuard scoped_lock(m_cs); - return LogPrintStr_(str, std::move(source_loc), category, level); + return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit); } -void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) +// NOLINTNEXTLINE(misc-no-recursion) +void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) { std::string str_prefixed = LogEscapeMessage(str); @@ -451,6 +452,28 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so } FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); + bool ratelimit{false}; + if (should_ratelimit && m_limiter) { + auto status{m_limiter->Consume(source_loc, str_prefixed)}; + if (status == BCLog::LogRateLimiter::Status::NEWLY_SUPPRESSED) { + // NOLINTNEXTLINE(misc-no-recursion) + LogPrintStr_(strprintf( + "Excessive logging detected from %s:%d (%s): >%d bytes logged during " + "the last time window of %is. Suppressing logging to disk from this " + "source location until time window resets. Console logging " + "unaffected. Last log entry.\n", + source_loc.file_name(), source_loc.line(), source_loc.function_name(), + m_limiter->m_max_bytes, + Ticks(m_limiter->m_reset_window)), + std::source_location::current(), LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion + } + ratelimit = status == BCLog::LogRateLimiter::Status::STILL_SUPPRESSED; + // To avoid confusion caused by dropped log messages when debugging an issue, + // we prefix log lines with "[*]" when there are any suppressed source locations. + if (m_limiter->SuppressionsActive()) { + str_prefixed.insert(0, "[*] "); + } + } if (m_print_to_console) { // print to console @@ -460,7 +483,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so for (const auto& cb : m_print_callbacks) { cb(str_prefixed); } - if (m_print_to_file) { + if (m_print_to_file && !ratelimit) { assert(m_fileout != nullptr); // reopen the log file, if requested @@ -530,7 +553,7 @@ void BCLog::LogRateLimiter::Reset() uint64_t dropped_bytes{counter.GetDroppedBytes()}; if (dropped_bytes == 0) continue; LogPrintLevel_( - LogFlags::ALL, Level::Info, + LogFlags::ALL, Level::Info, /*should_ratelimit=*/false, "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.\n", source_loc.file_name(), source_loc.line(), source_loc.function_name(), dropped_bytes, Ticks(m_reset_window)); diff --git a/src/logging.h b/src/logging.h index 6ad6739adf8..c801e94e289 100644 --- a/src/logging.h +++ b/src/logging.h @@ -200,6 +200,9 @@ namespace BCLog { size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0}; size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0}; + //! Manages the rate limiting of each log location. + std::unique_ptr m_limiter GUARDED_BY(m_cs); + //! Category-specific log level. Overrides `m_log_level`. std::unordered_map m_category_log_levels GUARDED_BY(m_cs); @@ -218,7 +221,7 @@ namespace BCLog { std::list> m_print_callbacks GUARDED_BY(m_cs) {}; /** Send a string to the log output (internal) */ - void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) EXCLUSIVE_LOCKS_REQUIRED(m_cs); std::string GetLogPrefix(LogFlags category, Level level) const; @@ -237,7 +240,7 @@ namespace BCLog { std::atomic m_reopen_file{false}; /** Send a string to the log output */ - void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns whether logs will be written to any output */ @@ -267,6 +270,12 @@ namespace BCLog { /** Only for testing */ void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); + void SetRateLimiting(std::unique_ptr&& limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) + { + StdLockGuard scoped_lock(m_cs); + m_limiter = std::move(limiter); + } + /** Disable logging * This offers a slight speedup and slightly smaller memory usage * compared to leaving the logging system in its default state. @@ -334,7 +343,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); template -inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString fmt, const Args&... args) +inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, const bool should_ratelimit, util::ConstevalFormatString fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; @@ -343,19 +352,19 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLo } catch (tinyformat::format_error& fmterr) { log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt; } - LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level); + LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level, should_ratelimit); } } -#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(std::source_location::current(), category, level, __VA_ARGS__) +#define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) -// Log unconditionally. +// Log unconditionally. Uses basic rate limiting to mitigate disk filling attacks. // Be conservative when using functions that unconditionally log to debug.log! // It should not be the case that an inbound peer can fill up a user's storage // with debug.log entries. -#define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__) -#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, __VA_ARGS__) -#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, __VA_ARGS__) +#define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/true, __VA_ARGS__) +#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, /*should_ratelimit=*/true, __VA_ARGS__) +#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, /*should_ratelimit=*/true, __VA_ARGS__) // Deprecated unconditional logging. #define LogPrintf(...) LogInfo(__VA_ARGS__) @@ -363,12 +372,18 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLo // Use a macro instead of a function for conditional logging to prevent // evaluating arguments when logging for the category is not enabled. -// Log conditionally, prefixing the output with the passed category name and severity level. -#define LogPrintLevel(category, level, ...) \ - do { \ - if (LogAcceptCategory((category), (level))) { \ - LogPrintLevel_(category, level, __VA_ARGS__); \ - } \ +// Log by prefixing the output with the passed category name and severity level. This can either +// log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info +// is passed. If this function logs unconditionally, logging to disk is rate-limited. This is +// important so that callers don't need to worry about accidentally introducing a disk-fill +// vulnerability if level >= Info is used. Additionally, users specifying -debug are assumed to be +// developers or power users who are aware that -debug may cause excessive disk usage due to logging. +#define LogPrintLevel(category, level, ...) \ + do { \ + if (LogAcceptCategory((category), (level))) { \ + bool rate_limit{level >= BCLog::Level::Info}; \ + LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \ + } \ } while (0) // Log conditionally, prefixing the output with the passed category name. diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 8cf0735b086..f7f9ea175a0 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include @@ -15,8 +16,10 @@ #include #include #include +#include #include #include +#include #include #include #include @@ -113,7 +116,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) std::vector expected; for (auto& [msg, category, level, prefix, loc] : cases) { expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg)); - LogInstance().LogPrintStr(msg, std::move(loc), category, level); + LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false); } std::ifstream file{tmp_log_path}; std::vector log_lines; @@ -366,4 +369,106 @@ BOOST_AUTO_TEST_CASE(logging_log_limit_stats) BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 500ull); } +void LogFromLocation(int location, std::string message) +{ + switch (location) { + case 0: + LogInfo("%s\n", message); + break; + case 1: + LogInfo("%s\n", message); + break; + case 2: + LogPrintLevel(BCLog::LogFlags::NONE, BCLog::Level::Info, "%s\n", message); + break; + case 3: + LogPrintLevel(BCLog::LogFlags::ALL, BCLog::Level::Info, "%s\n", message); + break; + } +} + +void LogFromLocationAndExpect(int location, std::string message, std::string expect) +{ + ASSERT_DEBUG_LOG(expect); + LogFromLocation(location, message); +} + +BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup) +{ + bool prev_log_timestamps = LogInstance().m_log_timestamps; + LogInstance().m_log_timestamps = false; + bool prev_log_sourcelocations = LogInstance().m_log_sourcelocations; + LogInstance().m_log_sourcelocations = false; + bool prev_log_threadnames = LogInstance().m_log_threadnames; + LogInstance().m_log_threadnames = false; + + CScheduler scheduler{}; + scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); }); + auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); }; + auto limiter = std::make_unique(sched_func, 1024 * 1024, 20s); + LogInstance().SetRateLimiting(std::move(limiter)); + + // Log 1024-character lines (1023 plus newline) to make the math simple. + std::string log_message(1023, 'a'); + + std::string utf8_path{LogInstance().m_file_path.utf8string()}; + const char* log_path{utf8_path.c_str()}; + + // Use GetFileSize because fs::file_size may require a flush to be accurate. + std::streamsize log_file_size{static_cast(GetFileSize(log_path))}; + + // Logging 1 MiB should be allowed. + for (int i = 0; i < 1024; ++i) { + LogFromLocation(0, log_message); + } + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "should be able to log 1 MiB from location 0"); + + log_file_size = GetFileSize(log_path); + + BOOST_CHECK_NO_THROW(LogFromLocationAndExpect(0, log_message, "Excessive logging detected")); + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the start of the suppression period should be logged"); + + log_file_size = GetFileSize(log_path); + for (int i = 0; i < 1024; ++i) { + LogFromLocation(0, log_message); + } + + BOOST_CHECK_MESSAGE(log_file_size == GetFileSize(log_path), "all further logs from location 0 should be dropped"); + + BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Excessive logging detected"), std::runtime_error); + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 1 should be unaffected by other locations"); + + log_file_size = GetFileSize(log_path); + { + ASSERT_DEBUG_LOG("Restarting logging"); + MockForwardAndSync(scheduler, 1min); + } + + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the end of the suppression period should be logged"); + + BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Restarting logging"), std::runtime_error); + + // Attempt to log 1MiB from location 2 and 1MiB from location 3. These exempt locations should be allowed to log + // without limit. + log_file_size = GetFileSize(log_path); + for (int i = 0; i < 1024; ++i) { + BOOST_CHECK_THROW(LogFromLocationAndExpect(2, log_message, "Excessive logging detected"), std::runtime_error); + } + + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 2 should be exempt from rate limiting"); + + log_file_size = GetFileSize(log_path); + for (int i = 0; i < 1024; ++i) { + BOOST_CHECK_THROW(LogFromLocationAndExpect(3, log_message, "Excessive logging detected"), std::runtime_error); + } + + BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 3 should be exempt from rate limiting"); + + LogInstance().m_log_timestamps = prev_log_timestamps; + LogInstance().m_log_sourcelocations = prev_log_sourcelocations; + LogInstance().m_log_threadnames = prev_log_threadnames; + scheduler.stop(); + LogInstance().SetRateLimiting(nullptr); +} + BOOST_AUTO_TEST_SUITE_END() diff --git a/src/validation.cpp b/src/validation.cpp index 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)