mirror of
https://github.com/ElementsProject/elements.git
synced 2026-08-13 12:33:42 +02:00
Merge ElementsProject/elements#1514: Mitigate disk filling attacks by rate limiting Log writing
d23b6c86d0[log] Introduce log rate limiter class (Niklas Gögge)817c68a64fMerge bitcoin/bitcoin#24464: logging: Add severity level to logs (laanwj) Pull request description: Mitigation of [CVE-2025-54604](https://bitcoincore.org/en/2025/10/24/disclose-cve-2025-54604/) and [CVE-2025-54605 - Disk filling from invalid blocks](https://bitcoincore.org/en/2025/10/24/disclose-cve-2025-54605/) Port of https://github.com/bitcoin/bitcoin/pull/21603 (the later PR merged for inclusion in bitcoin v30 https://github.com/bitcoin/bitcoin/pull/32604 relies on `std::source_location` in C++20). 21603 implements `SourceLocation ` and `SourceLocationHasher` for use with C++17. Dependent on: bitcoin/bitcoin#24464: logging: Add severity level to logs ACKs for top commit: delta1: ACKd23b6c86d0Tree-SHA512: 0e49eb9fa46e65c7f5deb5f4cc40f25812756510fbe7eb16140e482e0259c91b4584e65cb43a7d83b7aa9dcf586fd26436aed4efa2757de32cc3f3c3a71acbf0
This commit is contained in:
merge-script
commit
53dc403306
10 changed files with 619 additions and 62 deletions
|
|
@ -76,6 +76,7 @@ void AddLoggingArgs(ArgsManager& argsman)
|
|||
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("-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);
|
||||
argsman.AddArg("-ratelimitlogging", strprintf("Rate limit unconditional logging to disk (default: %u)", DEFAULT_RATELIMITLOGGING), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS);
|
||||
}
|
||||
|
||||
void SetLoggingOptions(const ArgsManager& args)
|
||||
|
|
@ -89,6 +90,7 @@ void SetLoggingOptions(const ArgsManager& args)
|
|||
LogInstance().m_log_threadnames = args.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
|
||||
#endif
|
||||
LogInstance().m_log_sourcelocations = args.GetBoolArg("-logsourcelocations", DEFAULT_LOGSOURCELOCATIONS);
|
||||
LogInstance().m_ratelimit = args.GetBoolArg("-ratelimitlogging", DEFAULT_RATELIMITLOGGING);
|
||||
|
||||
fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
|
||||
}
|
||||
|
|
|
|||
187
src/logging.cpp
187
src/logging.cpp
|
|
@ -7,7 +7,6 @@
|
|||
#include <logging.h>
|
||||
#include <util/threadnames.h>
|
||||
#include <util/string.h>
|
||||
#include <util/time.h>
|
||||
|
||||
#include <algorithm>
|
||||
#include <array>
|
||||
|
|
@ -124,7 +123,7 @@ bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
|
|||
|
||||
bool BCLog::Logger::DefaultShrinkDebugFile() const
|
||||
{
|
||||
return m_categories == BCLog::NONE;
|
||||
return m_categories == DEFAULT_LOG_FLAGS;
|
||||
}
|
||||
|
||||
struct CLogCategoryDesc {
|
||||
|
|
@ -165,13 +164,15 @@ const CLogCategoryDesc LogCategories[] =
|
|||
#endif
|
||||
{BCLog::UTIL, "util"},
|
||||
{BCLog::BLOCKSTORE, "blockstorage"},
|
||||
{BCLog::UNCONDITIONAL_RATE_LIMITED, "uncond_rate_limited"},
|
||||
{BCLog::UNCONDITIONAL_ALWAYS, "uncond_always"},
|
||||
{BCLog::ALL, "1"},
|
||||
{BCLog::ALL, "all"},
|
||||
};
|
||||
|
||||
bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
|
||||
{
|
||||
if (str == "") {
|
||||
if (str.empty()) {
|
||||
flag = BCLog::ALL;
|
||||
return true;
|
||||
}
|
||||
|
|
@ -184,6 +185,95 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
|
|||
return false;
|
||||
}
|
||||
|
||||
std::string LogLevelToStr(BCLog::Level level)
|
||||
{
|
||||
switch (level) {
|
||||
case BCLog::Level::None:
|
||||
return "none";
|
||||
case BCLog::Level::Debug:
|
||||
return "debug";
|
||||
case BCLog::Level::Info:
|
||||
return "info";
|
||||
case BCLog::Level::Warning:
|
||||
return "warning";
|
||||
case BCLog::Level::Error:
|
||||
return "error";
|
||||
}
|
||||
assert(false);
|
||||
}
|
||||
|
||||
std::string LogCategoryToStr(BCLog::LogFlags category)
|
||||
{
|
||||
// Each log category string representation should sync with LogCategories
|
||||
switch (category) {
|
||||
case BCLog::LogFlags::NONE:
|
||||
return "none";
|
||||
case BCLog::LogFlags::NET:
|
||||
return "net";
|
||||
case BCLog::LogFlags::TOR:
|
||||
return "tor";
|
||||
case BCLog::LogFlags::MEMPOOL:
|
||||
return "mempool";
|
||||
case BCLog::LogFlags::HTTP:
|
||||
return "http";
|
||||
case BCLog::LogFlags::BENCH:
|
||||
return "bench";
|
||||
case BCLog::LogFlags::ZMQ:
|
||||
return "zmq";
|
||||
case BCLog::LogFlags::WALLETDB:
|
||||
return "walletdb";
|
||||
case BCLog::LogFlags::RPC:
|
||||
return "rpc";
|
||||
case BCLog::LogFlags::ESTIMATEFEE:
|
||||
return "estimatefee";
|
||||
case BCLog::LogFlags::ADDRMAN:
|
||||
return "addrman";
|
||||
case BCLog::LogFlags::SELECTCOINS:
|
||||
return "selectcoins";
|
||||
case BCLog::LogFlags::REINDEX:
|
||||
return "reindex";
|
||||
case BCLog::LogFlags::CMPCTBLOCK:
|
||||
return "cmpctblock";
|
||||
case BCLog::LogFlags::RAND:
|
||||
return "rand";
|
||||
case BCLog::LogFlags::PRUNE:
|
||||
return "prune";
|
||||
case BCLog::LogFlags::PROXY:
|
||||
return "proxy";
|
||||
case BCLog::LogFlags::MEMPOOLREJ:
|
||||
return "mempoolrej";
|
||||
case BCLog::LogFlags::LIBEVENT:
|
||||
return "libevent";
|
||||
case BCLog::LogFlags::COINDB:
|
||||
return "coindb";
|
||||
case BCLog::LogFlags::QT:
|
||||
return "qt";
|
||||
case BCLog::LogFlags::LEVELDB:
|
||||
return "leveldb";
|
||||
case BCLog::LogFlags::VALIDATION:
|
||||
return "validation";
|
||||
case BCLog::LogFlags::I2P:
|
||||
return "i2p";
|
||||
case BCLog::LogFlags::IPC:
|
||||
return "ipc";
|
||||
#ifdef DEBUG_LOCKCONTENTION
|
||||
case BCLog::LogFlags::LOCK:
|
||||
return "lock";
|
||||
#endif
|
||||
case BCLog::LogFlags::UTIL:
|
||||
return "util";
|
||||
case BCLog::LogFlags::BLOCKSTORE:
|
||||
return "blockstorage";
|
||||
case BCLog::LogFlags::UNCONDITIONAL_RATE_LIMITED:
|
||||
return "uncond_rate_limited";
|
||||
case BCLog::LogFlags::UNCONDITIONAL_ALWAYS:
|
||||
return "uncond_always";
|
||||
case BCLog::LogFlags::ALL:
|
||||
return "all";
|
||||
}
|
||||
assert(false);
|
||||
}
|
||||
|
||||
std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
|
||||
{
|
||||
// Sort log categories by alphabetical order.
|
||||
|
|
@ -249,13 +339,36 @@ namespace BCLog {
|
|||
}
|
||||
} // namespace BCLog
|
||||
|
||||
void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line)
|
||||
void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function,
|
||||
const SourceLocation& source_location, const BCLog::LogFlags category,
|
||||
const BCLog::Level level)
|
||||
{
|
||||
StdLockGuard scoped_lock(m_cs);
|
||||
std::string str_prefixed = LogEscapeMessage(str);
|
||||
|
||||
const bool print_category{category != LogFlags::NONE && category != LogFlags::UNCONDITIONAL_ALWAYS && category != LogFlags::UNCONDITIONAL_RATE_LIMITED};
|
||||
if ((print_category || level != Level::None) && m_started_new_line) {
|
||||
std::string s{"["};
|
||||
|
||||
if (print_category) {
|
||||
s += LogCategoryToStr(category);
|
||||
}
|
||||
|
||||
if (print_category && level != Level::None) {
|
||||
// Only add separator if both flag and level are not NONE
|
||||
s += ":";
|
||||
}
|
||||
|
||||
if (level != Level::None) {
|
||||
s += LogLevelToStr(level);
|
||||
}
|
||||
|
||||
s += "] ";
|
||||
str_prefixed.insert(0, s);
|
||||
}
|
||||
|
||||
if (m_log_sourcelocations && m_started_new_line) {
|
||||
str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
|
||||
str_prefixed.insert(0, "[" + RemovePrefix(source_location.m_file, "./") + ":" + ToString(source_location.m_line) + "] [" + logging_function + "] ");
|
||||
}
|
||||
|
||||
if (m_log_threadnames && m_started_new_line) {
|
||||
|
|
@ -264,7 +377,43 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi
|
|||
|
||||
str_prefixed = LogTimestampStr(str_prefixed);
|
||||
|
||||
m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
|
||||
// Whether or not logging to disk was/is ratelimited for this source location.
|
||||
bool was_ratelimited{false};
|
||||
bool is_ratelimited{false};
|
||||
|
||||
if (category == UNCONDITIONAL_RATE_LIMITED && m_ratelimit) {
|
||||
was_ratelimited = m_supressed_locations.find(source_location) != m_supressed_locations.end();
|
||||
is_ratelimited = !m_ratelimiters[source_location].Consume(str_prefixed.size());
|
||||
|
||||
if (!is_ratelimited && was_ratelimited) {
|
||||
// Logging will restart for this source location.
|
||||
m_supressed_locations.erase(source_location);
|
||||
|
||||
str_prefixed = LogTimestampStr(strprintf(
|
||||
"Restarting logging from %s:%d (%s): "
|
||||
"(%d MiB) were dropped during the last hour.\n%s",
|
||||
source_location.m_file, source_location.m_line, logging_function,
|
||||
m_ratelimiters[source_location].GetDroppedBytes() / (1024 * 1024), str_prefixed));
|
||||
} else if (is_ratelimited && !was_ratelimited) {
|
||||
// Logging from this source location will be supressed until the current window resets.
|
||||
m_supressed_locations.insert(source_location);
|
||||
|
||||
str_prefixed = LogTimestampStr(strprintf(
|
||||
"Excessive logging detected from %s:%d (%s): >%d MiB logged during the last hour."
|
||||
"Suppressing logging to disk from this source location for up to one hour. "
|
||||
"Console logging unaffected. Last log entry: %s",
|
||||
source_location.m_file, source_location.m_line, logging_function,
|
||||
LogRateLimiter::WINDOW_MAX_BYTES / (1024 * 1024), str_prefixed));
|
||||
}
|
||||
}
|
||||
|
||||
// To avoid confusion caused by dropped log messages when debugging an issue,
|
||||
// we prefix log lines with "[*]" when there are any supressed source locations.
|
||||
if (m_supressed_locations.size() > 0) {
|
||||
str_prefixed.insert(0, "[*] ");
|
||||
}
|
||||
|
||||
m_started_new_line = !str.empty() && str[str.size() - 1] == '\n';
|
||||
|
||||
if (m_buffering) {
|
||||
// buffer if we haven't started logging yet
|
||||
|
|
@ -280,7 +429,7 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi
|
|||
for (const auto& cb : m_print_callbacks) {
|
||||
cb(str_prefixed);
|
||||
}
|
||||
if (m_print_to_file) {
|
||||
if (m_print_to_file && !(is_ratelimited && was_ratelimited)) {
|
||||
assert(m_fileout != nullptr);
|
||||
|
||||
// reopen the log file, if requested
|
||||
|
|
@ -337,3 +486,27 @@ void BCLog::Logger::ShrinkDebugFile()
|
|||
else if (file != nullptr)
|
||||
fclose(file);
|
||||
}
|
||||
|
||||
void BCLog::LogRateLimiter::MaybeReset()
|
||||
{
|
||||
const auto now{NodeClock::now()};
|
||||
if ((now - m_last_reset) >= WINDOW_SIZE) {
|
||||
m_available_bytes = WINDOW_MAX_BYTES;
|
||||
m_last_reset = now;
|
||||
m_dropped_bytes = 0;
|
||||
}
|
||||
}
|
||||
|
||||
bool BCLog::LogRateLimiter::Consume(uint64_t bytes)
|
||||
{
|
||||
MaybeReset();
|
||||
|
||||
if (bytes > m_available_bytes) {
|
||||
m_dropped_bytes += bytes;
|
||||
m_available_bytes = 0;
|
||||
return false;
|
||||
}
|
||||
|
||||
m_available_bytes -= bytes;
|
||||
return true;
|
||||
}
|
||||
|
|
|
|||
180
src/logging.h
180
src/logging.h
|
|
@ -6,10 +6,12 @@
|
|||
#ifndef BITCOIN_LOGGING_H
|
||||
#define BITCOIN_LOGGING_H
|
||||
|
||||
#include <crypto/siphash.h>
|
||||
#include <fs.h>
|
||||
#include <tinyformat.h>
|
||||
#include <threadsafety.h>
|
||||
#include <util/string.h>
|
||||
#include <util/time.h>
|
||||
|
||||
#include <atomic>
|
||||
#include <cstdint>
|
||||
|
|
@ -17,6 +19,8 @@
|
|||
#include <list>
|
||||
#include <mutex>
|
||||
#include <string>
|
||||
#include <unordered_map>
|
||||
#include <unordered_set>
|
||||
#include <vector>
|
||||
|
||||
static const bool DEFAULT_LOGTIMEMICROS = false;
|
||||
|
|
@ -24,10 +28,34 @@ static const bool DEFAULT_LOGIPS = false;
|
|||
static const bool DEFAULT_LOGTIMESTAMPS = true;
|
||||
static const bool DEFAULT_LOGTHREADNAMES = false;
|
||||
static const bool DEFAULT_LOGSOURCELOCATIONS = false;
|
||||
static constexpr bool DEFAULT_RATELIMITLOGGING{true};
|
||||
extern const char * const DEFAULT_DEBUGLOGFILE;
|
||||
|
||||
extern bool fLogIPs;
|
||||
|
||||
// TODO: use C++20 std::sourcelocation when available
|
||||
struct SourceLocation {
|
||||
std::string m_file;
|
||||
int m_line{0};
|
||||
|
||||
bool operator==(const SourceLocation& other) const
|
||||
{
|
||||
return m_file.compare(other.m_file) == 0 &&
|
||||
m_line == other.m_line;
|
||||
}
|
||||
};
|
||||
|
||||
struct SourceLocationHasher {
|
||||
size_t operator()(const SourceLocation& source_location) 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>{}(source_location.m_file))
|
||||
.Write(std::hash<int>{}(source_location.m_line))
|
||||
.Finalize());
|
||||
}
|
||||
};
|
||||
|
||||
struct LogCategory {
|
||||
std::string category;
|
||||
bool active;
|
||||
|
|
@ -35,37 +63,85 @@ struct LogCategory {
|
|||
|
||||
namespace BCLog {
|
||||
enum LogFlags : uint32_t {
|
||||
NONE = 0,
|
||||
NET = (1 << 0),
|
||||
TOR = (1 << 1),
|
||||
MEMPOOL = (1 << 2),
|
||||
HTTP = (1 << 3),
|
||||
BENCH = (1 << 4),
|
||||
ZMQ = (1 << 5),
|
||||
WALLETDB = (1 << 6),
|
||||
RPC = (1 << 7),
|
||||
ESTIMATEFEE = (1 << 8),
|
||||
ADDRMAN = (1 << 9),
|
||||
SELECTCOINS = (1 << 10),
|
||||
REINDEX = (1 << 11),
|
||||
CMPCTBLOCK = (1 << 12),
|
||||
RAND = (1 << 13),
|
||||
PRUNE = (1 << 14),
|
||||
PROXY = (1 << 15),
|
||||
MEMPOOLREJ = (1 << 16),
|
||||
LIBEVENT = (1 << 17),
|
||||
COINDB = (1 << 18),
|
||||
QT = (1 << 19),
|
||||
LEVELDB = (1 << 20),
|
||||
VALIDATION = (1 << 21),
|
||||
I2P = (1 << 22),
|
||||
IPC = (1 << 23),
|
||||
NONE = 0,
|
||||
NET = (1 << 0),
|
||||
TOR = (1 << 1),
|
||||
MEMPOOL = (1 << 2),
|
||||
HTTP = (1 << 3),
|
||||
BENCH = (1 << 4),
|
||||
ZMQ = (1 << 5),
|
||||
WALLETDB = (1 << 6),
|
||||
RPC = (1 << 7),
|
||||
ESTIMATEFEE = (1 << 8),
|
||||
ADDRMAN = (1 << 9),
|
||||
SELECTCOINS = (1 << 10),
|
||||
REINDEX = (1 << 11),
|
||||
CMPCTBLOCK = (1 << 12),
|
||||
RAND = (1 << 13),
|
||||
PRUNE = (1 << 14),
|
||||
PROXY = (1 << 15),
|
||||
MEMPOOLREJ = (1 << 16),
|
||||
LIBEVENT = (1 << 17),
|
||||
COINDB = (1 << 18),
|
||||
QT = (1 << 19),
|
||||
LEVELDB = (1 << 20),
|
||||
VALIDATION = (1 << 21),
|
||||
I2P = (1 << 22),
|
||||
IPC = (1 << 23),
|
||||
#ifdef DEBUG_LOCKCONTENTION
|
||||
LOCK = (1 << 24),
|
||||
LOCK = (1 << 24),
|
||||
#endif
|
||||
UTIL = (1 << 25),
|
||||
BLOCKSTORE = (1 << 26),
|
||||
ALL = ~(uint32_t)0,
|
||||
UTIL = (1 << 25),
|
||||
BLOCKSTORE = (1 << 26),
|
||||
UNCONDITIONAL_RATE_LIMITED = (1 << 27),
|
||||
UNCONDITIONAL_ALWAYS = (1 << 28),
|
||||
ALL = ~(uint32_t)0,
|
||||
};
|
||||
enum class Level {
|
||||
Debug = 0,
|
||||
None = 1,
|
||||
Info = 2,
|
||||
Warning = 3,
|
||||
Error = 4,
|
||||
};
|
||||
|
||||
static constexpr LogFlags DEFAULT_LOG_FLAGS{UNCONDITIONAL_RATE_LIMITED | UNCONDITIONAL_ALWAYS};
|
||||
|
||||
//! Fixed window rate limiter for logging.
|
||||
class LogRateLimiter
|
||||
{
|
||||
private:
|
||||
//! Timestamp of the last window reset.
|
||||
std::chrono::time_point<NodeClock> m_last_reset;
|
||||
//! Remaining bytes in the current window interval.
|
||||
uint64_t m_available_bytes{WINDOW_MAX_BYTES};
|
||||
//! Number of bytes that were not consumed within the current window.
|
||||
uint64_t m_dropped_bytes{0};
|
||||
//! Reset the window if the window interval has passed since the last reset.
|
||||
void MaybeReset();
|
||||
|
||||
public:
|
||||
//! Interval after which the window is reset.
|
||||
static constexpr std::chrono::hours WINDOW_SIZE{1};
|
||||
//! The maximum number of bytes that can be logged within one window.
|
||||
static constexpr uint64_t WINDOW_MAX_BYTES{1024 * 1024};
|
||||
|
||||
LogRateLimiter() : m_last_reset{NodeClock::now()} {}
|
||||
|
||||
//! Consume bytes from the window if enough bytes are available.
|
||||
//!
|
||||
//! Returns whether or not 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;
|
||||
}
|
||||
};
|
||||
|
||||
class Logger
|
||||
|
|
@ -77,6 +153,11 @@ namespace BCLog {
|
|||
std::list<std::string> m_msgs_before_open GUARDED_BY(m_cs);
|
||||
bool m_buffering GUARDED_BY(m_cs) = true; //!< Buffer messages before logging can be started.
|
||||
|
||||
//! Fixed window rate limiters for each source location that has attempted to log something.
|
||||
std::unordered_map<SourceLocation, LogRateLimiter, SourceLocationHasher> m_ratelimiters GUARDED_BY(m_cs);
|
||||
//! Set of source file locations that were dropped on the last log attempt.
|
||||
std::unordered_set<SourceLocation, SourceLocationHasher> m_supressed_locations GUARDED_BY(m_cs);
|
||||
|
||||
/**
|
||||
* m_started_new_line is a state variable that will suppress printing of
|
||||
* the timestamp when multiple calls are made that don't end in a
|
||||
|
|
@ -85,7 +166,7 @@ namespace BCLog {
|
|||
std::atomic_bool m_started_new_line{true};
|
||||
|
||||
/** Log categories bitfield. */
|
||||
std::atomic<uint32_t> m_categories{0};
|
||||
std::atomic<uint32_t> m_categories{DEFAULT_LOG_FLAGS};
|
||||
|
||||
std::string LogTimestampStr(const std::string& str);
|
||||
|
||||
|
|
@ -100,12 +181,15 @@ namespace BCLog {
|
|||
bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
|
||||
bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
|
||||
bool m_log_sourcelocations = DEFAULT_LOGSOURCELOCATIONS;
|
||||
bool m_ratelimit{DEFAULT_RATELIMITLOGGING};
|
||||
|
||||
fs::path m_file_path;
|
||||
std::atomic<bool> m_reopen_file{false};
|
||||
|
||||
/** Send a string to the log output */
|
||||
void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line);
|
||||
void LogPrintStr(const std::string& str, const std::string& logging_function,
|
||||
const SourceLocation& source_location, const BCLog::LogFlags category,
|
||||
const BCLog::Level level);
|
||||
|
||||
/** Returns whether logs will be written to any output */
|
||||
bool Enabled() const
|
||||
|
|
@ -154,7 +238,6 @@ namespace BCLog {
|
|||
|
||||
bool DefaultShrinkDebugFile() const;
|
||||
};
|
||||
|
||||
} // namespace BCLog
|
||||
|
||||
BCLog::Logger& LogInstance();
|
||||
|
|
@ -173,7 +256,7 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str);
|
|||
// peer can fill up a user's disk with debug.log entries.
|
||||
|
||||
template <typename... Args>
|
||||
static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const char* fmt, const Args&... args)
|
||||
static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, const char* fmt, const Args&... args)
|
||||
{
|
||||
if (LogInstance().Enabled()) {
|
||||
std::string log_msg;
|
||||
|
|
@ -183,19 +266,36 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st
|
|||
/* Original format string will have newline so don't add one here */
|
||||
log_msg = "Error \"" + std::string(fmterr.what()) + "\" while formatting log message: " + fmt;
|
||||
}
|
||||
LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line);
|
||||
|
||||
const SourceLocation source_location{source_file, source_line};
|
||||
LogInstance().LogPrintStr(log_msg, logging_function, source_location, flag, level);
|
||||
}
|
||||
}
|
||||
|
||||
#define LogPrintf(...) LogPrintf_(__func__, __FILE__, __LINE__, __VA_ARGS__)
|
||||
|
||||
#define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__)
|
||||
|
||||
// Unconditional logging. Uses basic rate limiting to mitigate disk filling attacks.
|
||||
#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::UNCONDITIONAL_RATE_LIMITED, BCLog::Level::None, __VA_ARGS__)
|
||||
|
||||
// Use a macro instead of a function for conditional logging to prevent
|
||||
// evaluating arguments when logging for the category is not enabled.
|
||||
#define LogPrint(category, ...) \
|
||||
do { \
|
||||
if (LogAcceptCategory((category))) { \
|
||||
LogPrintf(__VA_ARGS__); \
|
||||
} \
|
||||
//
|
||||
// Note that conditional logging is performed WITHOUT rate limiting. 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 LogPrint(category, ...) \
|
||||
do { \
|
||||
if (LogAcceptCategory((category))) { \
|
||||
LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \
|
||||
} \
|
||||
} while (0)
|
||||
|
||||
#define LogPrintLevel(level, category, ...) \
|
||||
do { \
|
||||
if (LogAcceptCategory((category))) { \
|
||||
LogPrintLevel_(category, level, __VA_ARGS__); \
|
||||
} \
|
||||
} while (0)
|
||||
|
||||
#endif // BITCOIN_LOGGING_H
|
||||
|
|
|
|||
24
src/net.cpp
24
src/net.cpp
|
|
@ -430,7 +430,7 @@ static CAddress GetBindAddress(SOCKET sock)
|
|||
if (!getsockname(sock, (struct sockaddr*)&sockaddr_bind, &sockaddr_bind_len)) {
|
||||
addr_bind.SetSockAddr((const struct sockaddr*)&sockaddr_bind);
|
||||
} else {
|
||||
LogPrint(BCLog::NET, "Warning: getsockname failed\n");
|
||||
LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "getsockname failed\n");
|
||||
}
|
||||
}
|
||||
return addr_bind;
|
||||
|
|
@ -454,9 +454,9 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo
|
|||
}
|
||||
|
||||
/// debug print
|
||||
LogPrint(BCLog::NET, "trying connection %s lastseen=%.1fhrs\n",
|
||||
pszDest ? pszDest : addrConnect.ToString(),
|
||||
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0);
|
||||
LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying connection %s lastseen=%.1fhrs\n",
|
||||
pszDest ? pszDest : addrConnect.ToString(),
|
||||
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime) / 3600.0);
|
||||
|
||||
// Resolve
|
||||
const uint16_t default_port{pszDest != nullptr ? Params().GetDefaultPort(pszDest) :
|
||||
|
|
@ -1158,7 +1158,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) {
|
|||
}
|
||||
|
||||
if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) {
|
||||
LogPrintf("Warning: Unknown socket family\n");
|
||||
LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "Unknown socket family\n");
|
||||
} else {
|
||||
addr = CAddress{MaybeFlipIPv6toCJDNS(addr), NODE_NONE};
|
||||
}
|
||||
|
|
@ -2404,15 +2404,15 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
|
|||
socklen_t len = sizeof(sockaddr);
|
||||
if (!addrBind.GetSockAddr((struct sockaddr*)&sockaddr, &len))
|
||||
{
|
||||
strError = strprintf(Untranslated("Error: Bind address family for %s not supported"), addrBind.ToString());
|
||||
LogPrintf("%s\n", strError.original);
|
||||
strError = strprintf(Untranslated("Bind address family for %s not supported"), addrBind.ToString());
|
||||
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
|
||||
return false;
|
||||
}
|
||||
|
||||
std::unique_ptr<Sock> sock = CreateSock(addrBind);
|
||||
if (!sock) {
|
||||
strError = strprintf(Untranslated("Error: Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
|
||||
LogPrintf("%s\n", strError.original);
|
||||
strError = strprintf(Untranslated("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
|
||||
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
|
||||
return false;
|
||||
}
|
||||
|
||||
|
|
@ -2439,7 +2439,7 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
|
|||
strError = strprintf(_("Unable to bind to %s on this computer. %s is probably already running."), addrBind.ToString(), PACKAGE_NAME);
|
||||
else
|
||||
strError = strprintf(_("Unable to bind to %s on this computer (bind returned error %s)"), addrBind.ToString(), NetworkErrorString(nErr));
|
||||
LogPrintf("%s\n", strError.original);
|
||||
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
|
||||
return false;
|
||||
}
|
||||
LogPrintf("Bound to %s\n", addrBind.ToString());
|
||||
|
|
@ -2447,8 +2447,8 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
|
|||
// Listen for incoming connections
|
||||
if (listen(sock->Get(), SOMAXCONN) == SOCKET_ERROR)
|
||||
{
|
||||
strError = strprintf(_("Error: Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError()));
|
||||
LogPrintf("%s\n", strError.original);
|
||||
strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError()));
|
||||
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
|
||||
return false;
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -314,7 +314,7 @@ QString TransactionDesc::toHTML(interfaces::Node& node, interfaces::Wallet& wall
|
|||
//
|
||||
// Debug view
|
||||
//
|
||||
if (node.getLogCategories() != BCLog::NONE && !g_con_elementsmode)
|
||||
if (node.getLogCategories() != BCLog::DEFAULT_LOG_FLAGS && !g_con_elementsmode)
|
||||
{
|
||||
strHTML += "<hr><br>" + tr("Debug information") + "<br><br>";
|
||||
for (const CTxIn& txin : wtx.tx->vin)
|
||||
|
|
|
|||
|
|
@ -4,14 +4,59 @@
|
|||
|
||||
#include <logging.h>
|
||||
#include <logging/timer.h>
|
||||
#include <test/util/logging.h>
|
||||
#include <test/util/setup_common.h>
|
||||
#include <util/string.h>
|
||||
|
||||
#include <chrono>
|
||||
#include <fstream>
|
||||
#include <iostream>
|
||||
#include <utility>
|
||||
#include <vector>
|
||||
|
||||
#include <boost/test/unit_test.hpp>
|
||||
#include <boost/algorithm/string/classification.hpp>
|
||||
#include <boost/algorithm/string/split.hpp>
|
||||
|
||||
BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
|
||||
|
||||
struct LogSetup : public BasicTestingSetup {
|
||||
fs::path prev_log_path;
|
||||
fs::path tmp_log_path;
|
||||
bool prev_reopen_file;
|
||||
bool prev_print_to_file;
|
||||
bool prev_log_timestamps;
|
||||
bool prev_log_threadnames;
|
||||
bool prev_log_sourcelocations;
|
||||
|
||||
LogSetup() : prev_log_path{LogInstance().m_file_path},
|
||||
tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
|
||||
prev_reopen_file{LogInstance().m_reopen_file},
|
||||
prev_print_to_file{LogInstance().m_print_to_file},
|
||||
prev_log_timestamps{LogInstance().m_log_timestamps},
|
||||
prev_log_threadnames{LogInstance().m_log_threadnames},
|
||||
prev_log_sourcelocations{LogInstance().m_log_sourcelocations}
|
||||
{
|
||||
LogInstance().m_file_path = tmp_log_path;
|
||||
LogInstance().m_reopen_file = true;
|
||||
LogInstance().m_print_to_file = true;
|
||||
LogInstance().m_log_timestamps = false;
|
||||
LogInstance().m_log_threadnames = false;
|
||||
LogInstance().m_log_sourcelocations = true;
|
||||
}
|
||||
|
||||
~LogSetup()
|
||||
{
|
||||
LogInstance().m_file_path = prev_log_path;
|
||||
LogPrintf("Sentinel log to reopen log file\n");
|
||||
LogInstance().m_print_to_file = prev_print_to_file;
|
||||
LogInstance().m_reopen_file = prev_reopen_file;
|
||||
LogInstance().m_log_timestamps = prev_log_timestamps;
|
||||
LogInstance().m_log_threadnames = prev_log_threadnames;
|
||||
LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
|
||||
}
|
||||
};
|
||||
|
||||
BOOST_AUTO_TEST_CASE(logging_timer)
|
||||
{
|
||||
SetMockTime(1);
|
||||
|
|
@ -30,4 +75,219 @@ BOOST_AUTO_TEST_CASE(logging_timer)
|
|||
BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)");
|
||||
}
|
||||
|
||||
BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)
|
||||
{
|
||||
LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s", "bar1\n");
|
||||
LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s", "bar2\n");
|
||||
LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s", "bar3\n");
|
||||
LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s", "bar4\n");
|
||||
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:debug] foo1: bar1",
|
||||
"[src2:2] [fn2] [net] foo2: bar2",
|
||||
"[src3:3] [fn3] [debug] foo3: bar3",
|
||||
"[src4:4] [fn4] foo4: bar4",
|
||||
};
|
||||
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
|
||||
}
|
||||
|
||||
BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
|
||||
{
|
||||
// Prevent tests from failing when the line number of the following log calls changes.
|
||||
LogInstance().m_log_sourcelocations = false;
|
||||
|
||||
LogPrintf("foo5: %s\n", "bar5");
|
||||
LogPrint(BCLog::NET, "foo6: %s\n", "bar6");
|
||||
LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "foo7: %s\n", "bar7");
|
||||
LogPrintLevel(BCLog::Level::Info, BCLog::NET, "foo8: %s\n", "bar8");
|
||||
LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "foo9: %s\n", "bar9");
|
||||
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "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> expected = {
|
||||
"foo5: bar5",
|
||||
"[net] foo6: bar6",
|
||||
"[net:debug] foo7: bar7",
|
||||
"[net:info] foo8: bar8",
|
||||
"[net:warning] foo9: bar9",
|
||||
"[net:error] foo10: bar10"};
|
||||
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
|
||||
}
|
||||
|
||||
BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
|
||||
{
|
||||
// Prevent tests from failing when the line number of the following log calls changes.
|
||||
LogInstance().m_log_sourcelocations = false;
|
||||
LogInstance().EnableCategory(BCLog::LogFlags::ALL);
|
||||
const auto concated_categery_names = LogInstance().LogCategoriesString();
|
||||
std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
|
||||
std::vector<std::string> category_names;
|
||||
boost::algorithm::split(category_names, concated_categery_names, boost::algorithm::is_any_of(","));
|
||||
for (const auto& category_name : category_names) {
|
||||
BCLog::LogFlags category = BCLog::NONE;
|
||||
const auto trimmed_category_name = TrimString(category_name);
|
||||
BOOST_TEST(GetLogCategory(category, trimmed_category_name));
|
||||
expected_category_names.emplace_back(category, trimmed_category_name);
|
||||
}
|
||||
|
||||
std::vector<std::string> expected;
|
||||
for (const auto& [category, name] : expected_category_names) {
|
||||
LogPrint(category, "foo: %s\n", "bar");
|
||||
if (category == BCLog::UNCONDITIONAL_ALWAYS || category == BCLog::UNCONDITIONAL_RATE_LIMITED) {
|
||||
expected.push_back("foo: bar");
|
||||
} else {
|
||||
expected.push_back("[" + name + "] foo: bar");
|
||||
}
|
||||
}
|
||||
|
||||
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);
|
||||
}
|
||||
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
|
||||
}
|
||||
|
||||
BOOST_AUTO_TEST_CASE(logging_ratelimit_window)
|
||||
{
|
||||
SetMockTime(std::chrono::hours{1});
|
||||
BCLog::LogRateLimiter window;
|
||||
|
||||
// Check that window gets initialised correctly.
|
||||
BOOST_CHECK_EQUAL(window.GetAvailableBytes(), BCLog::LogRateLimiter::WINDOW_MAX_BYTES);
|
||||
BOOST_CHECK_EQUAL(window.GetDroppedBytes(), 0ull);
|
||||
|
||||
const uint64_t MESSAGE_SIZE{512 * 1024};
|
||||
BOOST_CHECK(window.Consume(MESSAGE_SIZE));
|
||||
BOOST_CHECK_EQUAL(window.GetAvailableBytes(), BCLog::LogRateLimiter::WINDOW_MAX_BYTES - MESSAGE_SIZE);
|
||||
BOOST_CHECK_EQUAL(window.GetDroppedBytes(), 0ull);
|
||||
|
||||
BOOST_CHECK(window.Consume(MESSAGE_SIZE));
|
||||
BOOST_CHECK_EQUAL(window.GetAvailableBytes(), BCLog::LogRateLimiter::WINDOW_MAX_BYTES - MESSAGE_SIZE * 2);
|
||||
BOOST_CHECK_EQUAL(window.GetDroppedBytes(), 0ull);
|
||||
|
||||
// Consuming more bytes after already having consumed a 1MB should fail.
|
||||
BOOST_CHECK(!window.Consume(500));
|
||||
BOOST_CHECK_EQUAL(window.GetAvailableBytes(), 0ull);
|
||||
BOOST_CHECK_EQUAL(window.GetDroppedBytes(), 500ull);
|
||||
|
||||
// Advance time by one hour. This should trigger a window reset.
|
||||
SetMockTime(std::chrono::hours{2});
|
||||
|
||||
// Check that the window resets as expected when new bytes are consumed.
|
||||
BOOST_CHECK(window.Consume(MESSAGE_SIZE));
|
||||
BOOST_CHECK_EQUAL(window.GetAvailableBytes(), BCLog::LogRateLimiter::WINDOW_MAX_BYTES - MESSAGE_SIZE);
|
||||
BOOST_CHECK_EQUAL(window.GetDroppedBytes(), 0ull);
|
||||
}
|
||||
|
||||
void LogFromLocation(int location, std::string message)
|
||||
{
|
||||
switch (location) {
|
||||
case 0:
|
||||
LogPrint(BCLog::UNCONDITIONAL_RATE_LIMITED, "%s\n", message);
|
||||
break;
|
||||
case 1:
|
||||
LogPrint(BCLog::UNCONDITIONAL_RATE_LIMITED, "%s\n", message);
|
||||
break;
|
||||
case 2:
|
||||
LogPrint(BCLog::UNCONDITIONAL_ALWAYS, "%s\n", message);
|
||||
break;
|
||||
case 3:
|
||||
LogPrint(BCLog::ALL, "%s\n", message);
|
||||
break;
|
||||
}
|
||||
}
|
||||
|
||||
void LogFromLocationAndExpect(int location, std::string message, std::string expect)
|
||||
{
|
||||
ASSERT_DEBUG_LOG(expect);
|
||||
LogFromLocation(location, message);
|
||||
}
|
||||
|
||||
BOOST_AUTO_TEST_CASE(rate_limiting)
|
||||
{
|
||||
bool prev_log_timestamps = LogInstance().m_log_sourcelocations;
|
||||
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;
|
||||
|
||||
// Log 1024-character lines (1023 plus newline) to make the math simple.
|
||||
std::string log_message(1023, 'a');
|
||||
|
||||
SetMockTime(std::chrono::hours{1});
|
||||
|
||||
size_t log_file_size = std::filesystem::file_size(LogInstance().m_file_path);
|
||||
// Logging 1 MiB should be allowed.
|
||||
for (int i = 0; i < 1024; ++i) {
|
||||
LogFromLocation(0, log_message);
|
||||
}
|
||||
BOOST_CHECK_MESSAGE(log_file_size < std::filesystem::file_size(LogInstance().m_file_path), "should be able to log 1 MiB from location 0");
|
||||
|
||||
log_file_size = std::filesystem::file_size(LogInstance().m_file_path);
|
||||
BOOST_CHECK_NO_THROW(
|
||||
LogFromLocationAndExpect(0, log_message, "Excessive logging detected"));
|
||||
BOOST_CHECK_MESSAGE(log_file_size < std::filesystem::file_size(LogInstance().m_file_path), "the start of the supression period should be logged");
|
||||
|
||||
log_file_size = std::filesystem::file_size(LogInstance().m_file_path);
|
||||
for (int i = 0; i < 1024; ++i) {
|
||||
LogFromLocation(0, log_message);
|
||||
}
|
||||
BOOST_CHECK_MESSAGE(log_file_size == std::filesystem::file_size(LogInstance().m_file_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 < std::filesystem::file_size(LogInstance().m_file_path), "location 1 should be unaffected by other locations");
|
||||
|
||||
SetMockTime(std::chrono::hours{2});
|
||||
|
||||
log_file_size = std::filesystem::file_size(LogInstance().m_file_path);
|
||||
BOOST_CHECK_NO_THROW(
|
||||
LogFromLocationAndExpect(0, log_message, "Restarting logging"));
|
||||
BOOST_CHECK_MESSAGE(log_file_size < std::filesystem::file_size(LogInstance().m_file_path), "the end of the supression period should be logged");
|
||||
|
||||
BOOST_CHECK_THROW(
|
||||
LogFromLocationAndExpect(1, log_message, "Restarting logging"), std::runtime_error);
|
||||
|
||||
// Attempt to log 2 MiB to disk.
|
||||
// The exempt locations 2 and 3 should be allowed to log without limit.
|
||||
for (int i = 0; i < 2048; ++i) {
|
||||
log_file_size = std::filesystem::file_size(LogInstance().m_file_path);
|
||||
BOOST_CHECK_THROW(
|
||||
LogFromLocationAndExpect(2, log_message, "Excessive logging detected"), std::runtime_error);
|
||||
BOOST_CHECK_MESSAGE(log_file_size < std::filesystem::file_size(LogInstance().m_file_path), "location 2 should be exempt from rate limiting");
|
||||
|
||||
log_file_size = std::filesystem::file_size(LogInstance().m_file_path);
|
||||
BOOST_CHECK_THROW(
|
||||
LogFromLocationAndExpect(3, log_message, "Excessive logging detected"), std::runtime_error);
|
||||
BOOST_CHECK_MESSAGE(log_file_size < std::filesystem::file_size(LogInstance().m_file_path), "location 3 should be exempt from rate limiting");
|
||||
}
|
||||
|
||||
SetMockTime(std::chrono::hours{3});
|
||||
|
||||
// Disable rate limiting.
|
||||
// Source locations should now be able to log without limit.
|
||||
LogInstance().m_ratelimit = false;
|
||||
for (int i = 0; i < 2048; ++i) {
|
||||
log_file_size = std::filesystem::file_size(LogInstance().m_file_path);
|
||||
BOOST_CHECK_THROW(
|
||||
LogFromLocationAndExpect(0, log_message, "Excessive logging detected"), std::runtime_error);
|
||||
BOOST_CHECK_MESSAGE(log_file_size < std::filesystem::file_size(LogInstance().m_file_path), "location 0 should be able to log disk, when rate limiting is disabled");
|
||||
}
|
||||
LogInstance().m_ratelimit = true;
|
||||
|
||||
LogInstance().m_log_timestamps = prev_log_timestamps;
|
||||
LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
|
||||
LogInstance().m_log_threadnames = prev_log_threadnames;
|
||||
SetMockTime(std::chrono::seconds{0});
|
||||
}
|
||||
|
||||
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 PASTE2(debugloghelper, __COUNTER__)(message)
|
||||
|
|
|
|||
|
|
@ -76,6 +76,17 @@ bool ChronoSanityCheck()
|
|||
return true;
|
||||
}
|
||||
|
||||
NodeClock::time_point NodeClock::now() noexcept
|
||||
{
|
||||
const std::chrono::seconds mocktime{nMockTime.load(std::memory_order_relaxed)};
|
||||
const auto ret{
|
||||
mocktime.count() ?
|
||||
mocktime :
|
||||
std::chrono::system_clock::now().time_since_epoch()};
|
||||
assert(ret > 0s);
|
||||
return time_point{ret};
|
||||
};
|
||||
|
||||
template <typename T>
|
||||
T GetTime()
|
||||
{
|
||||
|
|
|
|||
|
|
@ -14,6 +14,17 @@
|
|||
|
||||
using namespace std::chrono_literals;
|
||||
|
||||
/** Mockable clock in the context of tests, otherwise the system clock */
|
||||
struct NodeClock : public std::chrono::system_clock {
|
||||
using time_point = std::chrono::time_point<NodeClock>;
|
||||
/** Return current system time or mocked time, if set */
|
||||
static time_point now() noexcept;
|
||||
static std::time_t to_time_t(const time_point&) = delete; // unused
|
||||
static time_point from_time_t(std::time_t) = delete; // unused
|
||||
};
|
||||
using NodeSeconds = std::chrono::time_point<NodeClock, std::chrono::seconds>;
|
||||
|
||||
|
||||
void UninterruptibleSleep(const std::chrono::microseconds& n);
|
||||
|
||||
/**
|
||||
|
|
|
|||
|
|
@ -2710,7 +2710,7 @@ 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",
|
||||
LogPrint(BCLog::UNCONDITIONAL_ALWAYS,"%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), (unsigned long)tip->nChainTx,
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue