From: Russ Combs (rucombs) Date: Fri, 9 Oct 2015 20:45:23 +0000 (-0400) Subject: Merge pull request #69 in SNORT/snort3 from throttled_error_logger to master X-Git-Tag: 3.0.0-233~792 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=3d4d2df4043094981d9c3b72e33bf2bc980249bd;p=thirdparty%2Fsnort3.git Merge pull request #69 in SNORT/snort3 from throttled_error_logger to master Squashed commit of the following: commit 5e4c20cb627c916d7f989a79e3ec5717063525c8 Author: Joel Cornett Date: Fri Oct 9 16:15:31 2015 -0400 - Removed legacy ErrorMessageThrottled() code - Moved definition of STD_BUF to messages.h - Renamed char* get_buf() -> const char* last_message() const commit d803671565c26046e3d879936af58462e9596c46 Author: Joel Cornett Date: Thu Oct 8 19:58:29 2015 -0400 added ThrottledErrorLogger class --- diff --git a/src/log/messages.cc b/src/log/messages.cc index 8ea03dd35..82797c8a5 100644 --- a/src/log/messages.cc +++ b/src/log/messages.cc @@ -49,6 +49,10 @@ #include "time/timersub.h" #include "sfip/sf_ip.h" +#ifdef UNIT_TEST +#include "test/catch.hpp" +#endif + static int already_fatal = 0; /* @@ -159,53 +163,53 @@ void ErrorMessage(const char* format,...) va_end(ap); } -/* - * Function: ErrorMessageThrottled(ThrottleInfo *,const char *, ...) - * - * Purpose: Print a message to stderr, and throttle when - * too many messages are printed. - * - * Arguments: throttleInfo => point to the saved throttle state information - * format => the formatted error string to print out - * ... => format commands/fillers - * - * Returns: void function - */ +ThrottledErrorLogger::ThrottledErrorLogger(uint32_t dur) : + throttle_duration { dur } +{ reset(); } -void ErrorMessageThrottled(ThrottleInfo* throttleInfo, const char* format,...) +bool ThrottledErrorLogger::log(const char* format, ...) { - char buf[STD_BUF+1]; + if ( !snort_conf ) + return false; + + if ( throttle() ) + return false; + va_list ap; - time_t current_time = packet_time(); - if ((snort_conf == NULL)||(!throttleInfo)) - return; + va_start(ap, format); + int index = vsnprintf(buf, STD_BUF, format, ap); + va_end(ap); - throttleInfo->count++; - DebugFormat(DEBUG_INIT, - "current_time: %d, throttle (%p): count " STDu64 ", last update: %d\n", - (int)current_time, throttleInfo, throttleInfo->count, (int)throttleInfo->lastUpdate); - /*Note: we only output the first error message, - * and the statistics after at least duration_to_log seconds - * when the same type of error message is printed out again */ - if (current_time - (time_t)throttleInfo->duration_to_log > throttleInfo->lastUpdate) - { - int index; - va_start(ap, format); - index = vsnprintf(buf, STD_BUF, format, ap); - va_end(ap); + if ( index && ( count > 1 ) ) + snprintf(&buf[index - 1], STD_BUF - index, + " (suppressed " STDu64 " times in the last %d seconds).\n", + count, delta); - if (index && (throttleInfo->count > 1)) - { - snprintf(&buf[index - 1], STD_BUF-index, - " (suppressed " STDu64 " times in the last %d seconds).\n", - throttleInfo->count, (int)(current_time - throttleInfo->lastUpdate)); - } + ErrorMessage("%s", buf); + return true; +} - ErrorMessage("%s",buf); - throttleInfo->lastUpdate = current_time; - throttleInfo->count = 0; +void ThrottledErrorLogger::reset() +{ count = 0; } + +bool ThrottledErrorLogger::throttle() +{ + time_t cur = packet_time(); + bool result = false; + + if ( count++ ) + { + delta = cur - last; + result = (decltype(throttle_duration))delta < throttle_duration; + + if ( !result ) + count = 0; } + + last = cur; + + return result; } /* @@ -390,3 +394,91 @@ char* ObfuscateIpToText(const sfip_t* ip) return ip_buf; } +#ifdef UNIT_TEST + +static void set_packet_time(time_t x) +{ + struct timeval t { x, 0 }; + packet_time_update(&t); +} + +static bool check_message(const char* buffer, const char* msg) +{ + if ( strncmp(buffer, msg, strnlen(msg, STD_BUF)) != 0 ) + { + INFO( buffer ); + return false; + } + + return true; +} + +TEST_CASE( "throttled error logger", "[ThrottledErrorLogger]" ) +{ + uint32_t dur = 5; + ThrottledErrorLogger logger(dur); + + set_packet_time(0); + + SECTION( "1st message" ) + { + const char msg[] = "first message"; + REQUIRE( logger.log("%s\n", msg) ); + + CHECK( check_message(logger.last_message(), msg) ); + } + + SECTION( "2nd message within 1 second" ) + { + const char msg[] = "second message"; + logger.log(""); + + REQUIRE_FALSE( logger.log("%s\n", msg) ); + } + + SECTION( "0 duration" ) + { + logger.throttle_duration = 0; + const char msg[] = "zero duration"; + + logger.log(""); // trigger throttling + REQUIRE( logger.log("%s\n", msg) ); + + CHECK( check_message(logger.last_message(), msg) ); + } + + SECTION( "message @ duration" ) + { + const char msg[] = "at duration"; + logger.log(""); // trigger throttling + + set_packet_time(dur - 1); + CHECK_FALSE( logger.log("%s\n", msg) ); + } + + SECTION( "message after duration" ) + { + const char msg[] = "after duration"; + logger.log(""); // trigger throttling + + set_packet_time(dur); + REQUIRE( logger.log("%s\n", msg) ); + + CHECK( check_message(logger.last_message(), msg) ); + } + + SECTION( "reversed packet time" ) + { + const char msg[] = "reversed packet time"; + + set_packet_time(10); + logger.log(""); + + set_packet_time(4); + REQUIRE( logger.log("%s\n", msg) ); + + CHECK( check_message(logger.last_message(), msg) ); + } +} + +#endif diff --git a/src/log/messages.h b/src/log/messages.h index 193cc1b58..e3ff1f136 100644 --- a/src/log/messages.h +++ b/src/log/messages.h @@ -33,19 +33,37 @@ #ifndef __GNUC__ #define __attribute__(x) /*NOTHING*/ #endif + +#define STD_BUF 1024 + SO_PUBLIC void LogMessage(const char*, ...) __attribute__((format (printf, 1, 2))); SO_PUBLIC void WarningMessage(const char*, ...) __attribute__((format (printf, 1, 2))); SO_PUBLIC void ErrorMessage(const char*, ...) __attribute__((format (printf, 1, 2))); -struct ThrottleInfo +// FIXIT-L should we be using STL timekeeping types for this? +class ThrottledErrorLogger { - time_t lastUpdate; - /*Within this duration (in seconds), maximal one distinct message is logged*/ +public: + ThrottledErrorLogger(uint32_t); + + bool log(const char*, ...) __attribute__((format (printf, 2, 3))); + void reset(); + + uint32_t throttle_duration; uint32_t duration_to_log; + + const char* last_message() const + { return buf; } + +private: + bool throttle(); + + time_t last; + int delta; uint64_t count; -}; -void ErrorMessageThrottled(ThrottleInfo*,const char*, ...) __attribute__((format (printf, 2, 3))); + char buf[STD_BUF + 1]; +}; // FIXIT-M do not call FatalError() during runtime SO_PUBLIC NORETURN void FatalError(const char*, ...) __attribute__((format (printf, 1, 2))); diff --git a/src/utils/util.h b/src/utils/util.h index 2de92d083..c6c0d2f45 100644 --- a/src/utils/util.h +++ b/src/utils/util.h @@ -61,8 +61,6 @@ #define SECONDS_PER_HOUR 3600 /* number of seconds in a hour */ #define SECONDS_PER_MIN 60 /* number of seconds in a minute */ -#define STD_BUF 1024 - #define COPY4(x, y) \ x[0] = y[0]; x[1] = y[1]; x[2] = y[2]; x[3] = y[3];