diff options
author | Vsevolod Stakhov <vsevolod@highsecure.ru> | 2020-02-10 14:43:31 +0000 |
---|---|---|
committer | Vsevolod Stakhov <vsevolod@highsecure.ru> | 2020-02-10 21:12:13 +0000 |
commit | adef14349a2c7c2b762ac2bbae6f52e93e4aa628 (patch) | |
tree | 3fcbb7267d788abbdeb5a0ed4506d65603654b55 /src/libutil | |
parent | 5e70c5980ce3401952cef57946ab6da18a5b153e (diff) | |
download | rspamd-adef14349a2c7c2b762ac2bbae6f52e93e4aa628.tar.gz rspamd-adef14349a2c7c2b762ac2bbae6f52e93e4aa628.zip |
[Rework] Start logger rework
Diffstat (limited to 'src/libutil')
-rw-r--r-- | src/libutil/CMakeLists.txt | 1 | ||||
-rw-r--r-- | src/libutil/logger.c | 727 | ||||
-rw-r--r-- | src/libutil/logger.h | 33 | ||||
-rw-r--r-- | src/libutil/logger_file.c | 588 | ||||
-rw-r--r-- | 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 */ @@ -933,62 +610,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 */ static void @@ -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) { - 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 */ @@ -1707,11 +994,9 @@ rspamd_logger_get_singleton (void) 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; @@ -1719,10 +1004,6 @@ rspamd_logger_set_log_function (rspamd_logger_t *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; diff --git a/src/libutil/logger.h b/src/libutil/logger.h index d2c690392..3cec58249 100644 --- a/src/libutil/logger.h +++ b/src/libutil/logger.h @@ -29,6 +29,25 @@ typedef void (*rspamd_log_func_t) (const gchar *module, const gchar *id, gsize mlen, rspamd_logger_t *logger, gpointer arg); +typedef void * (*rspamd_log_init_func) (rspamd_logger_t *logger, + struct rspamd_config *cfg, + uid_t uid, gid_t gid, + GError **err); +typedef void* (*rspamd_log_reload_func) (rspamd_logger_t *logger, + struct rspamd_config *cfg, + gpointer arg, + uid_t uid, gid_t gid, + GError **err); +typedef void (*rspamd_log_dtor_func) (rspamd_logger_t *logger, + gpointer arg); + +struct rspamd_logger_funcs { + rspamd_log_init_func init; + rspamd_log_reload_func reload; + rspamd_log_dtor_func dtor; + rspamd_log_func_t log; + gpointer specific; +}; #define RSPAMD_LOGBUF_SIZE 8192 @@ -200,17 +219,13 @@ ucl_object_t *rspamd_log_errorbuf_export (const rspamd_logger_t *logger); rspamd_logger_t *rspamd_logger_get_singleton (void); /** - * Sets new logging function + * Sets new logger functions and initialise logging if needed * @param logger - * @param nfunc - * @param narg - * @param old_arg - * @return old log function and old log function arg in (*old_arg) + * @param nfuncs + * @return static pointer to the old functions (so this function is not reentrant) */ -rspamd_log_func_t rspamd_logger_set_log_function (rspamd_logger_t *logger, - rspamd_log_func_t nfunc, - gpointer narg, - gpointer *old_arg); +struct rspamd_logger_funcs* rspamd_logger_set_log_function (rspamd_logger_t *logger, + struct rspamd_logger_funcs *nfuncs); /* Typical functions */ 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; +} diff --git a/src/libutil/logger_private.h b/src/libutil/logger_private.h new file mode 100644 index 000000000..4644e4e86 --- /dev/null +++ b/src/libutil/logger_private.h @@ -0,0 +1,109 @@ +/*- + * 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. + */ +#ifndef RSPAMD_LOGGER_PRIVATE_H +#define RSPAMD_LOGGER_PRIVATE_H + +/* 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 { + struct rspamd_logger_funcs ops; + gint log_facility; + gint log_level; + + struct rspamd_logger_error_log *errlog; + struct rspamd_cryptobox_pubkey *pk; + struct rspamd_cryptobox_keypair *keypair; + + guint flags; + gboolean enabled; + gboolean is_debug; + gboolean no_lock; + gboolean opened; + + pid_t pid; + GQuark process_type; + struct rspamd_radix_map_helper *debug_ip; + rspamd_mempool_mutex_t *mtx; +}; + +/* + * Common logging prototypes + */ + +/* + * File logging + */ +void * rspamd_log_file_init (rspamd_logger_t *logger, struct rspamd_config *cfg, + uid_t uid, gid_t gid, GError **err); +void * rspamd_log_file_reload (rspamd_logger_t *logger, struct rspamd_config *cfg, + gpointer arg, uid_t uid, gid_t gid, GError **err); +void rspamd_log_file_dtor (rspamd_logger_t *logger, gpointer arg); +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); + +const static struct rspamd_logger_funcs file_log_funcs = { + .init = rspamd_log_file_init, + .dtor = rspamd_log_file_dtor, + .reload = rspamd_log_file_reload, + .log = rspamd_log_file_log, +}; + +#endif |