/* * Copyright (c) 2009-2012, Vsevolod Stakhov * All rights reserved. * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions are met: * * Redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer. * * Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in the * documentation and/or other materials provided with the distribution. * * THIS SOFTWARE IS PROVIDED BY AUTHOR ''AS IS'' AND ANY * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE * DISCLAIMED. IN NO EVENT SHALL AUTHOR BE LIABLE FOR ANY * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. */ #include "config.h" #include "logger.h" #include "util.h" #include "main.h" #include "map.h" /* How much message should be repeated before it is count to be repeated one */ #define REPEATS_MIN 3 #define REPEATS_MAX 300 /** * 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; struct config_file *cfg; struct { guint32 size; guint32 used; u_char *buf; } io_buf; gint fd; gboolean is_buffered; gboolean enabled; gboolean is_debug; gboolean throttling; time_t throttling_time; sig_atomic_t do_reopen_log; enum rspamd_log_type type; pid_t pid; GQuark process_type; radix_tree_t *debug_ip; guint32 last_line_cksum; guint32 repeats; gchar *saved_message; gchar *saved_function; GMutex *mtx; }; static const gchar lf_chr = '\n'; static rspamd_logger_t *default_logger = NULL; static void syslog_log_function (const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg); static void file_log_function (const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg); /** * Calculate checksum for log line (used for repeating logic) */ static inline guint32 rspamd_log_calculate_cksum (const gchar *message, size_t mlen) { const gchar *bp = message; const gchar *be = bp + mlen; guint32 hval = 0; while (bp < be) { hval += (hval<<1) + (hval<<4) + (hval<<7) + (hval<<8) + (hval<<24); hval ^= (guint32)*bp++; } /* return our new hash value */ return hval; } /* * Write a line to log file (unbuffered) */ static void direct_write_log_line (rspamd_logger_t *rspamd_log, void *data, gint count, gboolean is_iov) { gchar errmsg[128]; struct iovec *iov; const gchar *line; gint r; if (rspamd_log->enabled) { if (is_iov) { iov = (struct iovec *)data; r = writev (rspamd_log->fd, iov, count); } else { line = (const gchar *)data; r = write (rspamd_log->fd, line, count); } if (r == -1) { /* We cannot write message to file, so we need to detect error and make decision */ r = rspamd_snprintf (errmsg, sizeof (errmsg), "direct_write_log_line: cannot write log line: %s", strerror (errno)); if (errno == EIO || errno == EINTR) { /* Descriptor is somehow invalid, try to restart */ reopen_log (rspamd_log); if (write (rspamd_log->fd, errmsg, r) != -1) { /* Try again */ direct_write_log_line (rspamd_log, data, count, is_iov); } } else 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; } } } /* Logging utility functions */ gint open_log_priv (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid) { switch (rspamd_log->cfg->log_type) { case RSPAMD_LOG_CONSOLE: /* Do nothing with console */ rspamd_log->enabled = TRUE; return 0; case RSPAMD_LOG_SYSLOG: openlog ("rspamd", LOG_NDELAY | LOG_PID, rspamd_log->cfg->log_facility); rspamd_log->enabled = TRUE; return 0; case RSPAMD_LOG_FILE: rspamd_log->fd = open (rspamd_log->cfg->log_file, O_CREAT | O_WRONLY | O_APPEND, S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH); if (rspamd_log->fd == -1) { fprintf (stderr, "open_log: cannot open desired log file: %s, %s", rspamd_log->cfg->log_file, strerror (errno)); return -1; } if (fchown (rspamd_log->fd, uid, gid) == -1) { fprintf (stderr, "open_log: cannot chown desired log file: %s, %s", rspamd_log->cfg->log_file, strerror (errno)); close (rspamd_log->fd); return -1; } rspamd_log->enabled = TRUE; return 0; } return -1; } void close_log_priv (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid) { gchar tmpbuf[256]; flush_log_buf (rspamd_log); switch (rspamd_log->type) { case RSPAMD_LOG_CONSOLE: /* Do nothing special */ break; case RSPAMD_LOG_SYSLOG: closelog (); break; case RSPAMD_LOG_FILE: if (rspamd_log->enabled) { if (rspamd_log->repeats > REPEATS_MIN) { 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 (NULL, rspamd_log->saved_function, rspamd_log->cfg->log_level, rspamd_log->saved_message, TRUE, rspamd_log); g_free (rspamd_log->saved_message); g_free (rspamd_log->saved_function); rspamd_log->saved_message = NULL; rspamd_log->saved_function = NULL; } /* It is safe to use temporary buffer here as it is not static */ file_log_function (NULL, __FUNCTION__, rspamd_log->cfg->log_level, tmpbuf, TRUE, rspamd_log); return; } if (fsync (rspamd_log->fd) == -1) { msg_err ("error syncing log file: %s", strerror (errno)); } close (rspamd_log->fd); } break; } rspamd_log->enabled = FALSE; } gint reopen_log_priv (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid) { close_log_priv (rspamd_log, uid, gid); if (open_log_priv (rspamd_log, uid, gid) == 0) { msg_info ("log file reopened"); return 0; } return -1; } /** * Open log file or initialize other structures */ gint open_log (rspamd_logger_t *logger) { return open_log_priv (logger, -1, -1); } /** * Close log file or destroy other structures */ void close_log (rspamd_logger_t *logger) { close_log_priv (logger, -1, -1); } /** * Close and open log again */ gint reopen_log (rspamd_logger_t *logger) { return reopen_log_priv (logger, -1, -1); } /* * Setup logger */ void rspamd_set_logger (enum rspamd_log_type type, GQuark ptype, struct rspamd_main *rspamd) { gchar **strvec, *p, *err; gint num, i, k; struct in_addr addr; guint32 mask = 0xFFFFFFFF; if (rspamd->logger == NULL) { rspamd->logger = g_malloc (sizeof (rspamd_logger_t)); memset (rspamd->logger, 0, sizeof (rspamd_logger_t)); } rspamd->logger->type = type; rspamd->logger->pid = getpid (); rspamd->logger->process_type = ptype; #if ((GLIB_MAJOR_VERSION == 2) && (GLIB_MINOR_VERSION <= 30)) rspamd->logger->mtx = g_mutex_new (); #else rspamd->logger->mtx = g_malloc (sizeof (GMutex)); g_mutex_init (rspamd->logger->mtx); #endif switch (type) { case RSPAMD_LOG_CONSOLE: rspamd->logger->log_func = file_log_function; rspamd->logger->fd = STDERR_FILENO; break; case RSPAMD_LOG_SYSLOG: rspamd->logger->log_func = syslog_log_function; break; case RSPAMD_LOG_FILE: rspamd->logger->log_func = file_log_function; break; } rspamd->logger->cfg = rspamd->cfg; /* Set up buffer */ if (rspamd->cfg->log_buffered) { if (rspamd->cfg->log_buf_size != 0) { rspamd->logger->io_buf.size = rspamd->cfg->log_buf_size; } else { rspamd->logger->io_buf.size = BUFSIZ; } rspamd->logger->is_buffered = TRUE; rspamd->logger->io_buf.buf = g_malloc (rspamd->logger->io_buf.size); } /* Set up conditional logging */ if (rspamd->cfg->debug_ip_map != NULL) { /* Try to add it as map first of all */ if (rspamd->logger->debug_ip) { radix_tree_free (rspamd->logger->debug_ip); } rspamd->logger->debug_ip = radix_tree_create (); if (!add_map (rspamd->cfg, rspamd->cfg->debug_ip_map, "IP addresses for which debug logs are enabled", read_radix_list, fin_radix_list, (void **)&rspamd->logger->debug_ip)) { /* Try to parse it as list */ strvec = g_strsplit_set (rspamd->cfg->debug_ip_map, ",; ", 0); num = g_strv_length (strvec); for (i = 0; i < num; i++) { g_strstrip (strvec[i]); if ((p = strchr (strvec[i], '/')) != NULL) { /* Try to extract mask */ *p = '\0'; p ++; errno = 0; k = strtoul (p, &err, 10); if (errno != 0 || *err != '\0' || k > 32) { continue; } } else { k = 32; } if (inet_aton (strvec[i], &addr)) { /* Check ip */ mask = mask << (32 - k); radix32tree_insert (rspamd->logger->debug_ip, ntohl (addr.s_addr), mask, 1); } } g_strfreev (strvec); } } else if (rspamd->logger->debug_ip) { radix_tree_free (rspamd->logger->debug_ip); rspamd->logger->debug_ip = NULL; } default_logger = rspamd->logger; } /** * Used after fork() for updating structure params */ void update_log_pid (GQuark ptype, rspamd_logger_t *rspamd_log) { rspamd_log->pid = getpid (); rspamd_log->process_type = ptype; } /** * Flush logging buffer */ void flush_log_buf (rspamd_logger_t *rspamd_log) { if (rspamd_log->is_buffered && (rspamd_log->type == RSPAMD_LOG_CONSOLE || rspamd_log->type == RSPAMD_LOG_FILE)) { direct_write_log_line (rspamd_log, rspamd_log->io_buf.buf, rspamd_log->io_buf.used, FALSE); rspamd_log->io_buf.used = 0; } } /** * This log functions select real logger and write message if level is less or equal to configured log level */ void rspamd_common_log_function (rspamd_logger_t *rspamd_log, GLogLevelFlags log_level, const gchar *function, const gchar *fmt, ...) { static gchar logbuf[BUFSIZ], escaped_logbuf[BUFSIZ]; va_list vp; u_char *end; if (log_level <= rspamd_log->cfg->log_level) { g_mutex_lock (rspamd_log->mtx); va_start (vp, fmt); end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp); *end = '\0'; (void)rspamd_escape_string (escaped_logbuf, logbuf, sizeof (escaped_logbuf)); va_end (vp); rspamd_log->log_func (NULL, function, log_level, escaped_logbuf, FALSE, rspamd_log); g_mutex_unlock (rspamd_log->mtx); } } void rspamd_default_log_function (GLogLevelFlags log_level, const gchar *function, const gchar *fmt, ...) { static gchar logbuf[BUFSIZ], escaped_logbuf[BUFSIZ]; va_list vp; u_char *end; if (default_logger == NULL) { /* Just fprintf message */ if (log_level >= G_LOG_LEVEL_INFO) { va_start (vp, fmt); end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp); *end = '\0'; (void)rspamd_escape_string (escaped_logbuf, logbuf, sizeof (escaped_logbuf)); va_end (vp); fprintf (stderr, "%s\n", escaped_logbuf); } } else if (log_level <= default_logger->cfg->log_level) { g_mutex_lock (default_logger->mtx); va_start (vp, fmt); end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp); *end = '\0'; (void)rspamd_escape_string (escaped_logbuf, logbuf, sizeof (escaped_logbuf)); va_end (vp); default_logger->log_func (NULL, function, log_level, escaped_logbuf, FALSE, default_logger); g_mutex_unlock (default_logger->mtx); } } /** * 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, gint iovcnt) { size_t len = 0; gint i; if (! rspamd_log->is_buffered) { /* Write string directly */ direct_write_log_line (rspamd_log, (void *)iov, iovcnt, TRUE); } 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 dirrectly */ flush_log_buf (rspamd_log); direct_write_log_line (rspamd_log, (void *)iov, iovcnt, TRUE); } else if (rspamd_log->io_buf.used + len >= rspamd_log->io_buf.size) { /* Buffer is full, try to write it dirrectly */ flush_log_buf (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 syslog_log_function (const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg) { rspamd_logger_t *rspamd_log = arg; if (! rspamd_log->enabled) { return; } if (function == NULL) { if (forced || log_level <= rspamd_log->cfg->log_level) { if (forced || log_level >= G_LOG_LEVEL_DEBUG) { syslog (LOG_DEBUG, "%s", message); } else if (log_level >= G_LOG_LEVEL_INFO) { syslog (LOG_INFO, "%s", message); } else if (log_level >= G_LOG_LEVEL_WARNING) { syslog (LOG_WARNING, "%s", message); } else if (log_level >= G_LOG_LEVEL_CRITICAL) { syslog (LOG_ERR, "%s", message); } } } else { if (forced || log_level <= rspamd_log->cfg->log_level) { if (log_level >= G_LOG_LEVEL_DEBUG) { syslog (LOG_DEBUG, "%s: %s", function, message); } else if (log_level >= G_LOG_LEVEL_INFO) { syslog (LOG_INFO, "%s: %s", function, message); } else if (log_level >= G_LOG_LEVEL_WARNING) { syslog (LOG_WARNING, "%s: %s", function, message); } else if (log_level >= G_LOG_LEVEL_CRITICAL) { syslog (LOG_ERR, "%s: %s", function, message); } } } } /** * Main file interface for logging */ static void file_log_function (const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg) { gchar tmpbuf[256], timebuf[32]; time_t now; struct tm *tms; struct iovec iov[4]; gint r = 0; guint32 cksum; size_t mlen; const gchar *cptype = NULL; gboolean got_time = FALSE; rspamd_logger_t *rspamd_log = arg; if (! rspamd_log->enabled) { return; } if (forced || log_level <= rspamd_log->cfg->log_level) { /* Check throttling due to write errors */ if (rspamd_log->throttling) { now = time (NULL); 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; } } /* Check repeats */ mlen = strlen (message); 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 == 0) { rspamd_log->saved_message = g_strdup (message); rspamd_log->saved_function = g_strdup (function); } return; } else if (rspamd_log->repeats > REPEATS_MAX) { 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 (log_domain, rspamd_log->saved_function, log_level, rspamd_log->saved_message, forced, arg); } file_log_function (log_domain, __FUNCTION__, log_level, tmpbuf, forced, arg); file_log_function (log_domain, function, log_level, message, forced, 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) { 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 (log_domain, rspamd_log->saved_function, log_level, rspamd_log->saved_message, forced, arg); g_free (rspamd_log->saved_message); g_free (rspamd_log->saved_function); rspamd_log->saved_message = NULL; rspamd_log->saved_function = NULL; } file_log_function (log_domain, __FUNCTION__, log_level, tmpbuf, forced, arg); /* It is safe to use temporary buffer here as it is not static */ file_log_function (log_domain, function, log_level, message, forced, arg); return; } else { rspamd_log->repeats = 0; } } if (rspamd_log->cfg->log_extended) { if (! got_time) { now = time (NULL); } /* Format time */ tms = localtime (&now); strftime (timebuf, sizeof (timebuf), "%F %H:%M:%S", tms); cptype = g_quark_to_string (rspamd_log->process_type); if (rspamd_log->cfg->log_color) { if (log_level >= G_LOG_LEVEL_INFO) { /* White */ r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[1;37m"); } else if (log_level >= G_LOG_LEVEL_WARNING) { /* Magenta */ r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[2;32m"); } else if (log_level >= G_LOG_LEVEL_CRITICAL) { /* Red */ r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[1;31m"); } } else { r = 0; } if (function == NULL) { 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 #%P(%s) %s: ", timebuf, rspamd_log->pid, cptype, function); } /* Construct IOV for log line */ iov[0].iov_base = tmpbuf; iov[0].iov_len = r; iov[1].iov_base = (void *)message; iov[1].iov_len = mlen; iov[2].iov_base = (void *)&lf_chr; iov[2].iov_len = 1; if (rspamd_log->cfg->log_color) { iov[3].iov_base = "\033[0m"; iov[3].iov_len = sizeof ("\033[0m") - 1; /* Call helper (for buffering) */ file_log_helper (rspamd_log, iov, 4); } else { /* Call helper (for buffering) */ file_log_helper (rspamd_log, iov, 3); } } else { iov[0].iov_base = (void *)message; iov[0].iov_len = mlen; iov[1].iov_base = (void *)&lf_chr; iov[1].iov_len = 1; if (rspamd_log->cfg->log_color) { iov[2].iov_base = "\033[0m"; iov[2].iov_len = sizeof ("\033[0m") - 1; /* Call helper (for buffering) */ file_log_helper (rspamd_log, iov, 3); } else { /* Call helper (for buffering) */ file_log_helper (rspamd_log, iov, 2); } } } } /** * Write log line depending on ip */ void rspamd_conditional_debug (rspamd_logger_t *rspamd_log, guint32 addr, const gchar *function, const gchar *fmt, ...) { static gchar logbuf[BUFSIZ], escaped_logbuf[BUFSIZ]; va_list vp; u_char *end; if (rspamd_log->cfg->log_level >= G_LOG_LEVEL_DEBUG || rspamd_log->is_debug || (rspamd_log->debug_ip != NULL && radix32tree_find (rspamd_log->debug_ip, ntohl (addr)) != RADIX_NO_VALUE)) { g_mutex_lock (rspamd_log->mtx); va_start (vp, fmt); end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp); *end = '\0'; (void)rspamd_escape_string (escaped_logbuf, logbuf, sizeof (escaped_logbuf)); va_end (vp); rspamd_log->log_func (NULL, function, G_LOG_LEVEL_DEBUG, escaped_logbuf, TRUE, rspamd_log); g_mutex_unlock (rspamd_log->mtx); } } /** * Wrapper for glib logger */ void rspamd_glib_log_function (const gchar *log_domain, GLogLevelFlags log_level, const gchar *message, gpointer arg) { gchar escaped_logbuf[BUFSIZ]; rspamd_logger_t *rspamd_log = arg; if (rspamd_log->enabled) { g_mutex_lock (rspamd_log->mtx); (void)rspamd_escape_string (escaped_logbuf, message, sizeof (escaped_logbuf)); rspamd_log->log_func (log_domain, NULL, log_level, escaped_logbuf, FALSE, rspamd_log); g_mutex_unlock (rspamd_log->mtx); } } /** * Temporary turn on debugging */ void rspamd_log_debug (rspamd_logger_t *rspamd_log) { rspamd_log->is_debug = TRUE; } /** * Turn off temporary debugging */ void rspamd_log_nodebug (rspamd_logger_t *rspamd_log) { rspamd_log->is_debug = FALSE; }