mirrors
/
rspamd
spogulis no https://github.com/vstakhov/rspamd.git
Vērot 1
Pievienot zvaigznīti 0
Atdalīts 0
Kods Problēmas 0 Laidieni 159 Vikivietne Aktivitāte
Pārlūkot izejas kodu

[Rework] Start logger rework

tags/2.4
Vsevolod Stakhov pirms 4 gadiem
vecāks
5e70c5980c
revīzija
adef14349a
5 mainītis faili ar 726 papildinājumiem un 732 dzēšanām
Dalītais skats Rādīt salīdzināšanas statistiku
  1. 1
    0
      src/libutil/CMakeLists.txt
  2. 4
    723
      src/libutil/logger.c
  3. 24
    9
      src/libutil/logger.h
  4. 588
    0
      src/libutil/logger_file.c
  5. 109
    0
      src/libutil/logger_private.h

+ 1
- 0
src/libutil/CMakeLists.txt Parādīt failu

@@ -11,6 +11,7 @@ SET(LIBRSPAMDUTILSRC
${CMAKE_CURRENT_SOURCE_DIR}/http_router.c
${CMAKE_CURRENT_SOURCE_DIR}/http_context.c
${CMAKE_CURRENT_SOURCE_DIR}/logger.c
${CMAKE_CURRENT_SOURCE_DIR}/logger_file.c
${CMAKE_CURRENT_SOURCE_DIR}/map.c
${CMAKE_CURRENT_SOURCE_DIR}/map_helpers.c
${CMAKE_CURRENT_SOURCE_DIR}/mem_pool.c

+ 4
- 723
src/libutil/logger.c Parādīt failu

@@ -20,288 +20,22 @@
#include "map_helpers.h"
#include "ottery.h"
#include "unix-std.h"
#include "logger_private.h"

#ifdef HAVE_SYSLOG_H
#include <syslog.h>
#endif

/* How much message should be repeated before it is count to be repeated one */
#define REPEATS_MIN 3
#define REPEATS_MAX 300
#define LOG_ID 6
#define LOGBUF_LEN 8192

struct rspamd_log_module {
gchar *mname;
guint id;
};

struct rspamd_log_modules {
guchar *bitset;
guint bitset_len; /* Number of BITS used in bitset */
guint bitset_allocated; /* Size of bitset allocated in BYTES */
GHashTable *modules;
};

struct rspamd_logger_error_elt {
gint completed;
GQuark ptype;
pid_t pid;
gdouble ts;
gchar id[LOG_ID + 1];
gchar module[9];
gchar message[];
};

struct rspamd_logger_error_log {
struct rspamd_logger_error_elt *elts;
rspamd_mempool_t *pool;
guint32 max_elts;
guint32 elt_len;
/* Avoid false cache sharing */
guchar __padding[64 - sizeof(gpointer) * 2 - sizeof(guint64)];
guint cur_row;
};

/**
* Static structure that store logging parameters
* It is NOT shared between processes and is created by main process
*/
struct rspamd_logger_s {
rspamd_log_func_t log_func;
gpointer log_arg;
enum rspamd_log_type log_type;
gint log_facility;
gint log_level;
gchar *log_file;
gboolean log_buffered;
gboolean log_silent_workers;
guint32 log_buf_size;

struct rspamd_logger_error_log *errlog;
struct rspamd_cryptobox_pubkey *pk;
struct rspamd_cryptobox_keypair *keypair;
struct {
guint32 size;
guint32 used;
u_char *buf;
} io_buf;
gint fd;
guint flags;
gboolean is_buffered;
gboolean enabled;
gboolean is_debug;
gboolean throttling;
gboolean no_lock;
gboolean opened;
time_t throttling_time;
enum rspamd_log_type type;
pid_t pid;
guint32 repeats;
GQuark process_type;
struct rspamd_radix_map_helper *debug_ip;
guint64 last_line_cksum;
gchar *saved_message;
gsize saved_mlen;
gchar *saved_function;
gchar *saved_module;
gchar *saved_id;
rspamd_mempool_mutex_t *mtx;
guint saved_loglevel;
guint64 log_cnt[4];
};

static const gchar lf_chr = '\n';

static rspamd_logger_t *default_logger = NULL;
static struct rspamd_log_modules *log_modules = NULL;

static void syslog_log_function (const gchar *module,
const gchar *id, const gchar *function,
gint log_level, const gchar *message, gsize mlen,
rspamd_logger_t *logger,
gpointer arg);

static void file_log_function (const gchar *module,
const gchar *id, const gchar *function,
gint log_level, const gchar *message, gsize mlen,
rspamd_logger_t *logger,
gpointer arg);

guint rspamd_task_log_id = (guint)-1;
RSPAMD_CONSTRUCTOR(rspamd_task_log_init)
{
rspamd_task_log_id = rspamd_logger_add_debug_module("task");
}

/**
* Calculate checksum for log line (used for repeating logic)
*/
static inline guint64
rspamd_log_calculate_cksum (const gchar *message, size_t mlen)
{
return rspamd_cryptobox_fast_hash (message, mlen, rspamd_hash_seed ());
}

/*
* Write a line to log file (unbuffered)
*/
static void
direct_write_log_line (rspamd_logger_t *rspamd_log,
void *data,
gsize count,
gboolean is_iov,
gint level_flags)
{
gchar errmsg[128];
struct iovec *iov;
const gchar *line;
glong r;
gint fd;
gboolean locked = FALSE;

iov = (struct iovec *) data;

if (rspamd_log->type == RSPAMD_LOG_CONSOLE) {

if (rspamd_log->flags & RSPAMD_LOG_FLAG_RSPAMADM) {
fd = STDOUT_FILENO;

if (level_flags & G_LOG_LEVEL_CRITICAL) {
fd = STDERR_FILENO;
}
}
else {
fd = rspamd_log->fd;
}
}
else {
fd = rspamd_log->fd;
}

if (!rspamd_log->no_lock) {
gsize tlen;

if (is_iov) {
tlen = 0;

for (guint i = 0; i < count; i ++) {
tlen += iov[i].iov_len;
}
}
else {
tlen = count;
}

if (tlen > PIPE_BUF || rspamd_log->flags & RSPAMD_LOG_FLAG_TTY) {
locked = TRUE;

#ifndef DISABLE_PTHREAD_MUTEX
if (rspamd_log->mtx) {
rspamd_mempool_lock_mutex (rspamd_log->mtx);
}
else {
rspamd_file_lock (fd, FALSE);
}
#else
rspamd_file_lock (fd, FALSE);
#endif
}
}

if (is_iov) {
r = writev (fd, iov, count);
}
else {
line = (const gchar *) data;
r = write (fd, line, count);
}

if (locked) {
#ifndef DISABLE_PTHREAD_MUTEX
if (rspamd_log->mtx) {
rspamd_mempool_unlock_mutex (rspamd_log->mtx);
}
else {
rspamd_file_unlock (fd, FALSE);
}
#else
rspamd_file_unlock (fd, FALSE);
#endif
}

if (r == -1) {
/* We cannot write message to file, so we need to detect error and make decision */
if (errno == EINTR) {
/* Try again */
direct_write_log_line (rspamd_log, data, count, is_iov, level_flags);
return;
}

r = rspamd_snprintf (errmsg,
sizeof (errmsg),
"direct_write_log_line: cannot write log line: %s",
strerror (errno));
if (errno == EFAULT || errno == EINVAL || errno == EFBIG ||
errno == ENOSPC) {
/* Rare case */
rspamd_log->throttling = TRUE;
rspamd_log->throttling_time = time (NULL);
}
else if (errno == EPIPE || errno == EBADF) {
/* We write to some pipe and it disappears, disable logging or we has opened bad file descriptor */
rspamd_log->enabled = FALSE;
}
}
else if (rspamd_log->throttling) {
rspamd_log->throttling = FALSE;
}
}

static void
rspamd_escape_log_string (gchar *str)
{
guchar *p = (guchar *) str;

while (*p) {
if ((*p & 0x80) || !g_ascii_isprint (*p)) {
*p = '?';
}
else if (*p == '\n' || *p == '\r') {
*p = ' ';
}
p++;
}
}

gint
rspamd_try_open_log_fd (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid)
{
gint fd;

fd = open (rspamd_log->log_file,
O_CREAT | O_WRONLY | O_APPEND,
S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH);
if (fd == -1) {
fprintf (stderr,
"open_log: cannot open desired log file: %s, %s\n",
rspamd_log->log_file, strerror (errno));
return -1;
}

if (uid != -1 || gid != -1) {
if (fchown (fd, uid, gid) == -1) {
fprintf (stderr,
"open_log: cannot chown desired log file: %s, %s\n",
rspamd_log->log_file, strerror (errno));
close (fd);

return -1;
}
}

return fd;
}

/* Logging utility functions */
gint
@@ -378,53 +112,6 @@ rspamd_log_open_priv (rspamd_logger_t *rspamd_log, uid_t uid, gid_t gid)
return 0;
}

static void
rspamd_log_reset_repeated (rspamd_logger_t *rspamd_log)
{
gchar tmpbuf[256];
gssize r;

if (rspamd_log->opened) {
if (rspamd_log->type == RSPAMD_LOG_FILE) {
if (rspamd_log->repeats > REPEATS_MIN) {
r = rspamd_snprintf (tmpbuf,
sizeof (tmpbuf),
"Last message repeated %ud times",
rspamd_log->repeats);
rspamd_log->repeats = 0;

if (rspamd_log->saved_message) {
file_log_function (rspamd_log->saved_module,
rspamd_log->saved_id,
rspamd_log->saved_function,
rspamd_log->saved_loglevel | RSPAMD_LOG_FORCED,
rspamd_log->saved_message,
rspamd_log->saved_mlen,
rspamd_log,
rspamd_log->log_arg);

g_free (rspamd_log->saved_message);
g_free (rspamd_log->saved_function);
g_free (rspamd_log->saved_module);
g_free (rspamd_log->saved_id);
rspamd_log->saved_message = NULL;
rspamd_log->saved_function = NULL;
rspamd_log->saved_module = NULL;
rspamd_log->saved_id = NULL;
}

/* It is safe to use temporary buffer here as it is not static */
file_log_function (NULL, NULL,
G_STRFUNC,
rspamd_log->saved_loglevel | RSPAMD_LOG_FORCED,
tmpbuf,
r,
rspamd_log,
rspamd_log->log_arg);
}
}
}
}

void
rspamd_log_close_priv (rspamd_logger_t *rspamd_log, gboolean termination, uid_t uid, gid_t gid)
@@ -611,17 +298,7 @@ rspamd_set_logger (struct rspamd_config *cfg,

logger->flags = cfg->log_flags;

/* Set up buffer */
if (cfg->log_buffered) {
if (cfg->log_buf_size != 0) {
logger->io_buf.size = cfg->log_buf_size;
}
else {
logger->io_buf.size = LOGBUF_LEN;
}
logger->is_buffered = TRUE;
logger->io_buf.buf = g_malloc (logger->io_buf.size);
}

/* Set up conditional logging */
if (cfg->debug_ip_map != NULL) {
/* Try to add it as map first of all */
@@ -932,62 +609,6 @@ rspamd_default_log_function (gint level_flags,
}


/**
* Fill buffer with message (limits must be checked BEFORE this call)
*/
static void
fill_buffer (rspamd_logger_t *rspamd_log, const struct iovec *iov, gint iovcnt)
{
gint i;

for (i = 0; i < iovcnt; i++) {
memcpy (rspamd_log->io_buf.buf + rspamd_log->io_buf.used,
iov[i].iov_base,
iov[i].iov_len);
rspamd_log->io_buf.used += iov[i].iov_len;
}

}

/*
* Write message to buffer or to file (using direct_write_log_line function)
*/
static void
file_log_helper (rspamd_logger_t *rspamd_log,
const struct iovec *iov,
guint iovcnt,
gint level_flags)
{
size_t len = 0;
guint i;

if (!rspamd_log->is_buffered) {
/* Write string directly */
direct_write_log_line (rspamd_log, (void *) iov, iovcnt, TRUE, level_flags);
}
else {
/* Calculate total length */
for (i = 0; i < iovcnt; i++) {
len += iov[i].iov_len;
}
/* Fill buffer */
if (rspamd_log->io_buf.size < len) {
/* Buffer is too small to hold this string, so write it directly */
rspamd_log_flush (rspamd_log);
direct_write_log_line (rspamd_log, (void *) iov, iovcnt, TRUE, level_flags);
}
else if (rspamd_log->io_buf.used + len >= rspamd_log->io_buf.size) {
/* Buffer is full, try to write it directly */
rspamd_log_flush (rspamd_log);
fill_buffer (rspamd_log, iov, iovcnt);
}
else {
/* Copy incoming string to buffer */
fill_buffer (rspamd_log, iov, iovcnt);
}
}
}

/**
* Syslog interface for logging
*/
@@ -1034,343 +655,9 @@ syslog_log_function (const gchar *module, const gchar *id,
#endif
}


static inline void
log_time (gdouble now, rspamd_logger_t *rspamd_log, gchar *timebuf,
size_t len)
{
time_t sec = (time_t)now;
gsize r;
struct tm tms;

rspamd_localtime (sec, &tms);
r = strftime (timebuf, len, "%F %H:%M:%S", &tms);

if (rspamd_log->flags & RSPAMD_LOG_FLAG_USEC) {
gchar usec_buf[16];

rspamd_snprintf (usec_buf, sizeof (usec_buf), "%.5f",
now - (gdouble)sec);
rspamd_snprintf (timebuf + r, len - r,
"%s", usec_buf + 1);
}
}

/**
* Main file interface for logging
*/
static void
file_log_function (const gchar *module, const gchar *id,
const gchar *function,
gint level_flags,
const gchar *message,
gsize mlen,
rspamd_logger_t *rspamd_log,
gpointer arg)
{
static gchar timebuf[64], modulebuf[64];
gchar tmpbuf[256];
gchar *m;
gdouble now;

struct iovec iov[6];
gulong r = 0, mr = 0;
guint64 cksum;
size_t mremain;
const gchar *cptype = NULL;
gboolean got_time = FALSE;

if (!(level_flags & RSPAMD_LOG_FORCED) && !rspamd_log->enabled) {
return;
}

/* Check throttling due to write errors */
if (!(level_flags & RSPAMD_LOG_FORCED) && rspamd_log->throttling) {
now = rspamd_get_calendar_ticks ();
if (rspamd_log->throttling_time != now) {
rspamd_log->throttling_time = now;
got_time = TRUE;
}
else {
/* Do not try to write to file too often while throttling */
return;
}
}

if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_RSPAMADM)) {
/* Check repeats */
cksum = rspamd_log_calculate_cksum (message, mlen);

if (cksum == rspamd_log->last_line_cksum) {
rspamd_log->repeats++;
if (rspamd_log->repeats > REPEATS_MIN && rspamd_log->repeats <
REPEATS_MAX) {
/* Do not log anything */
if (rspamd_log->saved_message == NULL) {
rspamd_log->saved_function = g_strdup (function);
rspamd_log->saved_mlen = mlen;
rspamd_log->saved_message = g_malloc (mlen);
memcpy (rspamd_log->saved_message, message, mlen);

if (module) {
rspamd_log->saved_module = g_strdup (module);
}

if (id) {
rspamd_log->saved_id = g_strdup (id);
}

rspamd_log->saved_loglevel = level_flags;
}

return;
}
else if (rspamd_log->repeats > REPEATS_MAX) {
gssize r = rspamd_snprintf (tmpbuf,
sizeof (tmpbuf),
"Last message repeated %ud times",
rspamd_log->repeats);
rspamd_log->repeats = 0;
/* It is safe to use temporary buffer here as it is not static */
if (rspamd_log->saved_message) {
file_log_function (rspamd_log->saved_module,
rspamd_log->saved_id,
rspamd_log->saved_function,
rspamd_log->saved_loglevel,
rspamd_log->saved_message,
rspamd_log->saved_mlen,
rspamd_log,
arg);

g_free (rspamd_log->saved_message);
g_free (rspamd_log->saved_function);
g_free (rspamd_log->saved_module);
g_free (rspamd_log->saved_id);
rspamd_log->saved_message = NULL;
rspamd_log->saved_function = NULL;
rspamd_log->saved_module = NULL;
rspamd_log->saved_id = NULL;
}

/* Two messages */
file_log_function ("logger", NULL,
G_STRFUNC,
rspamd_log->saved_loglevel,
tmpbuf,
r,
rspamd_log,
arg);

file_log_function (module, id,
function,
level_flags,
message,
mlen,
rspamd_log,
arg);

rspamd_log->repeats = REPEATS_MIN + 1;

return;
}
}
else {
/* Reset counter if new message differs from saved message */
rspamd_log->last_line_cksum = cksum;
if (rspamd_log->repeats > REPEATS_MIN) {
gssize r = rspamd_snprintf (tmpbuf,
sizeof (tmpbuf),
"Last message repeated %ud times",
rspamd_log->repeats);
rspamd_log->repeats = 0;

if (rspamd_log->saved_message) {
file_log_function (rspamd_log->saved_module,
rspamd_log->saved_id,
rspamd_log->saved_function,
rspamd_log->saved_loglevel,
rspamd_log->saved_message,
rspamd_log->saved_mlen,
rspamd_log,
arg);

g_free (rspamd_log->saved_message);
g_free (rspamd_log->saved_function);
g_free (rspamd_log->saved_module);
g_free (rspamd_log->saved_id);
rspamd_log->saved_message = NULL;
rspamd_log->saved_function = NULL;
rspamd_log->saved_module = NULL;
rspamd_log->saved_id = NULL;
}

file_log_function ("logger", NULL,
G_STRFUNC,
level_flags,
tmpbuf,
r,
rspamd_log,
arg);
/* It is safe to use temporary buffer here as it is not static */
file_log_function (module, id,
function,
level_flags,
message,
mlen,
rspamd_log,
arg);
return;
}
else {
rspamd_log->repeats = 0;
}
}
if (!got_time) {
now = rspamd_get_calendar_ticks ();
}

/* Format time */
if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_SYSTEMD)) {
log_time (now, rspamd_log, timebuf, sizeof (timebuf));
}

cptype = g_quark_to_string (rspamd_log->process_type);

if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
if (level_flags & (G_LOG_LEVEL_INFO|G_LOG_LEVEL_MESSAGE)) {
/* White */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;37m");
}
else if (level_flags & G_LOG_LEVEL_WARNING) {
/* Magenta */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;32m");
}
else if (level_flags & G_LOG_LEVEL_CRITICAL) {
/* Red */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[1;31m");
}
}
else {
r = 0;
}

if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_SYSTEMD)) {
r += rspamd_snprintf (tmpbuf + r,
sizeof (tmpbuf) - r,
"%s #%P(%s) ",
timebuf,
rspamd_log->pid,
cptype);
}
else {
r += rspamd_snprintf (tmpbuf + r,
sizeof (tmpbuf) - r,
"(%s) ",
cptype);
}

modulebuf[0] = '\0';
mremain = sizeof (modulebuf);
m = modulebuf;

if (id != NULL) {
guint slen = strlen (id);
slen = MIN (LOG_ID, slen);
mr = rspamd_snprintf (m, mremain, "<%*.s>; ", slen,
id);
m += mr;
mremain -= mr;
}
if (module != NULL) {
mr = rspamd_snprintf (m, mremain, "%s; ", module);
m += mr;
mremain -= mr;
}
if (function != NULL) {
mr = rspamd_snprintf (m, mremain, "%s: ", function);
m += mr;
mremain -= mr;
}
else {
mr = rspamd_snprintf (m, mremain, ": ");
m += mr;
mremain -= mr;
}

/* Construct IOV for log line */
iov[0].iov_base = tmpbuf;
iov[0].iov_len = r;
iov[1].iov_base = modulebuf;
iov[1].iov_len = m - modulebuf;
iov[2].iov_base = (void *) message;
iov[2].iov_len = mlen;
iov[3].iov_base = (void *) &lf_chr;
iov[3].iov_len = 1;

if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
iov[4].iov_base = "\033[0m";
iov[4].iov_len = sizeof ("\033[0m") - 1;
/* Call helper (for buffering) */
file_log_helper (rspamd_log, iov, 5, level_flags);
}
else {
/* Call helper (for buffering) */
file_log_helper (rspamd_log, iov, 4, level_flags);
}
}
else {
/* Rspamadm logging version */

if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
if (level_flags & (G_LOG_LEVEL_INFO|G_LOG_LEVEL_MESSAGE)) {
/* White */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;37m");
}
else if (level_flags & G_LOG_LEVEL_WARNING) {
/* Magenta */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;32m");
}
else if (level_flags & G_LOG_LEVEL_CRITICAL) {
/* Red */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[1;31m");
}

iov[0].iov_base = (void *) tmpbuf;
iov[0].iov_len = r;
r = 1;
}
else {
r = 0;
}


if (rspamd_log->log_level == G_LOG_LEVEL_DEBUG) {
log_time (rspamd_get_calendar_ticks (),
rspamd_log, timebuf, sizeof (timebuf));
iov[r].iov_base = (void *) timebuf;
iov[r++].iov_len = strlen (timebuf);
iov[r].iov_base = (void *) " ";
iov[r++].iov_len = 1;
}

iov[r].iov_base = (void *) message;
iov[r++].iov_len = mlen;
iov[r].iov_base = (void *) &lf_chr;
iov[r++].iov_len = 1;

if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
iov[r].iov_base = "\033[0m";
iov[r++].iov_len = sizeof ("\033[0m") - 1;
/* Call helper (for buffering) */
file_log_helper (rspamd_log, iov, r, level_flags);
}
else {
/* Call helper (for buffering) */
file_log_helper (rspamd_log, iov, r, level_flags);
}
}
}

/**
* Write log line depending on ip
*/
@@ -1707,11 +994,9 @@ rspamd_logger_get_singleton (void)
return default_logger;
}

rspamd_log_func_t
struct rspamd_logger_funcs*
rspamd_logger_set_log_function (rspamd_logger_t *logger,
rspamd_log_func_t nfunc,
gpointer narg,
gpointer *old_arg)
struct rspamd_logger_funcs *nfuncs);
{
if (logger == NULL) {
logger = default_logger;
@@ -1719,10 +1004,6 @@ rspamd_logger_set_log_function (rspamd_logger_t *logger,

g_assert (logger != NULL);

if (old_arg) {
*old_arg = logger->log_arg;
}

rspamd_log_func_t old_func = logger->log_func;

logger->log_func = nfunc;

+ 24
- 9
src/libutil/logger.h Parādīt failu

@@ -29,6 +29,25 @@ typedef void (*rspamd_log_func_t) (const gchar *module, const gchar *id,
gsize mlen,
rspamd_logger_t *logger,
gpointer arg);
typedef void * (*rspamd_log_init_func) (rspamd_logger_t *logger,
struct rspamd_config *cfg,
uid_t uid, gid_t gid,
GError **err);
typedef void* (*rspamd_log_reload_func) (rspamd_logger_t *logger,
struct rspamd_config *cfg,
gpointer arg,
uid_t uid, gid_t gid,
GError **err);
typedef void (*rspamd_log_dtor_func) (rspamd_logger_t *logger,
gpointer arg);

struct rspamd_logger_funcs {
rspamd_log_init_func init;
rspamd_log_reload_func reload;
rspamd_log_dtor_func dtor;
rspamd_log_func_t log;
gpointer specific;
};

#define RSPAMD_LOGBUF_SIZE 8192

@@ -200,17 +219,13 @@ ucl_object_t *rspamd_log_errorbuf_export (const rspamd_logger_t *logger);
rspamd_logger_t *rspamd_logger_get_singleton (void);

/**
* Sets new logging function
* Sets new logger functions and initialise logging if needed
* @param logger
* @param nfunc
* @param narg
* @param old_arg
* @return old log function and old log function arg in (*old_arg)
* @param nfuncs
* @return static pointer to the old functions (so this function is not reentrant)
*/
rspamd_log_func_t rspamd_logger_set_log_function (rspamd_logger_t *logger,
rspamd_log_func_t nfunc,
gpointer narg,
gpointer *old_arg);
struct rspamd_logger_funcs* rspamd_logger_set_log_function (rspamd_logger_t *logger,
struct rspamd_logger_funcs *nfuncs);

/* Typical functions */


+ 588
- 0
src/libutil/logger_file.c Parādīt failu

@@ -0,0 +1,588 @@
/*-
* 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 "libcryptobox/cryptobox.h"
#include "unix-std.h"

#include "logger_private.h"

#define FILE_LOG_QUARK g_quark_from_static_string ("file_logger")

static const gchar lf_chr = '\n';

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;
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;
guint64 log_cnt[4];
};

/**
* 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 ());
}

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);
}
}


/*
* Write a line to log file (unbuffered)
*/
static void
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)
{
gchar errmsg[128];
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 || rspamd_log->flags & RSPAMD_LOG_FLAG_TTY) {
locked = TRUE;

#ifndef DISABLE_PTHREAD_MUTEX
if (rspamd_log->mtx) {
rspamd_mempool_lock_mutex (rspamd_log->mtx);
}
else {
rspamd_file_lock (fd, FALSE);
}
#else
rspamd_file_lock (fd, FALSE);
#endif
}
}

if (is_iov) {
r = writev (fd, iov, count);
}
else {
line = (const gchar *) data;
r = write (fd, line, count);
}

if (locked) {
#ifndef DISABLE_PTHREAD_MUTEX
if (rspamd_log->mtx) {
rspamd_mempool_unlock_mutex (rspamd_log->mtx);
}
else {
rspamd_file_unlock (fd, FALSE);
}
#else
rspamd_file_unlock (fd, FALSE);
#endif
}

if (r == -1) {
/* We cannot write message to file, so we need to detect error and make decision */
if (errno == EINTR) {
/* Try again */
direct_write_log_line (rspamd_log, priv, data, count, is_iov, level_flags);
return;
}

r = rspamd_snprintf (errmsg,
sizeof (errmsg),
"direct_write_log_line: cannot write log line: %s",
strerror (errno));
if (errno == EFAULT || errno == EINVAL || errno == EFBIG ||
errno == ENOSPC) {
/* Rare case */
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;
}
}
else if (priv->throttling) {
priv->throttling = FALSE;
}
}

/**
* 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;
}

}

/*
* Write message to buffer or to file (using direct_write_log_line function)
*/
static void
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 */
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);
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);
fill_buffer (rspamd_log, priv, iov, iovcnt);
}
else {
/* Copy incoming string to buffer */
fill_buffer (rspamd_log, priv, iov, iovcnt);
}
}
}

static void
rspamd_log_reset_repeated (rspamd_logger_t *rspamd_log,
struct rspamd_file_logger_priv *priv)
{
gchar tmpbuf[256];
gssize r;

if (rspamd_log->opened) {
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);
}
}
}

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_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->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);

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);
}

void
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;
static gchar timebuf[64], modulebuf[64];
gchar tmpbuf[256];
gchar *m;
gdouble now;
struct iovec iov[6];
gulong r = 0, mr = 0;
guint64 cksum;
size_t mremain;
const gchar *cptype = NULL;
gboolean got_time = FALSE;


if (!(level_flags & RSPAMD_LOG_FORCED) && !rspamd_log->enabled) {
return;
}

/* Check throttling due to write errors */
if (!(level_flags & RSPAMD_LOG_FORCED) && 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;
}
}

/* 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;
}
else if (priv->repeats > REPEATS_MAX) {
rspamd_log_reset_repeated (rspamd_log, priv);

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;
}
}
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);
rspamd_log_file_log (module, id,
function,
level_flags,
message,
mlen,
rspamd_log,
arg);
return;
}
else {
priv->repeats = 0;
}
}
if (!got_time) {
now = rspamd_get_calendar_ticks ();
}

/* Format time */
if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_SYSTEMD)) {
log_time (now, rspamd_log, timebuf, sizeof (timebuf));
}

cptype = g_quark_to_string (rspamd_log->process_type);

if (rspamd_log->flags & RSPAMD_LOG_FLAG_COLOR) {
if (level_flags & (G_LOG_LEVEL_INFO|G_LOG_LEVEL_MESSAGE)) {
/* White */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;37m");
}
else if (level_flags & G_LOG_LEVEL_WARNING) {
/* Magenta */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[0;32m");
}
else if (level_flags & G_LOG_LEVEL_CRITICAL) {
/* Red */
r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "\033[1;31m");
}
}
else {
r = 0;
}

if (!(rspamd_log->flags & RSPAMD_LOG_FLAG_SYSTEMD)) {
r += rspamd_snprintf (tmpbuf + r,
sizeof (tmpbuf) - r,
"%s #%P(%s) ",
timebuf,
rspamd_log->pid,
cptype);
}
else {
r += rspamd_snprintf (tmpbuf + r,
sizeof (tmpbuf) - r,
"(%s) ",
cptype);
}

modulebuf[0] = '\0';
mremain = sizeof (modulebuf);
m = modulebuf;

if (id != NULL) {
guint slen = strlen (id);
slen = MIN (LOG_ID, slen);
mr = rspamd_snprintf (m, mremain, "<%*.s>; ", slen,
id);
m += mr;
mremain -= mr;
}
if (module != NULL) {
mr = rspamd_snprintf (m, mremain, "%s; ", module);
m += mr;
mremain -= mr;
}
if (function != NULL) {
mr = rspamd_snprintf (m, mremain, "%s: ", function);
m += mr;
mremain -= mr;
}
else {
mr = rspamd_snprintf (m, mremain, ": ");
m += mr;
mremain -= mr;
}

/* Construct IOV for log line */
iov[0].iov_base = tmpbuf;
iov[0].iov_len = r;
iov[1].iov_base = modulebuf;
iov[1].iov_len = m - modulebuf;
iov[2].iov_base = (void *) message;
iov[2].iov_len = mlen;
iov[3].iov_base = (void *) &lf_chr;
iov[3].iov_len = 1;

file_log_helper (rspamd_log, priv, iov, 4, level_flags);
}

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;
}

+ 109
- 0
src/libutil/logger_private.h Parādīt failu

@@ -0,0 +1,109 @@
/*-
* 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.
*/
#ifndef RSPAMD_LOGGER_PRIVATE_H
#define RSPAMD_LOGGER_PRIVATE_H

/* How much message should be repeated before it is count to be repeated one */
#define REPEATS_MIN 3
#define REPEATS_MAX 300
#define LOG_ID 6
#define LOGBUF_LEN 8192

struct rspamd_log_module {
gchar *mname;
guint id;
};

struct rspamd_log_modules {
guchar *bitset;
guint bitset_len; /* Number of BITS used in bitset */
guint bitset_allocated; /* Size of bitset allocated in BYTES */
GHashTable *modules;
};

struct rspamd_logger_error_elt {
gint completed;
GQuark ptype;
pid_t pid;
gdouble ts;
gchar id[LOG_ID + 1];
gchar module[9];
gchar message[];
};

struct rspamd_logger_error_log {
struct rspamd_logger_error_elt *elts;
rspamd_mempool_t *pool;
guint32 max_elts;
guint32 elt_len;
/* Avoid false cache sharing */
guchar __padding[64 - sizeof(gpointer) * 2 - sizeof(guint64)];
guint cur_row;
};

/**
* Static structure that store logging parameters
* It is NOT shared between processes and is created by main process
*/
struct rspamd_logger_s {
struct rspamd_logger_funcs ops;
gint log_facility;
gint log_level;

struct rspamd_logger_error_log *errlog;
struct rspamd_cryptobox_pubkey *pk;
struct rspamd_cryptobox_keypair *keypair;

guint flags;
gboolean enabled;
gboolean is_debug;
gboolean no_lock;
gboolean opened;

pid_t pid;
GQuark process_type;
struct rspamd_radix_map_helper *debug_ip;
rspamd_mempool_mutex_t *mtx;
};

/*
* 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);
void 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);

const static 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,
};

#endif

Rakstīt Priekšskatītījums
Notiek ielāde…
Atcelt
Saglabāt