log: introduce LogRateLimiter, LogLimitStats, Status

LogRateLimiter will be used to keep track of source locations and our
current time-based logging window. It contains an unordered_map and a
m_suppressions_active bool to track source locations. The map is keyed
by std::source_location, so a custom Hash function (SourceLocationHasher)
and custom KeyEqual function (SourceLocationEqual) is provided.
SourceLocationHasher uses CSipHasher(0,0) under the hood to get a
uniform distribution.

A public Reset method is provided so that a scheduler (e.g. the
"b-scheduler" thread) can periodically reset LogRateLimiter's state when
the time window has elapsed.

The LogRateLimiter::Consume method checks if we have enough available
bytes in our rate limiting budget to log an additional string. It
returns a Status enum that denotes the rate limiting status and can
be used by the caller to emit a warning, skip logging, etc.

The Status enum has three states:
- UNSUPPRESSED     (logging was successful)
- NEWLY_SUPPRESSED (logging was succcesful, next log will be suppressed)
- STILL_SUPPRESSED (logging was unsuccessful)

LogLimitStats counts the available bytes left for logging per source
location for the current logging window. It does not track actual source
locations; it is used as a value in m_source_locations.

Also exposes a SuppressionsActive() method so the logger can use
that in a later commit to prefix [*] to logs whenenever suppressions
are active.

Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
Co-Authored-By: stickies-v <stickies-v@protonmail.com>

Github-Pull: #32604
Rebased-From: afb9e39ec5
This commit is contained in:
Eugene Siegel
2025-06-05 12:19:28 -04:00
committed by fanquake
parent 4987c03531
commit 41262cc4d5
3 changed files with 227 additions and 0 deletions

View File

@@ -5,11 +5,13 @@
#include <init/common.h>
#include <logging.h>
#include <logging/timer.h>
#include <scheduler.h>
#include <test/util/setup_common.h>
#include <util/string.h>
#include <chrono>
#include <fstream>
#include <future>
#include <iostream>
#include <unordered_map>
#include <utility>
@@ -276,4 +278,79 @@ 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);
}
BOOST_AUTO_TEST_SUITE_END()