commit 883bd84: [Feature] Improve logging locking logic (remove it actually)

[Vsevolod Stakhov]

Author: Vsevolod Stakhov
Date: 2019-10-07 16:30:55 +0100
URL: https://github.com/rspamd/rspamd/commit/883bd841dc50fc667c3fed745feef4f099566c2a

[Feature] Improve logging locking logic (remove it actually)

---
 src/libserver/worker_util.c |  2 ++
 src/libutil/logger.c        | 52 +++++++++++++++++++++++++--------------------
 src/libutil/logger.h        | 10 ---------
 src/rspamd.c                |  3 ---
 4 files changed, 31 insertions(+), 36 deletions(-)

diff --git a/src/libserver/worker_util.c b/src/libserver/worker_util.c
index cdae2cfd2..6c478db6f 100644
--- a/src/libserver/worker_util.c
+++ b/src/libserver/worker_util.c
@@ -867,6 +867,8 @@ rspamd_fork_worker (struct rspamd_main *rspamd_main,
 	case 0:
 		/* Update pid for logging */
 		rspamd_log_update_pid (cf->type, rspamd_main->logger);
+		/* To avoid atomic writes issue */
+		rspamd_log_reopen (rspamd_main->logger);
 		wrk->pid = getpid ();
 
 		/* Init PRNG after fork */
diff --git a/src/libutil/logger.c b/src/libutil/logger.c
index 08cc15294..cb57b6825 100644
--- a/src/libutil/logger.c
+++ b/src/libutil/logger.c
@@ -154,6 +154,9 @@ direct_write_log_line (rspamd_logger_t *rspamd_log,
 	const gchar *line;
 	glong r;
 	gint fd;
+	gboolean locked = FALSE;
+
+	iov = (struct iovec *) data;
 
 	if (rspamd_log->type == RSPAMD_LOG_CONSOLE) {
 
@@ -173,20 +176,36 @@ direct_write_log_line (rspamd_logger_t *rspamd_log,
 	}
 
 	if (!rspamd_log->no_lock) {
-#ifndef DISABLE_PTHREAD_MUTEX
-		if (rspamd_log->mtx) {
-			rspamd_mempool_lock_mutex (rspamd_log->mtx);
+		gsize tlen;
+
+		if (is_iov) {
+			tlen = 0;
+
+			for (guint i = 0; i < count; i ++) {
+				tlen += iov[i].iov_len;
+			}
 		}
 		else {
-			rspamd_file_lock (fd, FALSE);
+			tlen = count;
 		}
+
+		if (tlen > PIPE_BUF) {
+			locked = TRUE;
+
+#ifndef DISABLE_PTHREAD_MUTEX
+			if (rspamd_log->mtx) {
+				rspamd_mempool_lock_mutex (rspamd_log->mtx);
+			}
+			else {
+				rspamd_file_lock (fd, FALSE);
+			}
 #else
-		rspamd_file_lock (fd, FALSE);
+			rspamd_file_lock (fd, FALSE);
 #endif
+		}
 	}
 
 	if (is_iov) {
-		iov = (struct iovec *) data;
 		r = writev (fd, iov, count);
 	}
 	else {
@@ -194,7 +213,7 @@ direct_write_log_line (rspamd_logger_t *rspamd_log,
 		r = write (fd, line, count);
 	}
 
-	if (!rspamd_log->no_lock) {
+	if (locked) {
 #ifndef DISABLE_PTHREAD_MUTEX
 		if (rspamd_log->mtx) {
 			rspamd_mempool_unlock_mutex (rspamd_log->mtx);
@@ -294,6 +313,7 @@ rspamd_log_open_priv (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid)
 #ifdef HAVE_SYSLOG_H
 			openlog ("rspamd", LOG_NDELAY | LOG_PID,
 					rspamd_log->log_facility);
+			rspamd_log->no_lock = TRUE;
 #endif
 			break;
 		case RSPAMD_LOG_FILE:
@@ -302,6 +322,8 @@ rspamd_log_open_priv (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid)
 			if (rspamd_log->fd == -1) {
 				return -1;
 			}
+
+			rspamd_log->no_lock = TRUE;
 			break;
 		default:
 			return -1;
@@ -1397,22 +1419,6 @@ rspamd_log_counters (rspamd_logger_t *logger)
 	return NULL;
 }
 
-void
-rspamd_log_nolock (rspamd_logger_t *logger)
-{
-	if (logger) {
-		logger->no_lock = TRUE;
-	}
-}
-
-void
-rspamd_log_lock (rspamd_logger_t *logger)
-{
-	if (logger) {
-		logger->no_lock = FALSE;
-	}
-}
-
 static gint
 rspamd_log_errlog_cmp (const ucl_object_t **o1, const ucl_object_t **o2)
 {
diff --git a/src/libutil/logger.h b/src/libutil/logger.h
index e56c37aad..1dff75211 100644
--- a/src/libutil/logger.h
+++ b/src/libutil/logger.h
@@ -168,16 +168,6 @@ void rspamd_log_debug (rspamd_logger_t *logger);
  */
 void rspamd_log_nodebug (rspamd_logger_t *logger);
 
-/**
- * Turn off locking on logger (useful to avoid races)
- */
-void rspamd_log_nolock (rspamd_logger_t *logger);
-
-/**
- * Turn on locking to avoid log output mix
- */
-void rspamd_log_lock (rspamd_logger_t *logger);
-
 /**
  * Return array of counters (4 numbers):
  * 0 - errors
diff --git a/src/rspamd.c b/src/rspamd.c
index 5f0e89414..f726865e7 100644
--- a/src/rspamd.c
+++ b/src/rspamd.c
@@ -957,7 +957,6 @@ rspamd_term_handler (struct ev_loop *loop, ev_signal *w, int revents)
 	if (!rspamd_main->wanna_die) {
 		rspamd_main->wanna_die = TRUE;
 		msg_info_main ("catch termination signal, waiting for children");
-		rspamd_log_nolock (rspamd_main->logger);
 		/* Stop srv events to avoid false notifications */
 		g_hash_table_foreach (rspamd_main->workers, stop_srv_ev, rspamd_main);
 		rspamd_pass_signal (rspamd_main->workers, SIGTERM);
@@ -1075,7 +1074,6 @@ rspamd_cld_handler (EV_P_ ev_child *w, struct rspamd_main *rspamd_main,
 
 	/* Turn off locking for logger */
 	ev_child_stop (EV_A_ w);
-	rspamd_log_nolock (rspamd_main->logger);
 
 	/* Remove dead child form children list */
 	g_hash_table_remove (rspamd_main->workers, GSIZE_TO_POINTER (wrk->pid));
@@ -1113,7 +1111,6 @@ rspamd_cld_handler (EV_P_ ev_child *w, struct rspamd_main *rspamd_main,
 				wrk->pid);
 		rspamd_check_core_limits (rspamd_main);
 		rspamd_fork_delayed (wrk->cf, wrk->index, rspamd_main);
-		rspamd_log_lock (rspamd_main->logger);
 	}
 	else {
 		msg_info_main ("do not respawn process %s after found terminated process with pid %P",