From: Victor Julien Date: Mon, 18 Apr 2016 13:09:13 +0000 (+0200) Subject: time: improve offline time handling X-Git-Tag: suricata-3.1RC1~126 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=6f560144c1b97906ad41f621cadc08f4c99dff89;p=thirdparty%2Fsuricata.git 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 cff52542a1..92fb6f6fa2 100644 --- 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 eec197f9fd..941211dc4d 100644 --- 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 1d7b5fe149..89db9812b4 100644 --- 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 d92e1a9462..1942ae1ce5 100644 --- 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 7c7a362458..f768ac733d 100644 --- 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(¤t_time_spinlock); - tv->tv_sec = current_time.tv_sec; - tv->tv_usec = current_time.tv_usec; - SCSpinUnlock(¤t_time_spinlock); +#ifdef UNITTESTS + if (unlikely(RunmodeIsUnittests())) { + SCSpinLock(¤t_time_spinlock); + tv->tv_sec = current_time.tv_sec; + tv->tv_usec = current_time.tv_usec; + SCSpinUnlock(¤t_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 cdf1d5bf7a..350f8bf440 100644 --- 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 e58644a530..2eb2df2073 100644 --- 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;