mirror of
https://github.com/ElementsProject/elements.git
synced 2026-08-13 12:33:42 +02:00
Merge c5196bc9c4 into merged_master (Bitcoin PR bitcoin/bitcoin#33225)
This commit is contained in:
ivanlele
commit
7ae876ad52
10 changed files with 512 additions and 89 deletions
|
|
@ -48,6 +48,17 @@ Notable changes
|
|||
|
||||
- #32521 policy: make pathological transactions packed with legacy sigops non-standard
|
||||
|
||||
### 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)
|
||||
|
||||
### RPC
|
||||
|
||||
- The `dumptxoutset` RPC now requires a `type` parameter to be specified. To maintain pre
|
||||
|
|
@ -163,6 +174,7 @@ Thanks to everyone who directly contributed to this release:
|
|||
- brunoerg
|
||||
- Bufo
|
||||
- Christewart
|
||||
- Crypt-iQ
|
||||
- davidgumberg
|
||||
- deadmanoz
|
||||
- dergoegge
|
||||
|
|
|
|||
|
|
@ -1537,6 +1537,15 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
|
|||
}
|
||||
}, std::chrono::minutes{5});
|
||||
|
||||
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));
|
||||
auto& validation_signals = *node.validation_signals;
|
||||
|
|
|
|||
|
|
@ -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);
|
||||
}
|
||||
|
|
|
|||
126
src/logging.cpp
126
src/logging.cpp
|
|
@ -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,50 @@ 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(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)
|
||||
{
|
||||
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(
|
||||
const std::source_location& source_loc,
|
||||
const std::string& str)
|
||||
{
|
||||
StdLockGuard scoped_lock(m_mutex);
|
||||
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 (!stats.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 +419,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 +458,31 @@ 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 == 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.",
|
||||
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;
|
||||
}
|
||||
}
|
||||
|
||||
// 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) {
|
||||
// print to console
|
||||
|
|
@ -434,7 +492,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 +550,36 @@ 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, stats] : source_locations) {
|
||||
if (stats.m_dropped_bytes == 0) continue;
|
||||
LogPrintLevel_(
|
||||
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(),
|
||||
stats.m_dropped_bytes, Ticks<std::chrono::seconds>(m_reset_window));
|
||||
}
|
||||
}
|
||||
|
||||
bool BCLog::LogRateLimiter::Stats::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);
|
||||
|
|
|
|||
137
src/logging.h
137
src/logging.h
|
|
@ -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,15 @@
|
|||
|
||||
#include <atomic>
|
||||
#include <cstdint>
|
||||
#include <cstring>
|
||||
#include <functional>
|
||||
#include <list>
|
||||
#include <memory>
|
||||
#include <mutex>
|
||||
#include <source_location>
|
||||
#include <string>
|
||||
#include <unordered_map>
|
||||
#include <unordered_set>
|
||||
#include <vector>
|
||||
|
||||
static const bool DEFAULT_LOGTIMEMICROS = false;
|
||||
|
|
@ -31,6 +36,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 size_t(CSipHasher(0, 0)
|
||||
.Write(s.line())
|
||||
.Write(MakeUCharSpan(std::string_view{s.file_name()}))
|
||||
.Finalize());
|
||||
}
|
||||
};
|
||||
|
||||
struct LogCategory {
|
||||
std::string category;
|
||||
bool active;
|
||||
|
|
@ -82,6 +105,69 @@ 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 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};
|
||||
|
||||
//! 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;
|
||||
|
||||
//! 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)>;
|
||||
/**
|
||||
* @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 stats are reset.
|
||||
*/
|
||||
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.
|
||||
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 +175,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 +191,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::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);
|
||||
|
||||
|
|
@ -115,7 +204,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 +212,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 +231,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 +261,12 @@ namespace BCLog {
|
|||
/** Only for testing */
|
||||
void DisconnectTestLogger() 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);
|
||||
}
|
||||
|
||||
/** Disable logging
|
||||
* This offers a slight speedup and slightly smaller memory usage
|
||||
* compared to leaving the logging system in its default state.
|
||||
|
|
@ -239,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::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, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
|
||||
{
|
||||
if (LogInstance().Enabled()) {
|
||||
std::string log_msg;
|
||||
|
|
@ -248,19 +343,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 +363,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.
|
||||
|
|
|
|||
|
|
@ -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>
|
||||
|
|
@ -28,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;
|
||||
|
|
@ -38,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"},
|
||||
|
|
@ -47,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;
|
||||
|
|
@ -59,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()
|
||||
|
|
@ -73,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});
|
||||
}
|
||||
};
|
||||
|
||||
|
|
@ -86,41 +112,43 @@ 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);
|
||||
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",
|
||||
|
||||
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::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",
|
||||
|
|
@ -133,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",
|
||||
|
|
@ -174,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
|
||||
|
|
@ -207,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());
|
||||
}
|
||||
|
||||
|
|
@ -276,4 +291,197 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
|
|||
}
|
||||
}
|
||||
|
||||
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)
|
||||
{
|
||||
uint64_t max_bytes{1024};
|
||||
auto reset_window{1min};
|
||||
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()};
|
||||
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.
|
||||
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);
|
||||
}
|
||||
|
||||
BOOST_AUTO_TEST_CASE(logging_log_limit_stats)
|
||||
{
|
||||
BCLog::LogRateLimiter::Stats stats(BCLog::RATELIMIT_MAX_BYTES);
|
||||
|
||||
// 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{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(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 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});
|
||||
}
|
||||
|
||||
namespace {
|
||||
|
||||
enum class Location {
|
||||
INFO_1,
|
||||
INFO_2,
|
||||
DEBUG_LOG,
|
||||
INFO_NOLIMIT,
|
||||
};
|
||||
|
||||
void LogFromLocation(Location location, const std::string& message) {
|
||||
switch (location) {
|
||||
case Location::INFO_1:
|
||||
LogInfo("%s\n", message);
|
||||
return;
|
||||
case Location::INFO_2:
|
||||
LogInfo("%s\n", message);
|
||||
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())
|
||||
{
|
||||
BOOST_TEST_INFO_SCOPE("TestLogFromLocation called from " << source.file_name() << ":" << source.line());
|
||||
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_INFO_SCOPE(log_lines.size() << " log_lines read: \n" << util::Join(log_lines, "\n"));
|
||||
|
||||
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));
|
||||
}
|
||||
|
||||
} // namespace
|
||||
|
||||
BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
|
||||
{
|
||||
using Status = BCLog::LogRateLimiter::Status;
|
||||
LogInstance().m_log_timestamps = false;
|
||||
LogInstance().m_log_sourcelocations = false;
|
||||
LogInstance().m_log_threadnames = false;
|
||||
LogInstance().EnableCategory(BCLog::LogFlags::HTTP);
|
||||
|
||||
constexpr int64_t line_length{1024};
|
||||
constexpr int64_t num_lines{10};
|
||||
constexpr int64_t bytes_quota{line_length * num_lines};
|
||||
constexpr auto time_window{1h};
|
||||
|
||||
ScopedScheduler scheduler{};
|
||||
auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};
|
||||
LogInstance().SetRateLimiting(limiter);
|
||||
|
||||
const std::string log_message(line_length - 1, 'a'); // subtract one for newline
|
||||
|
||||
for (int i = 0; i < num_lines; ++i) {
|
||||
TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
|
||||
}
|
||||
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);
|
||||
{
|
||||
scheduler.MockForwardAndSync(time_window);
|
||||
BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging"));
|
||||
}
|
||||
// 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_AUTO_TEST_SUITE_END()
|
||||
|
|
|
|||
|
|
@ -33,7 +33,7 @@ class DebugLogHelper
|
|||
|
||||
public:
|
||||
explicit DebugLogHelper(std::string message, MatchFn match = [](const std::string*){ return true; });
|
||||
~DebugLogHelper() { check_found(); }
|
||||
~DebugLogHelper() noexcept(false) { check_found(); }
|
||||
};
|
||||
|
||||
#define ASSERT_DEBUG_LOG(message) DebugLogHelper UNIQUE_NAME(debugloghelper)(message)
|
||||
|
|
|
|||
|
|
@ -3445,15 +3445,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 ForceUntrimHeader(const CBlockIndex *pindex_) EXCLUSIVE_LOCKS_REQUIRED(::cs_main)
|
||||
|
|
|
|||
|
|
@ -81,7 +81,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 "elements.conf" file which is explicitly ignored using -noconf.']
|
||||
ignored_file_message = [f'Data directory "{self.nodes[0].datadir_path}" contains a "elements.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)
|
||||
|
|
|
|||
|
|
@ -137,6 +137,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.
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue