diff options
Diffstat (limited to 'src/libutil/logger.c')
-rw-r--r-- | src/libutil/logger.c | 727 |
1 files changed, 4 insertions, 723 deletions
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; |