Merge pull request #71 from sy-c/master

v2.1.0

Author: sy-c

doc/README.md

@@ -233,6 +233,14 @@ The InfoLogger library allows to inject messages directly from programs, as show
  * InfoLogger library is also available for: Tcl, Python, Go, Node.js.
    It allows to log message from scripting languages. A simplified subset of the InfoLogger C++ API is made available through SWIG-generated modules.
    Details of the functions accessible from the scripting interface are provided in [a separate document](scriptingAPI.md).
+
+ * C++ API provides a mean to automatically control / reduce the verbosity of some log messages.
+   Auto-mute occurs when a defined amount of messages using the same token in a period of time is exceeded.
+   The token parameter defines the limits for this maximum verbosity (max messages + time interval), and keeps internal count of usage.
+   * the time interval starts on the first message, and is reset on the next message after an interval completed. (it is not equal to "X seconds before last message").
+   * when the number of messages counted in an interval exceeds the threshold, auto-mute triggers ON: next messages (with this token) are discarded.
+   * when auto-mute is ON, one message is still printed for each time interval, with statistics about the number of discarded messages. The logging rate is effectively limited to a couple of messages per interval.
+   * the auto-mute triggers OFF when there was no message received for a duration equal to the interval time. (this is equal to "X seconds before last message").
    
 
 

doc/releaseNotes.md

@@ -94,3 +94,6 @@ This file describes the main feature changes for each InfoLogger released versio
 
 ## v2.0.1 - 05/05/2021
 - fix reconnect timeout in stdout fallback mode (now 5s).
+
+## v2.1.0 - 11/05/2021
+- API: added auto-mute feature for potentially verbose/repetitive messages. To be enabled message per message, using an AutoMuteToken (c++ only, see InfoLogger.hxx and testInfoLogger.cxx).

include/InfoLogger/InfoLogger.hxx

@@ -26,6 +26,8 @@
 #include <list>
 #include <utility>
 #include <type_traits>
+#include <atomic>
+#include <chrono>
 
 // here are some macros to help including source code info in infologger messages
 // to be used to quickly specify "infoLoggerMessageOption" argument in some logging functions
@@ -248,6 +250,36 @@ class InfoLogger
     -1,                  // sourceLine
   };
 
+  // Token used to control the flow of messages.
+  // Allows auto-mute when defined amount of messages using same token in a period of time is exceeded.
+  //
+  // Constructor parameters:
+  // logOptions: Logging options used for the log calls associated to this token.
+  // maxMsg: Maximum number of messages for the selected time interval, triggering auto-mute.
+  // interval: Time interval (duration in seconds) used for counting the number of messages.
+  struct AutoMuteToken {
+    public:
+    AutoMuteToken(const InfoLogger::InfoLoggerMessageOption vLogOptions, unsigned int vMaxMsg = 10, unsigned int vInterval = 5) {
+      count = 0;
+      logOptions = vLogOptions;
+      maxMsg = vMaxMsg;
+      interval = vInterval;
+    };
+    ~AutoMuteToken() {
+    };
+    
+    protected:
+    friend class InfoLogger;
+    InfoLogger::InfoLoggerMessageOption logOptions; // options used for associated logs
+    unsigned int maxMsg; // maximum number of messages for the selected time interval
+    unsigned int interval; // duration of interval (seconds)
+    std::atomic<unsigned int> count; // number of messages so far in interval
+    std::chrono::time_point<std::chrono::steady_clock> t0; // time of beginning of interval
+    std::chrono::time_point<std::chrono::steady_clock> t1; // time of previous message
+    unsigned int ndiscarded; // number of messages discarded in last interval
+    unsigned int ndiscardedtotal; // number of messages discarded since beginning of verbose phase    
+  };
+
   /// Convert a string to an infologger severity
   /// \param text  NUL-terminated word to convert to InfoLogger severity type. Current implementation is not exact-match, it takes closest based on first-letter value
   /// \return      Corresponding severity (InfoLogger::Undefined if no match found)
@@ -261,13 +293,30 @@ class InfoLogger
   static int setMessageOption(const char* fieldName, const char* fieldValue, InfoLoggerMessageOption& output);
 
   /// extended log function, with all extra fields, including a specific context
-  /// \return         0 on success, an error code otherwise (but never throw exceptions)..
+  /// \return         0 on success, an error code otherwise (but never throw exceptions).
   int log(const InfoLoggerMessageOption& options, const InfoLoggerContext& context, const char* message, ...) __attribute__((format(printf, 4, 5)));
 
   /// extended log function, with all extra fields, using default context
-  /// \return         0 on success, an error code otherwise (but never throw exceptions)..
+  /// \return         0 on success, an error code otherwise (but never throw exceptions).
   int log(const InfoLoggerMessageOption& options, const char* message, ...) __attribute__((format(printf, 3, 4)));
 
+  /// extended log function, with all extra fields, using default context
+  /// with automatic message muting, according to the usage of the token parameter provided.
+  /// Auto-mute occurs when defined amount of messages using same token in a period of time is exceeded.
+  /// The token parameter defines the limits for this maximum verbosity, and keeps internal count of usage.
+  /// The token should be the same variable used between consecutive calls for a given type of messages,
+  /// typically a static variable properly initialized with desired settings, close to the log call(s) to be controlled.
+  ///
+  ///
+  /// Auto-mute behavior is as follows:
+  /// - the time interval starts on the first message, and is reset on the next message after an interval completed. (it is not equal to "X seconds before last message").
+  /// - when the number of messages counted in an interval exceeds the threshold, auto-mute triggers ON: next messages (with this token) are discarded
+  /// - when auto-mute is on, one message is still printed for each time interval, with statistics about the number of discarded messages -> the logging rate is effectively limited to a couple of messages per interval
+  /// - the auto-mute triggers off when there was no message received for a duration equal to the interval time. (this is equal to "X seconds before last message").
+  /// 
+  /// \return         0 on success, an error code otherwise (but never throw exceptions).
+  int log(AutoMuteToken &token, const char* message, ...) __attribute__((format(printf, 3, 4)));
+
   //////////////////////////
   // iostream-like interface
   //////////////////////////

src/InfoLogger.cxx

@@ -1110,7 +1110,67 @@ void InfoLogger::filterReset() {
   mPimpl->filterDiscardLevel = InfoLogger::undefinedMessageOption.level;
 }
 
+int InfoLogger::log(AutoMuteToken &limit, const char* message, ...) { 
+  if (mPimpl->magicTag != InfoLoggerMagicNumber) {
+    return __LINE__;
+  }
 
+  unsigned int n = ++limit.count; // number of messages so far
+  auto now= std::chrono::steady_clock::now(); // current clock
+
+  // start interval timer
+  if (n == 1) {
+    limit.t0 = now;
+    limit.ndiscarded = 0;
+  }  
+  // end of interval flag
+  bool endOfInterval = ((n > 1) && ((std::chrono::duration_cast<std::chrono::seconds>(now - limit.t0)).count() >= limit.interval));
+
+  // discard when number of messages exceeded in interval
+  if ((n>limit.maxMsg) && (!endOfInterval)) {
+    limit.ndiscarded++;
+    limit.ndiscardedtotal++;
+    limit.t1 = now;
+    return -1;
+  }
+  
+  #define LOG_MUTE_PREFIX "[auto-mute] "
+  
+  if (endOfInterval) {
+    // report once per interval about excess logs
+    log(LOG_MUTE_PREFIX "%lu similar messages discarded since last sample (total: %u / %u)", limit.ndiscarded, limit.ndiscardedtotal, n-1);
+    if ((limit.ndiscarded == 0) || ((std::chrono::duration_cast<std::chrono::seconds>(now - limit.t1)).count() >= limit.interval)) {
+       // no message discarded / no message at all for one period, reset full count
+      limit.count = 1;
+      log(limit.logOptions, LOG_MUTE_PREFIX "It was quiet for a while, restoring full logging for similar messages");
+      limit.ndiscardedtotal = 0;
+    }
+    // reset period
+    limit.ndiscarded = 0;
+    limit.t0 = now;
+  }
+  
+  // log message
+  // forward variable list of arguments to logV method
+  int err;
+  va_list ap;
+  va_start(ap, message);
+  err = mPimpl->logV(limit.logOptions, mPimpl->currentContext, message, ap);
+  va_end(ap);
+  
+  if (!endOfInterval) {
+    // warn on limit on first excess
+    if ( n == limit.maxMsg) {
+      log(limit.logOptions, LOG_MUTE_PREFIX "Verbosity threshold exceeded (%u msg < %u s), discarding next similar messages", n, limit.interval);
+      limit.t0 = now;
+      limit.ndiscarded = 0;
+      limit.ndiscardedtotal = 0;
+    }
+  }
+  limit.t1 = now;
+
+  return err;
+}
 
 // end of namespace
 } // namespace InfoLogger

test/testInfoLogger.cxx

@@ -72,5 +72,27 @@ int main()
   theLog.log(LogInfoDevel, "Info message with severity filter - you should see this");
   theLog.filterReset();
   theLog.log(LogDebugDevel, "Debug message with severity filter - you should see this again");
+  
+  // message verbosity control with auto-mute
+  const int limitN = 5; // max number of messages ...
+  const int limitT = 3; // ... for given time interval
+  theLog.log("Will now test auto-mute: limit = %d msg / %d s", limitN, limitT);
+  // define a static variable token, and pass it to all relevant log() calls
+  static InfoLogger::AutoMuteToken msgLimit(LogInfoDevel_(1234), limitN, limitT);  
+  // a couple of loops to show behavior
+  for (int j=0; j<2; j++) {
+    const int nmsg = 20 * limitN;
+    const float msgRate = 10;
+    theLog.log("Injecting %d msgs at %.2f Hz", nmsg, msgRate);
+    for (int i=1; i<= nmsg; i++) {
+      theLog.log(msgLimit, "This is message loop %d", i);
+      usleep((int)(1000000/msgRate));
+    }
+    const int pauseTime = limitT+1;
+    theLog.log("Pause %d s", pauseTime);
+    usleep(pauseTime*1000000);
+  }
+  theLog.log(msgLimit, "Final message test for auto-mute");
+  theLog.log("End of test");  
   return 0;
 }