Merge bitcoin/bitcoin#32604: log: Mitigate disk filling attacks by rate limiting LogPrintf, LogInfo, LogWarning, LogError

4c772cbd83 doc: add release notes for new rate limiting logging behavior (Eugene Siegel)
d541409a64 log: Add rate limiting to LogPrintf, LogInfo, LogWarning, LogError, LogPrintLevel (Eugene Siegel)
a6a35cc0c2 log: use std::source_location in place of __func__, __FILE__, __LINE__ (Eugene Siegel)
afb9e39ec5 log: introduce LogRateLimiter, LogLimitStats, Status (Eugene Siegel)
df7972a6cf test: Mark ~DebugLogHelper as noexcept(false) (Eugene Siegel)

Pull request description:

  This revives the work done by dergoegge in https://github.com/bitcoin/bitcoin/pull/21603. The approach is similar — this PR uses `std::source_location` under the hood now that we can use c++20 features. It also resets the rate limiting statistics via the `CScheduler`. The logging functions have also changed slightly since that PR was opened, so work has been done to preserve the intent of the original rate limiting change. I have tried to give commit attribution where possible.

  **Approach:**
  Each source code location is given an hourly logging quota of 1MiB of logging per hour. Logging is only dropped from source locations that exceed the quota.
  - Only logging to disk is rate limited. Logging to console is not rate limited.
  - Printing with the category argument is not rate limited.
  - `UpdateTip: new best=[…]` is logged without rate limiting. High log volume is expected for that source location during IBD.
  - When logging is restarted a tally of how many bytes were dropped is printed.
  - All logs will be prefixed with [*] if there is at least one source location that is currently being suppressed.

  I've repurposed the old logging rpc mentioned in #21603 in another branch for testing [here](https://github.com/Crypt-iQ/bitcoin/tree/log_ratelimiting_05192025_rpc). This can be used to log from source locations and test out the new changes in logging behavior. Note that the `setmocktime` RPC needs to be used to set the mock time past the current clock time to reset the logging messages.

  Example usage:
  ```
  bitcoin-cli -regtest excessivelog 1 1048500 # log just under 1MiB
  bitcoin-cli -regtest excessivelog 1 100 # this should get the total amount logged above 1MiB
                                          # and the rate limiting logic should kick in
  bitcoin-cli -regtest excessivelog 2 1048500
  bitcoin-cli -regtest excessivelog 2 100 # trigger rate limiting from another location
  bitcoin-cli -regtest mockscheduler 3600 # fast-forward the scheduler
  bitcoin-cli -regtest excessivelog 1 100 # this should trigger logging to resume and will log the source locations that were reset
  ```

  Example output:
  ```
  2025-07-02T22:03:56Z [warning] Excessive logging detected from rpc/node.cpp:142 (RPCHelpMan excessivelog()): >1048576 bytes logged during the last time window of 3600s. Suppressing logging to disk from this source location until time window resets. Console logging unaffected. Last log entry.
  [*] 2025-07-02T22:03:56Z aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
  2025-07-02T22:04:58Z (mocktime: 2262-04-11T23:47:15Z) Restarting logging from rpc/node.cpp:142 (RPCHelpMan excessivelog()): 121 bytes were dropped during the last 3600s.
  2025-07-02T22:04:58Z (mocktime: 2262-04-11T23:47:15Z) Restarting logging from rpc/node.cpp:139 (RPCHelpMan excessivelog()): 121 bytes were dropped during the last 3600s.
  ```

ACKs for top commit:
  maflcko:
    re-ACK 4c772cbd83 🕚
  glozow:
    reACK 4c772cb
  stickies-v:
    re-ACK 4c772cbd83, no changes except release notes update

Tree-SHA512: d07087cd0f2b188100b51c9b8c3da376fa24ec3612a2a284bd83f650bba0ea409f9fa0acd5f3b10f45e664ef4fdf3abc97ed3da08098d2beb599cc83e3fc4504
This commit is contained in:
merge-script
2025-07-09 14:43:39 -04:00
8 changed files with 466 additions and 62 deletions

View File

@@ -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)

View File

@@ -1378,6 +1378,11 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
}
}, std::chrono::minutes{5});
LogInstance().SetRateLimiting(std::make_unique<BCLog::LogRateLimiter>(
[&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<ValidationSignals>(std::make_unique<SerialTaskRunner>(scheduler));
auto& validation_signals = *node.validation_signals;

View File

@@ -12,8 +12,10 @@
#include <util/time.h>
#include <array>
#include <cstring>
#include <map>
#include <optional>
#include <utility>
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<BCLog::Logger::BufferedLog>));
return memusage::DynamicUsage(buflog.str) +
memusage::DynamicUsage(buflog.threadname) +
memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
}
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<std::chrono::seconds>(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<std::chrono::seconds>(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);

View File

@@ -6,6 +6,7 @@
#ifndef BITCOIN_LOGGING_H
#define BITCOIN_LOGGING_H
#include <crypto/siphash.h>
#include <threadsafety.h>
#include <tinyformat.h>
#include <util/fs.h>
@@ -14,11 +15,14 @@
#include <atomic>
#include <cstdint>
#include <cstring>
#include <functional>
#include <list>
#include <mutex>
#include <source_location>
#include <string>
#include <unordered_map>
#include <unordered_set>
#include <vector>
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<size_t>(CSipHasher(0, 0)
.Write(std::hash<std::string_view>{}(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<std::source_location, LogLimitStats, SourceLocationHasher, SourceLocationEqual> 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<bool> m_suppression_active{false};
public:
using SchedulerFunction = std::function<void(std::function<void()>, 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<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
//! Category-specific log level. Overrides `m_log_level`.
std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
@@ -115,7 +213,7 @@ namespace BCLog {
/** Log categories bitfield. */
std::atomic<CategoryMask> 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<std::function<void(const std::string&)>> 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<bool> 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<LogRateLimiter>&& 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 <typename... Args>
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<sizeof...(Args)> 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<sizeof...(Args)> 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.

View File

@@ -5,12 +5,21 @@
#include <init/common.h>
#include <logging.h>
#include <logging/timer.h>
#include <scheduler.h>
#include <test/util/logging.h>
#include <test/util/setup_common.h>
#include <tinyformat.h>
#include <util/fs.h>
#include <util/fs_helpers.h>
#include <util/string.h>
#include <chrono>
#include <fstream>
#include <future>
#include <ios>
#include <iostream>
#include <source_location>
#include <string>
#include <unordered_map>
#include <utility>
#include <vector>
@@ -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<Case> 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<std::string> 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<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> 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<void> 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<BCLog::LogRateLimiter>(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<std::streamsize>(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()

View File

@@ -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)

View File

@@ -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)

View File

@@ -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)