From: Eric Leblond <eric@regit.org>
Date: Wed, 31 May 2017 16:14:29 +0000 (+0200)
Subject: filestore: avoid open write close sequence
X-Git-Tag: suricata-4.0.0-beta1~14
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=775e67459cdcb8723feb2b58feeba7500f212c6b;p=thirdparty%2Fsuricata.git

filestore: avoid open write close sequence

Current file storing approach is using a open file, write data,
close file logic. If this technic is fixing the problem of getting
too much open files in Suricata it is not optimal.

Test on a loop shows that open, write, close on a single file is
two time slower than a single open, loop of write, close.

This patch updates the logic by storing the fd in the File structure.
This is done for a certain number of files. If this amount is exceeded
then the previous logic is used.

This patch also adds two counters. First is the number of
currently open files. The second one is the number of time
the open, write, close sequence has been used due to too much
open files.

In EVE, the entries are:
 stats {file_store: {"open_files_max_hit":0,"open_files":5}}
---

diff --git a/src/log-filestore.c b/src/log-filestore.c
index 90e6cd7f46..8777b4a60f 100644
--- a/src/log-filestore.c
+++ b/src/log-filestore.c
@@ -64,12 +64,21 @@
 
 static char g_logfile_base_dir[PATH_MAX] = "/tmp";
 
+SC_ATOMIC_DECLARE(uint32_t, filestore_open_file_cnt);  /**< Atomic counter of simultaneously open files */
+
 typedef struct LogFilestoreLogThread_ {
     LogFileCtx *file_ctx;
     /** LogFilestoreCtx has the pointer to the file and a mutex to allow multithreading */
     uint32_t file_cnt;
+    uint16_t counter_max_hits;
 } LogFilestoreLogThread;
 
+static uint64_t LogFilestoreOpenFilesCounter(void)
+{
+    uint64_t fcopy = SC_ATOMIC_GET(filestore_open_file_cnt);
+    return fcopy;
+}
+
 static void LogFilestoreMetaGetUri(FILE *fp, const Packet *p, const File *ff)
 {
     HtpState *htp_state = (HtpState *)p->flow->alstate;
@@ -182,6 +191,18 @@ static int FileWriteMeta(void)
     return g_file_write_meta;
 }
 
+static uint32_t g_file_store_max_open_files = 0;
+
+static void FileSetMaxOpenFiles(uint32_t count)
+{
+    g_file_store_max_open_files = count;
+}
+
+static uint32_t FileGetMaxOpenFiles(void)
+{
+    return g_file_store_max_open_files;
+}
+
 static void LogFilestoreLogCreateMetaFile(const Packet *p, const File *ff, char *filename, int ipver) {
     if (!FileWriteMeta())
         return;
@@ -321,7 +342,7 @@ static void LogFilestoreLogCloseMetaFile(const File *ff)
 }
 
 static int LogFilestoreLogger(ThreadVars *tv, void *thread_data, const Packet *p,
-        const File *ff, const uint8_t *data, uint32_t data_len, uint8_t flags)
+        File *ff, const uint8_t *data, uint32_t data_len, uint8_t flags)
 {
     SCEnter();
     LogFilestoreLogThread *aft = (LogFilestoreLogThread *)thread_data;
@@ -353,17 +374,34 @@ static int LogFilestoreLogger(ThreadVars *tv, void *thread_data, const Packet *p
         /* create a .meta file that contains time, src/dst/sp/dp/proto */
         LogFilestoreLogCreateMetaFile(p, ff, filename, ipver);
 
-        file_fd = open(filename, O_CREAT | O_TRUNC | O_NOFOLLOW | O_WRONLY, 0644);
-        if (file_fd == -1) {
-            SCLogDebug("failed to create file");
-            return -1;
+        if (SC_ATOMIC_GET(filestore_open_file_cnt) < FileGetMaxOpenFiles()) {
+            SC_ATOMIC_ADD(filestore_open_file_cnt, 1);
+            ff->fd = open(filename, O_CREAT | O_TRUNC | O_NOFOLLOW | O_WRONLY, 0644);
+            if (ff->fd == -1) {
+                SCLogDebug("failed to create file");
+                return -1;
+            }
+            file_fd = ff->fd;
+        } else {
+            file_fd = open(filename, O_CREAT | O_TRUNC | O_NOFOLLOW | O_WRONLY, 0644);
+            if (file_fd == -1) {
+                SCLogDebug("failed to create file");
+                return -1;
+            }
+            if (FileGetMaxOpenFiles() > 0) {
+                StatsIncr(tv, aft->counter_max_hits);
+            }
         }
     /* we can get called with a NULL ffd when we need to close */
     } else if (data != NULL) {
-        file_fd = open(filename, O_APPEND | O_NOFOLLOW | O_WRONLY);
-        if (file_fd == -1) {
-            SCLogDebug("failed to open file %s: %s", filename, strerror(errno));
-            return -1;
+        if (ff->fd == -1) {
+            file_fd = open(filename, O_APPEND | O_NOFOLLOW | O_WRONLY);
+            if (file_fd == -1) {
+                SCLogDebug("failed to open file %s: %s", filename, strerror(errno));
+                return -1;
+            }
+        } else {
+            file_fd = ff->fd;
         }
     }
 
@@ -371,11 +409,22 @@ static int LogFilestoreLogger(ThreadVars *tv, void *thread_data, const Packet *p
         ssize_t r = write(file_fd, (const void *)data, (size_t)data_len);
         if (r == -1) {
             SCLogDebug("write failed: %s", strerror(errno));
+            if (ff->fd != -1) {
+                SC_ATOMIC_SUB(filestore_open_file_cnt, 1);
+            }
+            ff->fd = -1;
+        }
+        if (ff->fd == -1) {
+            close(file_fd);
         }
-        close(file_fd);
     }
 
     if (flags & OUTPUT_FILEDATA_FLAG_CLOSE) {
+        if (ff->fd != -1) {
+            close(ff->fd);
+            ff->fd = -1;
+            SC_ATOMIC_SUB(filestore_open_file_cnt, 1);
+        }
         LogFilestoreLogCloseMetaFile(ff);
     }
 
@@ -418,6 +467,8 @@ static TmEcode LogFilestoreLogThreadInit(ThreadVars *t, const void *initdata, vo
 
     }
 
+    aft->counter_max_hits = StatsRegisterCounter("file_store.open_files_max_hit", t);
+
     *data = (void *)aft;
     return TM_ECODE_OK;
 }
@@ -528,9 +579,35 @@ static OutputCtx *LogFilestoreLogInitCtx(ConfNode *conf)
         }
     }
 
+    const char *file_count_str = ConfNodeLookupChildValue(conf, "max-open-files");
+    if (file_count_str != NULL) {
+        uint32_t file_count = 0;
+        if (ParseSizeStringU32(file_count_str,
+                               &file_count) < 0) {
+            SCLogError(SC_ERR_SIZE_PARSE, "Error parsing "
+                       "file-store.max-open-files "
+                       "from conf file - %s.  Killing engine",
+                       stream_depth_str);
+            exit(EXIT_FAILURE);
+        } else {
+            if (file_count != 0) {
+                FileSetMaxOpenFiles(file_count);
+                SCLogInfo("file-store will keep a max of %d simultaneously"
+                          " open files", file_count);
+            }
+        }
+    }
+
     SCReturnPtr(output_ctx, "OutputCtx");
 }
 
+
+void LogFilestoreInitConfig(void)
+{
+    StatsRegisterGlobalCounter("file_store.open_files", LogFilestoreOpenFilesCounter);
+}
+
+
 void LogFilestoreRegister (void)
 {
     OutputRegisterFiledataModule(LOGGER_FILE_STORE, MODULE_NAME, "file",
@@ -540,5 +617,7 @@ void LogFilestoreRegister (void)
         LogFilestoreLogInitCtx, LogFilestoreLogger, LogFilestoreLogThreadInit,
         LogFilestoreLogThreadDeinit, LogFilestoreLogExitPrintStats);
 
+    SC_ATOMIC_INIT(filestore_open_file_cnt);
+    SC_ATOMIC_SET(filestore_open_file_cnt, 0);
     SCLogDebug("registered");
 }
diff --git a/src/log-filestore.h b/src/log-filestore.h
index d477506fc5..07b8da96b2 100644
--- a/src/log-filestore.h
+++ b/src/log-filestore.h
@@ -25,5 +25,6 @@
 #define __LOG_FILESTORE_H__
 
 void LogFilestoreRegister(void);
+void LogFilestoreInitConfig(void);
 
 #endif /* __LOG_FILELOG_H__ */
diff --git a/src/output-filedata.c b/src/output-filedata.c
index 3964de86c2..224ab7adc0 100644
--- a/src/output-filedata.c
+++ b/src/output-filedata.c
@@ -98,7 +98,7 @@ int OutputRegisterFiledataLogger(LoggerId id, const char *name,
 SC_ATOMIC_DECLARE(unsigned int, g_file_store_id);
 
 static int CallLoggers(ThreadVars *tv, OutputLoggerThreadStore *store_list,
-        Packet *p, const File *ff,
+        Packet *p, File *ff,
         const uint8_t *data, uint32_t data_len, uint8_t flags)
 {
     OutputFiledataLogger *logger = list;
diff --git a/src/output-filedata.h b/src/output-filedata.h
index 4c661b2de1..8a280b6752 100644
--- a/src/output-filedata.h
+++ b/src/output-filedata.h
@@ -34,7 +34,7 @@
 
 /** filedata logger function pointer type */
 typedef int (*FiledataLogger)(ThreadVars *, void *thread_data, const Packet *,
-        const File *, const uint8_t *, uint32_t, uint8_t);
+        File *, const uint8_t *, uint32_t, uint8_t);
 
 /** packet logger condition function pointer type,
  *  must return true for packets that should be logged
diff --git a/src/suricata.c b/src/suricata.c
index ee5499faa0..1ec7f1c6b4 100644
--- a/src/suricata.c
+++ b/src/suricata.c
@@ -172,6 +172,7 @@
 #include "host-storage.h"
 
 #include "util-lua.h"
+#include "log-filestore.h"
 
 #ifdef HAVE_RUST
 #include "rust.h"
@@ -2218,6 +2219,7 @@ void PreRunInit(const int runmode)
     DefragInit();
     FlowInitConfig(FLOW_QUIET);
     IPPairInitConfig(FLOW_QUIET);
+    LogFilestoreInitConfig();
     StreamTcpInitConfig(STREAM_VERBOSE);
     AppLayerParserPostStreamSetup();
     AppLayerRegisterGlobalCounters();
diff --git a/src/util-file.c b/src/util-file.c
index 86dd8df267..c7ee27e45a 100644
--- a/src/util-file.c
+++ b/src/util-file.c
@@ -776,6 +776,8 @@ File *FileOpenFile(FileContainer *ffc, const StreamingBufferConfig *sbcfg,
     ff->state = FILE_STATE_OPENED;
     SCLogDebug("flowfile state transitioned to FILE_STATE_OPENED");
 
+    ff->fd = -1;
+
     FileContainerAdd(ffc, ff);
 
     if (data != NULL) {
diff --git a/src/util-file.h b/src/util-file.h
index 4c52adae1d..6d6ae9e75d 100644
--- a/src/util-file.h
+++ b/src/util-file.h
@@ -69,6 +69,8 @@ typedef struct File_ {
     uint32_t file_track_id;         /**< id used by protocol parser. Optional
                                      *   only used if FILE_USE_TRACKID flag set */
     uint32_t file_store_id;         /**< id used in store file name file.<id> */
+    int fd;                         /**< file descriptor for filestore, not
+                                        open if equal to -1 */
     uint8_t *name;
 #ifdef HAVE_MAGIC
     char *magic;
diff --git a/suricata.yaml.in b/suricata.yaml.in
index d0462f7079..c7a4ea8be3 100644
--- a/suricata.yaml.in
+++ b/suricata.yaml.in
@@ -442,6 +442,10 @@ outputs:
       #waldo: file.waldo # waldo file to store the file_id across runs
       # uncomment to disable meta file writing
       #write-meta: no
+      # uncomment the following variable to define how many files can
+      # remain open for filestore by Suricata. Default value is 0 which
+      # means files get closed after each write
+      #max-open-files: 1000
 
   # output module to log files tracked in a easily parsable json format
   - file-log: