From 02a6d987bbdf55e06375544a14c046d1724f946e Mon Sep 17 00:00:00 2001 From: Vsevolod Stakhov Date: Tue, 27 Apr 2010 18:43:22 +0400 Subject: [PATCH] * Improve logging system: - do not write many repeated messages to log - add process name to log line * Small fixes to FreeBSD port and to start script as we have xml version now * Reconfig modules while rereading config file --- freebsd/port/Makefile | 8 +-- freebsd/rspamd.sh.in | 2 +- src/logger.c | 139 ++++++++++++++++++++++++++++++++++++-- src/logger.h | 23 ++----- src/main.c | 8 +-- src/plugins/fuzzy_check.c | 2 + 6 files changed, 146 insertions(+), 36 deletions(-) diff --git a/freebsd/port/Makefile b/freebsd/port/Makefile index 668d8d8d4..d75fc40e4 100644 --- a/freebsd/port/Makefile +++ b/freebsd/port/Makefile @@ -6,7 +6,7 @@ # PORTNAME= rspamd -PORTVERSION= 0.2.9 +PORTVERSION= 0.3.0 CATEGORIES= mail MASTER_SITES= SF/${PORTNAME}/${PORTNAME}/${PORTNAME}-${PORTVERSION} @@ -27,7 +27,6 @@ USE_PERL5= yes OPTIONS= RSPAMD_GPERF "Enable google perf-tools profiling" off \ RSPAMD_JUDY "Enable judy arrays usage for performance" off \ - RSPAMD_LUA "Enable lua plugins support in rspamd" on \ RSPAMD_OPTFLAGS "Turn on compiler optimizations" off \ RSPAMD_REDIRECTOR "Install HTTP redirector" off \ RSPAMD_STATIC "Build static version of rspamd" off @@ -47,13 +46,8 @@ LIB_DEPENDS+= profiler.0:${PORTSDIR}/devel/google-perftools LIB_DEPENDS+= Judy:${PORTSDIR}/devel/judy .endif -.if defined(WITH_RSPAMD_LUA) USE_LUA= 5.1- PLIST_SUB+= LUA="" -.else -CMAKE_ARGS+= -DENABLE_LUA=OFF -PLIST_SUB+= LUA="@comment" -.endif .if defined(WITH_RSPAMD_OPTFLAGS) CMAKE_ARGS+= -DENABLE_OPTIMIZATION=ON diff --git a/freebsd/rspamd.sh.in b/freebsd/rspamd.sh.in index 5bb3a5cc2..42e82f140 100755 --- a/freebsd/rspamd.sh.in +++ b/freebsd/rspamd.sh.in @@ -41,6 +41,6 @@ extra_commands="reload configtest" sig_reload="USR1" command="$procname" -command_args="-u ${rspamd_user} -g ${rspamd_group} -c @CMAKE_INSTALL_PREFIX@/etc/rspamd.conf" +command_args="-u ${rspamd_user} -g ${rspamd_group} -c @CMAKE_INSTALL_PREFIX@/etc/rspamd.xml" run_rc_command "$1" diff --git a/src/logger.c b/src/logger.c index 0d8daa75f..72bb9da73 100644 --- a/src/logger.c +++ b/src/logger.c @@ -29,12 +29,36 @@ #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 #ifdef RSPAMD_MAIN sig_atomic_t do_reopen_log = 0; #endif -rspamd_logger_t *rspamd_log; +typedef struct rspamd_logger_s { + rspamd_log_func_t log_func; + struct config_file *cfg; + struct { + uint32_t size; + uint32_t used; + u_char *buf; + } io_buf; + int fd; + gboolean is_buffered; + gboolean enabled; + enum rspamd_log_type type; + pid_t pid; + enum process_type process_type; + radix_tree_t *debug_ip; + uint32_t last_line_cksum; + uint32_t repeats; + gchar *saved_message; + gchar *saved_function; +} rspamd_logger_t; + +rspamd_logger_t *rspamd_log = NULL; static const char lf_chr = '\n'; @@ -47,6 +71,23 @@ file_log_function (const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg); +static inline uint32_t +rspamd_log_calculate_cksum (const gchar *message, size_t mlen) +{ + const gchar *bp = message; + const gchar *be = bp + mlen; + uint32_t hval = 0; + + while (bp < be) { + hval += (hval<<1) + (hval<<4) + (hval<<7) + (hval<<8) + (hval<<24); + hval ^= (uint32_t)*bp++; + } + + /* return our new hash value */ + return hval; + +} + static void direct_write_log_line (void *data, int count, gboolean is_iov) { @@ -115,6 +156,7 @@ open_log (void) void close_log (void) { + char tmpbuf[256]; flush_log_buf (); switch (rspamd_log->type) { @@ -126,6 +168,21 @@ close_log (void) break; case RSPAMD_LOG_FILE: if (rspamd_log->enabled) { + if (rspamd_log->repeats > REPEATS_MIN) { + snprintf (tmpbuf, sizeof (tmpbuf), "Last message repeated %u 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, NULL); + 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, NULL); + return; + } + if (fsync (rspamd_log->fd) == -1) { msg_err ("error syncing log file: %s", strerror (errno)); } @@ -138,7 +195,7 @@ close_log (void) } void -rspamd_set_logger (enum rspamd_log_type type, struct config_file *cfg) +rspamd_set_logger (enum rspamd_log_type type, enum process_type ptype, struct config_file *cfg) { char **strvec, *p, *err; int num, i, k; @@ -152,6 +209,7 @@ rspamd_set_logger (enum rspamd_log_type type, struct config_file *cfg) rspamd_log->type = type; rspamd_log->pid = getpid (); + rspamd_log->process_type = ptype; switch (type) { case RSPAMD_LOG_CONSOLE: @@ -225,9 +283,10 @@ reopen_log (void) } void -update_log_pid (void) +update_log_pid (enum process_type ptype) { rspamd_log->pid = getpid (); + rspamd_log->process_type = ptype; } void @@ -358,6 +417,9 @@ file_log_function (const gchar * log_domain, const gchar *function, GLogLevelFla struct tm *tms; struct iovec iov[3]; int r; + uint32_t cksum; + size_t mlen; + const char *cptype = NULL; if (! rspamd_log->enabled) { return; @@ -369,20 +431,85 @@ file_log_function (const gchar * log_domain, const gchar *function, GLogLevelFla #endif if (forced || log_level <= rspamd_log->cfg->log_level) { + /* 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) { + snprintf (tmpbuf, sizeof (tmpbuf), "Last message repeated %u 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 { + rspamd_log->last_line_cksum = cksum; + if (rspamd_log->repeats > REPEATS_MIN) { + snprintf (tmpbuf, sizeof (tmpbuf), "Last message repeated %u 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; + } + } + now = time (NULL); tms = localtime (&now); strftime (timebuf, sizeof (timebuf), "%b %d %H:%M:%S", tms); + switch (rspamd_log->process_type) { + case TYPE_MAIN: + cptype = "main"; + break; + case TYPE_WORKER: + cptype = "worker"; + break; + case TYPE_CONTROLLER: + cptype = "controller"; + break; + case TYPE_LMTP: + cptype = "lmtp"; + break; + case TYPE_FUZZY: + cptype = "fuzzy"; + break; + } if (function == NULL) { - r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "#%P: %s rspamd ", rspamd_log->pid, timebuf); + r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "#%P(%s): %s rspamd ", rspamd_log->pid, cptype, timebuf); } else { - r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "#%P: %s rspamd %s: ", rspamd_log->pid, timebuf, function); + r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "#%P(%s): %s rspamd %s: ", rspamd_log->pid, cptype, timebuf, function); } iov[0].iov_base = tmpbuf; iov[0].iov_len = r; iov[1].iov_base = (void *)message; - iov[1].iov_len = strlen (message); + iov[1].iov_len = mlen; iov[2].iov_base = (void *)&lf_chr; iov[2].iov_len = 1; diff --git a/src/logger.h b/src/logger.h index e86901cfc..c923b25ed 100644 --- a/src/logger.h +++ b/src/logger.h @@ -5,30 +5,17 @@ #include "cfg_file.h" #include "radix.h" +/* Forwarded declaration */ +enum process_type; + typedef void (*rspamd_log_func_t)(const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg); -typedef struct rspamd_logger_s { - rspamd_log_func_t log_func; - struct config_file *cfg; - struct { - uint32_t size; - uint32_t used; - u_char *buf; - } io_buf; - int fd; - gboolean is_buffered; - gboolean enabled; - enum rspamd_log_type type; - pid_t pid; - radix_tree_t *debug_ip; -} rspamd_logger_t; - /** * Init logger */ -void rspamd_set_logger (enum rspamd_log_type type, struct config_file *cfg); +void rspamd_set_logger (enum rspamd_log_type type, enum process_type ptype, struct config_file *cfg); /** * Open log file or initialize other structures */ @@ -44,7 +31,7 @@ int reopen_log (void); /** * Set log pid */ -void update_log_pid (void); +void update_log_pid (enum process_type ptype); /** * Flush log buffer for some types of logging diff --git a/src/main.c b/src/main.c index 123a69940..522af5736 100644 --- a/src/main.c +++ b/src/main.c @@ -236,7 +236,7 @@ drop_priv (struct config_file *cfg) static void config_logger (struct rspamd_main *rspamd, gboolean is_fatal) { - rspamd_set_logger (rspamd->cfg->log_type, rspamd->cfg); + rspamd_set_logger (rspamd->cfg->log_type, RSPAMD_MAIN, rspamd->cfg); if (open_log () == -1) { if (is_fatal) { fprintf (stderr, "Fatal error, cannot open logfile, exiting\n"); @@ -284,7 +284,7 @@ reread_config (struct rspamd_main *rspamd) while (l) { filt = l->data; if (filt->module) { - (void)filt->module->module_config_func (rspamd->cfg); + (void)filt->module->module_reconfig_func (rspamd->cfg); } l = g_list_next (l); } @@ -336,7 +336,7 @@ fork_worker (struct rspamd_main *rspamd, struct worker_conf *cf) switch (cur->pid) { case 0: /* Update pid for logging */ - update_log_pid (); + update_log_pid (cf->type); /* Drop privilleges */ drop_priv (rspamd->cfg); /* Set limits */ @@ -781,7 +781,7 @@ main (int argc, char **argv, char **env) #endif /* First set logger to console logger */ - rspamd_set_logger (RSPAMD_LOG_CONSOLE, rspamd->cfg); + rspamd_set_logger (RSPAMD_LOG_CONSOLE, RSPAMD_MAIN, rspamd->cfg); (void)open_log (); g_log_set_default_handler (rspamd_glib_log_function, rspamd->cfg); diff --git a/src/plugins/fuzzy_check.c b/src/plugins/fuzzy_check.c index bb66d1037..aa2b788ff 100644 --- a/src/plugins/fuzzy_check.c +++ b/src/plugins/fuzzy_check.c @@ -283,6 +283,8 @@ int fuzzy_check_module_reconfig (struct config_file *cfg) { memory_pool_delete (fuzzy_module_ctx->fuzzy_pool); + fuzzy_module_ctx->servers = NULL; + fuzzy_module_ctx->servers_num = 0; fuzzy_module_ctx->fuzzy_pool = memory_pool_new (memory_pool_get_size ()); return fuzzy_check_module_config (cfg); -- 2.39.5