logging: don't block on socket writes

Writing to a unix socket can cause Suricata to block in the
packet path. This could happen if the read-endpoint of the
unix socket stays connected, but stops reading, or simply
can't read fast enough as part of its event processing.

To choose packets over events, do non-blocking socket
writes and drop the event if the write would block and
update a dropped counter.

src/util-logopenfile.c

@@ -121,6 +121,57 @@ static int SCLogUnixSocketReconnect(LogFileCtx *log_ctx)
     return log_ctx->fp ? 1 : 0;
 }
 
+static int SCLogFileWriteSocket(const char *buffer, int buffer_len,
+        LogFileCtx *ctx)
+{
+    int tries = 0;
+    int ret = 0;
+    bool reopen = false;
+
+    if (ctx->fp == NULL && ctx->is_sock) {
+        SCLogUnixSocketReconnect(ctx);
+    }
+
+tryagain:
+    ret = -1;
+    reopen = 0;
+    errno = 0;
+    if (ctx->fp != NULL) {
+        int fd = fileno(ctx->fp);
+        ssize_t size = send(fd, buffer, buffer_len, MSG_DONTWAIT);
+        if (size > -1) {
+            ret = 0;
+        } else {
+            if (errno == EAGAIN || errno == EWOULDBLOCK) {
+                SCLogDebug("Socket would block, dropping event.");
+            } else if (errno == EINTR) {
+                if (tries++ == 0) {
+                    SCLogDebug("Interrupted system call, trying again.");
+                    goto tryagain;
+                }
+                SCLogDebug("Too many interrupted system calls, "
+                        "dropping event.");
+            } else {
+                /* Some other error. Assume badness and reopen. */
+                SCLogDebug("Send failed: %s", strerror(errno));
+                reopen = true;
+            }
+        }
+    }
+
+    if (reopen && tries++ == 0) {
+        if (SCLogUnixSocketReconnect(ctx)) {
+            goto tryagain;
+        }
+    }
+
+    if (ret == -1) {
+        ctx->dropped++;
+    }
+
+    return ret;
+}
+
 /**
  * \brief Write buffer to log file.
  * \retval 0 on failure; otherwise, the return value of fwrite (number of
@@ -129,38 +180,31 @@ static int SCLogUnixSocketReconnect(LogFileCtx *log_ctx)
 static int SCLogFileWrite(const char *buffer, int buffer_len, LogFileCtx *log_ctx)
 {
     SCMutexLock(&log_ctx->fp_mutex);
+    int ret = 0;
 
-    /* Check for rotation. */
-    if (log_ctx->rotation_flag) {
-        log_ctx->rotation_flag = 0;
-        SCConfLogReopen(log_ctx);
-    }
+    if (log_ctx->is_sock) {
+        ret = SCLogFileWriteSocket(buffer, buffer_len, log_ctx);
+    } else {
 
-    if (log_ctx->flags & LOGFILE_ROTATE_INTERVAL) {
-        time_t now = time(NULL);
-        if (now >= log_ctx->rotate_time) {
+        /* Check for rotation. */
+        if (log_ctx->rotation_flag) {
+            log_ctx->rotation_flag = 0;
             SCConfLogReopen(log_ctx);
-            log_ctx->rotate_time = now + log_ctx->rotate_interval;
         }
-    }
-
-    int ret = 0;
 
-    if (log_ctx->fp == NULL && log_ctx->is_sock)
-        SCLogUnixSocketReconnect(log_ctx);
-
-    if (log_ctx->fp) {
-        clearerr(log_ctx->fp);
-        ret = fwrite(buffer, buffer_len, 1, log_ctx->fp);
-        fflush(log_ctx->fp);
-
-        if (ferror(log_ctx->fp) && log_ctx->is_sock) {
-            /* Error on Unix socket, maybe needs reconnect */
-            if (SCLogUnixSocketReconnect(log_ctx)) {
-                ret = fwrite(buffer, buffer_len, 1, log_ctx->fp);
-                fflush(log_ctx->fp);
+        if (log_ctx->flags & LOGFILE_ROTATE_INTERVAL) {
+            time_t now = time(NULL);
+            if (now >= log_ctx->rotate_time) {
+                SCConfLogReopen(log_ctx);
+                log_ctx->rotate_time = now + log_ctx->rotate_interval;
             }
         }
+
+        if (log_ctx->fp) {
+            clearerr(log_ctx->fp);
+            ret = fwrite(buffer, buffer_len, 1, log_ctx->fp);
+            fflush(log_ctx->fp);
+        }
     }
 
     SCMutexUnlock(&log_ctx->fp_mutex);

src/util-logopenfile.h

@@ -134,6 +134,10 @@ typedef struct LogFileCtx_ {
 
     /* Set to true if the filename should not be timestamped. */
     bool nostamp;
+
+    /* Socket types may need to drop events to keep from blocking
+     * Suricata. */
+    uint64_t dropped;
 } LogFileCtx;
 
 /* Min time (msecs) before trying to reconnect a Unix domain socket */