1 files changed, 588 insertions, 0 deletions

diff --git a/src/libutil/logger_file.c b/src/libutil/logger_file.c
new file mode 100644
index 000000000..b2e01cf81
--- /dev/null
+++ b/src/libutil/logger_file.c
@@ -0,0 +1,588 @@
+/*-
+ * Copyright 2020 Vsevolod Stakhov
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "config.h"
+#include "logger.h"
+#include "libserver/cfg_file.h"
+#include "libcryptobox/cryptobox.h"
+#include "unix-std.h"
+
+#include "logger_private.h"
+
+#define FILE_LOG_QUARK g_quark_from_static_string ("file_logger")
+
+static const gchar lf_chr = '\n';
+
+struct rspamd_file_logger_priv {
+	gint fd;
+	struct {
+		guint32 size;
+		guint32 used;
+		u_char *buf;
+	} io_buf;
+	gboolean throttling;
+	gchar *log_file;
+	gboolean is_buffered;
+	time_t throttling_time;
+	guint32 repeats;
+	guint64 last_line_cksum;
+	gchar *saved_message;
+	gsize saved_mlen;
+	gchar *saved_function;
+	gchar *saved_module;
+	gchar *saved_id;
+	guint saved_loglevel;
+	guint64 log_cnt[4];
+};
+
+/**
+ * Calculate checksum for log line (used for repeating logic)
+ */
+static inline guint64
+rspamd_log_calculate_cksum (const gchar *message, size_t mlen)
+{
+	return rspamd_cryptobox_fast_hash (message, mlen, rspamd_hash_seed ());
+}
+
+static inline void
+log_time (gdouble now, rspamd_logger_t *rspamd_log, gchar *timebuf,
+		  size_t len)
+{
+	time_t sec = (time_t)now;
+	gsize r;
+	struct tm tms;
+
+	rspamd_localtime (sec, &tms);
+	r = strftime (timebuf, len, "%F %H:%M:%S", &tms);
+
+	if (rspamd_log->flags & RSPAMD_LOG_FLAG_USEC) {
+		gchar usec_buf[16];
+
+		rspamd_snprintf (usec_buf, sizeof (usec_buf), "%.5f",
+				now - (gdouble)sec);
+		rspamd_snprintf (timebuf + r, len - r,
+				"%s", usec_buf + 1);
+	}
+}
+
+
+/*
+ * Write a line to log file (unbuffered)
+ */
+static void
+direct_write_log_line (rspamd_logger_t *rspamd_log,
+					   struct rspamd_file_logger_priv *priv,
+					   void *data,
+					   gsize count,
+					   gboolean is_iov,
+					   gint level_flags)
+{
+	gchar errmsg[128];
+	struct iovec *iov;
+	const gchar *line;
+	glong r;
+	gint fd;
+	gboolean locked = FALSE;
+
+	iov = (struct iovec *) data;
+	fd = priv->fd;
+
+	if (!rspamd_log->no_lock) {
+		gsize tlen;
+
+		if (is_iov) {
+			tlen = 0;
+
+			for (guint i = 0; i < count; i ++) {
+				tlen += iov[i].iov_len;
+			}
+		}
+		else {
+			tlen = count;
+		}
+
+		if (tlen > PIPE_BUF || rspamd_log->flags & RSPAMD_LOG_FLAG_TTY) {
+			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);
+#endif
+		}
+	}
+
+	if (is_iov) {
+		r = writev (fd, iov, count);
+	}
+	else {
+		line = (const gchar *) data;
+		r = write (fd, line, count);
+	}
+
+	if (locked) {
+#ifndef DISABLE_PTHREAD_MUTEX
+		if (rspamd_log->mtx) {
+			rspamd_mempool_unlock_mutex (rspamd_log->mtx);
+		}
+		else {
+			rspamd_file_unlock (fd, FALSE);
+		}
+#else
+		rspamd_file_unlock (fd, FALSE);
+#endif
+	}
+
+	if (r == -1) {
+		/* We cannot write message to file, so we need to detect error and make decision */
+		if (errno == EINTR) {
+			/* Try again */
+			direct_write_log_line (rspamd_log, priv, data, count, is_iov, level_flags);
+			return;
+		}
+
+		r = rspamd_snprintf (errmsg,
+				sizeof (errmsg),
+				"direct_write_log_line: cannot write log line: %s",
+				strerror (errno));
+		if (errno == EFAULT || errno == EINVAL || errno == EFBIG ||
+			errno == ENOSPC) {
+			/* Rare case */
+			priv->throttling = TRUE;
+			priv->throttling_time = time (NULL);
+		}
+		else if (errno == EPIPE || errno == EBADF) {
+			/* We write to some pipe and it disappears, disable logging or we has opened bad file descriptor */
+			rspamd_log->enabled = FALSE;
+		}
+	}
+	else if (priv->throttling) {
+		priv->throttling = FALSE;
+	}
+}
+
+/**
+ * Fill buffer with message (limits must be checked BEFORE this call)
+ */
+static void
+fill_buffer (rspamd_logger_t *rspamd_log,
+			 struct rspamd_file_logger_priv *priv,
+			 const struct iovec *iov, gint iovcnt)
+{
+	gint i;
+
+	for (i = 0; i < iovcnt; i++) {
+		memcpy (priv->io_buf.buf + priv->io_buf.used,
+				iov[i].iov_base,
+				iov[i].iov_len);
+		priv->io_buf.used += iov[i].iov_len;
+	}
+
+}
+
+/*
+ * Write message to buffer or to file (using direct_write_log_line function)
+ */
+static void
+file_log_helper (rspamd_logger_t *rspamd_log,
+				 struct rspamd_file_logger_priv *priv,
+				 const struct iovec *iov,
+				 guint iovcnt,
+				 gint level_flags)
+{
+	size_t len = 0;
+	guint i;
+
+	if (!priv->is_buffered) {
+		/* Write string directly */
+		direct_write_log_line (rspamd_log, priv, (void *) iov, iovcnt,
+				TRUE, level_flags);
+	}
+	else {
+		/* Calculate total length */
+		for (i = 0; i < iovcnt; i++) {
+			len += iov[i].iov_len;
+		}
+		/* Fill buffer */
+		if (priv->io_buf.size < len) {
+			/* Buffer is too small to hold this string, so write it directly */
+			rspamd_log_flush (rspamd_log);
+			direct_write_log_line (rspamd_log, priv, (void *) iov, iovcnt,
+					TRUE, level_flags);
+		}
+		else if (priv->io_buf.used + len >= priv->io_buf.size) {
+			/* Buffer is full, try to write it directly */
+			rspamd_log_flush (rspamd_log);
+			fill_buffer (rspamd_log, priv, iov, iovcnt);
+		}
+		else {
+			/* Copy incoming string to buffer */
+			fill_buffer (rspamd_log, priv, iov, iovcnt);
+		}
+	}
+}
+
+static void
+rspamd_log_reset_repeated (rspamd_logger_t *rspamd_log,
+						   struct rspamd_file_logger_priv *priv)
+{
+	gchar tmpbuf[256];
+	gssize r;
+
+	if (rspamd_log->opened) {
+		if (priv->repeats > REPEATS_MIN) {
+			r = rspamd_snprintf (tmpbuf,
+					sizeof (tmpbuf),
+					"Last message repeated %ud times",
+					priv->repeats - REPEATS_MIN);
+			priv->repeats = 0;
+
+			if (priv->saved_message) {
+				rspamd_log_file_log (priv->saved_module,
+						priv->saved_id,
+						priv->saved_function,
+						priv->saved_loglevel | RSPAMD_LOG_FORCED,
+						priv->saved_message,
+						priv->saved_mlen,
+						rspamd_log,
+						priv);
+
+				g_free (priv->saved_message);
+				g_free (priv->saved_function);
+				g_free (priv->saved_module);
+				g_free (priv->saved_id);
+				priv->saved_message = NULL;
+				priv->saved_function = NULL;
+				priv->saved_module = NULL;
+				priv->saved_id = NULL;
+			}
+
+			/* It is safe to use temporary buffer here as it is not static */
+			rspamd_log_file_log (NULL, NULL,
+					G_STRFUNC,
+					priv->saved_loglevel | RSPAMD_LOG_FORCED,
+					tmpbuf,
+					r,
+					rspamd_log,
+					priv);
+		}
+	}
+}
+
+static gint
+rspamd_try_open_log_fd (rspamd_logger_t *rspamd_log,
+						struct rspamd_file_logger_priv *priv,
+						uid_t uid, gid_t gid,
+						GError **err)
+{
+	gint fd;
+
+	fd = open (priv->log_file,
+			O_CREAT | O_WRONLY | O_APPEND,
+			S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH);
+	if (fd == -1) {
+		g_set_error (err, FILE_LOG_QUARK, errno,
+				"open_log: cannot open desired log file: %s, %s\n",
+				priv->log_file, strerror (errno));
+		return -1;
+	}
+
+	if (uid != -1 || gid != -1) {
+		if (fchown (fd, uid, gid) == -1) {
+			g_set_error (err, FILE_LOG_QUARK, errno,
+					"open_log: cannot chown desired log file: %s, %s\n",
+					priv->log_file, strerror (errno));
+			close (fd);
+
+			return -1;
+		}
+	}
+
+	return fd;
+}
+
+void *
+rspamd_log_file_init (rspamd_logger_t *logger, struct rspamd_config *cfg,
+					  uid_t uid, gid_t gid, GError **err)
+{
+	struct rspamd_file_logger_priv *priv;
+
+	if (!cfg->cfg_name) {
+		g_set_error (err, FILE_LOG_QUARK, EINVAL,
+				"no log file specified");
+		return NULL;
+	}
+
+	priv = g_malloc0 (sizeof (*priv));
+
+	if (cfg->log_buffered) {
+		if (cfg->log_buf_size != 0) {
+			priv->io_buf.size = cfg->log_buf_size;
+		}
+		else {
+			priv->io_buf.size = LOGBUF_LEN;
+		}
+		priv->is_buffered = TRUE;
+		priv->io_buf.buf = g_malloc (priv->io_buf.size);
+	}
+
+	if (cfg->log_file) {
+		priv->log_file = g_strdup (cfg->log_file);
+	}
+
+	priv->fd = rspamd_try_open_log_fd (logger, priv, uid, gid, err);
+
+	if (priv->fd == -1) {
+		rspamd_log_file_dtor (logger, priv);
+
+		return NULL;
+	}
+
+	return priv;
+}
+
+void
+rspamd_log_file_dtor (rspamd_logger_t *logger, gpointer arg)
+{
+	struct rspamd_file_logger_priv *priv = (struct rspamd_file_logger_priv *)arg;
+
+	rspamd_log_reset_repeated (logger, priv);
+
+	if (priv->fd != -1) {
+		if (close (priv->fd) == -1) {
+			rspamd_fprintf (stderr, "cannot close log fd %d: %s; log file = %s\n",
+					priv->fd, strerror (errno), priv->log_file);
+		}
+	}
+
+	g_free (priv->log_file);
+	g_free (priv);
+}
+
+void
+rspamd_log_file_log (const gchar *module, const gchar *id,
+				   const gchar *function,
+				   gint level_flags,
+				   const gchar *message,
+				   gsize mlen,
+				   rspamd_logger_t *rspamd_log,
+				   gpointer arg)
+{
+	struct rspamd_file_logger_priv *priv = (struct rspamd_file_logger_priv *)arg;
+	static gchar timebuf[64], modulebuf[64];
+	gchar tmpbuf[256];
+	gchar *m;
+	gdouble now;
+	struct iovec iov[6];
+	gulong r = 0, mr = 0;
+	guint64 cksum;
+	size_t mremain;
+	const gchar *cptype = NULL;
+	gboolean got_time = FALSE;
+
+
+	if (!(level_flags & RSPAMD_LOG_FORCED) && !rspamd_log->enabled) {
+		return;
+	}
+
+	/* Check throttling due to write errors */
+	if (!(level_flags & RSPAMD_LOG_FORCED) && priv->throttling) {
+		now = rspamd_get_calendar_ticks ();
+		if (priv->throttling_time != now) {
+			priv->throttling_time = now;
+			got_time = TRUE;
+		}
+		else {
+			/* Do not try to write to file too often while throttling */
+			return;
+		}
+	}
+
+	/* Check repeats */
+	cksum = rspamd_log_calculate_cksum (message, mlen);
+
+	if (cksum == priv->last_line_cksum) {
+		priv->repeats++;
+
+		if (priv->repeats > REPEATS_MIN && priv->repeats <
+												 REPEATS_MAX) {
+			/* Do not log anything but save message for future */
+			if (priv->saved_message == NULL) {
+				priv->saved_function = g_strdup (function);
+				priv->saved_mlen = mlen;
+				priv->saved_message = g_malloc (mlen);
+				memcpy (priv->saved_message, message, mlen);
+
+				if (module) {
+					priv->saved_module = g_strdup (module);
+				}
+
+				if (id) {
+					priv->saved_id = g_strdup (id);
+				}
+
+				priv->saved_loglevel = level_flags;
+			}
+
+			return;
+		}
+		else if (priv->repeats > REPEATS_MAX) {
+			rspamd_log_reset_repeated (rspamd_log, priv);
+
+			rspamd_log_file_log (module, id,
+					function,
+					level_flags,
+					message,
+					mlen,
+					rspamd_log,
+					priv);
+
+			/* Probably we have more repeats in future */
+			priv->repeats = REPEATS_MIN + 1;
+
+			return;
+		}
+	}
+	else {
+		/* Reset counter if new message differs from saved message */
+		priv->last_line_cksum = cksum;
+
+		if (priv->repeats > REPEATS_MIN) {
+			rspamd_log_reset_repeated (rspamd_log, priv);
+			rspamd_log_file_log (module, id,
+					function,
+					level_flags,
+					message,
+					mlen,
+					rspamd_log,
+					arg);
+			return;
+		}
+		else {
+			priv->repeats = 0;
+		}
+	}
+	if (!got_time) {
+		now = rspamd_get_calendar_ticks ();
+	}
+
+	/* Format time */
+	if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_SYSTEMD)) {
+		log_time (now, rspamd_log, timebuf, sizeof (timebuf));
+	}
+
+	cptype = g_quark_to_string (rspamd_log->process_type);
+
+	if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
+		if (level_flags & (G_LOG_LEVEL_INFO|G_LOG_LEVEL_MESSAGE)) {
+			/* White */
+			r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;37m");
+		}
+		else if (level_flags & G_LOG_LEVEL_WARNING) {
+			/* Magenta */
+			r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;32m");
+		}
+		else if (level_flags & G_LOG_LEVEL_CRITICAL) {
+			/* Red */
+			r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[1;31m");
+		}
+	}
+	else {
+		r = 0;
+	}
+
+	if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_SYSTEMD)) {
+		r += rspamd_snprintf (tmpbuf + r,
+				sizeof (tmpbuf) - r,
+				"%s #%P(%s) ",
+				timebuf,
+				rspamd_log->pid,
+				cptype);
+	}
+	else {
+		r += rspamd_snprintf (tmpbuf + r,
+				sizeof (tmpbuf) - r,
+				"(%s) ",
+				cptype);
+	}
+
+	modulebuf[0] = '\0';
+	mremain = sizeof (modulebuf);
+	m = modulebuf;
+
+	if (id != NULL) {
+		guint slen = strlen (id);
+		slen = MIN (LOG_ID, slen);
+		mr = rspamd_snprintf (m, mremain, "<%*.s>; ", slen,
+				id);
+		m += mr;
+		mremain -= mr;
+	}
+	if (module != NULL) {
+		mr = rspamd_snprintf (m, mremain, "%s; ", module);
+		m += mr;
+		mremain -= mr;
+	}
+	if (function != NULL) {
+		mr = rspamd_snprintf (m, mremain, "%s: ", function);
+		m += mr;
+		mremain -= mr;
+	}
+	else {
+		mr = rspamd_snprintf (m, mremain, ": ");
+		m += mr;
+		mremain -= mr;
+	}
+
+	/* Construct IOV for log line */
+	iov[0].iov_base = tmpbuf;
+	iov[0].iov_len = r;
+	iov[1].iov_base = modulebuf;
+	iov[1].iov_len = m - modulebuf;
+	iov[2].iov_base = (void *) message;
+	iov[2].iov_len = mlen;
+	iov[3].iov_base = (void *) &lf_chr;
+	iov[3].iov_len = 1;
+
+	file_log_helper (rspamd_log, priv, iov, 4, level_flags);
+}
+
+void *
+rspamd_log_file_reload (rspamd_logger_t *logger, struct rspamd_config *cfg,
+						gpointer arg, uid_t uid, gid_t gid, GError **err)
+{
+	struct rspamd_file_logger_priv *npriv;
+
+	if (!cfg->cfg_name) {
+		g_set_error (err, FILE_LOG_QUARK, EINVAL,
+				"no log file specified");
+		return NULL;
+	}
+
+	npriv = rspamd_log_file_init (logger, cfg, uid, gid, err);
+
+	if (npriv) {
+		/* Close old */
+		rspamd_log_file_dtor (logger, arg);
+	}
+
+	return npriv;
+}