From 1ef58b31777f48c410b0529ee3cc3bc45b277d6e Mon Sep 17 00:00:00 2001 From: Olivier Valentin Date: Thu, 25 Jan 2024 08:51:55 +0100 Subject: [PATCH 1/5] Count the number of throttled log message and print it. --- collector/lib/Logging.cpp | 2 +- collector/lib/Logging.h | 24 ++++++++++++++---------- 2 files changed, 15 insertions(+), 11 deletions(-) diff --git a/collector/lib/Logging.cpp b/collector/lib/Logging.cpp index 5897f68bc8..3f0a9678ec 100644 --- a/collector/lib/Logging.cpp +++ b/collector/lib/Logging.cpp @@ -113,7 +113,7 @@ void InspectorLogCallback(std::string&& msg, sinsp_logger::severity severity) { return; } - collector::logging::LogMessage(__FILE__, __LINE__, false, collector_severity) << msg; + collector::logging::LogMessage(__FILE__, __LINE__, collector_severity) << msg; } const char* GetGlobalLogPrefix() { diff --git a/collector/lib/Logging.h b/collector/lib/Logging.h index 8620979fff..b03be8a637 100644 --- a/collector/lib/Logging.h +++ b/collector/lib/Logging.h @@ -56,8 +56,8 @@ const size_t LevelPaddingWidth = 7; class LogMessage { public: - LogMessage(const char* file, int line, bool throttled, LogLevel level) - : file_(file), line_(line), level_(level), throttled_(throttled) { + LogMessage(const char* file, int line, LogLevel level, unsigned long throttled_times = 0) + : file_(file), line_(line), level_(level), throttled_times_(throttled_times) { // if in debug mode, output file names associated with log messages include_file_ = CheckLogLevel(LogLevel::DEBUG); } @@ -72,8 +72,8 @@ class LogMessage { << " " << std::put_time(nowTm, "%Y/%m/%d %H:%M:%S") << "] "; - if (throttled_) { - std::cerr << "[Throttled] "; + if (throttled_times_ != 0) { + std::cerr << "[Throttled " << throttled_times_ << " messages] "; } if (include_file_) { @@ -107,7 +107,7 @@ class LogMessage { LogLevel level_; std::stringstream buf_; bool include_file_; - bool throttled_; + bool throttled_times_; }; } // namespace logging @@ -118,16 +118,20 @@ class LogMessage { #define CLOG_IF(cond, lvl) \ if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) \ - collector::logging::LogMessage(__FILE__, __LINE__, false, collector::logging::LogLevel::lvl) + collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl) #define CLOG(lvl) CLOG_IF(true, lvl) #define CLOG_THROTTLED_IF(cond, lvl, interval) \ static std::chrono::steady_clock::time_point _clog_lastlog_##__LINE__; \ - 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) + static unsigned long _clog_lastlog_##__LINE__##_times_ = 0; \ + if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) { \ + if (std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__ < interval) \ + _clog_lastlog_##__LINE__##_times_++; \ + } else \ + _clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \ + _clog_lastlog_##__LINE__##_times_ = 0, \ + collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, _clog_lastlog_##__LINE__##_times_) #define CLOG_THROTTLED(lvl, interval) CLOG_THROTTLED_IF(true, lvl, interval) From fba49a40b69713ce1c4498c35a74b284d04cdb15 Mon Sep 17 00:00:00 2001 From: Olivier Valentin Date: Thu, 4 Jul 2024 18:19:20 +0200 Subject: [PATCH 2/5] Use implicit if-else precedence. --- collector/lib/Logging.h | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/collector/lib/Logging.h b/collector/lib/Logging.h index b03be8a637..58b5f6d403 100644 --- a/collector/lib/Logging.h +++ b/collector/lib/Logging.h @@ -122,16 +122,16 @@ class LogMessage { #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 unsigned long _clog_lastlog_##__LINE__##_times_ = 0; \ - if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) { \ - if (std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__ < interval) \ - _clog_lastlog_##__LINE__##_times_++; \ - } else \ - _clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \ - _clog_lastlog_##__LINE__##_times_ = 0, \ - collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, _clog_lastlog_##__LINE__##_times_) +#define CLOG_THROTTLED_IF(cond, lvl, interval) \ + static std::chrono::steady_clock::time_point _clog_lastlog_##__LINE__; \ + static unsigned long _clog_lastlog_##__LINE__##_times_ = 0; \ + if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) \ + if (std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__ < interval) \ + _clog_lastlog_##__LINE__##_times_++; \ + else \ + _clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \ + _clog_lastlog_##__LINE__##_times_ = 0, \ + collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, _clog_lastlog_##__LINE__##_times_) #define CLOG_THROTTLED(lvl, interval) CLOG_THROTTLED_IF(true, lvl, interval) From 29cf48f60853d21388ae1c16e5db4ccb196abc93 Mon Sep 17 00:00:00 2001 From: Olivier Valentin Date: Fri, 5 Jul 2024 15:24:26 +0200 Subject: [PATCH 3/5] Reset the throttling counter as a side-effect of LogMessage constructor --- collector/lib/Logging.h | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/collector/lib/Logging.h b/collector/lib/Logging.h index 58b5f6d403..4df9a12582 100644 --- a/collector/lib/Logging.h +++ b/collector/lib/Logging.h @@ -56,10 +56,15 @@ const size_t LevelPaddingWidth = 7; class LogMessage { public: - LogMessage(const char* file, int line, LogLevel level, unsigned long throttled_times = 0) + LogMessage(const char* file, int line, LogLevel level, unsigned long* throttled_times = 0) : file_(file), line_(line), level_(level), throttled_times_(throttled_times) { // if in debug mode, output file names associated with log messages include_file_ = CheckLogLevel(LogLevel::DEBUG); + if (throttled_times) { + // this is a throttled message, take the occurrences number and reset it + throttled_times_ = *throttled_times; + *throttled_times = 0; + } } ~LogMessage() { @@ -130,8 +135,7 @@ class LogMessage { _clog_lastlog_##__LINE__##_times_++; \ else \ _clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \ - _clog_lastlog_##__LINE__##_times_ = 0, \ - collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, _clog_lastlog_##__LINE__##_times_) + collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, &_clog_lastlog_##__LINE__##_times_) #define CLOG_THROTTLED(lvl, interval) CLOG_THROTTLED_IF(true, lvl, interval) From 5d81b21738763db93ba7ff93fb5895bb1331c76d Mon Sep 17 00:00:00 2001 From: Olivier Valentin Date: Fri, 5 Jul 2024 15:57:40 +0200 Subject: [PATCH 4/5] Break the if-else into two distinct if statements This is likely less efficient, but prevents warnings about ambiguous dangling else statement. --- collector/lib/Logging.h | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/collector/lib/Logging.h b/collector/lib/Logging.h index 4df9a12582..9741ef9cc5 100644 --- a/collector/lib/Logging.h +++ b/collector/lib/Logging.h @@ -127,15 +127,16 @@ class LogMessage { #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 unsigned long _clog_lastlog_##__LINE__##_times_ = 0; \ - if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) \ - if (std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__ < interval) \ - _clog_lastlog_##__LINE__##_times_++; \ - else \ - _clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \ - collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, &_clog_lastlog_##__LINE__##_times_) +#define CLOG_THROTTLED_IF(cond, lvl, interval) \ + static std::chrono::steady_clock::time_point _clog_lastlog_##__LINE__; \ + static unsigned long _clog_throttle_times_##__LINE__ = 0; \ + std::chrono::duration _clog_elapsed_##__LINE__ = std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__; \ + if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond) && _clog_elapsed_##__LINE__ < interval) { \ + _clog_throttle_times_##__LINE__++; \ + } \ + if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond) && _clog_elapsed_##__LINE__ >= interval) \ + _clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \ + collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, &_clog_throttle_times_##__LINE__) #define CLOG_THROTTLED(lvl, interval) CLOG_THROTTLED_IF(true, lvl, interval) From dd3573054b71285cc7713a55f0ced58bb5febf10 Mon Sep 17 00:00:00 2001 From: Olivier Valentin Date: Fri, 5 Jul 2024 16:04:28 +0200 Subject: [PATCH 5/5] Initialize throttled_times properly --- collector/lib/Logging.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/collector/lib/Logging.h b/collector/lib/Logging.h index 9741ef9cc5..4e213b3795 100644 --- a/collector/lib/Logging.h +++ b/collector/lib/Logging.h @@ -57,7 +57,7 @@ const size_t LevelPaddingWidth = 7; class LogMessage { public: LogMessage(const char* file, int line, LogLevel level, unsigned long* throttled_times = 0) - : file_(file), line_(line), level_(level), throttled_times_(throttled_times) { + : file_(file), line_(line), level_(level), throttled_times_(0) { // if in debug mode, output file names associated with log messages include_file_ = CheckLogLevel(LogLevel::DEBUG); if (throttled_times) { @@ -112,7 +112,7 @@ class LogMessage { LogLevel level_; std::stringstream buf_; bool include_file_; - bool throttled_times_; + unsigned long throttled_times_; }; } // namespace logging