Reduce time the file lock is held to write an alert to Fast.log

Generate the alert string into a temporary buffer before aquiring the
file lock. Only hold the file lock while writing the alert string to the
file.

In the case of multiple alerts, it would be better to generate all the
alerts, then aquire the lock once and write them all and then flush.

Changed PrintRawLineHexFp, which printed to a file, to PrintBufferRawLineHex,
that puts the same output into a string buffer. It was only used by fast.log.

diff --git a/src/alert-fastlog.c b/src/alert-fastlog.c
index 550c023946274b347b782ccfff94a2caf0f71262..6657aed49599e62ec1cdea3ecfca36600147937a 100644 (file)
--- a/src/alert-fastlog.c
+++ b/src/alert-fastlog.c
@@ -62,6 +62,8 @@
 
 #define MODULE_NAME "AlertFastLog"
 
+#define MAX_FASTLOG_ALERT_SIZE 2048
+
 TmEcode AlertFastLogThreadInit(ThreadVars *, void *, void **);
 TmEcode AlertFastLogThreadDeinit(ThreadVars *, void *);
 void AlertFastLogExitPrintStats(ThreadVars *, void *);
@@ -93,6 +95,26 @@ int AlertFastLogCondition(ThreadVars *tv, const Packet *p) {
     return (p->alerts.cnt ? TRUE : FALSE);
 }
 
+static inline void AlertFastLogOutputAlert(AlertFastLogThread *aft, char *buffer,
+                                           int alert_size)
+{
+    FILE *fp = aft->file_ctx->fp;
+    /* fp should never be NULL, but checking here makes sure the value
+     * is available before the lock is aquired, rather than possibly
+     * stalling while holding the lock.
+     */
+    if (unlikely(fp == NULL))
+        return;
+
+    /* Output the alert string. Only need to lock here. */
+    SCMutex *file_lock = &aft->file_ctx->fp_mutex;
+    SCMutexLock(file_lock);
+    aft->file_ctx->alerts++;
+    fwrite(buffer, alert_size, 1, fp);
+    fflush(fp);
+    SCMutexUnlock(file_lock);
+}
+
 int AlertFastLogger(ThreadVars *tv, void *data, const Packet *p)
 {
     AlertFastLogThread *aft = (AlertFastLogThread *)data;
@@ -115,6 +137,11 @@ int AlertFastLogger(ThreadVars *tv, void *data, const Packet *p)
         decoder_event = 1;
     }
 
+    /* Buffer to store the generated alert string. The buffer is
+     * reused for each alert.
+     */
+    char alert_buffer[MAX_FASTLOG_ALERT_SIZE];
+
     for (i = 0; i < p->alerts.cnt; i++) {
         const PacketAlert *pa = &p->alerts.alerts[i];
         if (unlikely(pa->s == NULL)) {
@@ -136,34 +163,37 @@ int AlertFastLogger(ThreadVars *tv, void *data, const Packet *p)
             }
         }
 
-        SCMutexLock(&aft->file_ctx->fp_mutex);
+        /* Create the alert string without locking. */
+        int size = 0;
         if (likely(decoder_event == 0)) {
-            fprintf(aft->file_ctx->fp, "%s  %s[**] [%" PRIu32 ":%" PRIu32 ":%"
-                    PRIu32 "] %s [**] [Classification: %s] [Priority: %"PRIu32"]"
-                    " {%s} %s:%" PRIu32 " -> %s:%" PRIu32 "\n", timebuf, action,
-                    pa->s->gid, pa->s->id, pa->s->rev, pa->s->msg, pa->s->class_msg, pa->s->prio,
-                    proto, srcip, p->sp, dstip, p->dp);
+            PrintBufferData(alert_buffer, &size, MAX_FASTLOG_ALERT_SIZE, 
+                            "%s  %s[**] [%" PRIu32 ":%" PRIu32 ":%"
+                            PRIu32 "] %s [**] [Classification: %s] [Priority: %"PRIu32"]"
+                            " {%s} %s:%" PRIu32 " -> %s:%" PRIu32 "\n", timebuf, action,
+                            pa->s->gid, pa->s->id, pa->s->rev, pa->s->msg, pa->s->class_msg, pa->s->prio,
+                            proto, srcip, p->sp, dstip, p->dp);
         } else {
-            fprintf(aft->file_ctx->fp, "%s  %s[**] [%" PRIu32 ":%" PRIu32
-                    ":%" PRIu32 "] %s [**] [Classification: %s] [Priority: "
-                    "%" PRIu32 "] [**] [Raw pkt: ", timebuf, action, pa->s->gid,
-                    pa->s->id, pa->s->rev, pa->s->msg, pa->s->class_msg, pa->s->prio);
-            PrintRawLineHexFp(aft->file_ctx->fp, GET_PKT_DATA(p), GET_PKT_LEN(p) < 32 ? GET_PKT_LEN(p) : 32);
+            PrintBufferData(alert_buffer, &size, MAX_FASTLOG_ALERT_SIZE, 
+                            "%s  %s[**] [%" PRIu32 ":%" PRIu32
+                            ":%" PRIu32 "] %s [**] [Classification: %s] [Priority: "
+                            "%" PRIu32 "] [**] [Raw pkt: ", timebuf, action, pa->s->gid,
+                            pa->s->id, pa->s->rev, pa->s->msg, pa->s->class_msg, pa->s->prio);
+            PrintBufferRawLineHex(alert_buffer, &size, GET_PKT_DATA(p), GET_PKT_LEN(p) < 32 ? GET_PKT_LEN(p) : 32);
             if (p->pcap_cnt != 0) {
-                fprintf(aft->file_ctx->fp, "] [pcap file packet: %"PRIu64"]\n", p->pcap_cnt);
+                PrintBufferData(alert_buffer, &size, MAX_FASTLOG_ALERT_SIZE, 
+                                "] [pcap file packet: %"PRIu64"]\n", p->pcap_cnt);
             } else {
-                fprintf(aft->file_ctx->fp, "]\n");
+                PrintBufferData(alert_buffer, &size, MAX_FASTLOG_ALERT_SIZE, "]\n");
             }
         }
-        fflush(aft->file_ctx->fp);
-        aft->file_ctx->alerts++;
-        SCMutexUnlock(&aft->file_ctx->fp_mutex);
+
+        /* Write the alert to output file */
+        AlertFastLogOutputAlert(aft, alert_buffer, size);
     }
 
     return TM_ECODE_OK;
 }
 
-
 TmEcode AlertFastLogThreadInit(ThreadVars *t, void *initdata, void **data)
 {
     AlertFastLogThread *aft = SCMalloc(sizeof(AlertFastLogThread));

diff --git a/src/util-print.c b/src/util-print.c
index 71163852b8bf7c0a38d67d32ae53e2672b2e1ee3..b02c5f009c13f2699de46443274e413e350f83a8 100644 (file)
--- a/src/util-print.c
+++ b/src/util-print.c
@@ -33,21 +33,19 @@
  *
  *  Prints in the format "00 AA BB"
  *
- *  \param fp FILE pointer to print to
+ *  \param nbuf buffer into which the output is written
+ *  \param offset of where to start writting into the buffer
+ *  \param max_size the size of the output buffer
  *  \param buf buffer to print from
  *  \param buflen length of the input buffer
  */
-void PrintRawLineHexFp(FILE *fp, uint8_t *buf, uint32_t buflen)
+void PrintBufferRawLineHex(char *nbuf, int *offset, int max_size, uint8_t *buf, uint32_t buflen)
 {
-#define BUFFER_LENGTH 2048
-    char nbuf[BUFFER_LENGTH] = "";
-    uint32_t offset = 0;
     uint32_t u = 0;
 
     for (u = 0; u < buflen; u++) {
-        PrintBufferData(nbuf, &offset, BUFFER_LENGTH, "%02X ", buf[u]);
+        PrintBufferData(nbuf, offset, max_size, "%02X ", buf[u]);
     }
-    fprintf(fp, "%s", nbuf);
 }
 
 /**

diff --git a/src/util-print.h b/src/util-print.h
index 111cfdac0ff17f450e6a6eeb2f7f40847ffb9e99..64a275215b37f33ab03051b2eec8df91f7a07988 100644 (file)
--- a/src/util-print.h
+++ b/src/util-print.h
@@ -41,7 +41,7 @@
         }                                                               \
     } while (0)
 
-void PrintRawLineHexFp(FILE *, uint8_t *, uint32_t);
+void PrintBufferRawLineHex(char *, int *,int, uint8_t *, uint32_t);
 void PrintRawUriFp(FILE *, uint8_t *, uint32_t);
 void PrintRawUriBuf(char *, uint32_t *, uint32_t,
                     uint8_t *, uint32_t);