diff options
Diffstat (limited to 'src/logging.cpp')
| -rw-r--r-- | src/logging.cpp | 174 |
1 files changed, 111 insertions, 63 deletions
diff --git a/src/logging.cpp b/src/logging.cpp index a9fea433be..5f055566ef 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -1,9 +1,11 @@ // Copyright (c) 2009-2010 Satoshi Nakamoto -// Copyright (c) 2009-2022 The Bitcoin Core developers +// Copyright (c) 2009-present The Bitcoin Core developers // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. #include <logging.h> +#include <memusage.h> +#include <util/check.h> #include <util/fs.h> #include <util/string.h> #include <util/threadnames.h> @@ -14,8 +16,7 @@ #include <optional> 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 +44,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 +72,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 +100,22 @@ 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,9 +167,7 @@ bool BCLog::Logger::DefaultShrinkDebugFile() const return m_categories == BCLog::NONE; } -static const std::map<std::string, BCLog::LogFlags> LOG_CATEGORIES_BY_STR{ - {"0", BCLog::NONE}, - {"", BCLog::NONE}, +static const std::map<std::string, BCLog::LogFlags, std::less<>> LOG_CATEGORIES_BY_STR{ {"net", BCLog::NET}, {"tor", BCLog::TOR}, {"mempool", BCLog::MEMPOOL}, @@ -179,28 +199,23 @@ static const std::map<std::string, BCLog::LogFlags> LOG_CATEGORIES_BY_STR{ {"txreconciliation", BCLog::TXRECONCILIATION}, {"scan", BCLog::SCAN}, {"txpackages", BCLog::TXPACKAGES}, - {"1", BCLog::ALL}, - {"all", BCLog::ALL}, }; static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{ // Swap keys and values from LOG_CATEGORIES_BY_STR. - [](const std::map<std::string, BCLog::LogFlags>& in) { + [](const auto& in) { std::unordered_map<BCLog::LogFlags, std::string> out; for (const auto& [k, v] : in) { - switch (v) { - case BCLog::NONE: out.emplace(BCLog::NONE, ""); break; - case BCLog::ALL: out.emplace(BCLog::ALL, "all"); break; - default: out.emplace(v, k); - } + const bool inserted{out.emplace(v, k).second}; + assert(inserted); } return out; }(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()) { + if (str.empty() || str == "1" || str == "all") { flag = BCLog::ALL; return true; } @@ -229,14 +244,17 @@ std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) assert(false); } -std::string LogCategoryToStr(BCLog::LogFlags category) +static std::string LogCategoryToStr(BCLog::LogFlags category) { + if (category == BCLog::ALL) { + return "all"; + } auto it = LOG_CATEGORIES_BY_FLAG.find(category); assert(it != LOG_CATEGORIES_BY_FLAG.end()); return it->second; } -static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str) +static std::optional<BCLog::Level> GetLogLevel(std::string_view level_str) { if (level_str == "trace") { return BCLog::Level::Trace; @@ -256,10 +274,9 @@ static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str) std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const { std::vector<LogCategory> ret; + ret.reserve(LOG_CATEGORIES_BY_STR.size()); for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) { - if (flag != BCLog::NONE && flag != BCLog::ALL) { - ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)}); - } + ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)}); } return ret; } @@ -276,28 +293,23 @@ std::string BCLog::Logger::LogLevelsString() const return Join(std::vector<BCLog::Level>{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; - - if (m_started_new_line) { - const auto now{SystemClock::now()}; - const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)}; - strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds)); - if (m_log_time_micros && !strStamped.empty()) { - strStamped.pop_back(); - strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds)); - } - std::chrono::seconds mocktime = GetMockTime(); - if (mocktime > 0s) { - strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")"; - } - strStamped += ' ' + str; - } else - strStamped = str; + return strStamped; + + const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)}; + strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds)); + if (m_log_time_micros && !strStamped.empty()) { + strStamped.pop_back(); + strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds)); + } + if (mocktime > 0s) { + strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")"; + } + strStamped += ' '; return strStamped; } @@ -310,7 +322,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 +362,70 @@ 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) { - StdLockGuard scoped_lock(m_cs); - std::string str_prefixed = LogEscapeMessage(str); + return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>)); +} - if (m_started_new_line) { - str_prefixed.insert(0, GetLogPrefix(category, level)); - } +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 +{ + if (!str.ends_with('\n')) str.push_back('\n'); - if (m_log_sourcelocations && m_started_new_line) { - str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] "); + 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 && m_started_new_line) { - const auto& threadname = util::ThreadGetInternalName(); - str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] "); + if (m_log_threadnames) { + str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname))); } - str_prefixed = LogTimestampStr(str_prefixed); + 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); +} - m_started_new_line = !str.empty() && str[str.size()-1] == '\n'; +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_buffering) { - // buffer if we haven't started logging yet - m_msgs_before_open.push_back(str_prefixed); + { + 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; } + 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 +492,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 +500,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; |