diff --git a/src/bitcoin-chainstate.cpp b/src/bitcoin-chainstate.cpp index 98af162b4d4..ebe013b638b 100644 --- a/src/bitcoin-chainstate.cpp +++ b/src/bitcoin-chainstate.cpp @@ -19,6 +19,7 @@ #include #include +#include #include #include #include @@ -41,6 +42,12 @@ int main(int argc, char* argv[]) { + // We do not enable logging for this app, so explicitly disable it. + // To enable logging instead, replace with: + // LogInstance().m_print_to_console = true; + // LogInstance().StartLogging(); + LogInstance().DisableLogging(); + // SETUP: Argument parsing and handling if (argc != 2) { std::cerr diff --git a/src/logging.cpp b/src/logging.cpp index a9fea433be4..9c87cfd2b71 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -4,6 +4,7 @@ // file COPYING or http://www.opensource.org/licenses/mit-license.php. #include +#include #include #include #include @@ -14,8 +15,7 @@ #include using util::Join; -using util::RemovePrefix; -using util::ToString; +using util::RemovePrefixView; const char * const DEFAULT_DEBUGLOGFILE = "debug.log"; constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info}; @@ -43,7 +43,7 @@ BCLog::Logger& LogInstance() bool fLogIPs = DEFAULT_LOGIPS; -static int FileWriteStr(const std::string &str, FILE *fp) +static int FileWriteStr(std::string_view str, FILE *fp) { return fwrite(str.data(), 1, str.size(), fp); } @@ -71,17 +71,22 @@ 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); + } while (!m_msgs_before_open.empty()) { - const std::string& s = m_msgs_before_open.front(); + 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); + m_msgs_before_open.pop_front(); if (m_print_to_file) FileWriteStr(s, m_fileout); if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout); for (const auto& cb : m_print_callbacks) { cb(s); } - - m_msgs_before_open.pop_front(); } + m_cur_buffer_memusage = 0; if (m_print_to_console) fflush(stdout); return true; @@ -94,6 +99,23 @@ void BCLog::Logger::DisconnectTestLogger() if (m_fileout != nullptr) fclose(m_fileout); m_fileout = nullptr; m_print_callbacks.clear(); + m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER; + m_cur_buffer_memusage = 0; + m_buffer_lines_discarded = 0; + m_msgs_before_open.clear(); + +} + +void BCLog::Logger::DisableLogging() +{ + { + StdLockGuard scoped_lock(m_cs); + assert(m_buffering); + assert(m_print_callbacks.empty()); + } + m_print_to_file = false; + m_print_to_console = false; + StartLogging(); } void BCLog::Logger::EnableCategory(BCLog::LogFlags flag) @@ -101,7 +123,7 @@ void BCLog::Logger::EnableCategory(BCLog::LogFlags flag) m_categories |= flag; } -bool BCLog::Logger::EnableCategory(const std::string& str) +bool BCLog::Logger::EnableCategory(std::string_view str) { BCLog::LogFlags flag; if (!GetLogCategory(flag, str)) return false; @@ -114,7 +136,7 @@ void BCLog::Logger::DisableCategory(BCLog::LogFlags flag) m_categories &= ~flag; } -bool BCLog::Logger::DisableCategory(const std::string& str) +bool BCLog::Logger::DisableCategory(std::string_view str) { BCLog::LogFlags flag; if (!GetLogCategory(flag, str)) return false; @@ -145,7 +167,7 @@ bool BCLog::Logger::DefaultShrinkDebugFile() const return m_categories == BCLog::NONE; } -static const std::map LOG_CATEGORIES_BY_STR{ +static const std::map> LOG_CATEGORIES_BY_STR{ {"0", BCLog::NONE}, {"", BCLog::NONE}, {"net", BCLog::NET}, @@ -185,7 +207,7 @@ static const std::map LOG_CATEGORIES_BY_STR{ static const std::unordered_map LOG_CATEGORIES_BY_FLAG{ // Swap keys and values from LOG_CATEGORIES_BY_STR. - [](const std::map& in) { + [](const auto& in) { std::unordered_map out; for (const auto& [k, v] : in) { switch (v) { @@ -198,7 +220,7 @@ static const std::unordered_map LOG_CATEGORIES_BY_ }(LOG_CATEGORIES_BY_STR) }; -bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) +bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str) { if (str.empty()) { flag = BCLog::ALL; @@ -236,7 +258,7 @@ std::string LogCategoryToStr(BCLog::LogFlags category) return it->second; } -static std::optional GetLogLevel(const std::string& level_str) +static std::optional GetLogLevel(std::string_view level_str) { if (level_str == "trace") { return BCLog::Level::Trace; @@ -276,28 +298,23 @@ std::string BCLog::Logger::LogLevelsString() const return Join(std::vector{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); }); } -std::string BCLog::Logger::LogTimestampStr(const std::string& str) +std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const { std::string strStamped; if (!m_log_timestamps) - return str; + return strStamped; - if (m_started_new_line) { - const auto now{SystemClock::now()}; - const auto now_seconds{std::chrono::time_point_cast(now)}; - strStamped = FormatISO8601DateTime(TicksSinceEpoch(now_seconds)); - if (m_log_time_micros && !strStamped.empty()) { - strStamped.pop_back(); - strStamped += strprintf(".%06dZ", Ticks(now - now_seconds)); - } - std::chrono::seconds mocktime = GetMockTime(); - if (mocktime > 0s) { - strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")"; - } - strStamped += ' ' + str; - } else - strStamped = str; + const auto now_seconds{std::chrono::time_point_cast(now)}; + strStamped = FormatISO8601DateTime(TicksSinceEpoch(now_seconds)); + if (m_log_time_micros && !strStamped.empty()) { + strStamped.pop_back(); + strStamped += strprintf(".%06dZ", Ticks(now - now_seconds)); + } + if (mocktime > 0s) { + strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")"; + } + strStamped += ' '; return strStamped; } @@ -310,7 +327,7 @@ namespace BCLog { * It escapes instead of removes them to still allow for troubleshooting * issues where they accidentally end up in strings. */ - std::string LogEscapeMessage(const std::string& str) { + std::string LogEscapeMessage(std::string_view str) { std::string ret; for (char ch_in : str) { uint8_t ch = (uint8_t)ch_in; @@ -350,34 +367,84 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l return s; } -void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) +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)); +} + +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 +{ + str.insert(0, GetLogPrefix(category, level)); + + if (m_log_sourcelocations) { + str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_file, "./"), source_line, logging_function)); + } + + if (m_log_threadnames) { + str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname))); + } + + 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) { StdLockGuard scoped_lock(m_cs); + return LogPrintStr_(str, logging_function, source_file, source_line, category, level); +} + +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) +{ std::string str_prefixed = LogEscapeMessage(str); - if (m_started_new_line) { - str_prefixed.insert(0, GetLogPrefix(category, level)); - } - - if (m_log_sourcelocations && m_started_new_line) { - str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] "); - } - - if (m_log_threadnames && m_started_new_line) { - const auto& threadname = util::ThreadGetInternalName(); - str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] "); - } - - str_prefixed = LogTimestampStr(str_prefixed); - + const bool starts_new_line = m_started_new_line; m_started_new_line = !str.empty() && str[str.size()-1] == '\n'; if (m_buffering) { - // buffer if we haven't started logging yet - m_msgs_before_open.push_back(str_prefixed); + if (!starts_new_line) { + if (!m_msgs_before_open.empty()) { + m_msgs_before_open.back().str += str_prefixed; + m_cur_buffer_memusage += str_prefixed.size(); + return; + } else { + // unlikely edge case; add a marker that something was trimmed + str_prefixed.insert(0, "[...] "); + } + } + + { + 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, + }; + m_cur_buffer_memusage += MemUsage(buf); + m_msgs_before_open.push_back(std::move(buf)); + } + + while (m_cur_buffer_memusage > m_max_buffer_memusage) { + if (m_msgs_before_open.empty()) { + m_cur_buffer_memusage = 0; + break; + } + m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front()); + m_msgs_before_open.pop_front(); + ++m_buffer_lines_discarded; + } + return; } + if (starts_new_line) { + FormatLogStrInPlace(str_prefixed, category, level, source_file, source_line, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); + } + if (m_print_to_console) { // print to console fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout); @@ -444,7 +511,7 @@ void BCLog::Logger::ShrinkDebugFile() fclose(file); } -bool BCLog::Logger::SetLogLevel(const std::string& level_str) +bool BCLog::Logger::SetLogLevel(std::string_view level_str) { const auto level = GetLogLevel(level_str); if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false; @@ -452,7 +519,7 @@ bool BCLog::Logger::SetLogLevel(const std::string& level_str) return true; } -bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str) +bool BCLog::Logger::SetCategoryLogLevel(std::string_view category_str, std::string_view level_str) { BCLog::LogFlags flag; if (!GetLogCategory(flag, category_str)) return false; diff --git a/src/logging.h b/src/logging.h index fe6b7051baf..91f919e8223 100644 --- a/src/logging.h +++ b/src/logging.h @@ -10,6 +10,7 @@ #include #include #include +#include #include #include @@ -79,15 +80,29 @@ namespace BCLog { Error, }; 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 class Logger { + public: + struct BufferedLog { + SystemClock::time_point now; + std::chrono::seconds mocktime; + std::string str, logging_function, source_file, threadname; + int source_line; + LogFlags category; + Level level; + }; + private: mutable StdMutex m_cs; // Can not use Mutex from sync.h because in debug mode it would cause a deadlock when a potential deadlock was detected FILE* m_fileout GUARDED_BY(m_cs) = nullptr; - std::list m_msgs_before_open GUARDED_BY(m_cs); + 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. + size_t m_max_buffer_memusage GUARDED_BY(m_cs){DEFAULT_MAX_LOG_BUFFER}; + size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0}; + size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0}; /** * m_started_new_line is a state variable that will suppress printing of @@ -106,11 +121,17 @@ namespace BCLog { /** Log categories bitfield. */ std::atomic m_categories{0}; - std::string LogTimestampStr(const std::string& str); + 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; + + std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const; /** Slots that connect to the print signal */ std::list> 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) + EXCLUSIVE_LOCKS_REQUIRED(m_cs); + public: bool m_print_to_console = false; bool m_print_to_file = false; @@ -127,17 +148,18 @@ namespace BCLog { std::string GetLogPrefix(LogFlags category, Level level) const; /** Send a string to the log output */ - void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level); + 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) + EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns whether logs will be written to any output */ - bool Enabled() const + bool Enabled() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs) { StdLockGuard scoped_lock(m_cs); return m_buffering || m_print_to_console || m_print_to_file || !m_print_callbacks.empty(); } /** Connect a slot to the print signal and return the connection */ - std::list>::iterator PushBackCallback(std::function fun) + std::list>::iterator PushBackCallback(std::function fun) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) { StdLockGuard scoped_lock(m_cs); m_print_callbacks.push_back(std::move(fun)); @@ -145,44 +167,52 @@ namespace BCLog { } /** Delete a connection */ - void DeleteCallback(std::list>::iterator it) + void DeleteCallback(std::list>::iterator it) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) { StdLockGuard scoped_lock(m_cs); m_print_callbacks.erase(it); } /** Start logging (and flush all buffered messages) */ - bool StartLogging(); + bool StartLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Only for testing */ - void DisconnectTestLogger(); + void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); + + /** Disable logging + * This offers a slight speedup and slightly smaller memory usage + * compared to leaving the logging system in its default state. + * Mostly intended for libbitcoin-kernel apps that don't want any logging. + * Should be used instead of StartLogging(). + */ + void DisableLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); void ShrinkDebugFile(); - std::unordered_map CategoryLevels() const + std::unordered_map CategoryLevels() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs) { StdLockGuard scoped_lock(m_cs); return m_category_log_levels; } - void SetCategoryLogLevel(const std::unordered_map& levels) + void SetCategoryLogLevel(const std::unordered_map& levels) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) { StdLockGuard scoped_lock(m_cs); m_category_log_levels = levels; } - bool SetCategoryLogLevel(const std::string& category_str, const std::string& level_str); + bool SetCategoryLogLevel(std::string_view category_str, std::string_view level_str) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); Level LogLevel() const { return m_log_level.load(); } void SetLogLevel(Level level) { m_log_level = level; } - bool SetLogLevel(const std::string& level); + bool SetLogLevel(std::string_view level); uint32_t GetCategoryMask() const { return m_categories.load(); } void EnableCategory(LogFlags flag); - bool EnableCategory(const std::string& str); + bool EnableCategory(std::string_view str); void DisableCategory(LogFlags flag); - bool DisableCategory(const std::string& str); + bool DisableCategory(std::string_view str); bool WillLogCategory(LogFlags category) const; - bool WillLogCategoryLevel(LogFlags category, Level level) const; + bool WillLogCategoryLevel(LogFlags category, Level level) const EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns a vector of the log categories in alphabetical order. */ std::vector LogCategoriesList() const; @@ -212,14 +242,14 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve } /** Return true if str parses as a log category and set the flag */ -bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str); +bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); // 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 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 BCLog::LogFlags flag, const BCLog::Level level, const char* fmt, const Args&... args) +static inline void LogPrintf_(std::string_view logging_function, std::string_view 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; diff --git a/src/test/util_tests.cpp b/src/test/util_tests.cpp index 5654c8b0a84..bf1fc1ea0af 100644 --- a/src/test/util_tests.cpp +++ b/src/test/util_tests.cpp @@ -58,7 +58,7 @@ static const std::string STRING_WITH_EMBEDDED_NULL_CHAR{"1"s "\0" "1"s}; /* defined in logging.cpp */ namespace BCLog { - std::string LogEscapeMessage(const std::string& str); + std::string LogEscapeMessage(std::string_view str); } BOOST_FIXTURE_TEST_SUITE(util_tests, BasicTestingSetup)