From 9673734623b8972c86179b2c71ef6d2b353ee07f Mon Sep 17 00:00:00 2001 From: Vsevolod Stakhov Date: Sun, 6 Aug 2017 17:55:22 +0100 Subject: [PATCH] [Feature] Allow to have high precision timestamps in logs --- src/libserver/cfg_file.h | 1 + src/libserver/cfg_rcl.c | 6 ++++++ src/libutil/logger.c | 23 +++++++++++++++++------ 3 files changed, 24 insertions(+), 6 deletions(-) diff --git a/src/libserver/cfg_file.h b/src/libserver/cfg_file.h index 45202f5ab..d96c6e474 100644 --- a/src/libserver/cfg_file.h +++ b/src/libserver/cfg_file.h @@ -334,6 +334,7 @@ struct rspamd_config { gboolean log_extended; /**< log extended information */ gboolean log_systemd; /**< special case for systemd logger */ gboolean log_re_cache; /**< show statistics about regexps */ + gboolean log_usec; /**< log microseconds if possible */ guint log_error_elts; /**< number of elements in error logbuf */ guint log_error_elt_maxlen; /**< maximum size of error log element */ struct rspamd_worker_log_pipe *log_pipes; diff --git a/src/libserver/cfg_rcl.c b/src/libserver/cfg_rcl.c index 596be1cf6..acd108f6c 100644 --- a/src/libserver/cfg_rcl.c +++ b/src/libserver/cfg_rcl.c @@ -1851,6 +1851,12 @@ rspamd_rcl_config_init (struct rspamd_config *cfg) G_STRUCT_OFFSET (struct rspamd_config, log_error_elt_maxlen), RSPAMD_CL_FLAG_UINT, "Size of each element in error log buffer (1000 by default)"); + rspamd_rcl_add_default_handler (sub, + "log_usec", + rspamd_rcl_parse_struct_boolean, + G_STRUCT_OFFSET (struct rspamd_config, log_usec), + 0, + "Use microseconds resolution for timestamps"); /** * Options section */ diff --git a/src/libutil/logger.c b/src/libutil/logger.c index d4e3e95a7..de301cc62 100644 --- a/src/libutil/logger.c +++ b/src/libutil/logger.c @@ -833,9 +833,9 @@ file_log_function (const gchar *module, const gchar *id, const gchar *message, gpointer arg) { - gchar tmpbuf[256], timebuf[32], modulebuf[64]; + gchar tmpbuf[256], timebuf[64], modulebuf[64]; gchar *m; - time_t now; + gdouble now; struct tm *tms; struct iovec iov[5]; gulong r = 0, mr = 0; @@ -851,7 +851,7 @@ file_log_function (const gchar *module, const gchar *id, /* Check throttling due to write errors */ if (!(level_flags & RSPAMD_LOG_FORCED) && rspamd_log->throttling) { - now = time (NULL); + now = rspamd_get_calendar_ticks (); if (rspamd_log->throttling_time != now) { rspamd_log->throttling_time = now; got_time = TRUE; @@ -973,14 +973,25 @@ file_log_function (const gchar *module, const gchar *id, if (rspamd_log->cfg->log_extended) { if (!got_time) { - now = time (NULL); + now = rspamd_get_calendar_ticks (); } /* Format time */ if (!rspamd_log->cfg->log_systemd) { - tms = localtime (&now); + time_t sec = now; + gsize r; - strftime (timebuf, sizeof (timebuf), "%F %H:%M:%S", tms); + tms = localtime (&sec); + r = strftime (timebuf, sizeof (timebuf), "%F %H:%M:%S", tms); + + if (rspamd_log->cfg->log_usec) { + gchar usec_buf[16]; + + rspamd_snprintf (usec_buf, sizeof (usec_buf), "%.5f", + now - (gdouble)sec); + rspamd_snprintf (timebuf + r, sizeof (timebuf) - r, + "%s", usec_buf + 1); + } } cptype = g_quark_to_string (rspamd_log->process_type); -- 2.39.5