highperfocused/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-08-23 18:02:22 +02:00
Code Issues Packages Projects Releases Wiki Activity

Merge bitcoin/bitcoin#33011: log: rate limiting followups

Browse Source 
5c74a0b397 config: add DEBUG_ONLY -logratelimit (Eugene Siegel)
9f3b017bcc test: logging_filesize_rate_limit improvements (stickies-v)
350193e5e2 test: don't leak log category mask across tests (stickies-v)
05d7c22479 test: add ReadDebugLogLines helper function (stickies-v)
3d630c2544 log: make m_limiter a shared_ptr (stickies-v)
e8f9c37a3b log: clean up LogPrintStr_ and Reset, prefix all logs with "[*]" when there are suppressions (Eugene Siegel)
3c7cae49b6 log: change LogLimitStats to struct LogRateLimiter::Stats (Eugene Siegel)
8319a13468 log: clarify RATELIMIT_MAX_BYTES comment, use RATELIMIT_WINDOW (Eugene Siegel)
5f70bc80df log: remove const qualifier from arguments in LogPrintFormatInternal (Eugene Siegel)
b8e92fb3d4 log: avoid double hashing in SourceLocationHasher (Eugene Siegel)
616bc22f13 test: remove noexcept(false) comment in ~DebugLogHelper (Eugene Siegel)

Pull request description:

  Followups to #32604.

  There are two behavior changes:
  - prefixing with `[*]` is done to all logs (regardless of `should_ratelimit`) per [this comment](https://github.com/bitcoin/bitcoin/pull/32604#discussion_r2195710943).
  - a DEBUG_ONLY `-disableratelimitlogging` flag is added by default to functional tests so they don't encounter rate limiting.

ACKs for top commit:
  stickies-v:
    re-ACK 5c74a0b397
  achow101:
    ACK 5c74a0b397
  l0rinc:
    Code review ACK 5c74a0b397

Tree-SHA512: d32db5fcc28bb9b2a850f0048c8062200a3725b88f1cd9a0e137da065c0cf9a5d22e5d03cb16fe75ea7494801313ab34ffec7cf3e8577cd7527e636af53591c4
This commit is contained in:
Ava Chow
2025-08-14 15:15:25 -07:00
parent 8405fdb06e 5c74a0b397
commit 578b512bdd
7 changed files with 227 additions and 209 deletions
Download Patch File Download Diff File Expand all files Collapse all files

12
src/init.cpp
View File

@@ -1400,10 +1400,14 @@ 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));
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<ValidationSignals>(std::make_unique<SerialTaskRunner>(scheduler));

1
src/init/common.cpp
View File

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

54
src/logging.cpp
View File

@@ -371,12 +371,19 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
}
BCLog::LogRateLimiter::LogRateLimiter(
SchedulerFunction scheduler_func,
uint64_t max_bytes,
std::chrono::seconds reset_window) : m_max_bytes{max_bytes}, m_reset_window{reset_window}
BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
: m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
{
scheduler_func([this] { Reset(); }, reset_window);
auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
auto reset = [weak_limiter] {
if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
};
scheduler_func(reset, limiter->m_reset_window);
return limiter;
}
BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
@@ -384,10 +391,10 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
const std::string& str)
{
StdLockGuard scoped_lock(m_mutex);
auto& counter{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second};
Status status{counter.GetDroppedBytes() > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED};
auto& stats{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second};
Status status{stats.m_dropped_bytes > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED};
if (!counter.Consume(str.size()) && status == Status::UNSUPPRESSED) {
if (!stats.Consume(str.size()) && status == Status::UNSUPPRESSED) {
status = Status::NEWLY_SUPPRESSED;
m_suppression_active = true;
}
@@ -455,24 +462,26 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so
bool ratelimit{false};
if (should_ratelimit && m_limiter) {
auto status{m_limiter->Consume(source_loc, str_prefixed)};
if (status == BCLog::LogRateLimiter::Status::NEWLY_SUPPRESSED) {
if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
// NOLINTNEXTLINE(misc-no-recursion)
LogPrintStr_(strprintf(
"Excessive logging detected from %s:%d (%s): >%d bytes logged during "
"the last time window of %is. Suppressing logging to disk from this "
"source location until time window resets. Console logging "
"unaffected. Last log entry.\n",
"unaffected. Last log entry.",
source_loc.file_name(), source_loc.line(), source_loc.function_name(),
m_limiter->m_max_bytes,
Ticks<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
} else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
ratelimit = true;
}
ratelimit = status == BCLog::LogRateLimiter::Status::STILL_SUPPRESSED;
// To avoid confusion caused by dropped log messages when debugging an issue,
// we prefix log lines with "[*]" when there are any suppressed source locations.
if (m_limiter->SuppressionsActive()) {
str_prefixed.insert(0, "[*] ");
}
}
// To avoid confusion caused by dropped log messages when debugging an issue,
// we prefix log lines with "[*]" when there are any suppressed source locations.
if (m_limiter && m_limiter->SuppressionsActive()) {
str_prefixed.insert(0, "[*] ");
}
if (m_print_to_console) {
@@ -549,18 +558,17 @@ void BCLog::LogRateLimiter::Reset()
source_locations.swap(m_source_locations);
m_suppression_active = false;
}
for (const auto& [source_loc, counter] : source_locations) {
uint64_t dropped_bytes{counter.GetDroppedBytes()};
if (dropped_bytes == 0) continue;
for (const auto& [source_loc, stats] : source_locations) {
if (stats.m_dropped_bytes == 0) continue;
LogPrintLevel_(
LogFlags::ALL, Level::Info, /*should_ratelimit=*/false,
"Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.\n",
LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false,
"Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.",
source_loc.file_name(), source_loc.line(), source_loc.function_name(),
dropped_bytes, Ticks<std::chrono::seconds>(m_reset_window));
stats.m_dropped_bytes, Ticks<std::chrono::seconds>(m_reset_window));
}
}
bool BCLog::LogLimitStats::Consume(uint64_t bytes)
bool BCLog::LogRateLimiter::Stats::Consume(uint64_t bytes)
{
if (bytes > m_available_bytes) {
m_dropped_bytes += bytes;

77
src/logging.h
View File

@@ -18,6 +18,7 @@
#include <cstring>
#include <functional>
#include <list>
#include <memory>
#include <mutex>
#include <source_location>
#include <string>
@@ -46,10 +47,10 @@ struct SourceLocationHasher {
size_t operator()(const std::source_location& s) const noexcept
{
// Use CSipHasher(0, 0) as a simple way to get uniform distribution.
return static_cast<size_t>(CSipHasher(0, 0)
.Write(std::hash<std::string_view>{}(s.file_name()))
.Write(s.line())
.Finalize());
return size_t(CSipHasher(0, 0)
.Write(s.line())
.Write(MakeUCharSpan(std::string_view{s.file_name()}))
.Finalize());
}
};
@@ -104,47 +105,34 @@ namespace BCLog {
};
constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes that can be logged within one window
constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW
constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset
constexpr bool DEFAULT_LOGRATELIMIT{true};
//! Keeps track of an individual source location and how many available bytes are left for logging from it.
class LogLimitStats
{
private:
//! Remaining bytes in the current window interval.
uint64_t m_available_bytes;
//! Number of bytes that were not consumed within the current window.
uint64_t m_dropped_bytes{0};
public:
LogLimitStats(uint64_t max_bytes) : m_available_bytes{max_bytes} {}
//! Consume bytes from the window if enough bytes are available.
//!
//! Returns whether enough bytes were available.
bool Consume(uint64_t bytes);
uint64_t GetAvailableBytes() const
{
return m_available_bytes;
}
uint64_t GetDroppedBytes() const
{
return m_dropped_bytes;
}
};
/**
* Fixed window rate limiter for logging.
*/
//! Fixed window rate limiter for logging.
class LogRateLimiter
{
public:
//! Keeps track of an individual source location and how many available bytes are left for logging from it.
struct Stats {
//! Remaining bytes
uint64_t m_available_bytes;
//! Number of bytes that were consumed but didn't fit in the available bytes.
uint64_t m_dropped_bytes{0};
Stats(uint64_t max_bytes) : m_available_bytes{max_bytes} {}
//! Updates internal accounting and returns true if enough available_bytes were remaining
bool Consume(uint64_t bytes);
};
private:
mutable StdMutex m_mutex;
//! Counters for each source location that has attempted to log something.
std::unordered_map<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.
//! Stats for each source location that has attempted to log something.
std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
//! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons.
std::atomic<bool> m_suppression_active{false};
LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
public:
using SchedulerFunction = std::function<void(std::function<void()>, std::chrono::milliseconds)>;
@@ -154,9 +142,12 @@ namespace BCLog {
* reset_window interval.
* @param max_bytes Maximum number of bytes that can be logged for each source
* location.
* @param reset_window Time window after which the byte counters are reset.
* @param reset_window Time window after which the stats are reset.
*/
LogRateLimiter(SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window);
static std::shared_ptr<LogRateLimiter> Create(
SchedulerFunction&& scheduler_func,
uint64_t max_bytes,
std::chrono::seconds reset_window);
//! Maximum number of bytes logged per location per window.
const uint64_t m_max_bytes;
//! Interval after which the window is reset.
@@ -201,7 +192,7 @@ namespace BCLog {
size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0};
//! Manages the rate limiting of each log location.
std::unique_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
std::shared_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);
@@ -270,7 +261,7 @@ namespace BCLog {
/** Only for testing */
void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
void SetRateLimiting(std::unique_ptr<LogRateLimiter>&& limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
void SetRateLimiting(std::shared_ptr<LogRateLimiter> limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
{
StdLockGuard scoped_lock(m_cs);
m_limiter = std::move(limiter);
@@ -343,7 +334,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve
bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str);
template <typename... 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)
inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
{
if (LogInstance().Enabled()) {
std::string log_msg;

288
src/test/logging_tests.cpp
View File

@@ -37,6 +37,16 @@ static void ResetLogger()
LogInstance().SetCategoryLogLevel({});
}
static std::vector<std::string> ReadDebugLogLines()
{
std::vector<std::string> lines;
std::ifstream ifs{LogInstance().m_file_path};
for (std::string line; std::getline(ifs, line);) {
lines.push_back(std::move(line));
}
return lines;
}
struct LogSetup : public BasicTestingSetup {
fs::path prev_log_path;
fs::path tmp_log_path;
@@ -47,6 +57,7 @@ struct LogSetup : public BasicTestingSetup {
bool prev_log_sourcelocations;
std::unordered_map<BCLog::LogFlags, BCLog::Level> prev_category_levels;
BCLog::Level prev_log_level;
BCLog::CategoryMask prev_category_mask;
LogSetup() : prev_log_path{LogInstance().m_file_path},
tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
@@ -56,7 +67,8 @@ struct LogSetup : public BasicTestingSetup {
prev_log_threadnames{LogInstance().m_log_threadnames},
prev_log_sourcelocations{LogInstance().m_log_sourcelocations},
prev_category_levels{LogInstance().CategoryLevels()},
prev_log_level{LogInstance().LogLevel()}
prev_log_level{LogInstance().LogLevel()},
prev_category_mask{LogInstance().GetCategoryMask()}
{
LogInstance().m_file_path = tmp_log_path;
LogInstance().m_reopen_file = true;
@@ -68,7 +80,9 @@ struct LogSetup : public BasicTestingSetup {
LogInstance().m_log_sourcelocations = false;
LogInstance().SetLogLevel(BCLog::Level::Debug);
LogInstance().DisableCategory(BCLog::LogFlags::ALL);
LogInstance().SetCategoryLogLevel({});
LogInstance().SetRateLimiting(nullptr);
}
~LogSetup()
@@ -82,6 +96,9 @@ struct LogSetup : public BasicTestingSetup {
LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
LogInstance().SetLogLevel(prev_log_level);
LogInstance().SetCategoryLogLevel(prev_category_levels);
LogInstance().SetRateLimiting(nullptr);
LogInstance().DisableCategory(BCLog::LogFlags::ALL);
LogInstance().EnableCategory(BCLog::LogFlags{prev_category_mask});
}
};
@@ -118,27 +135,20 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg));
LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false);
}
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> 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<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> log_lines{ReadDebugLogLines()};
std::vector<std::string> expected = {
"foo5: bar5",
"[net] foo7: bar7",
@@ -151,16 +161,13 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup)
BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
{
LogInstance().EnableCategory(BCLog::NET);
LogTrace(BCLog::NET, "foo6: %s", "bar6"); // not logged
LogDebug(BCLog::NET, "foo7: %s", "bar7");
LogInfo("foo8: %s", "bar8");
LogWarning("foo9: %s", "bar9");
LogError("foo10: %s", "bar10");
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> log_lines{ReadDebugLogLines()};
std::vector<std::string> expected = {
"[net] foo7: bar7",
"foo8: bar8",
@@ -192,19 +199,13 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
expected.push_back(expected_log);
}
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> log_lines{ReadDebugLogLines()};
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
}
BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
{
LogInstance().EnableCategory(BCLog::LogFlags::ALL);
LogInstance().SetLogLevel(BCLog::Level::Debug);
LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
// Global log level
@@ -225,11 +226,7 @@ BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
"[net:warning] foo5: bar5",
"[net:error] foo7: bar7",
};
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> log_lines{ReadDebugLogLines()};
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
}
@@ -294,22 +291,40 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
}
}
void MockForwardAndSync(CScheduler& scheduler, std::chrono::seconds duration)
{
scheduler.MockForward(duration);
std::promise<void> promise;
scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms);
promise.get_future().wait();
}
struct ScopedScheduler {
CScheduler scheduler{};
ScopedScheduler()
{
scheduler.m_service_thread = std::thread([this] { scheduler.serviceQueue(); });
}
~ScopedScheduler()
{
scheduler.stop();
}
void MockForwardAndSync(std::chrono::seconds duration)
{
scheduler.MockForward(duration);
std::promise<void> promise;
scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms);
promise.get_future().wait();
}
std::shared_ptr<BCLog::LogRateLimiter> GetLimiter(size_t max_bytes, std::chrono::seconds window)
{
auto sched_func = [this](auto func, auto w) {
scheduler.scheduleEvery(std::move(func), w);
};
return BCLog::LogRateLimiter::Create(sched_func, max_bytes, window);
}
};
BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
{
CScheduler scheduler{};
scheduler.m_service_thread = std::thread([&scheduler] { scheduler.serviceQueue(); });
uint64_t max_bytes{1024};
auto reset_window{1min};
auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); };
BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window};
ScopedScheduler scheduler{};
auto limiter_{scheduler.GetLimiter(max_bytes, reset_window)};
auto& limiter{*Assert(limiter_)};
using Status = BCLog::LogRateLimiter::Status;
auto source_loc_1{std::source_location::current()};
@@ -337,138 +352,137 @@ BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
BOOST_CHECK(limiter.SuppressionsActive());
// After reset_window time has passed, all suppressions should be cleared.
MockForwardAndSync(scheduler, reset_window);
scheduler.MockForwardAndSync(reset_window);
BOOST_CHECK(!limiter.SuppressionsActive());
BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
scheduler.stop();
}
BOOST_AUTO_TEST_CASE(logging_log_limit_stats)
{
BCLog::LogLimitStats counter{BCLog::RATELIMIT_MAX_BYTES};
BCLog::LogRateLimiter::Stats stats(BCLog::RATELIMIT_MAX_BYTES);
// Check that counter gets initialized correctly.
BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES);
BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull);
// Check that stats gets initialized correctly.
BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES);
BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
const uint64_t MESSAGE_SIZE{512 * 1024};
BOOST_CHECK(counter.Consume(MESSAGE_SIZE));
BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE);
BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull);
const uint64_t MESSAGE_SIZE{BCLog::RATELIMIT_MAX_BYTES / 2};
BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE);
BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
BOOST_CHECK(counter.Consume(MESSAGE_SIZE));
BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2);
BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull);
BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2);
BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
// Consuming more bytes after already having consumed 1MB should fail.
BOOST_CHECK(!counter.Consume(500));
BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), 0ull);
BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 500ull);
// Consuming more bytes after already having consumed RATELIMIT_MAX_BYTES should fail.
BOOST_CHECK(!stats.Consume(500));
BOOST_CHECK_EQUAL(stats.m_available_bytes, uint64_t{0});
BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{500});
}
void LogFromLocation(int location, std::string message)
{
namespace {
enum class Location {
INFO_1,
INFO_2,
DEBUG_LOG,
INFO_NOLIMIT,
};
void LogFromLocation(Location location, const std::string& message) {
switch (location) {
case 0:
case Location::INFO_1:
LogInfo("%s\n", message);
break;
case 1:
return;
case Location::INFO_2:
LogInfo("%s\n", message);
break;
case 2:
LogPrintLevel(BCLog::LogFlags::NONE, BCLog::Level::Info, "%s\n", message);
break;
case 3:
LogPrintLevel(BCLog::LogFlags::ALL, BCLog::Level::Info, "%s\n", message);
break;
return;
case Location::DEBUG_LOG:
LogDebug(BCLog::LogFlags::HTTP, "%s\n", message);
return;
case Location::INFO_NOLIMIT:
LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, "%s\n", message);
return;
} // no default case, so the compiler can warn about missing cases
assert(false);
}
/**
* For a given `location` and `message`, ensure that the on-disk debug log behaviour resembles what
* we'd expect it to be for `status` and `suppressions_active`.
*/
void TestLogFromLocation(Location location, const std::string& message,
BCLog::LogRateLimiter::Status status, bool suppressions_active,
std::source_location source = std::source_location::current())
{
using Status = BCLog::LogRateLimiter::Status;
if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error
std::ofstream ofs(LogInstance().m_file_path, std::ios::out | std::ios::trunc); // clear debug log
LogFromLocation(location, message);
auto log_lines{ReadDebugLogLines()};
BOOST_TEST_CONTEXT("TestLogFromLocation failed from " << source.file_name() << ":" << source.line())
{
if (status == Status::STILL_SUPPRESSED) {
BOOST_CHECK_EQUAL(log_lines.size(), 0);
return;
}
if (status == Status::NEWLY_SUPPRESSED) {
BOOST_REQUIRE_EQUAL(log_lines.size(), 2);
BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected"));
log_lines.erase(log_lines.begin());
}
BOOST_REQUIRE_EQUAL(log_lines.size(), 1);
auto& payload{log_lines.back()};
BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]"));
BOOST_CHECK(payload.ends_with(message));
}
}
void LogFromLocationAndExpect(int location, std::string message, std::string expect)
{
ASSERT_DEBUG_LOG(expect);
LogFromLocation(location, message);
}
} // namespace
BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
{
bool prev_log_timestamps = LogInstance().m_log_timestamps;
using Status = BCLog::LogRateLimiter::Status;
LogInstance().m_log_timestamps = false;
bool prev_log_sourcelocations = LogInstance().m_log_sourcelocations;
LogInstance().m_log_sourcelocations = false;
bool prev_log_threadnames = LogInstance().m_log_threadnames;
LogInstance().m_log_threadnames = false;
LogInstance().EnableCategory(BCLog::LogFlags::HTTP);
CScheduler scheduler{};
scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); });
auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); };
auto limiter = std::make_unique<BCLog::LogRateLimiter>(sched_func, 1024 * 1024, 20s);
LogInstance().SetRateLimiting(std::move(limiter));
constexpr int64_t line_length{1024};
constexpr int64_t num_lines{1024};
constexpr int64_t bytes_quota{line_length * num_lines};
constexpr auto time_window{20s};
// Log 1024-character lines (1023 plus newline) to make the math simple.
std::string log_message(1023, 'a');
ScopedScheduler scheduler{};
auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};
LogInstance().SetRateLimiting(limiter);
std::string utf8_path{LogInstance().m_file_path.utf8string()};
const char* log_path{utf8_path.c_str()};
const std::string log_message(line_length - 1, 'a'); // subtract one for newline
// Use GetFileSize because fs::file_size may require a flush to be accurate.
std::streamsize log_file_size{static_cast<std::streamsize>(GetFileSize(log_path))};
// Logging 1 MiB should be allowed.
for (int i = 0; i < 1024; ++i) {
LogFromLocation(0, log_message);
for (int i = 0; i < num_lines; ++i) {
TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
}
BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "should be able to log 1 MiB from location 0");
log_file_size = GetFileSize(log_path);
BOOST_CHECK_NO_THROW(LogFromLocationAndExpect(0, log_message, "Excessive logging detected"));
BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the start of the suppression period should be logged");
log_file_size = GetFileSize(log_path);
for (int i = 0; i < 1024; ++i) {
LogFromLocation(0, log_message);
}
BOOST_CHECK_MESSAGE(log_file_size == GetFileSize(log_path), "all further logs from location 0 should be dropped");
BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Excessive logging detected"), std::runtime_error);
BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 1 should be unaffected by other locations");
log_file_size = GetFileSize(log_path);
TestLogFromLocation(Location::INFO_1, "a", Status::NEWLY_SUPPRESSED, /*suppressions_active=*/true);
TestLogFromLocation(Location::INFO_1, "b", Status::STILL_SUPPRESSED, /*suppressions_active=*/true);
TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true);
{
ASSERT_DEBUG_LOG("Restarting logging");
MockForwardAndSync(scheduler, 1min);
scheduler.MockForwardAndSync(time_window);
BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging"));
}
BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the end of the suppression period should be logged");
BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Restarting logging"), std::runtime_error);
// Attempt to log 1MiB from location 2 and 1MiB from location 3. These exempt locations should be allowed to log
// without limit.
log_file_size = GetFileSize(log_path);
for (int i = 0; i < 1024; ++i) {
BOOST_CHECK_THROW(LogFromLocationAndExpect(2, log_message, "Excessive logging detected"), std::runtime_error);
// Check that logging from previously suppressed location is unsuppressed again.
TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
// Check that conditional logging, and unconditional logging with should_ratelimit=false is
// not being ratelimited.
for (Location location : {Location::DEBUG_LOG, Location::INFO_NOLIMIT}) {
for (int i = 0; i < num_lines + 2; ++i) {
TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
}
}
BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 2 should be exempt from rate limiting");
log_file_size = GetFileSize(log_path);
for (int i = 0; i < 1024; ++i) {
BOOST_CHECK_THROW(LogFromLocationAndExpect(3, log_message, "Excessive logging detected"), std::runtime_error);
}
BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 3 should be exempt from rate limiting");
LogInstance().m_log_timestamps = prev_log_timestamps;
LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
LogInstance().m_log_threadnames = prev_log_threadnames;
scheduler.stop();
LogInstance().SetRateLimiting(nullptr);
}
BOOST_AUTO_TEST_SUITE_END()

2
src/test/util/logging.h
View File

@@ -33,8 +33,6 @@ class DebugLogHelper
public:
explicit DebugLogHelper(std::string message, MatchFn match = [](const std::string*){ return true; });
//! Mark as noexcept(false) to catch any thrown exceptions.
~DebugLogHelper() noexcept(false) { check_found(); }
};

2
test/functional/test_framework/test_node.py
View File

@@ -136,6 +136,8 @@ class TestNode():
self.args.append("-logsourcelocations")
if self.version_is_at_least(239000):
self.args.append("-loglevel=trace")
if self.version_is_at_least(299900):
self.args.append("-nologratelimit")
# Default behavior from global -v2transport flag is added to args to persist it over restarts.
# May be overwritten in individual tests, using extra_args.