diff --git a/includes/ziti/ziti_log.h b/includes/ziti/ziti_log.h index cf18ff3f..22decc84 100644 --- a/includes/ziti/ziti_log.h +++ b/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); diff --git a/library/utils.c b/library/utils.c index 0409c28d..7726ea0b 100644 --- a/library/utils.c +++ b/library/utils.c @@ -115,6 +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_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 @@ void ziti_log_set_logger(log_writer log) { 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 @@ 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 +346,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 +388,36 @@ 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_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) { diff --git a/tests/util_tests.cpp b/tests/util_tests.cpp index 159d7b2a..8d0ffb37 100644 --- a/tests/util_tests.cpp +++ b/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); } \ No newline at end of file