[Feature] Add lockless logging

Sometimes, it is needed to turn off logging mutex to avoid recursive
mutex obtaining. It is especially useful to do it within children wait
code in the main processes dispatcher.

diff --git a/src/libutil/logger.c b/src/libutil/logger.c
index 56f7822a5e7b31f113b5d9efdfadd72ad2e05cb0..e6c18811337298506593754f329085f1c0cfe66c 100644 (file)
--- a/src/libutil/logger.c
+++ b/src/libutil/logger.c
@@ -48,6 +48,7 @@ struct rspamd_logger_s {
        gboolean enabled;
        gboolean is_debug;
        gboolean throttling;
+       gboolean no_lock;
        time_t throttling_time;
        sig_atomic_t do_reopen_log;
        enum rspamd_log_type type;
@@ -69,6 +70,18 @@ static const gchar lf_chr = '\n';
 
 static rspamd_logger_t *default_logger = NULL;
 
+#define RSPAMD_LOGGER_LOCK(l) do {                             \
+       if ((l) != NULL && !(l)->no_lock) {                     \
+               rspamd_mempool_lock_mutex ((l)->mtx);   \
+       }                                                                                       \
+} while (0)
+
+#define RSPAMD_LOGGER_UNLOCK(l) do {                   \
+       if ((l) != NULL && !(l)->no_lock) {                     \
+               rspamd_mempool_unlock_mutex ((l)->mtx); \
+       }                                                                                       \
+} while (0)
+
 
 static void
                syslog_log_function (const gchar *log_domain, const gchar *module,
@@ -456,14 +469,14 @@ rspamd_common_logv (rspamd_logger_t *rspamd_log, GLogLevelFlags log_level,
        else {
                if (rspamd_logger_need_log (rspamd_log, log_level, module)) {
                        rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, args);
-                       rspamd_mempool_lock_mutex (rspamd_log->mtx);
+                       RSPAMD_LOGGER_LOCK (rspamd_log);
                        rspamd_log->log_func (NULL, module, id,
                                        function,
                                        log_level,
                                        logbuf,
                                        FALSE,
                                        rspamd_log);
-                       rspamd_mempool_unlock_mutex (rspamd_log->mtx);
+                       RSPAMD_LOGGER_UNLOCK (rspamd_log);
                }
 
                switch (log_level) {
@@ -918,7 +931,8 @@ rspamd_conditional_debug (rspamd_logger_t *rspamd_log,
                                return;
                        }
                }
-               rspamd_mempool_lock_mutex (rspamd_log->mtx);
+
+               RSPAMD_LOGGER_LOCK (rspamd_log);
                va_start (vp, fmt);
                end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp);
                *end = '\0';
@@ -929,7 +943,7 @@ rspamd_conditional_debug (rspamd_logger_t *rspamd_log,
                                logbuf,
                                TRUE,
                                rspamd_log);
-               rspamd_mempool_unlock_mutex (rspamd_log->mtx);
+               RSPAMD_LOGGER_UNLOCK (rspamd_log);
        }
 }
 
@@ -946,14 +960,14 @@ rspamd_glib_log_function (const gchar *log_domain,
 
        if (rspamd_log->enabled &&
                        rspamd_logger_need_log (rspamd_log, log_level, NULL)) {
-               rspamd_mempool_lock_mutex (rspamd_log->mtx);
+               RSPAMD_LOGGER_LOCK (rspamd_log);
                rspamd_log->log_func (log_domain, "glib", NULL,
                                NULL,
                                log_level,
                                message,
                                FALSE,
                                rspamd_log);
-               rspamd_mempool_unlock_mutex (rspamd_log->mtx);
+               RSPAMD_LOGGER_UNLOCK (rspamd_log);
        }
 }
 
@@ -992,3 +1006,19 @@ 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;
+       }
+}

diff --git a/src/libutil/logger.h b/src/libutil/logger.h
index 7bf8307c834b0372ed8d4a4492963854804f657a..2523efad3234a967645541b76948c4fb1146b155 100644 (file)
--- a/src/libutil/logger.h
+++ b/src/libutil/logger.h
@@ -123,6 +123,16 @@ 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 8ff95cd7aa50f0d19b435db4e7e03db6cc3eb91a..cada080b902383631554c1ae774257fc892dd66e 100644 (file)
--- a/src/rspamd.c
+++ b/src/rspamd.c
@@ -821,6 +821,9 @@ rspamd_cld_handler (gint signo, short what, gpointer arg)
        struct rspamd_worker *cur;
        pid_t wrk;
 
+       /* Turn off locking for logger */
+       rspamd_log_nolock (rspamd_main->logger);
+
        msg_debug_main ("catch SIGCHLD signal, finding terminated worker");
        /* Remove dead child form children list */
        wrk = waitpid (0, &res, 0);
@@ -891,6 +894,8 @@ rspamd_cld_handler (gint signo, short what, gpointer arg)
                        }
                }
        }
+
+       rspamd_log_lock (rspamd_main->logger);
 }
 
 static void