Merge bitcoin/bitcoin#34865: logging: better use of log::Entry internally

c5ec2d5313 logging: replace FormatLogStrInPlace with Format (stickies-v)
3b92ec2036 logging: replace BufferedLog with log::Entry (stickies-v)
8115001cd4 logging: pass log::Entry through to logging functions (stickies-v)
b414913c73 util: add timestamp and thread_name to log::Entry (stickies-v)
8a55b17751 util: make SourceLocation constructor explicit (stickies-v)

Pull request description:

  Preparatory work to enable struct-based logging for kernel (#34374), but I think it's a mild improvement by itself too.

  #34465 introduced `util::log::Entry`. This PR updates some internal functions and structs to make better use of that new plumbing.

  Mostly a refactor, except for very minor timing differences for `timestamp` and `mocktime` which are now uniformly captured at `Entry` generation.

ACKs for top commit:
  maflcko:
    review ACK c5ec2d5313 🚐
  ryanofsky:
    Code review ACK c5ec2d5313. Just suggested changes since last review: adding (void) std::move, making SourceLocation constructor explicit, dropping BufferedLog struct. Overall PR is a nice code simplification, and I don't think it has downsides other than buffered logs now containing [ignored](https://github.com/bitcoin/bitcoin/pull/34865#discussion_r3054379230) `should_ratelimit` fields, which can be fixed in a followup by separating log entries from log options.
  sedited:
    ACK c5ec2d5313

Tree-SHA512: 3943f380a426b2c1b405226f231db51548c737467a278936b36a4cc738e01a790258f0886817d7caa1dbba7874f2e7f9ad93c36a137fa35f721f2d988b9863aa

src/logging.cpp

@@ -75,12 +75,17 @@ 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), SourceLocation{__func__}, BCLog::ALL, Level::Info, /*should_ratelimit=*/false);
+        LogPrint_({
+            .category = BCLog::ALL,
+            .level = Level::Info,
+            .should_ratelimit = false,
+            .source_loc = SourceLocation{__func__},
+            .message = strprintf("Early logging buffer overflowed, %d log lines discarded.", m_buffer_lines_discarded),
+        });
     }
     while (!m_msgs_before_open.empty()) {
         const auto& buflog = m_msgs_before_open.front();
-        std::string s{buflog.str};
-        FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_loc, buflog.threadname, buflog.now, buflog.mocktime);
+        std::string s{Format(buflog)};
         m_msgs_before_open.pop_front();
 
         if (m_print_to_file) FileWriteStr(s, m_fileout);
@@ -366,11 +371,11 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
     return s;
 }
 
-static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
+static size_t MemUsage(const util::log::Entry& log)
 {
-    return memusage::DynamicUsage(buflog.str) +
-           memusage::DynamicUsage(buflog.threadname) +
-           memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
+    return memusage::DynamicUsage(log.message) +
+           memusage::DynamicUsage(log.thread_name) +
+           memusage::MallocUsage(sizeof(memusage::list_node<util::log::Entry>));
 }
 
 BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
@@ -404,47 +409,38 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
     return status;
 }
 
-void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, const SourceLocation& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
+std::string BCLog::Logger::Format(const util::log::Entry& entry) const
 {
-    if (!str.ends_with('\n')) str.push_back('\n');
-
-    str.insert(0, GetLogPrefix(category, level));
-
-    if (m_log_sourcelocations) {
-        str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name_short()));
-    }
+    std::string result{LogTimestampStr(entry.timestamp, entry.mocktime)};
 
     if (m_log_threadnames) {
-        str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname)));
+        result += strprintf("[%s] ", (entry.thread_name.empty() ? "unknown" : entry.thread_name));
     }
 
-    str.insert(0, LogTimestampStr(now, mocktime));
+    if (m_log_sourcelocations) {
+        result += strprintf("[%s:%d] [%s] ", RemovePrefixView(entry.source_loc.file_name(), "./"), entry.source_loc.line(), entry.source_loc.function_name_short());
+    }
+
+    result += GetLogPrefix(static_cast<LogFlags>(entry.category), entry.level);
+    result += LogEscapeMessage(entry.message);
+
+    if (!result.ends_with('\n')) result += '\n';
+    return result;
 }
 
-void BCLog::Logger::LogPrintStr(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
+void BCLog::Logger::LogPrint(util::log::Entry entry)
 {
     STDLOCK(m_cs);
-    return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit);
+    return LogPrint_(std::move(entry));
 }
 
 // NOLINTNEXTLINE(misc-no-recursion)
-void BCLog::Logger::LogPrintStr_(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
+void BCLog::Logger::LogPrint_(util::log::Entry entry)
 {
-    std::string str_prefixed = LogEscapeMessage(str);
-
     if (m_buffering) {
         {
-            BufferedLog buf{
-                .now = SystemClock::now(),
-                .mocktime = GetMockTime(),
-                .str = str_prefixed,
-                .threadname = util::ThreadGetInternalName(),
-                .source_loc = std::move(source_loc),
-                .category = category,
-                .level = level,
-            };
-            m_cur_buffer_memusage += MemUsage(buf);
-            m_msgs_before_open.push_back(std::move(buf));
+            m_cur_buffer_memusage += MemUsage(entry);
+            m_msgs_before_open.push_back(std::move(entry));
         }
 
         while (m_cur_buffer_memusage > m_max_buffer_memusage) {
@@ -460,21 +456,26 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, SourceLocation&& source_l
         return;
     }
 
-    FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
+    std::string str_prefixed{Format(entry)};
     bool ratelimit{false};
-    if (should_ratelimit && m_limiter) {
-        auto status{m_limiter->Consume(source_loc, str_prefixed)};
+    if (entry.should_ratelimit && m_limiter) {
+        auto status{m_limiter->Consume(entry.source_loc, str_prefixed)};
         if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
             // NOLINTNEXTLINE(misc-no-recursion)
-            LogPrintStr_(strprintf(
-                             "Excessive logging detected from %s:%d (%s): >%d bytes logged during "
-                             "the last time window of %is. Suppressing logging to disk from this "
-                             "source location until time window resets. Console logging "
-                             "unaffected. Last log entry.",
-                             source_loc.file_name(), source_loc.line(), source_loc.function_name_short(),
-                             m_limiter->m_max_bytes,
-                             Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
-                         SourceLocation{__func__}, LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion
+            LogPrint_({
+                .category = LogFlags::ALL,
+                .level = Level::Warning,
+                .should_ratelimit = false, // with should_ratelimit=false, this cannot lead to infinite recursion
+                .source_loc = SourceLocation{__func__},
+                .message = strprintf(
+                    "Excessive logging detected from %s:%d (%s): >%d bytes logged during "
+                    "the last time window of %is. Suppressing logging to disk from this "
+                    "source location until time window resets. Console logging "
+                    "unaffected. Last log entry.",
+                    entry.source_loc.file_name(), entry.source_loc.line(), entry.source_loc.function_name_short(),
+                    m_limiter->m_max_bytes,
+                    Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
+            });
         } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
             ratelimit = true;
         }
@@ -612,6 +613,6 @@ void util::log::Log(util::log::Entry entry)
 {
     BCLog::Logger& logger{LogInstance()};
     if (logger.Enabled()) {
-        logger.LogPrintStr(std::move(entry.message), std::move(entry.source_loc), static_cast<BCLog::LogFlags>(entry.category), entry.level, entry.should_ratelimit);
+        logger.LogPrint(std::move(entry));
     }
 }

src/logging.h

@@ -129,21 +129,11 @@ namespace BCLog {
 
     class Logger
     {
-    public:
-        struct BufferedLog {
-            SystemClock::time_point now;
-            std::chrono::seconds mocktime;
-            std::string str, threadname;
-            SourceLocation source_loc;
-            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<BufferedLog> m_msgs_before_open GUARDED_BY(m_cs);
+        std::list<util::log::Entry> 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};
@@ -162,16 +152,15 @@ namespace BCLog {
         /** Log categories bitfield. */
         std::atomic<CategoryMask> m_categories{BCLog::NONE};
 
-        void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, const SourceLocation& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const;
+        std::string Format(const util::log::Entry& entry) 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) {};
+        std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs){};
 
-        /** Send a string to the log output (internal) */
-        void LogPrintStr_(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
-            EXCLUSIVE_LOCKS_REQUIRED(m_cs);
+        /** Send an entry to the log output (internal) */
+        void LogPrint_(util::log::Entry log_entry) EXCLUSIVE_LOCKS_REQUIRED(m_cs);
 
         std::string GetLogPrefix(LogFlags category, Level level) const;
 
@@ -188,9 +177,8 @@ namespace BCLog {
         fs::path m_file_path;
         std::atomic<bool> m_reopen_file{false};
 
-        /** Send a string to the log output */
-        void LogPrintStr(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
-            EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
+        /** Send an entry to the log output */
+        void LogPrint(util::log::Entry log_entry) EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
 
         /** Returns whether logs will be written to any output */
         bool Enabled() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs)

src/test/logging_tests.cpp

@@ -110,7 +110,7 @@ BOOST_AUTO_TEST_CASE(logging_timer)
     BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix);
 }
 
-BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
+BOOST_FIXTURE_TEST_CASE(logging_LogPrint, LogSetup)
 {
     LogInstance().m_log_sourcelocations = true;
 
@@ -134,7 +134,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
     std::vector<std::string> expected;
     for (auto& [msg, category, level, prefix, loc] : cases) {
         expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name_short(), prefix, msg));
-        LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false);
+        LogInstance().LogPrint({.category = category, .level = level, .should_ratelimit = false, .source_loc = std::move(loc), .message = msg});
     }
     std::vector<std::string> log_lines{ReadDebugLogLines()};
     BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());

src/util/log.h

@@ -10,6 +10,8 @@
 #include <logging/categories.h> // IWYU pragma: export
 #include <tinyformat.h>
 #include <util/check.h>
+#include <util/threadnames.h>
+#include <util/time.h>
 
 #include <cstdint>
 #include <source_location>
@@ -23,8 +25,9 @@ public:
     /// The func argument must be constructed from the C++11 __func__ macro.
     /// Ref: https://en.cppreference.com/w/cpp/language/function.html#func
     /// Non-static string literals are not supported.
-    SourceLocation(const char* func,
-                   std::source_location loc = std::source_location::current())
+    explicit SourceLocation(
+        const char* func,
+        std::source_location loc = std::source_location::current())
         : m_func{func}, m_loc{loc} {}
 
     std::string_view file_name() const { return m_loc.file_name(); }
@@ -52,6 +55,9 @@ struct Entry {
     Category category;
     Level level;
     bool should_ratelimit{false}; //!< Hint for consumers if this entry should be ratelimited
+    SystemClock::time_point timestamp{SystemClock::now()};
+    std::chrono::seconds mocktime{GetMockTime()};
+    std::string thread_name{util::ThreadGetInternalName()};
     SourceLocation source_loc;
     std::string message;
 };