time: improve offline time handling

When we run on live traffic, time handling is simple. Packets have a
timestamp set by the capture method. Management threads can simply
use 'gettimeofday' to know the current time. There should never be
any serious gap between the two or major differnces between the
threads.

In offline mode, things are dramatically different. Here we try to keep
the time from the pcap, which means that if the packets are recorded in
2011 the log output should also reflect this. Multiple issues:

 1. merged pcaps might have huge time jumps or time going backward
 2. slowly recorded pcaps may be processed much faster than their
    'realtime'
 3. management threads need a concept of what the 'current' time is for
    enforcing timeouts
 4. due to (1) individual threads may have very different views on what
    the current time is. E.g. T1 processed packet 1 with TS X, while T2
    at the very same time processes packet 2 with TS X+100000s.

The changes in flow handling make the problems worse. The capture thread
no longer handles the flow lookup, while it did set the global 'time'.
This meant that a thread may be working on Packet 1 with TS 1, while the
capture thread already saw packet 2 with TS 10000. Management threads
would take TS 10000 as the 'current time', considering a flow created by
the first thread as timed out immediately.

This was less of a problem before the flow changes as the capture thread
would also create a flow reference for a packet, meaning the flow
couldn't time out as easily. Packets in the queues between capture
thread and workers would all hold such references.

The patch updates the time handling to be as follows.

In offline mode we keep the timestamp per thread. If a management thread
needs current time, it will get the minimum of the threads' values. This
is to avoid the problem that T2s time value might already trigger a flow
timeout as the flow lastts + 100000s is almost certainly meaning the
flow would be considered timed out.

diff --git a/src/source-pcap-file.c b/src/source-pcap-file.c
index cff52542a198748976cb944d993811229f63ff92..92fb6f6fa20ac9c253cf2f88e84e10cad3b6bad3 100644 (file)
--- a/src/source-pcap-file.c
+++ b/src/source-pcap-file.c
@@ -420,10 +420,6 @@ TmEcode DecodePcapFile(ThreadVars *tv, Packet *p, void *data, PacketQueue *pq, P
         FlowWakeupFlowManagerThread();
     }
 
-    /* update the engine time representation based on the timestamp
-     * of the packet. */
-    TimeSet(&p->ts);
-
     /* call the decoder */
     pcap_g.Decoder(tv, dtv, p, GET_PKT_DATA(p), GET_PKT_LEN(p), pq);
 

diff --git a/src/stream-tcp.c b/src/stream-tcp.c
index eec197f9fd52785f63d9e8cb73267089a73fc6eb..941211dc4d7b04a0ae994e77dab28131f61baf1f 100644 (file)
--- a/src/stream-tcp.c
+++ b/src/stream-tcp.c
@@ -4880,6 +4880,8 @@ TmEcode StreamTcp (ThreadVars *tv, Packet *p, void *data, PacketQueue *pq, Packe
 
     SCLogDebug("p->pcap_cnt %"PRIu64, p->pcap_cnt);
 
+    TimeSetByThread(tv->id, &p->ts);
+
     if (p->flow && p->flags & PKT_PSEUDO_STREAM_END) {
         FLOWLOCK_WRLOCK(p->flow);
         AppLayerProfilingReset(stt->ra_ctx->app_tctx);

diff --git a/src/tm-threads.c b/src/tm-threads.c
index 1d7b5fe149cc46f8dfae25a1c457477c4091dac5..89db9812b4215b8dd3f67e4c77b0ff4b0d35941d 100644 (file)
--- a/src/tm-threads.c
+++ b/src/tm-threads.c
@@ -2224,6 +2224,8 @@ typedef struct Thread_ {
     const char *name;
     int type;
     int in_use;         /**< bool to indicate this is in use */
+
+    struct timeval ts;  /**< current time of this thread (offline mode) */
 } Thread;
 
 typedef struct Threads_ {
@@ -2332,6 +2334,53 @@ end:
     SCMutexUnlock(&thread_store_lock);
 }
 
+void TmThreadsSetThreadTimestamp(const int id, const struct timeval *ts)
+{
+    SCMutexLock(&thread_store_lock);
+    if (unlikely(id <= 0 || id > (int)thread_store.threads_size)) {
+        SCMutexUnlock(&thread_store_lock);
+        return;
+    }
+
+    int idx = id - 1;
+    Thread *t = &thread_store.threads[idx];
+    t->ts.tv_sec = ts->tv_sec;
+    t->ts.tv_usec = ts->tv_usec;
+    SCMutexUnlock(&thread_store_lock);
+}
+
+#define COPY_TIMESTAMP(src,dst) ((dst)->tv_sec = (src)->tv_sec, (dst)->tv_usec = (src)->tv_usec) // XXX unify with flow-util.h
+void TmreadsGetMinimalTimestamp(struct timeval *ts)
+{
+    struct timeval local, nullts;
+    memset(&local, 0, sizeof(local));
+    memset(&nullts, 0, sizeof(nullts));
+    int set = 0;
+    size_t s;
+
+    SCMutexLock(&thread_store_lock);
+    for (s = 0; s < thread_store.threads_size; s++) {
+        Thread *t = &thread_store.threads[s];
+        if (t == NULL || t->in_use == 0)
+            continue;
+        if (!(timercmp(&t->ts, &nullts, ==))) {
+            if (!set) {
+                local.tv_sec = t->ts.tv_sec;
+                local.tv_usec = t->ts.tv_usec;
+                set = 1;
+            } else {
+                if (timercmp(&t->ts, &local, <)) {
+                    COPY_TIMESTAMP(&t->ts, &local);
+                }
+            }
+        }
+    }
+    SCMutexUnlock(&thread_store_lock);
+    COPY_TIMESTAMP(&local, ts);
+    SCLogDebug("ts->tv_sec %u", (uint)ts->tv_sec);
+}
+#undef COPY_TIMESTAMP
+
 /**
  *  \retval r 1 if packet was accepted, 0 otherwise
  *  \note if packet was not accepted, it's still the responsibility

diff --git a/src/tm-threads.h b/src/tm-threads.h
index d92e1a946201dcb608c00b70c97427512ab6f550..1942ae1ce54a388fc3e19432557cdebe99f27865 100644 (file)
--- a/src/tm-threads.h
+++ b/src/tm-threads.h
@@ -222,4 +222,7 @@ int TmThreadsRegisterThread(ThreadVars *tv, const int type);
 void TmThreadsUnregisterThread(const int id);
 int TmThreadsInjectPacketsById(Packet **, int id);
 
+void TmThreadsSetThreadTimestamp(const int id, const struct timeval *ts);
+void TmreadsGetMinimalTimestamp(struct timeval *ts);
+
 #endif /* __TM_THREADS_H__ */

diff --git a/src/util-time.c b/src/util-time.c
index 7c7a362458bbc8214f83b440e11dd3b54171b296..f768ac733db0c12b3913c26b277d340e24930f77 100644 (file)
--- a/src/util-time.c
+++ b/src/util-time.c
@@ -1,4 +1,4 @@
-/* Copyright (C) 2007-2013 Open Information Security Foundation
+/* Copyright (C) 2007-2016 Open Information Security Foundation
  *
  * You can copy, redistribute or modify this Program under the terms of
  * the GNU General Public License version 2 as published by the Free
@@ -25,17 +25,44 @@
  * And time string generation for alerts.
  */
 
+/* Real time vs offline time
+ *
+ * When we run on live traffic, time handling is simple. Packets have a
+ * timestamp set by the capture method. Management threads can simply
+ * use 'gettimeofday' to know the current time. There should never be
+ * any serious gap between the two.
+ *
+ * In offline mode, things are dramatically different. Here we try to keep
+ * the time from the pcap, which means that if the packets are in 2011 the
+ * log output should also reflect this. Multiple issues:
+ * 1. merged pcaps might have huge time jumps or time going backward
+ * 2. slowly recorded pcaps may be processed much faster than their 'realtime'
+ * 3. management threads need a concept of what the 'current' time is for
+ *    enforcing timeouts
+ * 4. due to (1) individual threads may have very different views on what
+ *    the current time is. E.g. T1 processed packet 1 with TS X, while T2
+ *    at the very same time processes packet 2 with TS X+100000s.
+ *
+ * In offline mode we keep the timestamp per thread. If a management thread
+ * needs current time, it will get the minimum of the threads' values. This
+ * is to avoid the problem that T2s time value might already trigger a flow
+ * timeout as the flow lastts + 100000s is almost certainly meaning the flow
+ * would be considered timed out.
+ */
+
 #include "suricata-common.h"
 #include "detect.h"
 #include "threads.h"
+#include "tm-threads.h"
 #include "util-debug.h"
 
+#ifdef UNITTESTS
 static struct timeval current_time = { 0, 0 };
+#endif
 //static SCMutex current_time_mutex = SCMUTEX_INITIALIZER;
 static SCSpinlock current_time_spinlock;
 static char live = TRUE;
 
-
 struct tm *SCLocalTime(time_t timep, struct tm *result);
 
 void TimeInit(void)
@@ -63,6 +90,15 @@ void TimeModeSetOffline (void)
     SCLogDebug("offline time mode enabled");
 }
 
+void TimeSetByThread(const int thread_id, const struct timeval *tv)
+{
+    if (live == TRUE)
+        return;
+
+    TmThreadsSetThreadTimestamp(thread_id, tv);
+}
+
+#ifdef UNITTESTS
 void TimeSet(struct timeval *tv)
 {
     if (live == TRUE)
@@ -91,6 +127,7 @@ void TimeSetToCurrentTime(void)
 
     TimeSet(&tv);
 }
+#endif
 
 void TimeGet(struct timeval *tv)
 {
@@ -100,16 +137,25 @@ void TimeGet(struct timeval *tv)
     if (live == TRUE) {
         gettimeofday(tv, NULL);
     } else {
-        SCSpinLock(&current_time_spinlock);
-        tv->tv_sec = current_time.tv_sec;
-        tv->tv_usec = current_time.tv_usec;
-        SCSpinUnlock(&current_time_spinlock);
+#ifdef UNITTESTS
+        if (unlikely(RunmodeIsUnittests())) {
+            SCSpinLock(&current_time_spinlock);
+            tv->tv_sec = current_time.tv_sec;
+            tv->tv_usec = current_time.tv_usec;
+            SCSpinUnlock(&current_time_spinlock);
+        } else {
+#endif
+            TmreadsGetMinimalTimestamp(tv);
+#ifdef UNITTESTS
+        }
+#endif
     }
 
     SCLogDebug("time we got is %" PRIuMAX " sec, %" PRIuMAX " usec",
                (uintmax_t)tv->tv_sec, (uintmax_t)tv->tv_usec);
 }
 
+#ifdef UNITTESTS
 /** \brief increment the time in the engine
  *  \param tv_sec seconds to increment the time with */
 void TimeSetIncrementTime(uint32_t tv_sec)
@@ -122,6 +168,7 @@ void TimeSetIncrementTime(uint32_t tv_sec)
 
     TimeSet(&tv);
 }
+#endif
 
 void CreateIsoTimeString (const struct timeval *ts, char *str, size_t size)
 {

diff --git a/src/util-time.h b/src/util-time.h
index cdf1d5bf7afed78a47c0c4d88343dbc6bada1d28..350f8bf4407d41ab995ef5f141ee11b81d667e35 100644 (file)
--- a/src/util-time.h
+++ b/src/util-time.h
@@ -37,11 +37,14 @@ typedef struct SCTimeval32_ {
 void TimeInit(void);
 void TimeDeinit(void);
 
-void TimeSet(struct timeval *);
+void TimeSetByThread(const int thread_id, const struct timeval *tv);
 void TimeGet(struct timeval *);
 
+#ifdef UNITTESTS
+void TimeSet(struct timeval *);
 void TimeSetToCurrentTime(void);
 void TimeSetIncrementTime(uint32_t);
+#endif
 
 void TimeModeSetLive(void);
 void TimeModeSetOffline (void);

diff --git a/src/util-unittest-helper.c b/src/util-unittest-helper.c
index e58644a5308c56b46e3e32554cf4169eafc9e074..2eb2df207385073e82e963b5d57a70682a66cbfc 100644 (file)
--- a/src/util-unittest-helper.c
+++ b/src/util-unittest-helper.c
@@ -85,7 +85,7 @@ Packet *UTHBuildPacketIPV6Real(uint8_t *payload, uint16_t payload_len,
     if (unlikely(p == NULL))
         return NULL;
 
-    TimeSet(&p->ts);
+    TimeGet(&p->ts);
 
     p->src.family = AF_INET6;
     p->dst.family = AF_INET6;