Merge pull request #69 in SNORT/snort3 from throttled_error_logger to master

Squashed commit of the following:

commit 5e4c20cb627c916d7f989a79e3ec5717063525c8
Author: Joel Cornett <joel.cornett@gmail.com>
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 <joel.cornett@gmail.com>
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 8ea03dd35bec38223a2c37ca47b823e73efcf466..82797c8a57916a106de4827ac9b5d44b132a3242 100644 (file)
--- 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 193cc1b58a97b34cbfe2ecbdd40c76c68bd29eae..e3ff1f136449c95bbf4158b89d8c2850ab3d7926 100644 (file)
--- 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 2de92d083054ac1a0c8564c0da061d9e07bdc65e..c6c0d2f45b9eb8869220da79b47c5369b9da6a33 100644 (file)
--- 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];