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.

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);
 

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);

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

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__ */

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 {
+#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)
 {

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);

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;