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.

Author: ajtowns

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<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;
 }
@@ -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<std::string>));
+    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
+}
+
+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);

src/logging.h

@@ -10,6 +10,7 @@
 #include <tinyformat.h>
 #include <util/fs.h>
 #include <util/string.h>
+#include <util/time.h>
 
 #include <atomic>
 #include <cstdint>
@@ -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<std::string> m_msgs_before_open GUARDED_BY(m_cs);
+        std::list<BufferedLog> 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<uint32_t> 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<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {};