[Feature] Allow to have high precision timestamps in logs

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;

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

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