From 0456828a50b86fd9185b7428e9012b7c18e970f9 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Thu, 4 Jul 2024 00:16:49 +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 | 113 ++++++++++++++++++++++++++++-------------------- src/logging.h | 17 +++++++- 2 files changed, 80 insertions(+), 50 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 8cd26f603fab1e..0a4f3ebbfe0741 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 skipped\n", m_buffer_lines_skipped), __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; - - 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; + return strStamped; + + 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 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 source_file, int source_line, std::string logging_function, std::string threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const { - return str.size() + memusage::MallocUsage(sizeof(memusage::list_node)); + 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,38 +398,44 @@ 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); - - 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; - break; + if (!starts_new_line && !m_msgs_before_open.empty()) { + m_msgs_before_open.back().str += str; + m_cur_buffer_memusage += str.size(); + } else { + 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_msgs_before_open.push_back(buf); + m_cur_buffer_memusage += MemUsage(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_skipped; } - m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front()); - m_msgs_before_open.pop_front(); - ++m_buffer_lines_skipped; } 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 91aab0f3816f86..cbfe7cc425016c 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, std::string source_file, int source_line, std::string logging_function, 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) {};