diff options
author | Vsevolod Stakhov <vsevolod@rspamd.com> | 2023-10-30 17:19:02 +0000 |
---|---|---|
committer | GitHub <noreply@github.com> | 2023-10-30 17:19:02 +0000 |
commit | bfa09768e54ffe92d330d4c095c6002fa4a36db4 (patch) | |
tree | 2ea990c6f8c7e5cf495cd6501f0e36b1fa183eef /src | |
parent | be7504e39329d94f1fae1fbeca36906cfcd12a7c (diff) | |
parent | e50a30ca356d1d0ac4398d672853cf74707a93d4 (diff) | |
download | rspamd-bfa09768e54ffe92d330d4c095c6002fa4a36db4.tar.gz rspamd-bfa09768e54ffe92d330d4c095c6002fa4a36db4.zip |
Merge pull request #4674 from rspamd/log_json
[Project] Support of JSON logging
Diffstat (limited to 'src')
-rw-r--r-- | src/libserver/cfg_file.h | 17 | ||||
-rw-r--r-- | src/libserver/cfg_rcl.cxx | 5 | ||||
-rw-r--r-- | src/libserver/logger/logger.c | 395 | ||||
-rw-r--r-- | src/libserver/logger/logger_console.c | 37 | ||||
-rw-r--r-- | src/libserver/logger/logger_file.c | 12 | ||||
-rw-r--r-- | src/libserver/logger/logger_private.h | 34 |
6 files changed, 329 insertions, 171 deletions
diff --git a/src/libserver/cfg_file.h b/src/libserver/cfg_file.h index 4e432af60..22f754938 100644 --- a/src/libserver/cfg_file.h +++ b/src/libserver/cfg_file.h @@ -59,14 +59,15 @@ enum rspamd_log_type { }; enum rspamd_log_cfg_flags { - RSPAMD_LOG_FLAG_DEFAULT = 0, - RSPAMD_LOG_FLAG_SYSTEMD = (1 << 0), - RSPAMD_LOG_FLAG_COLOR = (1 << 1), - RSPAMD_LOG_FLAG_RE_CACHE = (1 << 2), - RSPAMD_LOG_FLAG_USEC = (1 << 3), - RSPAMD_LOG_FLAG_RSPAMADM = (1 << 4), - RSPAMD_LOG_FLAG_ENFORCED = (1 << 5), - RSPAMD_LOG_FLAG_SEVERITY = (1 << 6), + RSPAMD_LOG_FLAG_DEFAULT = 0u, + RSPAMD_LOG_FLAG_SYSTEMD = (1u << 0u), + RSPAMD_LOG_FLAG_COLOR = (1u << 1u), + RSPAMD_LOG_FLAG_RE_CACHE = (1u << 2u), + RSPAMD_LOG_FLAG_USEC = (1u << 3u), + RSPAMD_LOG_FLAG_RSPAMADM = (1u << 4u), + RSPAMD_LOG_FLAG_ENFORCED = (1u << 5u), + RSPAMD_LOG_FLAG_SEVERITY = (1u << 6u), + RSPAMD_LOG_FLAG_JSON = (1u << 7u), }; struct rspamd_worker_log_pipe { diff --git a/src/libserver/cfg_rcl.cxx b/src/libserver/cfg_rcl.cxx index e7828ff90..3f6ca2c56 100644 --- a/src/libserver/cfg_rcl.cxx +++ b/src/libserver/cfg_rcl.cxx @@ -283,6 +283,11 @@ rspamd_rcl_logging_handler(rspamd_mempool_t *pool, const ucl_object_t *obj, cfg->log_flags |= RSPAMD_LOG_FLAG_SYSTEMD; } + val = ucl_object_lookup_any(obj, "json", "log_json", nullptr); + if (val && ucl_object_toboolean(val)) { + cfg->log_flags |= RSPAMD_LOG_FLAG_JSON; + } + val = ucl_object_lookup(obj, "log_re_cache"); if (val && ucl_object_toboolean(val)) { cfg->log_flags |= RSPAMD_LOG_FLAG_RE_CACHE; diff --git a/src/libserver/logger/logger.c b/src/libserver/logger/logger.c index 9b9d302f2..e10dfd392 100644 --- a/src/libserver/logger/logger.c +++ b/src/libserver/logger/logger.c @@ -1028,173 +1028,312 @@ log_time(gdouble now, rspamd_logger_t *rspamd_log, gchar *timebuf, } } -gsize rspamd_log_fill_iov(struct iovec *iov, - double ts, - const gchar *module, - const gchar *id, - const gchar *function, - gint level_flags, - const gchar *message, - gsize mlen, - rspamd_logger_t *logger) +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; + } - gint r; + glong r; - if (iov == NULL) { - if (log_rspamadm) { - if (logger->log_level == G_LOG_LEVEL_DEBUG) { - return 4; + if (iov_ctx->niov == 0) { + /* This is the case when we just return a number of IOV required for the logging */ + if (log_json) { + iov_ctx->niov = 3; /* Preamble, message, "}\n" */ + } + else { + if (log_rspamadm) { + if (logger->log_level == G_LOG_LEVEL_DEBUG) { + iov_ctx->niov = 4; + } + else { + iov_ctx->niov = 3; /* No time component */ + } + } + else if (log_systemd) { + iov_ctx->niov = 3; } else { - return 3; /* No time component */ + if (log_color) { + iov_ctx->niov = 5; + } + else { + iov_ctx->niov = 4; + } } } - else if (log_systemd) { - return 3; + + g_assert(iov_ctx->niov <= G_N_ELEMENTS(iov_ctx->iov)); + } + + 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 { - if (log_color) { - return 5; + /* 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; + } } - else { - return 4; + + + 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; } - else { - static gchar timebuf[64], modulebuf[64]; - static gchar tmpbuf[256]; - + else if (G_LIKELY(!log_rspamadm)) { if (!log_systemd) { - log_time(ts, logger, timebuf, sizeof(timebuf)); - } - - if (!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; - } + 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 { - r = 0; + else if (level_flags & G_LOG_LEVEL_WARNING) { + /* Magenta */ + r = rspamd_snprintf(tmpbuf, sizeof(tmpbuf), "\033[0;32m"); } - - 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 if (level_flags & G_LOG_LEVEL_CRITICAL) { + /* Red */ + r = rspamd_snprintf(tmpbuf, sizeof(tmpbuf), "\033[1;31m"); } else { - r += rspamd_snprintf(tmpbuf + r, - sizeof(tmpbuf) - r, - "%s #%P(%s) ", - timebuf, - logger->pid, - logger->process_type); + r = 0; } } else { r = 0; + } + + if (log_severity) { r += rspamd_snprintf(tmpbuf + r, sizeof(tmpbuf) - r, - "(%s) ", + "%s [%s] #%P(%s) ", + timebuf, + rspamd_get_log_severity_string(level_flags), + logger->pid, logger->process_type); } - - int 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) = ' '; + 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); + } - /* 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 (log_color) { - iov[4].iov_base = "\033[0m"; - iov[4].iov_len = sizeof("\033[0m") - 1; + glong mremain, mr; + char *m; - return 5; - } + modulebuf[0] = '\0'; + mremain = sizeof(modulebuf); + m = modulebuf; - return 4; + 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 { - /* Rspamadm case */ - int niov = 0; - - if (logger->log_level == G_LOG_LEVEL_DEBUG) { - iov[niov].iov_base = (void *) timebuf; - iov[niov++].iov_len = strlen(timebuf); - iov[niov].iov_base = (void *) " "; - iov[niov++].iov_len = 1; - } + mr = rspamd_snprintf(m, mremain, ": "); + m += mr; + mremain -= mr; + } - iov[niov].iov_base = (void *) message; - iov[niov++].iov_len = mlen; - iov[niov].iov_base = (void *) &lf_chr; - iov[niov++].iov_len = 1; + /* Ensure that we have a space at the end */ + if (m > modulebuf && *(m - 1) != ' ') { + *(m - 1) = ' '; + } - return niov; + /* 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; + + if (log_color) { + iov_ctx->iov[4].iov_base = "\033[0m"; + iov_ctx->iov[4].iov_len = sizeof("\033[0m") - 1; } } + 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; + } +} + +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 index 691566ab9..7f3c7708f 100644 --- a/src/libserver/logger/logger_console.c +++ b/src/libserver/logger/logger_console.c @@ -28,10 +28,6 @@ static const gchar lf_chr = '\n'; struct rspamd_console_logger_priv { gint fd; gint crit_fd; - gboolean log_severity; - gboolean log_color; - gboolean log_rspamadm; - gboolean log_tty; }; /* Copy & paste :( */ @@ -63,11 +59,8 @@ rspamd_log_console_init(rspamd_logger_t *logger, struct rspamd_config *cfg, struct rspamd_console_logger_priv *priv; priv = g_malloc0(sizeof(*priv)); - priv->log_color = (logger->flags & RSPAMD_LOG_FLAG_COLOR); - priv->log_severity = (logger->flags & RSPAMD_LOG_FLAG_SEVERITY); - priv->log_rspamadm = (logger->flags & RSPAMD_LOG_FLAG_RSPAMADM); - if (priv->log_rspamadm) { + if (logger->flags & RSPAMD_LOG_FLAG_RSPAMADM) { priv->fd = dup(STDOUT_FILENO); priv->crit_fd = dup(STDERR_FILENO); } @@ -85,12 +78,11 @@ rspamd_log_console_init(rspamd_logger_t *logger, struct rspamd_config *cfg, return NULL; } - if (isatty(priv->fd)) { - priv->log_tty = true; - } - else if (priv->log_color) { - /* Disable colors for not a tty */ - priv->log_color = false; + 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; @@ -160,7 +152,8 @@ bool rspamd_log_console_log(const gchar *module, const gchar *id, fd = priv->crit_fd; } else { - if (priv->log_rspamadm && (level_flags & G_LOG_LEVEL_WARNING)) { + /* 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 { @@ -180,15 +173,15 @@ bool rspamd_log_console_log(const gchar *module, const gchar *id, #endif now = rspamd_get_calendar_ticks(); - gsize niov = rspamd_log_fill_iov(NULL, now, module, id, - function, level_flags, message, - mlen, rspamd_log); - struct iovec *iov = g_alloca(sizeof(struct iovec) * niov); - rspamd_log_fill_iov(iov, now, module, id, function, level_flags, message, + + 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, niov); + r = writev(fd, iov_ctx.iov, iov_ctx.niov); if (r == -1) { if (errno == EAGAIN || errno == EINTR) { @@ -202,6 +195,7 @@ again: rspamd_file_unlock(fd, FALSE); } + rspamd_log_iov_free(&iov_ctx); return false; } @@ -212,5 +206,6 @@ again: 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 index 490cf0b65..20b04b852 100644 --- a/src/libserver/logger/logger_file.c +++ b/src/libserver/logger/logger_file.c @@ -465,13 +465,15 @@ bool rspamd_log_file_log(const gchar *module, const gchar *id, now = rspamd_get_calendar_ticks(); } - gsize niov = rspamd_log_fill_iov(NULL, now, module, id, function, level_flags, message, - mlen, rspamd_log); - struct iovec *iov = g_alloca(sizeof(struct iovec) * niov); - rspamd_log_fill_iov(iov, now, module, id, function, level_flags, message, + 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); - return file_log_helper(rspamd_log, priv, iov, niov, level_flags); + 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 * diff --git a/src/libserver/logger/logger_private.h b/src/libserver/logger/logger_private.h index 138f8df91..234a207e5 100644 --- a/src/libserver/logger/logger_private.h +++ b/src/libserver/logger/logger_private.h @@ -103,10 +103,20 @@ bool rspamd_log_file_log(const gchar *module, const gchar *id, 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 if NULL just returns the number of elements required in IOV array + * @param iov filled by this function * @param module * @param id * @param function @@ -116,14 +126,20 @@ bool rspamd_log_file_on_fork(rspamd_logger_t *logger, struct rspamd_config *cfg, * @param rspamd_log * @return number of iov elements being filled */ -gsize rspamd_log_fill_iov(struct iovec *iov, - double ts, - const gchar *module, const gchar *id, - const gchar *function, - gint level_flags, - const gchar *message, - gsize mlen, - rspamd_logger_t *rspamd_log); +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 |