logging: move lock into write function

All loggers were wrapping just the write in a lock with some updating a counter. This moves the lock into the write function. The log_ctx alerts counter was also removed as many modules have stopped using this and the alert count is available elsewhere. Should satisfy Coverity CID 1400798: CID 1400798 (#1 of 1): Data race condition (MISSING_LOCK) 2. missing_lock: Accessing log_ctx->rotation_flag without holding lock LogFileCtx_.fp_mutex. Elsewhere, "LogFileCtx_.rotation_flag" is accessed with LogFileCtx_.fp_mutex held 4 out of 5 times. Which appears to be a false positive as all calls to SCLogFileWrite were done under lock, but this will make it more explicit.
regit · Feb 21, 2017 · 0c3f1e2 · 0c3f1e2
1 parent ddf1bf6
commit 0c3f1e2
Show file tree

Hide file tree

Showing 11 changed files with 5 additions and 43 deletions.
diff --git a/src/alert-debuglog.c b/src/alert-debuglog.c
@@ -304,11 +304,8 @@ static TmEcode AlertDebugLogger(ThreadVars *tv, const Packet *p, void *thread_da
         }
     }
 
-    SCMutexLock(&aft->file_ctx->fp_mutex);
     aft->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
         MEMBUFFER_OFFSET(aft->buffer), aft->file_ctx);
-    aft->file_ctx->alerts += p->alerts.cnt;
-    SCMutexUnlock(&aft->file_ctx->fp_mutex);
 
     return TM_ECODE_OK;
 }
@@ -367,11 +364,8 @@ static TmEcode AlertDebugLogDecoderEvent(ThreadVars *tv, const Packet *p, void *
     PrintRawDataToBuffer(aft->buffer->buffer, &aft->buffer->offset, aft->buffer->size,
                          GET_PKT_DATA(p), GET_PKT_LEN(p));
 
-    SCMutexLock(&aft->file_ctx->fp_mutex);
     aft->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
         MEMBUFFER_OFFSET(aft->buffer), aft->file_ctx);
-    aft->file_ctx->alerts += p->alerts.cnt;
-    SCMutexUnlock(&aft->file_ctx->fp_mutex);
 
     return TM_ECODE_OK;
 }
@@ -424,8 +418,6 @@ static void AlertDebugLogExitPrintStats(ThreadVars *tv, void *data)
     if (aft == NULL) {
         return;
     }
-
-    SCLogInfo("(%s) Alerts %" PRIu64 "", tv->name, aft->file_ctx->alerts);
 }
 
 static void AlertDebugLogDeInitCtx(OutputCtx *output_ctx)

diff --git a/src/alert-fastlog.c b/src/alert-fastlog.c
@@ -98,12 +98,8 @@ int AlertFastLogCondition(ThreadVars *tv, const Packet *p)
 static inline void AlertFastLogOutputAlert(AlertFastLogThread *aft, char *buffer,
                                            int alert_size)
 {
-    SCMutex *file_lock = &aft->file_ctx->fp_mutex;
     /* Output the alert string and count alerts. Only need to lock here. */
-    SCMutexLock(file_lock);
-    aft->file_ctx->alerts++;
     aft->file_ctx->Write(buffer, alert_size, aft->file_ctx);
-    SCMutexUnlock(file_lock);
 }
 
 int AlertFastLogger(ThreadVars *tv, void *data, const Packet *p)

diff --git a/src/alert-syslog.c b/src/alert-syslog.c
@@ -205,10 +205,9 @@ static TmEcode AlertSyslogIPv4(ThreadVars *tv, const Packet *p, void *data)
     if (p->alerts.cnt == 0)
         return TM_ECODE_OK;
 
+    /* Not sure if this mutex is needed around calls to syslog. */
     SCMutexLock(&ast->file_ctx->fp_mutex);
 
-    ast->file_ctx->alerts += p->alerts.cnt;
-
     for (i = 0; i < p->alerts.cnt; i++) {
         const PacketAlert *pa = &p->alerts.alerts[i];
         if (unlikely(pa->s == NULL)) {
@@ -265,8 +264,6 @@ static TmEcode AlertSyslogIPv6(ThreadVars *tv, const Packet *p, void *data)
 
     SCMutexLock(&ast->file_ctx->fp_mutex);
 
-    ast->file_ctx->alerts += p->alerts.cnt;
-
     for (i = 0; i < p->alerts.cnt; i++) {
         const PacketAlert *pa = &p->alerts.alerts[i];
         if (unlikely(pa->s == NULL)) {
@@ -328,7 +325,6 @@ static TmEcode AlertSyslogDecoderEvent(ThreadVars *tv, const Packet *p, void *da
 
     SCMutexLock(&ast->file_ctx->fp_mutex);
 
-    ast->file_ctx->alerts += p->alerts.cnt;
     char temp_buf_hdr[512];
     char temp_buf_pkt[65] = "";
     char temp_buf_tail[32];
@@ -383,8 +379,6 @@ static void AlertSyslogExitPrintStats(ThreadVars *tv, void *data)
     if (ast == NULL) {
         return;
     }
-
-    SCLogInfo("(%s) Alerts %" PRIu64 "", tv->name, ast->file_ctx->alerts);
 }
 
 static int AlertSyslogCondition(ThreadVars *tv, const Packet *p)

diff --git a/src/alert-unified2-alert.c b/src/alert-unified2-alert.c
@@ -928,15 +928,13 @@ static int Unified2IPv6TypeAlert(ThreadVars *t, const Packet *p, void *data)
             ? true : false;
         if (truncate || file_ctx->rotation_flag) {
             if (Unified2AlertRotateFile(aun, truncate) < 0) {
-                aun->unified2alert_ctx->file_ctx->alerts += i;
                 SCMutexUnlock(&file_ctx->fp_mutex);
                 return -1;
             }
             file_ctx->rotation_flag = 0;
         }
 
         if (Unified2Write(aun) != 1) {
-            file_ctx->alerts += i;
             SCMutexUnlock(&file_ctx->fp_mutex);
             return -1;
         }
@@ -951,12 +949,10 @@ static int Unified2IPv6TypeAlert(ThreadVars *t, const Packet *p, void *data)
         ret = Unified2PacketTypeAlert(aun, p, phdr->event_id, stream);
         if (ret != 1) {
             SCLogError(SC_ERR_FWRITE, "Error: fwrite failed: %s", strerror(errno));
-            aun->unified2alert_ctx->file_ctx->alerts += i;
             SCMutexUnlock(&file_ctx->fp_mutex);
             return -1;
         }
         fflush(aun->unified2alert_ctx->file_ctx->fp);
-        aun->unified2alert_ctx->file_ctx->alerts++;
         SCMutexUnlock(&file_ctx->fp_mutex);
     }
 
@@ -1108,15 +1104,13 @@ static int Unified2IPv4TypeAlert (ThreadVars *tv, const Packet *p, void *data)
             ? true : false;
         if (truncate || file_ctx->rotation_flag) {
             if (Unified2AlertRotateFile(aun, truncate) < 0) {
-                file_ctx->alerts += i;
                 SCMutexUnlock(&file_ctx->fp_mutex);
                 return -1;
             }
             file_ctx->rotation_flag = 0;
         }
 
         if (Unified2Write(aun) != 1) {
-            file_ctx->alerts += i;
             SCMutexUnlock(&file_ctx->fp_mutex);
             return -1;
         }
@@ -1132,13 +1126,11 @@ static int Unified2IPv4TypeAlert (ThreadVars *tv, const Packet *p, void *data)
             (pa->flags & (PACKET_ALERT_FLAG_STATE_MATCH|PACKET_ALERT_FLAG_STREAM_MATCH) ? 1 : 0) : 0;
         ret = Unified2PacketTypeAlert(aun, p, event_id, stream);
         if (ret != 1) {
-            aun->unified2alert_ctx->file_ctx->alerts += i;
             SCMutexUnlock(&file_ctx->fp_mutex);
             return -1;
         }
 
         fflush(aun->unified2alert_ctx->file_ctx->fp);
-        aun->unified2alert_ctx->file_ctx->alerts++;
         SCMutexUnlock(&file_ctx->fp_mutex);
     }
 

diff --git a/src/log-dnslog.c b/src/log-dnslog.c
@@ -96,10 +96,8 @@ static void LogQuery(LogDnsLogThread *aft, char *timebuf, char *srcip, char *dst
             " [**] %s [**] %s:%" PRIu16 " -> %s:%" PRIu16 "\n",
             record, srcip, sp, dstip, dp);
 
-    SCMutexLock(&hlog->file_ctx->fp_mutex);
     hlog->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
         MEMBUFFER_OFFSET(aft->buffer), hlog->file_ctx);
-    SCMutexUnlock(&hlog->file_ctx->fp_mutex);
 }
 
 static void LogAnswer(LogDnsLogThread *aft, char *timebuf, char *srcip, char *dstip, Port sp, Port dp, DNSTransaction *tx, DNSAnswerEntry *entry)
@@ -159,10 +157,8 @@ static void LogAnswer(LogDnsLogThread *aft, char *timebuf, char *srcip, char *ds
             " [**] %s:%" PRIu16 " -> %s:%" PRIu16 "\n",
             srcip, sp, dstip, dp);
 
-    SCMutexLock(&hlog->file_ctx->fp_mutex);
     hlog->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
         MEMBUFFER_OFFSET(aft->buffer), hlog->file_ctx);
-    SCMutexUnlock(&hlog->file_ctx->fp_mutex);
 }
 
 static int LogDnsLogger(ThreadVars *tv, void *data, const Packet *p,

diff --git a/src/log-httplog.c b/src/log-httplog.c
@@ -498,10 +498,8 @@ static TmEcode LogHttpLogIPWrapper(ThreadVars *tv, void *data, const Packet *p,
 
     aft->uri_cnt ++;
 
-    SCMutexLock(&hlog->file_ctx->fp_mutex);
     hlog->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
         MEMBUFFER_OFFSET(aft->buffer), hlog->file_ctx);
-    SCMutexUnlock(&hlog->file_ctx->fp_mutex);
 
 end:
     SCReturnInt(0);

diff --git a/src/log-stats.c b/src/log-stats.c
@@ -156,10 +156,8 @@ int LogStatsLogger(ThreadVars *tv, void *thread_data, const StatsTable *st)
         }
     }
 
-    SCMutexLock(&aft->statslog_ctx->file_ctx->fp_mutex);
     aft->statslog_ctx->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
         MEMBUFFER_OFFSET(aft->buffer), aft->statslog_ctx->file_ctx);
-    SCMutexUnlock(&aft->statslog_ctx->file_ctx->fp_mutex);
 
     MemBufferReset(aft->buffer);
 

diff --git a/src/log-tcp-data.c b/src/log-tcp-data.c
@@ -161,10 +161,8 @@ static int LogTcpDataLoggerFile(ThreadVars *tv, void *thread_data, const Flow *f
         PrintRawDataToBuffer(aft->buffer->buffer, &aft->buffer->offset,
                 aft->buffer->size, (uint8_t *)data,data_len);
 
-        SCMutexLock(&td->file_ctx->fp_mutex);
         td->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
                 MEMBUFFER_OFFSET(aft->buffer), td->file_ctx);
-        SCMutexUnlock(&td->file_ctx->fp_mutex);
     }
     SCReturnInt(TM_ECODE_OK);
 }

diff --git a/src/log-tlslog.c b/src/log-tlslog.c
@@ -323,10 +323,8 @@ static int LogTlsLogger(ThreadVars *tv, void *thread_data, const Packet *p,
 
     aft->tls_cnt++;
 
-    SCMutexLock(&hlog->file_ctx->fp_mutex);
     hlog->file_ctx->Write((const char *)MEMBUFFER_BUFFER(aft->buffer),
         MEMBUFFER_OFFSET(aft->buffer), hlog->file_ctx);
-    SCMutexUnlock(&hlog->file_ctx->fp_mutex);
 
     return 0;
 }

diff --git a/src/util-logopenfile.c b/src/util-logopenfile.c
@@ -127,6 +127,8 @@ static int SCLogUnixSocketReconnect(LogFileCtx *log_ctx)
  */
 static int SCLogFileWrite(const char *buffer, int buffer_len, LogFileCtx *log_ctx)
 {
+    SCMutexLock(&log_ctx->fp_mutex);
+
     /* Check for rotation. */
     if (log_ctx->rotation_flag) {
         log_ctx->rotation_flag = 0;
@@ -152,6 +154,8 @@ static int SCLogFileWrite(const char *buffer, int buffer_len, LogFileCtx *log_ct
         }
     }
 
+    SCMutexUnlock(&log_ctx->fp_mutex);
+
     return ret;
 }
 
@@ -671,10 +675,8 @@ int LogFileWrite(LogFileCtx *file_ctx, MemBuffer *buffer)
     {
         /* append \n for files only */
         MemBufferWriteString(buffer, "\n");
-        SCMutexLock(&file_ctx->fp_mutex);
         file_ctx->Write((const char *)MEMBUFFER_BUFFER(buffer),
                         MEMBUFFER_OFFSET(buffer), file_ctx);
-        SCMutexUnlock(&file_ctx->fp_mutex);
     }
 #ifdef HAVE_LIBHIREDIS
     else if (file_ctx->type == LOGFILE_TYPE_REDIS) {

diff --git a/src/util-logopenfile.h b/src/util-logopenfile.h
@@ -109,8 +109,6 @@ typedef struct LogFileCtx_ {
     uint64_t size_limit;    /**< file size limit */
     uint64_t size_current;  /**< file current size */
 
-    /* Alerts on the module (not on the file) */
-    uint64_t alerts;
     /* flag to avoid multiple threads printing the same stats */
     uint8_t flags;