commit adef143: [Rework] Start logger rework
Vsevolod Stakhov
vsevolod at highsecure.ru
Mon Feb 10 21:28:08 UTC 2020
Author: Vsevolod Stakhov
Date: 2020-02-10 14:43:31 +0000
URL: https://github.com/rspamd/rspamd/commit/adef14349a2c7c2b762ac2bbae6f52e93e4aa628
[Rework] Start logger rework
---
src/libutil/CMakeLists.txt | 1 +
src/libutil/logger.c | 727 +------------------------------------------
src/libutil/logger.h | 33 +-
src/libutil/logger_file.c | 588 ++++++++++++++++++++++++++++++++++
src/libutil/logger_private.h | 109 +++++++
5 files changed, 726 insertions(+), 732 deletions(-)
diff --git a/src/libutil/CMakeLists.txt b/src/libutil/CMakeLists.txt
index 290841373..6cd5df8a0 100644
--- a/src/libutil/CMakeLists.txt
+++ b/src/libutil/CMakeLists.txt
@@ -11,6 +11,7 @@ SET(LIBRSPAMDUTILSRC
${CMAKE_CURRENT_SOURCE_DIR}/http_router.c
${CMAKE_CURRENT_SOURCE_DIR}/http_context.c
${CMAKE_CURRENT_SOURCE_DIR}/logger.c
+ ${CMAKE_CURRENT_SOURCE_DIR}/logger_file.c
${CMAKE_CURRENT_SOURCE_DIR}/map.c
${CMAKE_CURRENT_SOURCE_DIR}/map_helpers.c
${CMAKE_CURRENT_SOURCE_DIR}/mem_pool.c
diff --git a/src/libutil/logger.c b/src/libutil/logger.c
index cb1e39209..1f586b111 100644
--- a/src/libutil/logger.c
+++ b/src/libutil/logger.c
@@ -20,288 +20,22 @@
#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
@@ -378,53 +112,6 @@ rspamd_log_open_priv (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid)
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)
@@ -611,17 +298,7 @@ rspamd_set_logger (struct rspamd_config *cfg,
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 */
@@ -932,62 +609,6 @@ rspamd_default_log_function (gint level_flags,
}
-/**
- * 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
*/
@@ -1034,343 +655,9 @@ syslog_log_function (const gchar *module, const gchar *id,
#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) {
*** OUTPUT TRUNCATED, 887 LINES SKIPPED ***
More information about the Commits
mailing list