From 558df5c733d31456faf856d44f7037f41981d797 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Fri, 12 Jul 2024 10:19:55 +1000 Subject: [PATCH] logging: Apply formatting to early log messages The formatting of log messages isn't defined until StartLogging() is called; so can't be correctly applied to early log messages from prior to that call. Instead of saving the output log message, save the inputs to the logging invocation (including time, mocktime and thread name), and format those inputs into a log message when StartLogging() is called. --- src/logging.cpp | 105 ++++++++++++++++++++++++++++++------------------ src/logging.h | 17 +++++++- 2 files changed, 80 insertions(+), 42 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 9dafa720544..4b3b58a0b74 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -76,15 +76,16 @@ bool BCLog::Logger::StartLogging() 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); @@ -298,28 +299,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; } @@ -372,9 +368,24 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l return s; } -static size_t MemUsage(const std::string& str) +static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog) { - return str.size() + memusage::MallocUsage(sizeof(memusage::list_node)); + 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, const std::string& source_file, int source_line, const std::string& logging_function, const std::string& threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const +{ + str.insert(0, GetLogPrefix(category, level)); + + if (m_log_sourcelocations) { + str.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] "); + } + + if (m_log_threadnames) { + str.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] "); + } + + str.insert(0, LogTimestampStr(now, mocktime)); } 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) @@ -387,28 +398,37 @@ void BCLog::Logger::LogPrintStr_(const std::string& str, const std::string& logg { 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=logging_function, + .source_file=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)); + } - m_cur_buffer_memusage += MemUsage(str_prefixed); while (m_cur_buffer_memusage > m_max_buffer_memusage) { if (m_msgs_before_open.empty()) { m_cur_buffer_memusage = 0; @@ -418,9 +438,14 @@ void BCLog::Logger::LogPrintStr_(const std::string& str, const std::string& logg 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); diff --git a/src/logging.h b/src/logging.h index b3fe70cca70..5c64c9e447e 100644 --- a/src/logging.h +++ b/src/logging.h @@ -10,6 +10,7 @@ #include #include #include +#include #include #include @@ -83,11 +84,21 @@ namespace BCLog { 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}; @@ -110,7 +121,9 @@ 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, const std::string& source_file, int source_line, const std::string& logging_function, const std::string& 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) {};