#include "map_helpers.h"
#include "ottery.h"
#include "unix-std.h"
+#include "logger_private.h"
#ifdef HAVE_SYSLOG_H
#include <syslog.h>
#endif
-/* How much message should be repeated before it is count to be repeated one */
-#define REPEATS_MIN 3
-#define REPEATS_MAX 300
-#define LOG_ID 6
-#define LOGBUF_LEN 8192
-
-struct rspamd_log_module {
- gchar *mname;
- guint id;
-};
-
-struct rspamd_log_modules {
- guchar *bitset;
- guint bitset_len; /* Number of BITS used in bitset */
- guint bitset_allocated; /* Size of bitset allocated in BYTES */
- GHashTable *modules;
-};
-
-struct rspamd_logger_error_elt {
- gint completed;
- GQuark ptype;
- pid_t pid;
- gdouble ts;
- gchar id[LOG_ID + 1];
- gchar module[9];
- gchar message[];
-};
-
-struct rspamd_logger_error_log {
- struct rspamd_logger_error_elt *elts;
- rspamd_mempool_t *pool;
- guint32 max_elts;
- guint32 elt_len;
- /* Avoid false cache sharing */
- guchar __padding[64 - sizeof(gpointer) * 2 - sizeof(guint64)];
- guint cur_row;
-};
-
-/**
- * Static structure that store logging parameters
- * It is NOT shared between processes and is created by main process
- */
-struct rspamd_logger_s {
- rspamd_log_func_t log_func;
- gpointer log_arg;
- enum rspamd_log_type log_type;
- gint log_facility;
- gint log_level;
- gchar *log_file;
- gboolean log_buffered;
- gboolean log_silent_workers;
- guint32 log_buf_size;
-
- struct rspamd_logger_error_log *errlog;
- struct rspamd_cryptobox_pubkey *pk;
- struct rspamd_cryptobox_keypair *keypair;
- struct {
- guint32 size;
- guint32 used;
- u_char *buf;
- } io_buf;
- gint fd;
- guint flags;
- gboolean is_buffered;
- gboolean enabled;
- gboolean is_debug;
- gboolean throttling;
- gboolean no_lock;
- gboolean opened;
- time_t throttling_time;
- enum rspamd_log_type type;
- pid_t pid;
- guint32 repeats;
- GQuark process_type;
- struct rspamd_radix_map_helper *debug_ip;
- guint64 last_line_cksum;
- gchar *saved_message;
- gsize saved_mlen;
- gchar *saved_function;
- gchar *saved_module;
- gchar *saved_id;
- rspamd_mempool_mutex_t *mtx;
- guint saved_loglevel;
- guint64 log_cnt[4];
-};
-
-static const gchar lf_chr = '\n';
static rspamd_logger_t *default_logger = NULL;
static struct rspamd_log_modules *log_modules = NULL;
-static void syslog_log_function (const gchar *module,
- const gchar *id, const gchar *function,
- gint log_level, const gchar *message, gsize mlen,
- rspamd_logger_t *logger,
- gpointer arg);
-
-static void file_log_function (const gchar *module,
- const gchar *id, const gchar *function,
- gint log_level, const gchar *message, gsize mlen,
- rspamd_logger_t *logger,
- gpointer arg);
-
guint rspamd_task_log_id = (guint)-1;
RSPAMD_CONSTRUCTOR(rspamd_task_log_init)
{
rspamd_task_log_id = rspamd_logger_add_debug_module("task");
}
-/**
- * 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 ());
-}
-
-/*
- * Write a line to log file (unbuffered)
- */
-static void
-direct_write_log_line (rspamd_logger_t *rspamd_log,
- 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;
-
- if (rspamd_log->type == RSPAMD_LOG_CONSOLE) {
-
- if (rspamd_log->flags & RSPAMD_LOG_FLAG_RSPAMADM) {
- fd = STDOUT_FILENO;
-
- if (level_flags & G_LOG_LEVEL_CRITICAL) {
- fd = STDERR_FILENO;
- }
- }
- else {
- fd = rspamd_log->fd;
- }
- }
- else {
- fd = rspamd_log->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, 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 */
- rspamd_log->throttling = TRUE;
- rspamd_log->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 (rspamd_log->throttling) {
- rspamd_log->throttling = FALSE;
- }
-}
-
-static void
-rspamd_escape_log_string (gchar *str)
-{
- guchar *p = (guchar *) str;
-
- while (*p) {
- if ((*p & 0x80) || !g_ascii_isprint (*p)) {
- *p = '?';
- }
- else if (*p == '\n' || *p == '\r') {
- *p = ' ';
- }
- p++;
- }
-}
-
-gint
-rspamd_try_open_log_fd (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid)
-{
- gint fd;
-
- fd = open (rspamd_log->log_file,
- O_CREAT | O_WRONLY | O_APPEND,
- S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH);
- if (fd == -1) {
- fprintf (stderr,
- "open_log: cannot open desired log file: %s, %s\n",
- rspamd_log->log_file, strerror (errno));
- return -1;
- }
-
- if (uid != -1 || gid != -1) {
- if (fchown (fd, uid, gid) == -1) {
- fprintf (stderr,
- "open_log: cannot chown desired log file: %s, %s\n",
- rspamd_log->log_file, strerror (errno));
- close (fd);
-
- return -1;
- }
- }
-
- return fd;
-}
/* Logging utility functions */
gint
return 0;
}
-static void
-rspamd_log_reset_repeated (rspamd_logger_t *rspamd_log)
-{
- gchar tmpbuf[256];
- gssize r;
-
- if (rspamd_log->opened) {
- if (rspamd_log->type == RSPAMD_LOG_FILE) {
- if (rspamd_log->repeats > REPEATS_MIN) {
- r = rspamd_snprintf (tmpbuf,
- sizeof (tmpbuf),
- "Last message repeated %ud times",
- rspamd_log->repeats);
- rspamd_log->repeats = 0;
-
- if (rspamd_log->saved_message) {
- file_log_function (rspamd_log->saved_module,
- rspamd_log->saved_id,
- rspamd_log->saved_function,
- rspamd_log->saved_loglevel | RSPAMD_LOG_FORCED,
- rspamd_log->saved_message,
- rspamd_log->saved_mlen,
- rspamd_log,
- rspamd_log->log_arg);
-
- g_free (rspamd_log->saved_message);
- g_free (rspamd_log->saved_function);
- g_free (rspamd_log->saved_module);
- g_free (rspamd_log->saved_id);
- rspamd_log->saved_message = NULL;
- rspamd_log->saved_function = NULL;
- rspamd_log->saved_module = NULL;
- rspamd_log->saved_id = NULL;
- }
-
- /* It is safe to use temporary buffer here as it is not static */
- file_log_function (NULL, NULL,
- G_STRFUNC,
- rspamd_log->saved_loglevel | RSPAMD_LOG_FORCED,
- tmpbuf,
- r,
- rspamd_log,
- rspamd_log->log_arg);
- }
- }
- }
-}
void
rspamd_log_close_priv (rspamd_logger_t *rspamd_log, gboolean termination, uid_t uid, gid_t gid)
logger->flags = cfg->log_flags;
- /* Set up buffer */
- if (cfg->log_buffered) {
- if (cfg->log_buf_size != 0) {
- logger->io_buf.size = cfg->log_buf_size;
- }
- else {
- logger->io_buf.size = LOGBUF_LEN;
- }
- logger->is_buffered = TRUE;
- logger->io_buf.buf = g_malloc (logger->io_buf.size);
- }
+
/* Set up conditional logging */
if (cfg->debug_ip_map != NULL) {
/* Try to add it as map first of all */
}
-/**
- * Fill buffer with message (limits must be checked BEFORE this call)
- */
-static void
-fill_buffer (rspamd_logger_t *rspamd_log, const struct iovec *iov, gint iovcnt)
-{
- gint i;
-
- for (i = 0; i < iovcnt; i++) {
- memcpy (rspamd_log->io_buf.buf + rspamd_log->io_buf.used,
- iov[i].iov_base,
- iov[i].iov_len);
- rspamd_log->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,
- const struct iovec *iov,
- guint iovcnt,
- gint level_flags)
-{
- size_t len = 0;
- guint i;
-
- if (!rspamd_log->is_buffered) {
- /* Write string directly */
- direct_write_log_line (rspamd_log, (void *) iov, iovcnt, TRUE, level_flags);
- }
- else {
- /* Calculate total length */
- for (i = 0; i < iovcnt; i++) {
- len += iov[i].iov_len;
- }
- /* Fill buffer */
- if (rspamd_log->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, (void *) iov, iovcnt, TRUE, level_flags);
- }
- else if (rspamd_log->io_buf.used + len >= rspamd_log->io_buf.size) {
- /* Buffer is full, try to write it directly */
- rspamd_log_flush (rspamd_log);
- fill_buffer (rspamd_log, iov, iovcnt);
- }
- else {
- /* Copy incoming string to buffer */
- fill_buffer (rspamd_log, iov, iovcnt);
- }
- }
-}
-
/**
* Syslog interface for logging
*/
#endif
}
-
-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);
- }
-}
-
/**
* Main file interface for logging
*/
-static void
-file_log_function (const gchar *module, const gchar *id,
- const gchar *function,
- gint level_flags,
- const gchar *message,
- gsize mlen,
- rspamd_logger_t *rspamd_log,
- gpointer 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) && rspamd_log->throttling) {
- now = rspamd_get_calendar_ticks ();
- if (rspamd_log->throttling_time != now) {
- rspamd_log->throttling_time = now;
- got_time = TRUE;
- }
- else {
- /* Do not try to write to file too often while throttling */
- return;
- }
- }
-
- if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_RSPAMADM)) {
- /* Check repeats */
- cksum = rspamd_log_calculate_cksum (message, mlen);
-
- if (cksum == rspamd_log->last_line_cksum) {
- rspamd_log->repeats++;
- if (rspamd_log->repeats > REPEATS_MIN && rspamd_log->repeats <
- REPEATS_MAX) {
- /* Do not log anything */
- if (rspamd_log->saved_message == NULL) {
- rspamd_log->saved_function = g_strdup (function);
- rspamd_log->saved_mlen = mlen;
- rspamd_log->saved_message = g_malloc (mlen);
- memcpy (rspamd_log->saved_message, message, mlen);
-
- if (module) {
- rspamd_log->saved_module = g_strdup (module);
- }
-
- if (id) {
- rspamd_log->saved_id = g_strdup (id);
- }
-
- rspamd_log->saved_loglevel = level_flags;
- }
-
- return;
- }
- else if (rspamd_log->repeats > REPEATS_MAX) {
- gssize r = rspamd_snprintf (tmpbuf,
- sizeof (tmpbuf),
- "Last message repeated %ud times",
- rspamd_log->repeats);
- rspamd_log->repeats = 0;
- /* It is safe to use temporary buffer here as it is not static */
- if (rspamd_log->saved_message) {
- file_log_function (rspamd_log->saved_module,
- rspamd_log->saved_id,
- rspamd_log->saved_function,
- rspamd_log->saved_loglevel,
- rspamd_log->saved_message,
- rspamd_log->saved_mlen,
- rspamd_log,
- arg);
-
- g_free (rspamd_log->saved_message);
- g_free (rspamd_log->saved_function);
- g_free (rspamd_log->saved_module);
- g_free (rspamd_log->saved_id);
- rspamd_log->saved_message = NULL;
- rspamd_log->saved_function = NULL;
- rspamd_log->saved_module = NULL;
- rspamd_log->saved_id = NULL;
- }
-
- /* Two messages */
- file_log_function ("logger", NULL,
- G_STRFUNC,
- rspamd_log->saved_loglevel,
- tmpbuf,
- r,
- rspamd_log,
- arg);
-
- file_log_function (module, id,
- function,
- level_flags,
- message,
- mlen,
- rspamd_log,
- arg);
-
- rspamd_log->repeats = REPEATS_MIN + 1;
-
- return;
- }
- }
- else {
- /* Reset counter if new message differs from saved message */
- rspamd_log->last_line_cksum = cksum;
- if (rspamd_log->repeats > REPEATS_MIN) {
- gssize r = rspamd_snprintf (tmpbuf,
- sizeof (tmpbuf),
- "Last message repeated %ud times",
- rspamd_log->repeats);
- rspamd_log->repeats = 0;
-
- if (rspamd_log->saved_message) {
- file_log_function (rspamd_log->saved_module,
- rspamd_log->saved_id,
- rspamd_log->saved_function,
- rspamd_log->saved_loglevel,
- rspamd_log->saved_message,
- rspamd_log->saved_mlen,
- rspamd_log,
- arg);
-
- g_free (rspamd_log->saved_message);
- g_free (rspamd_log->saved_function);
- g_free (rspamd_log->saved_module);
- g_free (rspamd_log->saved_id);
- rspamd_log->saved_message = NULL;
- rspamd_log->saved_function = NULL;
- rspamd_log->saved_module = NULL;
- rspamd_log->saved_id = NULL;
- }
-
- file_log_function ("logger", NULL,
- G_STRFUNC,
- level_flags,
- tmpbuf,
- r,
- rspamd_log,
- arg);
- /* It is safe to use temporary buffer here as it is not static */
- file_log_function (module, id,
- function,
- level_flags,
- message,
- mlen,
- rspamd_log,
- arg);
- return;
- }
- else {
- rspamd_log->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;
-
- if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
- iov[4].iov_base = "\033[0m";
- iov[4].iov_len = sizeof ("\033[0m") - 1;
- /* Call helper (for buffering) */
- file_log_helper (rspamd_log, iov, 5, level_flags);
- }
- else {
- /* Call helper (for buffering) */
- file_log_helper (rspamd_log, iov, 4, level_flags);
- }
- }
- else {
- /* Rspamadm logging version */
-
- 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");
- }
-
- iov[0].iov_base = (void *) tmpbuf;
- iov[0].iov_len = r;
- r = 1;
- }
- else {
- r = 0;
- }
-
-
- if (rspamd_log->log_level == G_LOG_LEVEL_DEBUG) {
- log_time (rspamd_get_calendar_ticks (),
- rspamd_log, timebuf, sizeof (timebuf));
- iov[r].iov_base = (void *) timebuf;
- iov[r++].iov_len = strlen (timebuf);
- iov[r].iov_base = (void *) " ";
- iov[r++].iov_len = 1;
- }
-
- iov[r].iov_base = (void *) message;
- iov[r++].iov_len = mlen;
- iov[r].iov_base = (void *) &lf_chr;
- iov[r++].iov_len = 1;
-
- if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
- iov[r].iov_base = "\033[0m";
- iov[r++].iov_len = sizeof ("\033[0m") - 1;
- /* Call helper (for buffering) */
- file_log_helper (rspamd_log, iov, r, level_flags);
- }
- else {
- /* Call helper (for buffering) */
- file_log_helper (rspamd_log, iov, r, level_flags);
- }
- }
-}
-
/**
* Write log line depending on ip
*/
return default_logger;
}
-rspamd_log_func_t
+struct rspamd_logger_funcs*
rspamd_logger_set_log_function (rspamd_logger_t *logger,
- rspamd_log_func_t nfunc,
- gpointer narg,
- gpointer *old_arg)
+ struct rspamd_logger_funcs *nfuncs);
{
if (logger == NULL) {
logger = default_logger;
g_assert (logger != NULL);
- if (old_arg) {
- *old_arg = logger->log_arg;
- }
-
rspamd_log_func_t old_func = logger->log_func;
logger->log_func = nfunc;
--- /dev/null
+/*-
+ * 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;
+}
projects / thirdparty / rspamd.git / commitdiff
