logging: Improve logging format

This commit adds 2 improvemens to the ply_trace logging format:

1) It prefixes the log messages with timestamps (since system boot)

2) Previously function-names where right aligned / left padded to 45
characters. But they were prefixed with a [file:line] prefix which does
not have a fixed width, making the column aligment for the actual messages
fail resulting in hard to read logs.

This commit fixes 2. by printing "<timestamp> file:line:func" to a
prefix-buffer and then left-aligning / right padding this prefix buffer
to 75 chars.

The resulting logged lines now look like this:

00:00:01.741 main.c:1928:check_logging                                     : checking if console messages should be redirected and logged
00:00:01.741 main.c:1937:check_logging                                     : logging will be enabled!

Signed-off-by: Hans de Goede <hdegoede@redhat.com>

diff --git a/src/libply/ply-logger.h b/src/libply/ply-logger.h
index 53d1ad9d29aa120716dac3fd0c9b2451f01008a6..0015c0cf6fc5153d446c294638848dc7dbd7f1a6 100644 (file)
--- a/src/libply/ply-logger.h
+++ b/src/libply/ply-logger.h
@@ -25,6 +25,7 @@
 #include <stdint.h>
 #include <string.h>
 #include <sys/types.h>
+#include <time.h>
 #include <unistd.h>
 
 typedef struct _ply_logger ply_logger_t;
@@ -88,11 +89,21 @@ bool ply_logger_is_tracing_enabled (ply_logger_t *logger);
                 _old_errno = errno;                                                        \
                 if (ply_logger_is_tracing_enabled (logger))                                \
                 {                                                                        \
+                        struct timespec timespec = { 0, 0 };                                   \
+                        char buf[128];                                                         \
+                        clock_gettime (CLOCK_MONOTONIC, &timespec);                            \
                         ply_logger_flush (logger);                                             \
+                        snprintf (buf, sizeof(buf),                                            \
+                                  "%02d:%02d:%02d.%03d %s:%d:%s",                              \
+                                  (int)(timespec.tv_sec / 3600),                               \
+                                  (int)((timespec.tv_sec / 60) % 60),                          \
+                                  (int)(timespec.tv_sec % 60),                                 \
+                                  (int)(timespec.tv_nsec / 1000000),                           \
+                                  __FILE__, __LINE__, __func__);                               \
                         errno = _old_errno;                                                    \
                         ply_logger_inject (logger,                                             \
-                                           "[%s:%d] %45.45s:" format "\n",                   \
-                                           __FILE__, __LINE__, __func__, ## args);              \
+                                           "%-75.75s: " format "\n",                           \
+                                           buf, ## args);                                      \
                         ply_logger_flush (logger);                                             \
                         errno = _old_errno;                                                    \
                 }                                                                        \