diff options
Diffstat (limited to 'src/libserver/logger')
-rw-r--r-- | src/libserver/logger/logger.c | 1319 | ||||
-rw-r--r-- | src/libserver/logger/logger_console.c | 211 | ||||
-rw-r--r-- | src/libserver/logger/logger_file.c | 510 | ||||
-rw-r--r-- | src/libserver/logger/logger_private.h | 218 | ||||
-rw-r--r-- | src/libserver/logger/logger_syslog.c | 143 |
5 files changed, 2401 insertions, 0 deletions
diff --git a/src/libserver/logger/logger.c b/src/libserver/logger/logger.c new file mode 100644 index 0000000..2dae632 --- /dev/null +++ b/src/libserver/logger/logger.c @@ -0,0 +1,1319 @@ +/* + * Copyright 2023 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 "rspamd.h" +#include "libserver/maps/map.h" +#include "libserver/maps/map_helpers.h" +#include "ottery.h" +#include "unix-std.h" +#include "logger_private.h" + + +static rspamd_logger_t *default_logger = NULL; +static rspamd_logger_t *emergency_logger = NULL; +static struct rspamd_log_modules *log_modules = NULL; + +static const gchar lf_chr = '\n'; + +guint rspamd_task_log_id = (guint) -1; +RSPAMD_CONSTRUCTOR(rspamd_task_log_init) +{ + rspamd_task_log_id = rspamd_logger_add_debug_module("task"); +} + +rspamd_logger_t * +rspamd_log_default_logger(void) +{ + return default_logger; +} + +rspamd_logger_t * +rspamd_log_emergency_logger(void) +{ + return emergency_logger; +} + +void rspamd_log_set_log_level(rspamd_logger_t *logger, gint level) +{ + if (logger == NULL) { + logger = default_logger; + } + + logger->log_level = level; +} + +gint rspamd_log_get_log_level(rspamd_logger_t *logger) +{ + if (logger == NULL) { + logger = default_logger; + } + + return logger->log_level; +} + +void rspamd_log_set_log_flags(rspamd_logger_t *logger, gint flags) +{ + g_assert(logger != NULL); + + logger->flags = flags; +} + +void rspamd_log_close(rspamd_logger_t *logger) +{ + g_assert(logger != NULL); + + if (logger->closed) { + return; + } + + logger->closed = TRUE; + + if (logger->debug_ip) { + rspamd_map_helper_destroy_radix(logger->debug_ip); + } + + if (logger->pk) { + rspamd_pubkey_unref(logger->pk); + } + + if (logger->keypair) { + rspamd_keypair_unref(logger->keypair); + } + + logger->ops.dtor(logger, logger->ops.specific); + + /* TODO: Do we really need that ? */ + if (logger == default_logger) { + default_logger = NULL; + } + + if (logger == emergency_logger) { + emergency_logger = NULL; + } + + if (!logger->pool) { + g_free(logger); + } +} + +bool rspamd_log_reopen(rspamd_logger_t *rspamd_log, struct rspamd_config *cfg, + uid_t uid, gid_t gid) +{ + void *nspec; + GError *err = NULL; + + g_assert(rspamd_log != NULL); + + nspec = rspamd_log->ops.reload(rspamd_log, cfg, rspamd_log->ops.specific, + uid, gid, &err); + + if (nspec != NULL) { + rspamd_log->ops.specific = nspec; + } + else { + } + + return nspec != NULL; +} + +static void +rspamd_emergency_logger_dtor(gpointer d) +{ + rspamd_logger_t *logger = (rspamd_logger_t *) d; + + rspamd_log_close(logger); +} + +rspamd_logger_t * +rspamd_log_open_emergency(rspamd_mempool_t *pool, gint flags) +{ + rspamd_logger_t *logger; + GError *err = NULL; + + g_assert(default_logger == NULL); + g_assert(emergency_logger == NULL); + + if (pool) { + logger = rspamd_mempool_alloc0(pool, sizeof(rspamd_logger_t)); + logger->mtx = rspamd_mempool_get_mutex(pool); + } + else { + logger = g_malloc0(sizeof(rspamd_logger_t)); + } + + logger->flags = flags; + logger->pool = pool; + logger->process_type = "main"; + logger->pid = getpid(); + + const struct rspamd_logger_funcs *funcs = &console_log_funcs; + memcpy(&logger->ops, funcs, sizeof(*funcs)); + + logger->ops.specific = logger->ops.init(logger, NULL, -1, -1, &err); + + if (logger->ops.specific == NULL) { + rspamd_fprintf(stderr, "fatal error: cannot init console logging: %e\n", + err); + g_error_free(err); + + exit(EXIT_FAILURE); + } + + default_logger = logger; + emergency_logger = logger; + + rspamd_mempool_add_destructor(pool, rspamd_emergency_logger_dtor, + emergency_logger); + + return logger; +} + +rspamd_logger_t * +rspamd_log_open_specific(rspamd_mempool_t *pool, + struct rspamd_config *cfg, + const gchar *ptype, + uid_t uid, gid_t gid) +{ + rspamd_logger_t *logger; + GError *err = NULL; + + if (pool) { + logger = rspamd_mempool_alloc0(pool, sizeof(rspamd_logger_t)); + logger->mtx = rspamd_mempool_get_mutex(pool); + } + else { + logger = g_malloc0(sizeof(rspamd_logger_t)); + } + + logger->pool = pool; + + if (cfg) { + if (cfg->log_error_elts > 0 && pool) { + logger->errlog = rspamd_mempool_alloc0_shared(pool, + sizeof(*logger->errlog)); + logger->errlog->pool = pool; + logger->errlog->max_elts = cfg->log_error_elts; + logger->errlog->elt_len = cfg->log_error_elt_maxlen; + logger->errlog->elts = rspamd_mempool_alloc0_shared(pool, + sizeof(struct rspamd_logger_error_elt) * cfg->log_error_elts + + cfg->log_error_elt_maxlen * cfg->log_error_elts); + } + + logger->log_level = cfg->log_level; + logger->flags = cfg->log_flags; + + if (!(logger->flags & RSPAMD_LOG_FLAG_ENFORCED)) { + logger->log_level = cfg->log_level; + } + } + + const struct rspamd_logger_funcs *funcs = NULL; + + if (cfg) { + switch (cfg->log_type) { + case RSPAMD_LOG_CONSOLE: + funcs = &console_log_funcs; + break; + case RSPAMD_LOG_SYSLOG: + funcs = &syslog_log_funcs; + break; + case RSPAMD_LOG_FILE: + funcs = &file_log_funcs; + break; + } + } + else { + funcs = &console_log_funcs; + } + + g_assert(funcs != NULL); + memcpy(&logger->ops, funcs, sizeof(*funcs)); + + logger->ops.specific = logger->ops.init(logger, cfg, uid, gid, &err); + + if (emergency_logger && logger->ops.specific == NULL) { + rspamd_common_log_function(emergency_logger, G_LOG_LEVEL_CRITICAL, + "logger", NULL, G_STRFUNC, + "cannot open specific logger: %e", err); + g_error_free(err); + + return NULL; + } + + logger->pid = getpid(); + logger->process_type = ptype; + logger->enabled = TRUE; + + /* Set up conditional logging */ + if (cfg) { + if (cfg->debug_ip_map != NULL) { + /* Try to add it as map first of all */ + if (logger->debug_ip) { + rspamd_map_helper_destroy_radix(logger->debug_ip); + } + + logger->debug_ip = NULL; + rspamd_config_radix_from_ucl(cfg, + cfg->debug_ip_map, + "IP addresses for which debug logs are enabled", + &logger->debug_ip, + NULL, + NULL, "debug ip"); + } + + if (cfg->log_encryption_key) { + logger->pk = rspamd_pubkey_ref(cfg->log_encryption_key); + logger->keypair = rspamd_keypair_new(RSPAMD_KEYPAIR_KEX, + RSPAMD_CRYPTOBOX_MODE_25519); + rspamd_pubkey_calculate_nm(logger->pk, logger->keypair); + } + } + + default_logger = logger; + + return logger; +} + + +/** + * Used after fork() for updating structure params + */ +void rspamd_log_on_fork(GQuark ptype, struct rspamd_config *cfg, + rspamd_logger_t *logger) +{ + logger->pid = getpid(); + logger->process_type = g_quark_to_string(ptype); + + if (logger->ops.on_fork) { + GError *err = NULL; + + bool ret = logger->ops.on_fork(logger, cfg, logger->ops.specific, &err); + + if (!ret && emergency_logger) { + rspamd_common_log_function(emergency_logger, G_LOG_LEVEL_CRITICAL, + "logger", NULL, G_STRFUNC, + "cannot update logging on fork: %e", err); + g_error_free(err); + } + } +} + +inline gboolean +rspamd_logger_need_log(rspamd_logger_t *rspamd_log, GLogLevelFlags log_level, + gint module_id) +{ + g_assert(rspamd_log != NULL); + + if ((log_level & RSPAMD_LOG_FORCED) || + (log_level & (RSPAMD_LOG_LEVEL_MASK & G_LOG_LEVEL_MASK)) <= rspamd_log->log_level) { + return TRUE; + } + + if (module_id != -1 && isset(log_modules->bitset, module_id)) { + return TRUE; + } + + return FALSE; +} + +static gchar * +rspamd_log_encrypt_message(const gchar *begin, const gchar *end, gsize *enc_len, + rspamd_logger_t *rspamd_log) +{ + guchar *out; + gchar *b64; + guchar *p, *nonce, *mac; + const guchar *comp; + guint len, inlen; + + g_assert(end > begin); + /* base64 (pubkey | nonce | message) */ + inlen = rspamd_cryptobox_nonce_bytes(RSPAMD_CRYPTOBOX_MODE_25519) + + rspamd_cryptobox_pk_bytes(RSPAMD_CRYPTOBOX_MODE_25519) + + rspamd_cryptobox_mac_bytes(RSPAMD_CRYPTOBOX_MODE_25519) + + (end - begin); + out = g_malloc(inlen); + + p = out; + comp = rspamd_pubkey_get_pk(rspamd_log->pk, &len); + memcpy(p, comp, len); + p += len; + ottery_rand_bytes(p, rspamd_cryptobox_nonce_bytes(RSPAMD_CRYPTOBOX_MODE_25519)); + nonce = p; + p += rspamd_cryptobox_nonce_bytes(RSPAMD_CRYPTOBOX_MODE_25519); + mac = p; + p += rspamd_cryptobox_mac_bytes(RSPAMD_CRYPTOBOX_MODE_25519); + memcpy(p, begin, end - begin); + comp = rspamd_pubkey_get_nm(rspamd_log->pk, rspamd_log->keypair); + g_assert(comp != NULL); + rspamd_cryptobox_encrypt_nm_inplace(p, end - begin, nonce, comp, mac, + RSPAMD_CRYPTOBOX_MODE_25519); + b64 = rspamd_encode_base64(out, inlen, 0, enc_len); + g_free(out); + + return b64; +} + +static void +rspamd_log_write_ringbuffer(rspamd_logger_t *rspamd_log, + const gchar *module, const gchar *id, + const gchar *data, glong len) +{ + guint32 row_num; + struct rspamd_logger_error_log *elog; + struct rspamd_logger_error_elt *elt; + + if (!rspamd_log->errlog) { + return; + } + + elog = rspamd_log->errlog; + + g_atomic_int_compare_and_exchange(&elog->cur_row, elog->max_elts, 0); +#if ((GLIB_MAJOR_VERSION == 2) && (GLIB_MINOR_VERSION > 30)) + row_num = g_atomic_int_add(&elog->cur_row, 1); +#else + row_num = g_atomic_int_exchange_and_add(&elog->cur_row, 1); +#endif + + if (row_num < elog->max_elts) { + elt = (struct rspamd_logger_error_elt *) (((guchar *) elog->elts) + + (sizeof(*elt) + elog->elt_len) * row_num); + g_atomic_int_set(&elt->completed, 0); + } + else { + /* Race condition */ + elog->cur_row = 0; + return; + } + + elt->pid = rspamd_log->pid; + elt->ptype = g_quark_from_string(rspamd_log->process_type); + elt->ts = rspamd_get_calendar_ticks(); + + if (id) { + rspamd_strlcpy(elt->id, id, sizeof(elt->id)); + } + else { + rspamd_strlcpy(elt->id, "", sizeof(elt->id)); + } + + if (module) { + rspamd_strlcpy(elt->module, module, sizeof(elt->module)); + } + else { + rspamd_strlcpy(elt->module, "", sizeof(elt->module)); + } + + rspamd_strlcpy(elt->message, data, MIN(len + 1, elog->elt_len)); + g_atomic_int_set(&elt->completed, 1); +} + +bool rspamd_common_logv(rspamd_logger_t *rspamd_log, gint level_flags, + const gchar *module, const gchar *id, const gchar *function, + const gchar *fmt, va_list args) +{ + gchar *end; + gint level = level_flags & (RSPAMD_LOG_LEVEL_MASK & G_LOG_LEVEL_MASK), mod_id; + bool ret = false; + gchar logbuf[RSPAMD_LOGBUF_SIZE], *log_line; + gsize nescaped; + + if (G_UNLIKELY(rspamd_log == NULL)) { + rspamd_log = default_logger; + } + + log_line = logbuf; + + if (G_UNLIKELY(rspamd_log == NULL)) { + /* Just fprintf message to stderr */ + if (level >= G_LOG_LEVEL_INFO) { + end = rspamd_vsnprintf(logbuf, sizeof(logbuf), fmt, args); + rspamd_fprintf(stderr, "%*s\n", (gint) (end - log_line), + log_line); + } + } + else { + if (level == G_LOG_LEVEL_DEBUG) { + mod_id = rspamd_logger_add_debug_module(module); + } + else { + mod_id = -1; + } + + if (rspamd_logger_need_log(rspamd_log, level_flags, mod_id)) { + end = rspamd_vsnprintf(logbuf, sizeof(logbuf), fmt, args); + + if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_RSPAMADM)) { + if ((nescaped = rspamd_log_line_need_escape(logbuf, end - logbuf)) != 0) { + gsize unescaped_len = end - logbuf; + gchar *logbuf_escaped = g_alloca(unescaped_len + nescaped * 4); + log_line = logbuf_escaped; + + end = rspamd_log_line_hex_escape(logbuf, unescaped_len, + logbuf_escaped, unescaped_len + nescaped * 4); + } + } + + if ((level_flags & RSPAMD_LOG_ENCRYPTED) && rspamd_log->pk) { + gchar *encrypted; + gsize enc_len; + + encrypted = rspamd_log_encrypt_message(log_line, end, &enc_len, + rspamd_log); + ret = rspamd_log->ops.log(module, id, + function, + level_flags, + encrypted, + enc_len, + rspamd_log, + rspamd_log->ops.specific); + g_free(encrypted); + } + else { + ret = rspamd_log->ops.log(module, id, + function, + level_flags, + log_line, + end - log_line, + rspamd_log, + rspamd_log->ops.specific); + } + + switch (level) { + case G_LOG_LEVEL_CRITICAL: + rspamd_log->log_cnt[0]++; + rspamd_log_write_ringbuffer(rspamd_log, module, id, log_line, + end - log_line); + break; + case G_LOG_LEVEL_WARNING: + rspamd_log->log_cnt[1]++; + break; + case G_LOG_LEVEL_INFO: + rspamd_log->log_cnt[2]++; + break; + case G_LOG_LEVEL_DEBUG: + rspamd_log->log_cnt[3]++; + break; + default: + break; + } + } + } + + return ret; +} + +/** + * This log functions select real logger and write message if level is less or equal to configured log level + */ +bool rspamd_common_log_function(rspamd_logger_t *rspamd_log, + gint level_flags, + const gchar *module, const gchar *id, + const gchar *function, + const gchar *fmt, + ...) +{ + va_list vp; + + va_start(vp, fmt); + bool ret = rspamd_common_logv(rspamd_log, level_flags, module, id, function, fmt, vp); + va_end(vp); + + return ret; +} + +bool rspamd_default_logv(gint level_flags, const gchar *module, const gchar *id, + const gchar *function, + const gchar *fmt, va_list args) +{ + return rspamd_common_logv(NULL, level_flags, module, id, function, fmt, args); +} + +bool rspamd_default_log_function(gint level_flags, + const gchar *module, const gchar *id, + const gchar *function, const gchar *fmt, ...) +{ + + va_list vp; + + va_start(vp, fmt); + bool ret = rspamd_default_logv(level_flags, module, id, function, fmt, vp); + va_end(vp); + + return ret; +} + + +/** + * Main file interface for logging + */ +/** + * Write log line depending on ip + */ +bool rspamd_conditional_debug(rspamd_logger_t *rspamd_log, + rspamd_inet_addr_t *addr, const gchar *module, const gchar *id, + const gchar *function, const gchar *fmt, ...) +{ + static gchar logbuf[LOGBUF_LEN]; + va_list vp; + gchar *end; + gint mod_id; + + if (rspamd_log == NULL) { + rspamd_log = default_logger; + } + + mod_id = rspamd_logger_add_debug_module(module); + + if (rspamd_logger_need_log(rspamd_log, G_LOG_LEVEL_DEBUG, mod_id) || + rspamd_log->is_debug) { + if (rspamd_log->debug_ip && addr != NULL) { + if (rspamd_match_radix_map_addr(rspamd_log->debug_ip, + addr) == NULL) { + return false; + } + } + + va_start(vp, fmt); + end = rspamd_vsnprintf(logbuf, sizeof(logbuf), fmt, vp); + *end = '\0'; + va_end(vp); + return rspamd_log->ops.log(module, id, + function, + G_LOG_LEVEL_DEBUG | RSPAMD_LOG_FORCED, + logbuf, + end - logbuf, + rspamd_log, + rspamd_log->ops.specific); + } + + return false; +} + +bool rspamd_conditional_debug_fast(rspamd_logger_t *rspamd_log, + rspamd_inet_addr_t *addr, + gint mod_id, const gchar *module, const gchar *id, + const gchar *function, const gchar *fmt, ...) +{ + static gchar logbuf[LOGBUF_LEN]; + va_list vp; + gchar *end; + + if (rspamd_log == NULL) { + rspamd_log = default_logger; + } + + if (rspamd_logger_need_log(rspamd_log, G_LOG_LEVEL_DEBUG, mod_id) || + rspamd_log->is_debug) { + if (rspamd_log->debug_ip && addr != NULL) { + if (rspamd_match_radix_map_addr(rspamd_log->debug_ip, addr) == NULL) { + return false; + } + } + + va_start(vp, fmt); + end = rspamd_vsnprintf(logbuf, sizeof(logbuf), fmt, vp); + *end = '\0'; + va_end(vp); + return rspamd_log->ops.log(module, id, + function, + G_LOG_LEVEL_DEBUG | RSPAMD_LOG_FORCED, + logbuf, + end - logbuf, + rspamd_log, + rspamd_log->ops.specific); + } + + return false; +} + +bool rspamd_conditional_debug_fast_num_id(rspamd_logger_t *rspamd_log, + rspamd_inet_addr_t *addr, + gint mod_id, const gchar *module, guint64 id, + const gchar *function, const gchar *fmt, ...) +{ + static gchar logbuf[LOGBUF_LEN], idbuf[64]; + va_list vp; + gchar *end; + + if (rspamd_log == NULL) { + rspamd_log = default_logger; + } + + if (rspamd_logger_need_log(rspamd_log, G_LOG_LEVEL_DEBUG, mod_id) || + rspamd_log->is_debug) { + if (rspamd_log->debug_ip && addr != NULL) { + if (rspamd_match_radix_map_addr(rspamd_log->debug_ip, addr) == NULL) { + return false; + } + } + + rspamd_snprintf(idbuf, sizeof(idbuf), "%XuL", id); + va_start(vp, fmt); + end = rspamd_vsnprintf(logbuf, sizeof(logbuf), fmt, vp); + *end = '\0'; + va_end(vp); + return rspamd_log->ops.log(module, idbuf, + function, + G_LOG_LEVEL_DEBUG | RSPAMD_LOG_FORCED, + logbuf, + end - logbuf, + rspamd_log, + rspamd_log->ops.specific); + } + + return false; +} + +/** + * Wrapper for glib logger + */ +void rspamd_glib_log_function(const gchar *log_domain, + GLogLevelFlags log_level, + const gchar *message, + gpointer arg) +{ + rspamd_logger_t *rspamd_log = (rspamd_logger_t *) arg; + + if (rspamd_log->enabled && + rspamd_logger_need_log(rspamd_log, log_level, -1)) { + rspamd_log->ops.log("glib", NULL, + NULL, + log_level, + message, + strlen(message), + rspamd_log, + rspamd_log->ops.specific); + } +} + +void rspamd_glib_printerr_function(const gchar *message) +{ + rspamd_common_log_function(NULL, G_LOG_LEVEL_CRITICAL, "glib", + NULL, G_STRFUNC, + "%s", message); +} + +/** + * 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; +} + +const guint64 * +rspamd_log_counters(rspamd_logger_t *logger) +{ + if (logger) { + return logger->log_cnt; + } + + return NULL; +} + +static gint +rspamd_log_errlog_cmp(const ucl_object_t **o1, const ucl_object_t **o2) +{ + const ucl_object_t *ts1, *ts2; + + ts1 = ucl_object_lookup(*o1, "ts"); + ts2 = ucl_object_lookup(*o2, "ts"); + + if (ts1 && ts2) { + gdouble t1 = ucl_object_todouble(ts1), t2 = ucl_object_todouble(ts2); + + if (t1 > t2) { + return -1; + } + else if (t2 > t1) { + return 1; + } + } + + return 0; +} + +ucl_object_t * +rspamd_log_errorbuf_export(const rspamd_logger_t *logger) +{ + struct rspamd_logger_error_elt *cpy, *cur; + ucl_object_t *top = ucl_object_typed_new(UCL_ARRAY); + guint i; + + if (logger->errlog == NULL) { + return top; + } + + cpy = g_malloc0_n(logger->errlog->max_elts, + sizeof(*cpy) + logger->errlog->elt_len); + memcpy(cpy, logger->errlog->elts, logger->errlog->max_elts * (sizeof(*cpy) + logger->errlog->elt_len)); + + for (i = 0; i < logger->errlog->max_elts; i++) { + cur = (struct rspamd_logger_error_elt *) ((guchar *) cpy + + i * ((sizeof(*cpy) + logger->errlog->elt_len))); + if (cur->completed) { + ucl_object_t *obj = ucl_object_typed_new(UCL_OBJECT); + + ucl_object_insert_key(obj, ucl_object_fromdouble(cur->ts), + "ts", 0, false); + ucl_object_insert_key(obj, ucl_object_fromint(cur->pid), + "pid", 0, false); + ucl_object_insert_key(obj, + ucl_object_fromstring(g_quark_to_string(cur->ptype)), + "type", 0, false); + ucl_object_insert_key(obj, ucl_object_fromstring(cur->id), + "id", 0, false); + ucl_object_insert_key(obj, ucl_object_fromstring(cur->module), + "module", 0, false); + ucl_object_insert_key(obj, ucl_object_fromstring(cur->message), + "message", 0, false); + + ucl_array_append(top, obj); + } + } + + ucl_object_array_sort(top, rspamd_log_errlog_cmp); + g_free(cpy); + + return top; +} + +static guint +rspamd_logger_allocate_mod_bit(void) +{ + if (log_modules->bitset_allocated * NBBY > log_modules->bitset_len + 1) { + log_modules->bitset_len++; + return log_modules->bitset_len - 1; + } + else { + /* Need to expand */ + log_modules->bitset_allocated *= 2; + log_modules->bitset = g_realloc(log_modules->bitset, + log_modules->bitset_allocated); + + return rspamd_logger_allocate_mod_bit(); + } +} + +RSPAMD_DESTRUCTOR(rspamd_debug_modules_dtor) +{ + if (log_modules) { + g_hash_table_unref(log_modules->modules); + g_free(log_modules->bitset); + g_free(log_modules); + } +} + +gint rspamd_logger_add_debug_module(const gchar *mname) +{ + struct rspamd_log_module *m; + + if (mname == NULL) { + return -1; + } + + if (log_modules == NULL) { + /* + * This is usually called from constructors, so we call init check + * each time to avoid dependency issues between ctors calls + */ + log_modules = g_malloc0(sizeof(*log_modules)); + log_modules->modules = g_hash_table_new_full(rspamd_strcase_hash, + rspamd_strcase_equal, g_free, g_free); + log_modules->bitset_allocated = 16; + log_modules->bitset_len = 0; + log_modules->bitset = g_malloc0(log_modules->bitset_allocated); + } + + if ((m = g_hash_table_lookup(log_modules->modules, mname)) == NULL) { + m = g_malloc0(sizeof(*m)); + m->mname = g_strdup(mname); + m->id = rspamd_logger_allocate_mod_bit(); + clrbit(log_modules->bitset, m->id); + g_hash_table_insert(log_modules->modules, m->mname, m); + } + + return m->id; +} + +void rspamd_logger_configure_modules(GHashTable *mods_enabled) +{ + GHashTableIter it; + gpointer k, v; + guint id; + + /* Clear all in bitset_allocated -> this are bytes not bits */ + memset(log_modules->bitset, 0, log_modules->bitset_allocated); + /* On first iteration, we go through all modules enabled and add missing ones */ + g_hash_table_iter_init(&it, mods_enabled); + + while (g_hash_table_iter_next(&it, &k, &v)) { + rspamd_logger_add_debug_module((const gchar *) k); + } + + g_hash_table_iter_init(&it, mods_enabled); + + while (g_hash_table_iter_next(&it, &k, &v)) { + id = rspamd_logger_add_debug_module((const gchar *) k); + + if (isclr(log_modules->bitset, id)) { + msg_info("enable debugging for module %s (%d)", (const gchar *) k, + id); + setbit(log_modules->bitset, id); + } + } +} + +struct rspamd_logger_funcs * +rspamd_logger_set_log_function(rspamd_logger_t *logger, + struct rspamd_logger_funcs *nfuncs) +{ + /* TODO: write this */ + + return NULL; +} + + +gchar * +rspamd_log_line_hex_escape(const guchar *src, gsize srclen, + gchar *dst, gsize dstlen) +{ + static const gchar hexdigests[16] = "0123456789ABCDEF"; + gchar *d = dst; + + static guint32 escape[] = { + 0xffffffff, /* 1111 1111 1111 1111 1111 1111 1111 1111 */ + + /* ?>=< ;:98 7654 3210 /.-, +*)( '&%$ #"! */ + 0x00000000, /* 0000 0000 0000 0000 0000 0000 0000 0100 */ + + /* _^]\ [ZYX WVUT SRQP ONML KJIH GFED CBA@ */ + 0x00000000, /* 0001 0000 0000 0000 0000 0000 0000 0000 */ + + /* ~}| {zyx wvut srqp onml kjih gfed cba` */ + 0x80000000, /* 1000 0000 0000 0000 0000 0000 0000 0000 */ + + /* Allow all 8bit characters (assuming they are valid utf8) */ + 0x00000000, + 0x00000000, + 0x00000000, + 0x00000000, + }; + + while (srclen && dstlen) { + if (escape[*src >> 5] & (1U << (*src & 0x1f))) { + if (dstlen >= 4) { + *d++ = '\\'; + *d++ = 'x'; + *d++ = hexdigests[*src >> 4]; + *d++ = hexdigests[*src & 0xf]; + src++; + dstlen -= 4; + } + else { + /* Overflow */ + break; + } + } + else { + *d++ = *src++; + dstlen--; + } + + srclen--; + } + + return d; +} + +gsize rspamd_log_line_need_escape(const guchar *src, gsize srclen) +{ + static guint32 escape[] = { + 0xffffffff, /* 1111 1111 1111 1111 1111 1111 1111 1111 */ + + /* ?>=< ;:98 7654 3210 /.-, +*)( '&%$ #"! */ + 0x00000000, /* 0000 0000 0000 0000 0000 0000 0000 0100 */ + + /* _^]\ [ZYX WVUT SRQP ONML KJIH GFED CBA@ */ + 0x00000000, /* 0001 0000 0000 0000 0000 0000 0000 0000 */ + + /* ~}| {zyx wvut srqp onml kjih gfed cba` */ + 0x80000000, /* 1000 0000 0000 0000 0000 0000 0000 0000 */ + + /* Allow all 8bit characters (assuming they are valid utf8) */ + 0x00000000, + 0x00000000, + 0x00000000, + 0x00000000, + }; + gsize n = 0; + + while (srclen) { + if (escape[*src >> 5] & (1U << (*src & 0x1f))) { + n++; + } + + src++; + srclen--; + } + + return n; +} + +const gchar * +rspamd_get_log_severity_string(gint level_flags) +{ + unsigned int bitnum; + static const char *level_strs[G_LOG_LEVEL_USER_SHIFT] = { + "", /* G_LOG_FLAG_RECURSION */ + "", /* G_LOG_FLAG_FATAL */ + "crit", + "error", + "warn", + "notice", + "info", + "debug"}; + level_flags &= ((1u << G_LOG_LEVEL_USER_SHIFT) - 1u) & ~(G_LOG_FLAG_RECURSION | G_LOG_FLAG_FATAL); +#ifdef __GNUC__ + /* We assume gcc >= 3 and clang >= 5 anyway */ + bitnum = __builtin_ffs(level_flags) - 1; +#else + bitnum = ffs(level_flags) - 1; +#endif + return level_strs[bitnum]; +} + +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); + } +} + +void rspamd_log_fill_iov(struct rspamd_logger_iov_ctx *iov_ctx, + double ts, + const gchar *module, + const gchar *id, + const gchar *function, + gint level_flags, + const gchar *message, + gsize mlen, + rspamd_logger_t *logger) +{ + bool log_color = (logger->flags & RSPAMD_LOG_FLAG_COLOR); + bool log_severity = (logger->flags & RSPAMD_LOG_FLAG_SEVERITY); + bool log_rspamadm = (logger->flags & RSPAMD_LOG_FLAG_RSPAMADM); + bool log_systemd = (logger->flags & RSPAMD_LOG_FLAG_SYSTEMD); + bool log_json = (logger->flags & RSPAMD_LOG_FLAG_JSON); + + if (log_json) { + /* Some sanity to avoid too many branches */ + log_color = false; + log_severity = true; + log_systemd = false; + } + + glong r; + static gchar timebuf[64], modulebuf[64]; + static gchar tmpbuf[256]; + + if (!log_json && !log_systemd) { + log_time(ts, logger, timebuf, sizeof(timebuf)); + } + + if (G_UNLIKELY(log_json)) { + /* Perform JSON logging */ + guint slen = id ? strlen(id) : strlen("(NULL)"); + slen = MIN(RSPAMD_LOG_ID_LEN, slen); + r = rspamd_snprintf(tmpbuf, sizeof(tmpbuf), "{\"ts\": %f, " + "\"pid\": %P, " + "\"severity\": \"%s\", " + "\"worker_type\": \"%s\", " + "\"id\": \"%*.s\", " + "\"module\": \"%s\", " + "\"function\": \"%s\", " + "\"message\": \"", + ts, + logger->pid, + rspamd_get_log_severity_string(level_flags), + logger->process_type, + slen, id, + module, + function); + iov_ctx->iov[0].iov_base = tmpbuf; + iov_ctx->iov[0].iov_len = r; + /* TODO: is it possible to have other 'bad' symbols here? */ + if (rspamd_memcspn(message, "\"\\\r\n\b\t\v", mlen) == mlen) { + iov_ctx->iov[1].iov_base = (void *) message; + iov_ctx->iov[1].iov_len = mlen; + } + else { + /* We need to do JSON escaping of the quotes */ + const char *p, *end = message + mlen; + long escaped_len; + + for (p = message, escaped_len = 0; p < end; p++, escaped_len++) { + switch (*p) { + case '\v': + case '\0': + escaped_len += 5; + break; + case '\\': + case '"': + case '\n': + case '\r': + case '\b': + case '\t': + escaped_len++; + break; + default: + break; + } + } + + + struct rspamd_logger_iov_thrash_stack *thrash_stack_elt = g_malloc( + sizeof(struct rspamd_logger_iov_thrash_stack) + + escaped_len); + + char *dst = ((char *) thrash_stack_elt) + sizeof(struct rspamd_logger_iov_thrash_stack); + char *d; + + thrash_stack_elt->prev = iov_ctx->thrash_stack; + iov_ctx->thrash_stack = thrash_stack_elt; + + for (p = message, d = dst; p < end; p++, d++) { + switch (*p) { + case '\n': + *d++ = '\\'; + *d = 'n'; + break; + case '\r': + *d++ = '\\'; + *d = 'r'; + break; + case '\b': + *d++ = '\\'; + *d = 'b'; + break; + case '\t': + *d++ = '\\'; + *d = 't'; + break; + case '\f': + *d++ = '\\'; + *d = 'f'; + break; + case '\0': + *d++ = '\\'; + *d++ = 'u'; + *d++ = '0'; + *d++ = '0'; + *d++ = '0'; + *d = '0'; + break; + case '\v': + *d++ = '\\'; + *d++ = 'u'; + *d++ = '0'; + *d++ = '0'; + *d++ = '0'; + *d = 'B'; + break; + case '\\': + *d++ = '\\'; + *d = '\\'; + break; + case '"': + *d++ = '\\'; + *d = '"'; + break; + default: + *d = *p; + break; + } + } + + iov_ctx->iov[1].iov_base = dst; + iov_ctx->iov[1].iov_len = d - dst; + } + iov_ctx->iov[2].iov_base = (void *) "\"}\n"; + iov_ctx->iov[2].iov_len = sizeof("\"}\n") - 1; + + iov_ctx->niov = 3; + } + else if (G_LIKELY(!log_rspamadm)) { + if (!log_systemd) { + if (log_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; + } + } + else { + r = 0; + } + + if (log_severity) { + r += rspamd_snprintf(tmpbuf + r, + sizeof(tmpbuf) - r, + "%s [%s] #%P(%s) ", + timebuf, + rspamd_get_log_severity_string(level_flags), + logger->pid, + logger->process_type); + } + else { + r += rspamd_snprintf(tmpbuf + r, + sizeof(tmpbuf) - r, + "%s #%P(%s) ", + timebuf, + logger->pid, + logger->process_type); + } + } + else { + r = 0; + r += rspamd_snprintf(tmpbuf + r, + sizeof(tmpbuf) - r, + "(%s) ", + logger->process_type); + } + + glong mremain, mr; + char *m; + + modulebuf[0] = '\0'; + mremain = sizeof(modulebuf); + m = modulebuf; + + if (id != NULL) { + guint slen = strlen(id); + slen = MIN(RSPAMD_LOG_ID_LEN, 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; + } + + /* Ensure that we have a space at the end */ + if (m > modulebuf && *(m - 1) != ' ') { + *(m - 1) = ' '; + } + + /* Construct IOV for log line */ + iov_ctx->iov[0].iov_base = tmpbuf; + iov_ctx->iov[0].iov_len = r; + iov_ctx->iov[1].iov_base = modulebuf; + iov_ctx->iov[1].iov_len = m - modulebuf; + iov_ctx->iov[2].iov_base = (void *) message; + iov_ctx->iov[2].iov_len = mlen; + iov_ctx->iov[3].iov_base = (void *) &lf_chr; + iov_ctx->iov[3].iov_len = 1; + + iov_ctx->niov = 4; + + if (log_color) { + iov_ctx->iov[4].iov_base = "\033[0m"; + iov_ctx->iov[4].iov_len = sizeof("\033[0m") - 1; + + iov_ctx->niov = 5; + } + } + else { + /* Rspamadm case */ + int niov = 0; + + if (logger->log_level == G_LOG_LEVEL_DEBUG) { + iov_ctx->iov[niov].iov_base = (void *) timebuf; + iov_ctx->iov[niov++].iov_len = strlen(timebuf); + iov_ctx->iov[niov].iov_base = (void *) " "; + iov_ctx->iov[niov++].iov_len = 1; + } + + iov_ctx->iov[niov].iov_base = (void *) message; + iov_ctx->iov[niov++].iov_len = mlen; + iov_ctx->iov[niov].iov_base = (void *) &lf_chr; + iov_ctx->iov[niov++].iov_len = 1; + + iov_ctx->niov = niov; + } + + // this is kind of "after-the-fact" check, but it's mostly for debugging-only + g_assert(iov_ctx->niov <= G_N_ELEMENTS(iov_ctx->iov)); +} + +void rspamd_log_iov_free(struct rspamd_logger_iov_ctx *iov_ctx) +{ + struct rspamd_logger_iov_thrash_stack *st = iov_ctx->thrash_stack; + + while (st) { + struct rspamd_logger_iov_thrash_stack *nst = st->prev; + g_free(st); + st = nst; + } +}
\ No newline at end of file diff --git a/src/libserver/logger/logger_console.c b/src/libserver/logger/logger_console.c new file mode 100644 index 0000000..7f3c770 --- /dev/null +++ b/src/libserver/logger/logger_console.c @@ -0,0 +1,211 @@ +/* + * Copyright 2023 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 CONSOLE_LOG_QUARK g_quark_from_static_string("console_logger") + +static const gchar lf_chr = '\n'; +struct rspamd_console_logger_priv { + gint fd; + gint crit_fd; +}; + +/* Copy & paste :( */ +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); + } +} + +void * +rspamd_log_console_init(rspamd_logger_t *logger, struct rspamd_config *cfg, + uid_t uid, gid_t gid, GError **err) +{ + struct rspamd_console_logger_priv *priv; + + priv = g_malloc0(sizeof(*priv)); + + if (logger->flags & RSPAMD_LOG_FLAG_RSPAMADM) { + priv->fd = dup(STDOUT_FILENO); + priv->crit_fd = dup(STDERR_FILENO); + } + else { + priv->fd = dup(STDERR_FILENO); + priv->crit_fd = priv->fd; + } + + if (priv->fd == -1) { + g_set_error(err, CONSOLE_LOG_QUARK, errno, + "open_log: cannot dup console fd: %s\n", + strerror(errno)); + rspamd_log_console_dtor(logger, priv); + + return NULL; + } + + if (!isatty(priv->fd)) { + if (logger->flags & RSPAMD_LOG_FLAG_COLOR) { + /* Disable colors for not a tty */ + logger->flags &= ~RSPAMD_LOG_FLAG_COLOR; + } + } + + return priv; +} + +void * +rspamd_log_console_reload(rspamd_logger_t *logger, struct rspamd_config *cfg, + gpointer arg, uid_t uid, gid_t gid, GError **err) +{ + struct rspamd_console_logger_priv *npriv; + + npriv = rspamd_log_console_init(logger, cfg, uid, gid, err); + + if (npriv) { + /* Close old */ + rspamd_log_console_dtor(logger, arg); + } + + return npriv; +} + +void rspamd_log_console_dtor(rspamd_logger_t *logger, gpointer arg) +{ + struct rspamd_console_logger_priv *priv = (struct rspamd_console_logger_priv *) arg; + + if (priv->fd != -1) { + if (priv->fd != priv->crit_fd) { + /* Two different FD case */ + if (close(priv->crit_fd) == -1) { + rspamd_fprintf(stderr, "cannot close log crit_fd %d: %s\n", + priv->crit_fd, strerror(errno)); + } + } + + if (close(priv->fd) == -1) { + rspamd_fprintf(stderr, "cannot close log fd %d: %s\n", + priv->fd, strerror(errno)); + } + + /* Avoid the next if to be executed as crit_fd is equal to fd */ + priv->crit_fd = -1; + } + + if (priv->crit_fd != -1) { + if (close(priv->crit_fd) == -1) { + rspamd_fprintf(stderr, "cannot close log crit_fd %d: %s\n", + priv->crit_fd, strerror(errno)); + } + } + + g_free(priv); +} + +bool rspamd_log_console_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_console_logger_priv *priv = (struct rspamd_console_logger_priv *) arg; + gint fd, r; + double now; + + if (level_flags & G_LOG_LEVEL_CRITICAL) { + fd = priv->crit_fd; + } + else { + /* Use stderr if we are in rspamadm mode and severity is more than WARNING */ + if ((rspamd_log->flags & RSPAMD_LOG_FLAG_RSPAMADM) && (level_flags & G_LOG_LEVEL_WARNING)) { + fd = priv->crit_fd; + } + else { + fd = priv->fd; + } + } + +#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 + + now = rspamd_get_calendar_ticks(); + + struct rspamd_logger_iov_ctx iov_ctx; + memset(&iov_ctx, 0, sizeof(iov_ctx)); + rspamd_log_fill_iov(&iov_ctx, now, module, id, + function, level_flags, message, + mlen, rspamd_log); + +again: + r = writev(fd, iov_ctx.iov, iov_ctx.niov); + + if (r == -1) { + if (errno == EAGAIN || errno == EINTR) { + goto again; + } + + if (rspamd_log->mtx) { + rspamd_mempool_unlock_mutex(rspamd_log->mtx); + } + else { + rspamd_file_unlock(fd, FALSE); + } + + rspamd_log_iov_free(&iov_ctx); + return false; + } + + if (rspamd_log->mtx) { + rspamd_mempool_unlock_mutex(rspamd_log->mtx); + } + else { + rspamd_file_unlock(fd, FALSE); + } + + rspamd_log_iov_free(&iov_ctx); + return true; +}
\ No newline at end of file diff --git a/src/libserver/logger/logger_file.c b/src/libserver/logger/logger_file.c new file mode 100644 index 0000000..20b04b8 --- /dev/null +++ b/src/libserver/logger/logger_file.c @@ -0,0 +1,510 @@ +/* + * Copyright 2023 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") + +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; + gboolean log_severity; + 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; +}; + +/** + * 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 bool +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) +{ + 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) { + 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 */ + return direct_write_log_line(rspamd_log, priv, data, count, is_iov, level_flags); + } + + 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; + } + + return false; + } + else if (priv->throttling) { + priv->throttling = FALSE; + } + + return true; +} + +/** + * 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; + } +} + +static void +rspamd_log_flush(rspamd_logger_t *rspamd_log, struct rspamd_file_logger_priv *priv) +{ + if (priv->is_buffered) { + direct_write_log_line(rspamd_log, + priv, + priv->io_buf.buf, + priv->io_buf.used, + FALSE, + rspamd_log->log_level); + priv->io_buf.used = 0; + } +} + +/* + * Write message to buffer or to file (using direct_write_log_line function) + */ +static bool +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 */ + return 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, priv); + return 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, priv); + fill_buffer(rspamd_log, priv, iov, iovcnt); + } + else { + /* Copy incoming string to buffer */ + fill_buffer(rspamd_log, priv, iov, iovcnt); + } + } + + return true; +} + +static void +rspamd_log_reset_repeated(rspamd_logger_t *rspamd_log, + struct rspamd_file_logger_priv *priv) +{ + gchar tmpbuf[256]; + gssize r; + + 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); + rspamd_log_flush(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->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->log_severity = (logger->flags & RSPAMD_LOG_FLAG_SEVERITY); + 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); + rspamd_log_flush(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); +} + +bool 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; + gdouble now; + guint64 cksum; + gboolean got_time = FALSE; + + + if (!(level_flags & RSPAMD_LOG_FORCED) && !rspamd_log->enabled) { + return false; + } + + /* 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 false; + } + } + + /* 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 true; + } + else if (priv->repeats > REPEATS_MAX) { + rspamd_log_reset_repeated(rspamd_log, priv); + + bool ret = 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 ret; + } + } + 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); + return rspamd_log_file_log(module, id, + function, + level_flags, + message, + mlen, + rspamd_log, + arg); + } + else { + priv->repeats = 0; + } + } + if (!got_time) { + now = rspamd_get_calendar_ticks(); + } + + struct rspamd_logger_iov_ctx iov_ctx; + memset(&iov_ctx, 0, sizeof(iov_ctx)); + rspamd_log_fill_iov(&iov_ctx, now, module, id, function, level_flags, message, + mlen, rspamd_log); + + bool ret = file_log_helper(rspamd_log, priv, iov_ctx.iov, iov_ctx.niov, level_flags); + rspamd_log_iov_free(&iov_ctx); + + return ret; +} + +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; +} + +bool rspamd_log_file_on_fork(rspamd_logger_t *logger, struct rspamd_config *cfg, + gpointer arg, GError **err) +{ + struct rspamd_file_logger_priv *priv = (struct rspamd_file_logger_priv *) arg; + + rspamd_log_reset_repeated(logger, priv); + rspamd_log_flush(logger, priv); + + return true; +}
\ No newline at end of file diff --git a/src/libserver/logger/logger_private.h b/src/libserver/logger/logger_private.h new file mode 100644 index 0000000..234a207 --- /dev/null +++ b/src/libserver/logger/logger_private.h @@ -0,0 +1,218 @@ +/* + * Copyright 2023 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 + +#include "logger.h" + +/* How much message should be repeated before it is count to be repeated one */ +#define REPEATS_MIN 3 +#define REPEATS_MAX 300 +#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[RSPAMD_LOG_ID_LEN + 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_level; + + struct rspamd_logger_error_log *errlog; + struct rspamd_cryptobox_pubkey *pk; + struct rspamd_cryptobox_keypair *keypair; + + guint flags; + gboolean closed; + gboolean enabled; + gboolean is_debug; + gboolean no_lock; + + pid_t pid; + const gchar *process_type; + struct rspamd_radix_map_helper *debug_ip; + rspamd_mempool_mutex_t *mtx; + rspamd_mempool_t *pool; + guint64 log_cnt[4]; +}; + +/* + * 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); +bool 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); +bool rspamd_log_file_on_fork(rspamd_logger_t *logger, struct rspamd_config *cfg, + gpointer arg, GError **err); + +struct rspamd_logger_iov_thrash_stack { + struct rspamd_logger_iov_thrash_stack *prev; + char data[0]; +}; +#define RSPAMD_LOGGER_MAX_IOV 8 +struct rspamd_logger_iov_ctx { + struct iovec iov[RSPAMD_LOGGER_MAX_IOV]; + int niov; + struct rspamd_logger_iov_thrash_stack *thrash_stack; +}; +/** + * Fills IOV of logger (usable for file/console logging) + * Warning: this function is NOT reentrant, do not call it twice from a single moment of execution + * @param iov filled by this function + * @param module + * @param id + * @param function + * @param level_flags + * @param message + * @param mlen + * @param rspamd_log + * @return number of iov elements being filled + */ +void rspamd_log_fill_iov(struct rspamd_logger_iov_ctx *iov_ctx, + double ts, + const gchar *module, const gchar *id, + const gchar *function, + gint level_flags, + const gchar *message, + gsize mlen, + rspamd_logger_t *rspamd_log); + +/** + * Frees IOV context + * @param iov_ctx + */ +void rspamd_log_iov_free(struct rspamd_logger_iov_ctx *iov_ctx); +/** + * Escape log line by replacing unprintable characters to hex escapes like \xNN + * @param src + * @param srclen + * @param dst + * @param dstlen + * @return end of the escaped buffer + */ +gchar *rspamd_log_line_hex_escape(const guchar *src, gsize srclen, + gchar *dst, gsize dstlen); +/** + * Returns number of characters to be escaped, e.g. a caller can allocate a new buffer + * the desired number of characters + * @param src + * @param srclen + * @return number of characters to be escaped + */ +gsize rspamd_log_line_need_escape(const guchar *src, gsize srclen); + +static const 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, + .on_fork = rspamd_log_file_on_fork, +}; + +/* + * Syslog logging + */ +void *rspamd_log_syslog_init(rspamd_logger_t *logger, struct rspamd_config *cfg, + uid_t uid, gid_t gid, GError **err); +void *rspamd_log_syslog_reload(rspamd_logger_t *logger, struct rspamd_config *cfg, + gpointer arg, uid_t uid, gid_t gid, GError **err); +void rspamd_log_syslog_dtor(rspamd_logger_t *logger, gpointer arg); +bool rspamd_log_syslog_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); + +static const struct rspamd_logger_funcs syslog_log_funcs = { + .init = rspamd_log_syslog_init, + .dtor = rspamd_log_syslog_dtor, + .reload = rspamd_log_syslog_reload, + .log = rspamd_log_syslog_log, + .on_fork = NULL, +}; + +/* + * Console logging + */ +void *rspamd_log_console_init(rspamd_logger_t *logger, struct rspamd_config *cfg, + uid_t uid, gid_t gid, GError **err); +void *rspamd_log_console_reload(rspamd_logger_t *logger, struct rspamd_config *cfg, + gpointer arg, uid_t uid, gid_t gid, GError **err); +void rspamd_log_console_dtor(rspamd_logger_t *logger, gpointer arg); +bool rspamd_log_console_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); + +static const struct rspamd_logger_funcs console_log_funcs = { + .init = rspamd_log_console_init, + .dtor = rspamd_log_console_dtor, + .reload = rspamd_log_console_reload, + .log = rspamd_log_console_log, + .on_fork = NULL, +}; + +#endif diff --git a/src/libserver/logger/logger_syslog.c b/src/libserver/logger/logger_syslog.c new file mode 100644 index 0000000..3c4f7f7 --- /dev/null +++ b/src/libserver/logger/logger_syslog.c @@ -0,0 +1,143 @@ +/*- + * 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 "logger_private.h" + +#define SYSLOG_LOG_QUARK g_quark_from_static_string("syslog_logger") + +struct rspamd_syslog_logger_priv { + gint log_facility; +}; + +#ifdef HAVE_SYSLOG_H +#include <syslog.h> + +void * +rspamd_log_syslog_init(rspamd_logger_t *logger, struct rspamd_config *cfg, + uid_t uid, gid_t gid, GError **err) +{ + struct rspamd_syslog_logger_priv *priv; + + if (!cfg) { + g_set_error(err, SYSLOG_LOG_QUARK, EINVAL, + "no log config specified"); + return NULL; + } + + priv = g_malloc0(sizeof(*priv)); + + priv->log_facility = cfg->log_facility; + openlog("rspamd", LOG_NDELAY | LOG_PID, priv->log_facility); + + return priv; +} + +void rspamd_log_syslog_dtor(rspamd_logger_t *logger, gpointer arg) +{ + struct rspamd_syslog_logger_priv *priv = (struct rspamd_syslog_logger_priv *) arg; + + closelog(); + g_free(priv); +} +bool rspamd_log_syslog_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) +{ + static const struct { + GLogLevelFlags glib_level; + gint syslog_level; + } levels_match[] = { + {G_LOG_LEVEL_DEBUG, LOG_DEBUG}, + {G_LOG_LEVEL_INFO, LOG_INFO}, + {G_LOG_LEVEL_WARNING, LOG_WARNING}, + {G_LOG_LEVEL_CRITICAL, LOG_ERR}}; + unsigned i; + gint syslog_level; + + if (!(level_flags & RSPAMD_LOG_FORCED) && !rspamd_log->enabled) { + return false; + } + + /* Detect level */ + syslog_level = LOG_DEBUG; + + for (i = 0; i < G_N_ELEMENTS(levels_match); i++) { + if (level_flags & levels_match[i].glib_level) { + syslog_level = levels_match[i].syslog_level; + break; + } + } + + syslog(syslog_level, "<%.*s>; %s; %s: %.*s", + RSPAMD_LOG_ID_LEN, id != NULL ? id : "", + module != NULL ? module : "", + function != NULL ? function : "", + (gint) mlen, message); + + return true; +} + +#else + +void * +rspamd_log_syslog_init(rspamd_logger_t *logger, struct rspamd_config *cfg, + uid_t uid, gid_t gid, GError **err) +{ + g_set_error(err, SYSLOG_LOG_QUARK, EINVAL, "syslog support is not compiled in"); + + return NULL; +} + +bool rspamd_log_syslog_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) +{ + return false; +} + +void rspamd_log_syslog_dtor(rspamd_logger_t *logger, gpointer arg) +{ + /* Left blank intentionally */ +} + +#endif + +void * +rspamd_log_syslog_reload(rspamd_logger_t *logger, struct rspamd_config *cfg, + gpointer arg, uid_t uid, gid_t gid, GError **err) +{ + struct rspamd_syslog_logger_priv *npriv; + + npriv = rspamd_log_syslog_init(logger, cfg, uid, gid, err); + + if (npriv) { + /* Close old */ + rspamd_log_syslog_dtor(logger, arg); + } + + return npriv; +} |