From 24dc347fe06f36ce6925e4c95939d022439fcc8f Mon Sep 17 00:00:00 2001 From: Shawn Carey Date: Thu, 6 Mar 2025 13:26:15 -0500 Subject: [PATCH 1/3] silence repeated log messages --- includes/ziti/ziti_log.h | 4 ++++ library/utils.c | 37 +++++++++++++++++++++++++++++++++---- tests/util_tests.cpp | 18 ++++++++++++++++++ 3 files changed, 55 insertions(+), 4 deletions(-) diff --git a/includes/ziti/ziti_log.h b/includes/ziti/ziti_log.h index cf18ff3f..e24b13aa 100644 --- a/includes/ziti/ziti_log.h +++ b/includes/ziti/ziti_log.h @@ -101,6 +101,10 @@ 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_max_repeat(int32_t max); + // don't use directly ZITI_FUNC extern int ziti_log_level(const char *module, const char *file); diff --git a/library/utils.c b/library/utils.c index 0409c28d..97c83a19 100644 --- a/library/utils.c +++ b/library/utils.c @@ -115,6 +115,7 @@ static const char *TLSUV_MODULE = "tlsuv"; static model_map log_levels; static int ziti_log_lvl = ZITI_LOG_DEFAULT_LEVEL; +static int ziti_log_max_repeat = -1; static FILE *ziti_debug_out; static bool log_initialized = false; static uv_pid_t log_pid = 0; @@ -242,6 +243,10 @@ void ziti_log_set_logger(log_writer log) { logger = log; } +void ziti_log_set_max_repeat(int32_t max) { + ziti_log_max_repeat = max; +} + static void init_uv_mbed_log() { char *lvl; if ((lvl = getenv("TLSUV_DEBUG")) != NULL) { @@ -320,6 +325,12 @@ static const char *basename(const char *path) { 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 +341,11 @@ void ziti_logger(int level, const char *module, const char *file, unsigned int l 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 +383,30 @@ void ziti_logger(int level, const char *module, const char *file, unsigned int l 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_max_repeat > 0) { + if (strcmp(logbuf->mesg, logbuf->prev_mesg) == 0) { + logbuf->repeat++; + if (logbuf->repeat >= ziti_log_max_repeat) return; + } else { + if (logbuf->repeat > ziti_log_max_repeat) { + // previous message had been silenced + int l = snprintf(logbuf->prev_mesg, loglinelen, "previous message repeated %u times", + logbuf->repeat - ziti_log_max_repeat + 1); + 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) { diff --git a/tests/util_tests.cpp b/tests/util_tests.cpp index 159d7b2a..fc10308a 100644 --- a/tests/util_tests.cpp +++ b/tests/util_tests.cpp @@ -92,4 +92,22 @@ 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) { + mesgs_logged++; +} + +TEST_CASE("check repeated logs are silenced") { + ziti_log_init(uv_default_loop(), INFO, test_log_writer); + ziti_log_set_max_repeat(5); + mesgs_logged = 0; + for (long i = 0; i < 10; i++) { + ZITI_LOG(INFO, "test message text"); + } + REQUIRE(mesgs_logged == 5); + mesgs_logged = 0; + ZITI_LOG(INFO, "something else now"); + REQUIRE(mesgs_logged == 2); // "message repeated" message, and "something else now" } \ No newline at end of file From e65677569003085a340483225848b7be291e4c3b Mon Sep 17 00:00:00 2001 From: Shawn Carey Date: Mon, 10 Mar 2025 15:52:54 -0400 Subject: [PATCH 2/3] add count-based suppressed log message notification --- includes/ziti/ziti_log.h | 5 ++++- library/utils.c | 27 +++++++++++++++++++-------- tests/util_tests.cpp | 31 ++++++++++++++++++++++++++++--- 3 files changed, 51 insertions(+), 12 deletions(-) diff --git a/includes/ziti/ziti_log.h b/includes/ziti/ziti_log.h index e24b13aa..72b0fa94 100644 --- a/includes/ziti/ziti_log.h +++ b/includes/ziti/ziti_log.h @@ -103,7 +103,10 @@ 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_max_repeat(int32_t max); +ZITI_FUNC extern void ziti_log_set_repeat_limit(int32_t n); + +// log a notification message after a message is suppressed n times +ZITI_FUNC extern void ziti_log_set_repeat_notify_count(uint32_t n); // don't use directly ZITI_FUNC extern int ziti_log_level(const char *module, const char *file); diff --git a/library/utils.c b/library/utils.c index 97c83a19..37b14ee4 100644 --- a/library/utils.c +++ b/library/utils.c @@ -115,7 +115,8 @@ static const char *TLSUV_MODULE = "tlsuv"; static model_map log_levels; static int ziti_log_lvl = ZITI_LOG_DEFAULT_LEVEL; -static int ziti_log_max_repeat = -1; +static int ziti_log_repeat_limit = -1; +static uint32_t ziti_log_repeat_notify_count = 500; static FILE *ziti_debug_out; static bool log_initialized = false; static uv_pid_t log_pid = 0; @@ -243,8 +244,12 @@ void ziti_log_set_logger(log_writer log) { logger = log; } -void ziti_log_set_max_repeat(int32_t max) { - ziti_log_max_repeat = max; +void ziti_log_set_repeat_limit(int32_t n) { + ziti_log_repeat_limit = n; +} + +void ziti_log_set_repeat_notify_count(uint32_t n) { + ziti_log_repeat_notify_count = n; } static void init_uv_mbed_log() { @@ -390,20 +395,26 @@ void ziti_logger(int level, const char *module, const char *file, unsigned int l len = (int) loglinelen; } - if (ziti_log_max_repeat > 0) { + if (ziti_log_repeat_limit > 0) { if (strcmp(logbuf->mesg, logbuf->prev_mesg) == 0) { logbuf->repeat++; - if (logbuf->repeat >= ziti_log_max_repeat) return; + if (logbuf->repeat >= ziti_log_repeat_limit) { + 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_max_repeat) { + if (logbuf->repeat > ziti_log_repeat_limit) { // previous message had been silenced int l = snprintf(logbuf->prev_mesg, loglinelen, "previous message repeated %u times", - logbuf->repeat - ziti_log_max_repeat + 1); + (logbuf->repeat - ziti_log_repeat_limit + 1) % 500); logfunc(level, "\b", logbuf->prev_mesg, l); } logbuf->repeat = 0; + strcpy(logbuf->prev_mesg, logbuf->mesg); } - strcpy(logbuf->prev_mesg, logbuf->mesg); } logfunc(level, location, logbuf->mesg, len); diff --git a/tests/util_tests.cpp b/tests/util_tests.cpp index fc10308a..8728a932 100644 --- a/tests/util_tests.cpp +++ b/tests/util_tests.cpp @@ -96,18 +96,43 @@ TEST_CASE("check hostname/domainname") { 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_max_repeat(5); + ziti_log_set_repeat_limit(5); + int i; + mesgs_logged = 0; - for (long i = 0; i < 10; i++) { + 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); // "message repeated" message, and "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); } \ No newline at end of file From a9d686e825e4e2f7bbd9e8a9b81bc2944ccbc585 Mon Sep 17 00:00:00 2001 From: Shawn Carey Date: Mon, 10 Mar 2025 17:25:47 -0400 Subject: [PATCH 3/3] rename log suppression functions --- includes/ziti/ziti_log.h | 6 +++--- library/utils.c | 20 ++++++++++---------- tests/util_tests.cpp | 2 +- 3 files changed, 14 insertions(+), 14 deletions(-) diff --git a/includes/ziti/ziti_log.h b/includes/ziti/ziti_log.h index 72b0fa94..22decc84 100644 --- a/includes/ziti/ziti_log.h +++ b/includes/ziti/ziti_log.h @@ -103,10 +103,10 @@ 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_repeat_limit(int32_t n); +ZITI_FUNC extern void ziti_log_set_suppress_threshold(int32_t n); -// log a notification message after a message is suppressed n times -ZITI_FUNC extern void ziti_log_set_repeat_notify_count(uint32_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); diff --git a/library/utils.c b/library/utils.c index 37b14ee4..7726ea0b 100644 --- a/library/utils.c +++ b/library/utils.c @@ -115,8 +115,8 @@ static const char *TLSUV_MODULE = "tlsuv"; static model_map log_levels; static int ziti_log_lvl = ZITI_LOG_DEFAULT_LEVEL; -static int ziti_log_repeat_limit = -1; -static uint32_t ziti_log_repeat_notify_count = 500; +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; @@ -244,12 +244,12 @@ void ziti_log_set_logger(log_writer log) { logger = log; } -void ziti_log_set_repeat_limit(int32_t n) { - ziti_log_repeat_limit = n; +void ziti_log_set_suppress_threshold(int32_t n) { + ziti_log_suppress_threshold = n; } -void ziti_log_set_repeat_notify_count(uint32_t n) { - ziti_log_repeat_notify_count = n; +void ziti_log_set_suppress_notify_count(uint32_t n) { + ziti_log_suppress_notify_count = n; } static void init_uv_mbed_log() { @@ -395,10 +395,10 @@ void ziti_logger(int level, const char *module, const char *file, unsigned int l len = (int) loglinelen; } - if (ziti_log_repeat_limit > 0) { + if (ziti_log_suppress_threshold > 0) { if (strcmp(logbuf->mesg, logbuf->prev_mesg) == 0) { logbuf->repeat++; - if (logbuf->repeat >= ziti_log_repeat_limit) { + 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); @@ -406,10 +406,10 @@ void ziti_logger(int level, const char *module, const char *file, unsigned int l return; // suppress } } else { - if (logbuf->repeat > ziti_log_repeat_limit) { + 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_repeat_limit + 1) % 500); + (logbuf->repeat - ziti_log_suppress_threshold + 1) % 500); logfunc(level, "\b", logbuf->prev_mesg, l); } logbuf->repeat = 0; diff --git a/tests/util_tests.cpp b/tests/util_tests.cpp index 8728a932..8d0ffb37 100644 --- a/tests/util_tests.cpp +++ b/tests/util_tests.cpp @@ -102,7 +102,7 @@ static void test_log_writer(int level, const char *loc, const char *msg, size_t TEST_CASE("check repeated logs are silenced") { ziti_log_init(uv_default_loop(), INFO, test_log_writer); - ziti_log_set_repeat_limit(5); + ziti_log_set_suppress_threshold(5); int i; mesgs_logged = 0;