mirror of
https://github.com/bitcoin/bitcoin.git
synced 2026-03-25 23:16:16 +01:00
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>
This commit is contained in:
@@ -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()
|
||||
|
||||
Reference in New Issue
Block a user