Merge bitcoin/bitcoin#30386: Early logging improvements

b4dd7ab logging: use std::string_view (Anthony Towns)
558df5c logging: Apply formatting to early log messages (Anthony Towns)
6cf9b34 logging: Limit early logging buffer (Anthony Towns)
0b1960f logging: Add DisableLogging() (Anthony Towns)
6bbc2dd logging: Add thread safety annotations (Anthony Towns)

Pull request description:

  In order to cope gracefully with `Log*()` calls that are invoked prior to logging being fully configured (indicated by calling `StartLogging()` we buffer early log messages in `m_msgs_before_open`. This has a couple of minor issues:

   * if there are many such log messages the buffer can become arbitrarily large; this can be a problem for users of libkernel that might not wish to worry about logging at all, and as a result never invoke `StartLogging()`
   * early log messages are formatted before the formatting options are configured, leading to inconsistent output

  Fix those issues by buffering the log info prior to formatting it, and setting a limit on the size of the buffer (dropping the oldest lines, and reporting the number of lines skipped).

  Also adds some thread safety annotations, and the ability to invoke `LogInstance().DisableLogging()` if you want to disable logging entirely, for a minor efficiency improvement.

ACKs for top commit:
  maflcko:
    re-ACK b4dd7ab 🕴
  ryanofsky:
    Code review ACK b4dd7ab
  TheCharlatan:
    Nice, ACK b4dd7ab

Tree-SHA512: 966660181276939225a9f776de6ee0665e44577d2ee9cc76b06c8937297217482e6e426bdc5772d1ce533a0ba093a8556b6a50857d4c876ad8923e432a200440

Author: ryanofsky

src/bitcoin-chainstate.cpp

@@ -19,6 +19,7 @@
 
 #include <consensus/validation.h>
 #include <core_io.h>
+#include <logging.h>
 #include <node/blockstorage.h>
 #include <node/caches.h>
 #include <node/chainstate.h>
@@ -41,6 +42,12 @@
 
 int main(int argc, char* argv[])
 {
+    // We do not enable logging for this app, so explicitly disable it.
+    // To enable logging instead, replace with:
+    //    LogInstance().m_print_to_console = true;
+    //    LogInstance().StartLogging();
+    LogInstance().DisableLogging();
+
     // SETUP: Argument parsing and handling
     if (argc != 2) {
         std::cerr

src/logging.cpp

@@ -4,6 +4,7 @@
 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
 
 #include <logging.h>
+#include <memusage.h>
 #include <util/fs.h>
 #include <util/string.h>
 #include <util/threadnames.h>
@@ -14,8 +15,7 @@
 #include <optional>
 
 using util::Join;
-using util::RemovePrefix;
-using util::ToString;
+using util::RemovePrefixView;
 
 const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
 constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
@@ -43,7 +43,7 @@ BCLog::Logger& LogInstance()
 
 bool fLogIPs = DEFAULT_LOGIPS;
 
-static int FileWriteStr(const std::string &str, FILE *fp)
+static int FileWriteStr(std::string_view str, FILE *fp)
 {
     return fwrite(str.data(), 1, str.size(), fp);
 }
@@ -71,17 +71,22 @@ 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), __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);
 
     return true;
@@ -94,14 +99,31 @@ void BCLog::Logger::DisconnectTestLogger()
     if (m_fileout != nullptr) fclose(m_fileout);
     m_fileout = nullptr;
     m_print_callbacks.clear();
+    m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;
+    m_cur_buffer_memusage = 0;
+    m_buffer_lines_discarded = 0;
+    m_msgs_before_open.clear();
+
+}
+
+void BCLog::Logger::DisableLogging()
+{
+    {
+        StdLockGuard scoped_lock(m_cs);
+        assert(m_buffering);
+        assert(m_print_callbacks.empty());
+    }
+    m_print_to_file = false;
+    m_print_to_console = false;
+    StartLogging();
 }
 
 void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
 {
     m_categories |= flag;
 }
 
-bool BCLog::Logger::EnableCategory(const std::string& str)
+bool BCLog::Logger::EnableCategory(std::string_view str)
 {
     BCLog::LogFlags flag;
     if (!GetLogCategory(flag, str)) return false;
@@ -114,7 +136,7 @@ void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
     m_categories &= ~flag;
 }
 
-bool BCLog::Logger::DisableCategory(const std::string& str)
+bool BCLog::Logger::DisableCategory(std::string_view str)
 {
     BCLog::LogFlags flag;
     if (!GetLogCategory(flag, str)) return false;
@@ -145,7 +167,7 @@ bool BCLog::Logger::DefaultShrinkDebugFile() const
     return m_categories == BCLog::NONE;
 }
 
-static const std::map<std::string, BCLog::LogFlags> LOG_CATEGORIES_BY_STR{
+static const std::map<std::string, BCLog::LogFlags, std::less<>> LOG_CATEGORIES_BY_STR{
     {"0", BCLog::NONE},
     {"", BCLog::NONE},
     {"net", BCLog::NET},
@@ -185,7 +207,7 @@ static const std::map<std::string, BCLog::LogFlags> LOG_CATEGORIES_BY_STR{
 
 static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{
     // Swap keys and values from LOG_CATEGORIES_BY_STR.
-    [](const std::map<std::string, BCLog::LogFlags>& in) {
+    [](const auto& in) {
         std::unordered_map<BCLog::LogFlags, std::string> out;
         for (const auto& [k, v] : in) {
             switch (v) {
@@ -198,7 +220,7 @@ static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_
     }(LOG_CATEGORIES_BY_STR)
 };
 
-bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
+bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str)
 {
     if (str.empty()) {
         flag = BCLog::ALL;
@@ -236,7 +258,7 @@ std::string LogCategoryToStr(BCLog::LogFlags category)
     return it->second;
 }
 
-static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
+static std::optional<BCLog::Level> GetLogLevel(std::string_view level_str)
 {
     if (level_str == "trace") {
         return BCLog::Level::Trace;
@@ -276,28 +298,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;
 }
@@ -310,7 +327,7 @@ namespace BCLog {
      * It escapes instead of removes them to still allow for troubleshooting
      * issues where they accidentally end up in strings.
      */
-    std::string LogEscapeMessage(const std::string& str) {
+    std::string LogEscapeMessage(std::string_view str) {
         std::string ret;
         for (char ch_in : str) {
             uint8_t ch = (uint8_t)ch_in;
@@ -350,34 +367,84 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
     return s;
 }
 
-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)
+static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
 {
-    StdLockGuard scoped_lock(m_cs);
-    std::string str_prefixed = LogEscapeMessage(str);
+    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
+}
 
-    if (m_started_new_line) {
-        str_prefixed.insert(0, GetLogPrefix(category, level));
-    }
+void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
+{
+    str.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_sourcelocations) {
+        str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_file, "./"), 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) + "] ");
+    if (m_log_threadnames) {
+        str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname)));
     }
 
-    str_prefixed = LogTimestampStr(str_prefixed);
+    str.insert(0, LogTimestampStr(now, mocktime));
+}
+
+void BCLog::Logger::LogPrintStr(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
+{
+    StdLockGuard scoped_lock(m_cs);
+    return LogPrintStr_(str, logging_function, source_file, source_line, category, level);
+}
 
+void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
+{
+    std::string str_prefixed = LogEscapeMessage(str);
+
+    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=std::string(logging_function),
+                .source_file=std::string(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));
+        }
+
+        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_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);
@@ -444,15 +511,15 @@ void BCLog::Logger::ShrinkDebugFile()
         fclose(file);
 }
 
-bool BCLog::Logger::SetLogLevel(const std::string& level_str)
+bool BCLog::Logger::SetLogLevel(std::string_view level_str)
 {
     const auto level = GetLogLevel(level_str);
     if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
     m_log_level = level.value();
     return true;
 }
 
-bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str)
+bool BCLog::Logger::SetCategoryLogLevel(std::string_view category_str, std::string_view level_str)
 {
     BCLog::LogFlags flag;
     if (!GetLogCategory(flag, category_str)) return false;