silence repeated log messages

includes/ziti/ziti_log.h

@@ -101,6 +101,13 @@ ZITI_FUNC extern void ziti_log_set_logger(log_writer logger);
 // use ZITI_LOG_DEFAULT_LEVEL to reset to default(INFO) or ZITI_LOG env var
 ZITI_FUNC extern void ziti_log_set_level(int level, const char *marker);
 
+// set limit for repeated log messages. set to negative value to log all messages.
+// default is -1.
+ZITI_FUNC extern void ziti_log_set_suppress_threshold(int32_t n);
+
+// log a notification message after a message is suppressed n times. default is 500.
+ZITI_FUNC extern void ziti_log_set_suppress_notify_count(uint32_t n);
+
 // don't use directly
 ZITI_FUNC extern int ziti_log_level(const char *module, const char *file);
 

library/utils.c

@@ -115,6 +115,8 @@
 
 static model_map log_levels;
 static int ziti_log_lvl = ZITI_LOG_DEFAULT_LEVEL;
+static int ziti_log_suppress_threshold = -1;
+static uint32_t ziti_log_suppress_notify_count = 500;
 static FILE *ziti_debug_out;
 static bool log_initialized = false;
 static uv_pid_t log_pid = 0;
@@ -242,6 +244,14 @@
     logger = log;
 }
 
+void ziti_log_set_suppress_threshold(int32_t n) {
+    ziti_log_suppress_threshold = n;
+}
+
+void ziti_log_set_suppress_notify_count(uint32_t n) {
+    ziti_log_suppress_notify_count = n;
+}
+
 static void init_uv_mbed_log() {
     char *lvl;
     if ((lvl = getenv("TLSUV_DEBUG")) != NULL) {
@@ -320,6 +330,12 @@
     return path;
 }
 
+struct counted_mesg {
+    uint16_t repeat;
+    char *mesg;
+    char *prev_mesg;
+};
+
 void ziti_logger(int level, const char *module, const char *file, unsigned int line, const char *func, FORMAT_STRING(const char *fmt), ...) {
 #ifdef ZITI_DEBUG
     static size_t loglinelen = 32768;
@@ -330,9 +346,11 @@
     log_writer logfunc = logger;
     if (logfunc == NULL) { return; }
 
-    char *logbuf = (char *) uv_key_get(&logbufs);
+    struct counted_mesg *logbuf = uv_key_get(&logbufs);
     if (!logbuf) {
-        logbuf = malloc(loglinelen);
+        logbuf = calloc(1, sizeof(struct counted_mesg));
+        logbuf->mesg = malloc(loglinelen);
+        logbuf->prev_mesg = calloc(loglinelen, sizeof(char));
         uv_key_set(&logbufs, logbuf);
     }
 
@@ -370,14 +388,36 @@
 
     va_list argp;
     va_start(argp, fmt);
-    int len = vsnprintf(logbuf, loglinelen, fmt, argp);
+    int len = vsnprintf(logbuf->mesg, loglinelen, fmt, argp);
     va_end(argp);
 
     if (len > loglinelen) {
         len = (int) loglinelen;
     }
 
-    logfunc(level, location, logbuf, len);
+    if (ziti_log_suppress_threshold > 0) {
+        if (strcmp(logbuf->mesg, logbuf->prev_mesg) == 0) {
+            logbuf->repeat++;
+            if (logbuf->repeat >= ziti_log_suppress_threshold) {
+                if (logbuf->repeat % 500 == 0) {
+                    int l = strlen("previous message repeated 500 times");
+                    logfunc(level, "\b", "previous message repeated 500 times", l);
+                }
+                return; // suppress
+            }
+        } else {
+            if (logbuf->repeat > ziti_log_suppress_threshold) {
+                // previous message had been silenced
+                int l = snprintf(logbuf->prev_mesg, loglinelen, "previous message repeated %u times",
+                                 (logbuf->repeat - ziti_log_suppress_threshold + 1) % 500);
+                logfunc(level, "\b", logbuf->prev_mesg, l);
+            }
+            logbuf->repeat = 0;
+            strcpy(logbuf->prev_mesg, logbuf->mesg);
+        }
+    }
+
+    logfunc(level, location, logbuf->mesg, len);
 }
 
 static void default_log_writer(int level, const char *loc, const char *msg, size_t msglen) {
@@ -409,7 +449,7 @@
         time_t t = ts.tv_sec;
         struct tm *tm = gmtime(&t);
 
         snprintf(log_timestamp, sizeof(log_timestamp), "%04d-%02d-%02dT%02d:%02d:%02d.%03dZ",
                  1900 + tm->tm_year, tm->tm_mon + 1, tm->tm_mday,
                  tm->tm_hour, tm->tm_min, tm->tm_sec, ts.tv_usec / 1000
         );

tests/util_tests.cpp

@@ -92,4 +92,47 @@ TEST_CASE("check hostname/domainname") {
 
     printf("hostname = %s\n", info->hostname);
     printf("domain = %s\n", info->domain);
+}
+
+static uint32_t mesgs_logged = 0;
+static void test_log_writer(int level, const char *loc, const char *msg, size_t msglen) {
+    printf("--> %.*s\n", (int) msglen, msg);
+    mesgs_logged++;
+}
+
+TEST_CASE("check repeated logs are silenced") {
+    ziti_log_init(uv_default_loop(), INFO, test_log_writer);
+    ziti_log_set_suppress_threshold(5);
+    int i;
+
+    mesgs_logged = 0;
+    printf("expect 5 'test' messages...\n");
+    for (i = 0; i < 10; i++) {
+        ZITI_LOG(INFO, "test message text");
+    }
+    REQUIRE(mesgs_logged == 5);
+
+    mesgs_logged = 0;
+    printf("expect 1 'message repeated' message, and 1 'something else' message...\n");
+    ZITI_LOG(INFO, "something else now");
+    REQUIRE(mesgs_logged == 2);
+
+    mesgs_logged = 0;
+    printf("expect 4 'something else' messages...\n");
+    for (i = 1; i < 500; i++) {
+        ZITI_LOG(INFO, "something else now");
+    }
+    REQUIRE(mesgs_logged == 4);
+
+    mesgs_logged = 0;
+    printf("expect 2 'message repeated' messages...\n");
+    for (i = 0; i < 602; i++) {
+        ZITI_LOG(INFO, "something else now");
+    }
+    REQUIRE(mesgs_logged == 2);
+
+    mesgs_logged = 0;
+    printf("expect 1 more 'message repeated' message, and 1 'farewell' message\n");
+    ZITI_LOG(INFO, "farewell for now");
+    REQUIRE(mesgs_logged == 2);
 }