log_timestamp setting supports now %{usecs}

This is mainly useful for debugging.

diff --git a/src/lib/failures.c b/src/lib/failures.c
index 249072d259e128aaf55794efd55f61741c70e1f0..5e4e7e6d97d9da75f0f5c48cd2269e76934b0731 100644 (file)
--- a/src/lib/failures.c
+++ b/src/lib/failures.c
@@ -45,7 +45,8 @@ static struct failure_context failure_ctx_error = { .type = LOG_TYPE_ERROR };
 
 static int log_fd = STDERR_FILENO, log_info_fd = STDERR_FILENO,
           log_debug_fd = STDERR_FILENO;
-static char *log_prefix = NULL, *log_stamp_format = NULL;
+static char *log_prefix = NULL;
+static char *log_stamp_format = NULL, *log_stamp_format_suffix = NULL;
 static bool failure_ignore_errors = FALSE, log_prefix_sent = FALSE;
 static bool coredump_on_error = FALSE;
 
@@ -54,12 +55,17 @@ i_internal_error_handler(const struct failure_context *ctx,
                         const char *format, va_list args);
 
 /* kludgy .. we want to trust log_stamp_format with -Wformat-nonliteral */
-static const char *get_log_stamp_format(const char *unused)
+static const char *
+get_log_stamp_format(const char *format_arg, unsigned int timestamp_usecs)
        ATTR_FORMAT_ARG(1);
 
-static const char *get_log_stamp_format(const char *unused ATTR_UNUSED)
+static const char *get_log_stamp_format(const char *format_arg ATTR_UNUSED,
+                                       unsigned int timestamp_usecs)
 {
-       return log_stamp_format;
+       if (log_stamp_format_suffix == NULL)
+               return log_stamp_format;
+       return t_strdup_printf("%s%06u%s", log_stamp_format,
+                              timestamp_usecs, log_stamp_format_suffix);
 }
 
 void failure_exit(int status)
@@ -73,16 +79,19 @@ static void log_prefix_add(const struct failure_context *ctx, string_t *str)
 {
        const struct tm *tm = ctx->timestamp;
        char buf[256];
-       time_t now;
+       struct timeval now;
 
        if (log_stamp_format != NULL) {
                if (tm == NULL) {
-                       now = time(NULL);
-                       tm = localtime(&now);
+                       if (gettimeofday(&now, NULL) < 0)
+                               i_panic("gettimeofday() failed: %m");
+                       tm = localtime(&now.tv_sec);
+               } else {
+                       now.tv_usec = ctx->timestamp_usecs;
                }
 
                if (strftime(buf, sizeof(buf),
-                            get_log_stamp_format("unused"), tm) > 0)
+                            get_log_stamp_format("unused", now.tv_usec), tm) > 0)
                        str_append(str, buf);
        }
        if (log_prefix != NULL)
@@ -702,8 +711,18 @@ void i_set_debug_file(const char *path)
 
 void i_set_failure_timestamp_format(const char *fmt)
 {
+       const char *p;
+
        i_free(log_stamp_format);
-        log_stamp_format = i_strdup(fmt);
+       i_free_and_null(log_stamp_format_suffix);
+
+       p = strstr(fmt, "%{usecs}");
+       if (p == NULL)
+               log_stamp_format = i_strdup(fmt);
+       else T_BEGIN {
+               log_stamp_format = i_strdup_until(fmt, p);
+               log_stamp_format_suffix = i_strdup(p + 8);
+       } T_END;
 }
 
 void i_set_failure_send_ip(const struct ip_addr *ip)
@@ -746,4 +765,5 @@ void failures_deinit(void)
 
        i_free_and_null(log_prefix);
        i_free_and_null(log_stamp_format);
+       i_free_and_null(log_stamp_format_suffix);
 }

diff --git a/src/lib/failures.h b/src/lib/failures.h
index 9861b6eb4bbcd606eb12e95d5968895d0a31547e..014c2142626eaf11be0f52846e012b7ebe2ae556 100644 (file)
--- a/src/lib/failures.h
+++ b/src/lib/failures.h
@@ -36,6 +36,7 @@ struct failure_context {
        enum log_type type;
        int exit_status; /* for LOG_TYPE_FATAL */
        const struct tm *timestamp; /* NULL = use time() + localtime() */
+       unsigned int timestamp_usecs;
 };
 
 #define DEFAULT_FAILURE_STAMP_FORMAT "%b %d %H:%M:%S "

diff --git a/src/log/log-connection.c b/src/log/log-connection.c
index 64faa8d9a490e3ced8a09e8f4182a02a4b4dbcd1..630aec6d8b9fd05685d816681c22f2b318a3df49 100644 (file)
--- a/src/log/log-connection.c
+++ b/src/log/log-connection.c
@@ -81,7 +81,8 @@ static void log_parse_option(struct log_connection *log,
 
 static void
 client_log_ctx(struct log_connection *log,
-              const struct failure_context *ctx, time_t log_time,
+              const struct failure_context *ctx,
+              const struct timeval *log_time,
               const char *prefix, const char *text)
 {
        struct log_error err;
@@ -98,7 +99,7 @@ client_log_ctx(struct log_connection *log,
        case LOG_TYPE_PANIC:
                memset(&err, 0, sizeof(err));
                err.type = ctx->type;
-               err.timestamp = log_time;
+               err.timestamp = log_time->tv_sec;
                err.prefix = prefix;
                err.text = text;
                log_error_buffer_add(log->errorbuf, &err);
@@ -111,7 +112,8 @@ client_log_ctx(struct log_connection *log,
 
 static void
 client_log_fatal(struct log_connection *log, struct log_client *client,
-                const char *line, time_t log_time, const struct tm *tm)
+                const char *line, const struct timeval *log_time,
+                const struct tm *tm)
 {
        struct failure_context failure_ctx;
        const char *prefix = log->default_prefix;
@@ -119,6 +121,7 @@ client_log_fatal(struct log_connection *log, struct log_client *client,
        memset(&failure_ctx, 0, sizeof(failure_ctx));
        failure_ctx.type = LOG_TYPE_FATAL;
        failure_ctx.timestamp = tm;
+       failure_ctx.timestamp_usecs = log_time->tv_usec;
 
        if (client != NULL) {
                if (client->prefix != NULL)
@@ -133,7 +136,8 @@ client_log_fatal(struct log_connection *log, struct log_client *client,
 }
 
 static void
-log_parse_master_line(const char *line, time_t log_time, const struct tm *tm)
+log_parse_master_line(const char *line, const struct timeval *log_time,
+                     const struct tm *tm)
 {
        struct log_connection *const *logs, *log;
        struct log_client *client;
@@ -186,7 +190,7 @@ log_parse_master_line(const char *line, time_t log_time, const struct tm *tm)
 
 static void
 log_it(struct log_connection *log, const char *line,
-       time_t log_time, const struct tm *tm)
+       const struct timeval *log_time, const struct tm *tm)
 {
        struct failure_line failure;
        struct failure_context failure_ctx;
@@ -223,6 +227,7 @@ log_it(struct log_connection *log, const char *line,
        memset(&failure_ctx, 0, sizeof(failure_ctx));
        failure_ctx.type = failure.log_type;
        failure_ctx.timestamp = tm;
+       failure_ctx.timestamp_usecs = log_time->tv_usec;
 
        prefix = client != NULL && client->prefix != NULL ?
                client->prefix : log->default_prefix;
@@ -279,7 +284,7 @@ static void log_connection_input(struct log_connection *log)
 {
        const char *line;
        ssize_t ret;
-       time_t now;
+       struct timeval now;
        struct tm tm;
 
        if (!log->handshaked) {
@@ -291,11 +296,12 @@ static void log_connection_input(struct log_connection *log)
 
        while ((ret = i_stream_read(log->input)) > 0 || ret == -2) {
                /* get new timestamps for every read() */
-               now = time(NULL);
-               tm = *localtime(&now);
+               if (gettimeofday(&now, NULL) < 0)
+                       i_panic("gettimeofday() failed: %m");
+               tm = *localtime(&now.tv_sec);
 
                while ((line = i_stream_next_line(log->input)) != NULL)
-                       log_it(log, line, now, &tm);
+                       log_it(log, line, &now, &tm);
        }
 
        if (log->input->eof)