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) {};