diff --git a/src/init/common.cpp b/src/init/common.cpp index 38c60366e3..e9c4bb9a65 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -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); } diff --git a/src/logging.cpp b/src/logging.cpp index a5e5fdb4cd..cb5624d158 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -7,7 +7,6 @@ #include #include #include -#include #include #include @@ -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 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; +} diff --git a/src/logging.h b/src/logging.h index ae8cad906c..e325c94028 100644 --- a/src/logging.h +++ b/src/logging.h @@ -6,10 +6,12 @@ #ifndef BITCOIN_LOGGING_H #define BITCOIN_LOGGING_H +#include #include #include #include #include +#include #include #include @@ -17,6 +19,8 @@ #include #include #include +#include +#include #include 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(CSipHasher(0, 0) + .Write(std::hash{}(source_location.m_file)) + .Write(std::hash{}(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 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 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 m_ratelimiters GUARDED_BY(m_cs); + //! Set of source file locations that were dropped on the last log attempt. + std::unordered_set 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 m_categories{0}; + std::atomic 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 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 -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 diff --git a/src/net.cpp b/src/net.cpp index 9d69b025da..135cc85684 100644 --- a/src/net.cpp +++ b/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 = 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; } diff --git a/src/qt/transactiondesc.cpp b/src/qt/transactiondesc.cpp index 8f33f60a5f..0e39dcb2a9 100644 --- a/src/qt/transactiondesc.cpp +++ b/src/qt/transactiondesc.cpp @@ -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 += "

" + tr("Debug information") + "

"; for (const CTxIn& txin : wtx.tx->vin) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index cbfb6c67c3..5d3518943c 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -4,14 +4,59 @@ #include #include +#include #include +#include #include +#include +#include +#include +#include #include +#include +#include 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 log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector 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 log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector 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> expected_category_names; + std::vector 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 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 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() diff --git a/src/test/util/logging.h b/src/test/util/logging.h index ebe0ecf623..697d3896be 100644 --- a/src/test/util/logging.h +++ b/src/test/util/logging.h @@ -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) diff --git a/src/util/time.cpp b/src/util/time.cpp index f7712f0dc8..278244313f 100644 --- a/src/util/time.cpp +++ b/src/util/time.cpp @@ -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 T GetTime() { diff --git a/src/util/time.h b/src/util/time.h index 9d92b23725..6c5419ba4d 100644 --- a/src/util/time.h +++ b/src/util/time.h @@ -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; + /** 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; + + void UninterruptibleSleep(const std::chrono::microseconds& n); /** diff --git a/src/validation.cpp b/src/validation.cpp index f86f105c21..a307c3036b 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -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,