Output the number of times a log has been throttled (#1876)

Adding the number of times a log message has been throttled can add
value in the sense that having the message show up once or twice may not
be as worrisome as it showing up thousands of times.

In order to achieve this, the log message can be split between its
header and the actual message. The header will now be handled by classes
separate to LogMessage that will hold the information necessary to print
them and use a common ILogHeader interface. This is done in order to
reduce the amount of code necessary in macros, there shouldn't be a huge
performance difference, but the current approach might take a bit more
memory in order to store this data, some testing is needed.

Co-authored-by: Olivier Valentin <ovalenti@redhat.com>

Author: Molter73

collector/lib/Logging.cpp

@@ -101,6 +101,8 @@ bool ParseLogLevelName(std::string name, LogLevel* level) {
 }
 
 void InspectorLogCallback(std::string&& msg, sinsp_logger::severity severity) {
+  using namespace collector::logging;
+
   auto collector_severity = (LogLevel)severity;
 
   if (collector_severity == LogLevel::DEBUG && msg.rfind("libbpf:", 0) == 0) {
@@ -109,11 +111,12 @@ void InspectorLogCallback(std::string&& msg, sinsp_logger::severity severity) {
     collector_severity = LogLevel::TRACE;
   }
 
-  if (!collector::logging::CheckLogLevel(collector_severity)) {
+  if (!CheckLogLevel(collector_severity)) {
     return;
   }
 
-  collector::logging::LogMessage(__FILE__, __LINE__, false, collector_severity) << msg;
+  static LogHeader header(__FILE__, __LINE__, collector_severity);
+  LogMessage(header) << msg;
 }
 
 const char* GetGlobalLogPrefix() {

collector/lib/Logging.h

@@ -3,6 +3,7 @@
 
 #include <chrono>
 #include <cstdint>
+#include <filesystem>
 #include <iomanip>
 #include <iostream>
 #include <sstream>
@@ -54,15 +55,35 @@ void WriteTerminationLog(std::string message);
 
 const size_t LevelPaddingWidth = 7;
 
-class LogMessage {
+/**
+ * Interface for log headers.
+ *
+ * This class defines how log headers should behave and provides some
+ * basic, reusable methods.
+ */
+class ILogHeader {
  public:
-  LogMessage(const char* file, int line, bool throttled, LogLevel level)
-      : file_(file), line_(line), level_(level), throttled_(throttled) {
-    // if in debug mode, output file names associated with log messages
-    include_file_ = CheckLogLevel(LogLevel::DEBUG);
+  ILogHeader(const char* file, int line, LogLevel level)
+      : line_(line), level_(level) {
+    std::filesystem::path p(file);
+    if (p.has_filename()) {
+      file_ = p.filename().string();
+    } else {
+      file_ = p.string();
+    }
   }
 
-  ~LogMessage() {
+  ILogHeader(const ILogHeader&) = delete;
+  ILogHeader(ILogHeader&&) = delete;
+  ILogHeader& operator=(const ILogHeader&) = delete;
+  ILogHeader& operator=(ILogHeader&&) = delete;
+  virtual ~ILogHeader() = default;
+
+  virtual void PrintHeader() = 0;
+  inline LogLevel GetLogLevel() const { return level_; }
+
+ protected:
+  void PrintPrefix() {
     auto now = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
     auto nowTm = gmtime(&now);
 
@@ -71,25 +92,106 @@ class LogMessage {
               << std::left << std::setw(LevelPaddingWidth) << GetLogLevelName(level_)
               << " " << std::put_time(nowTm, "%Y/%m/%d %H:%M:%S")
               << "] ";
+  }
 
-    if (throttled_) {
-      std::cerr << "[Throttled] ";
+  void PrintFile() {
+    if (CheckLogLevel(LogLevel::DEBUG)) {
+      std::cerr << "(" << file_ << ":" << line_ << ") ";
     }
+  }
+
+ private:
+  std::string file_;
+  int line_;
+  LogLevel level_;
+};
+
+/**
+ * Basic log header.
+ *
+ * Most log lines will use this header.
+ *
+ * The format when running in debug level will be:
+ * [LEVEL  YYYY/MM/DD HH:mm:SS] (file:line)
+ *
+ * Other log levels exclude the (file:line) part of the header.
+ */
+class LogHeader : public ILogHeader {
+ public:
+  LogHeader(const char* file, int line, LogLevel level)
+      : ILogHeader(file, line, level) {}
+
+  void PrintHeader() override {
+    PrintPrefix();
+    PrintFile();
+  }
+};
+
+/**
+ * Throttled log header.
+ *
+ * When the same log message is triggered multiple times, this header
+ * helps prevent flooding the logs and instead counts the occurrences
+ * of the message, which will be output after a given time window
+ * expires.
+ *
+ * The format when running in debug level will be:
+ * [LEVEL  YYYY/MM/DD HH:mm:SS] [Throttled COUNT message] (file:line)
+ *
+ * Other log levels exclude the (file:line) part of the header.
+ */
+class ThrottledLogHeader : public ILogHeader {
+ public:
+  ThrottledLogHeader(const char* file, int line, LogLevel level, std::chrono::duration<unsigned int> interval)
+      : ILogHeader(file, line, level), interval_(interval) {}
+
+  void PrintHeader() override {
+    PrintPrefix();
+
+    std::cerr << "[Throttled " << count_ << " messages] ";
+    count_ = 0;
+
+    PrintFile();
+  }
 
-    if (include_file_) {
-      const char* basename = strrchr(file_, '/');
-      if (!basename) {
-        basename = file_;
-      } else {
-        ++basename;
-      }
-      std::cerr << "(" << basename << ":" << line_ << ") ";
+  /**
+   * Check if the log message should be suppressed.
+   *
+   * Throttled logs only output a message every interval_ time windows.
+   * Every time this method is called, we increment count_ so the next
+   * time the log is printed we can add the amount of times the log has
+   * happened.
+   *
+   * @returns true if the log has to be suppressed.
+   */
+  bool Suppress() {
+    std::chrono::duration elapsed = std::chrono::steady_clock::now() - last_log_;
+    count_++;
+    if (elapsed < interval_) {
+      return true;
     }
 
+    last_log_ = std::chrono::steady_clock::now();
+    return false;
+  }
+
+ private:
+  std::chrono::steady_clock::time_point last_log_;
+  std::chrono::duration<unsigned int> interval_;
+  unsigned long count_{};
+};
+
+class LogMessage {
+ public:
+  LogMessage(ILogHeader& ls) : ls_(ls) {}
+
+  ~LogMessage() {
+    ls_.PrintHeader();
+
     std::cerr << buf_.str()
               << std::endl;
 
-    if (level_ == LogLevel::FATAL) {
+    if (ls_.GetLogLevel() == LogLevel::FATAL) {
       WriteTerminationLog(buf_.str());
       exit(1);
     }
@@ -102,32 +204,35 @@ class LogMessage {
   }
 
  private:
-  const char* file_;
-  int line_;
-  LogLevel level_;
+  ILogHeader& ls_;
   std::stringstream buf_;
-  bool include_file_;
-  bool throttled_;
 };
 
 }  // namespace logging
 
 }  // namespace collector
 
+// Helpers for creating unique variables within a compilation unit.
+#define CLOG_CAT_(a, b) a##b
+#define CLOG_CAT(a, b) CLOG_CAT_(a, b)
+#define CLOG_VAR(a) CLOG_CAT(a, __LINE__)
+
 #define CLOG_ENABLED(lvl) (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl))
 
 #define CLOG_IF(cond, lvl)                                                            \
+  static collector::logging::LogHeader CLOG_VAR(_clog_stmt_)(                         \
+      __FILE__, __LINE__, collector::logging::LogLevel::lvl);                         \
   if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) \
-  collector::logging::LogMessage(__FILE__, __LINE__, false, collector::logging::LogLevel::lvl)
+  collector::logging::LogMessage(CLOG_VAR(_clog_stmt_))
 
 #define CLOG(lvl) CLOG_IF(true, lvl)
 
 #define CLOG_THROTTLED_IF(cond, lvl, interval)                                          \
-  static std::chrono::steady_clock::time_point _clog_lastlog_##__LINE__;                \
+  static collector::logging::ThrottledLogHeader CLOG_VAR(_clog_stmt_)(                  \
+      __FILE__, __LINE__, collector::logging::LogLevel::lvl, interval);                 \
   if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond) && \
-      (std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__ >= interval))        \
-  _clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(),                          \
-  collector::logging::LogMessage(__FILE__, __LINE__, true, collector::logging::LogLevel::lvl)
+      !CLOG_VAR(_clog_stmt_).Suppress())                                                \
+  collector::logging::LogMessage(CLOG_VAR(_clog_stmt_))
 
 #define CLOG_THROTTLED(lvl, interval) CLOG_THROTTLED_IF(true, lvl, interval)