From 931b406f9bdc1f93ba8e99a8b8e634c4d1a6cb20 Mon Sep 17 00:00:00 2001
From: Mark Kemel <mkemel@redhat.com>
Date: Tue, 30 May 2023 15:10:45 +0300
Subject: [PATCH] log: improve timestamps on stderr log output

This adds date and milliseconds to the timestamp output to
stderr-full, and also adds timestamp to stderr log output

Signed-off-by: Mark Kemel <mkemel@redhat.com>
---
 src/libhirte/common/time-util.c | 31 +++++++++++++++++++++++++++++++
 src/libhirte/common/time-util.h |  5 +++++
 src/libhirte/log/log.c          | 14 ++++++--------
 3 files changed, 42 insertions(+), 8 deletions(-)

diff --git a/src/libhirte/common/time-util.c b/src/libhirte/common/time-util.c
index c3d342fc4a..475ab368f6 100644
--- a/src/libhirte/common/time-util.c
+++ b/src/libhirte/common/time-util.c
@@ -1,6 +1,9 @@
 /* SPDX-License-Identifier: GPL-2.0-or-later */
+#include <errno.h>
+#include <stdio.h>
 #include <time.h>
 
+#include "libhirte/common/common.h"
 #include "time-util.h"
 
 uint64_t get_time_micros() {
@@ -20,3 +23,31 @@ uint64_t finalize_time_interval_micros(int64_t start_time_micros) {
 double micros_to_millis(uint64_t time_micros) {
         return (double) time_micros * microsec_to_millisec_multiplier;
 }
+
+char *get_formatted_log_timestamp() {
+        struct timespec now;
+        int r = 0;
+        r = clock_gettime(CLOCK_REALTIME, &now);
+        if (r < 0) {
+                return malloc0(1);
+        }
+        return get_formatted_log_timestamp_for_timespec(now);
+}
+
+char *get_formatted_log_timestamp_for_timespec(struct timespec time) {
+        const size_t timestamp_size = 20;
+        const size_t timestamp_with_millis_size = timestamp_size + 4;
+        const size_t timestamp_offset_size = 7;
+        const size_t timestamp_full_size = timestamp_with_millis_size + timestamp_offset_size;
+        char timebuf[timestamp_size];
+        char offsetbuf[timestamp_offset_size];
+        char *timebuf_full = malloc0(timestamp_full_size);
+        struct tm *time_tm = localtime(&time.tv_sec);
+
+        strftime(timebuf, timestamp_size, "%Y-%m-%d %H:%M:%S", time_tm);
+        uint64_t millis = (uint64_t) ((double) time.tv_nsec * nanosec_to_millisec_multiplier);
+        strftime(offsetbuf, timestamp_offset_size, "%z", time_tm);
+        snprintf(timebuf_full, timestamp_full_size, "%s,%ld%s", timebuf, millis % millis_in_second, offsetbuf);
+
+        return timebuf_full;
+}
diff --git a/src/libhirte/common/time-util.h b/src/libhirte/common/time-util.h
index fe9956b4cd..c7490990de 100644
--- a/src/libhirte/common/time-util.h
+++ b/src/libhirte/common/time-util.h
@@ -2,11 +2,16 @@
 #pragma once
 
 #include <inttypes.h>
+#include <stdlib.h>
 
 static const uint64_t sec_to_microsec_multiplier = 1000000;
 static const double microsec_to_millisec_multiplier = 1e-3;
 static const double nanosec_to_microsec_multiplier = 1e-3;
+static const double nanosec_to_millisec_multiplier = 1e-6;
+static const uint64_t millis_in_second = 1000;
 
 uint64_t get_time_micros();
 uint64_t finalize_time_interval_micros(int64_t start_time_micros);
 double micros_to_millis(uint64_t time_micros);
+char *get_formatted_log_timestamp();
+char *get_formatted_log_timestamp_for_timespec(struct timespec time);
diff --git a/src/libhirte/log/log.c b/src/libhirte/log/log.c
index e832940479..d9e06e9103 100644
--- a/src/libhirte/log/log.c
+++ b/src/libhirte/log/log.c
@@ -2,6 +2,7 @@
 #include <errno.h>
 
 #include "libhirte/common/common.h"
+#include "libhirte/common/time-util.h"
 
 #include "log.h"
 
@@ -90,21 +91,17 @@ int hirte_log_to_stderr_full_with_location(
                 const char *func,
                 const char *msg,
                 const char *data) {
-
-        time_t t = time(NULL);
-        const size_t timestamp_size = 9;
-        char timebuf[timestamp_size];
-        timebuf[strftime(timebuf, sizeof(timebuf), "%H:%M:%S", localtime(&t))] = '\0';
+        _cleanup_free_ char *timestamp = get_formatted_log_timestamp();
 
         // clang-format off
         if (data && *data) {
                 fprintf(stderr, "%s %s\t%s:%s %s\tmsg=\"%s\", data=\"%s\"\n",
-                        timebuf, log_level_to_string(lvl),
+                        timestamp, log_level_to_string(lvl),
                         file, line, func,
                         msg, data);
         } else {
                 fprintf(stderr, "%s %s\t%s:%s %s\tmsg=\"%s\"\n",
-                        timebuf, log_level_to_string(lvl),
+                        timestamp, log_level_to_string(lvl),
                         file, line, func,
                         msg);
         }
@@ -119,7 +116,8 @@ int hirte_log_to_stderr_with_location(
                 UNUSED const char *func,
                 const char *msg,
                 UNUSED const char *data) {
-        fprintf(stderr, "%s\t: %s\n", log_level_to_string(lvl), msg);
+        _cleanup_free_ char *timestamp = get_formatted_log_timestamp();
+        fprintf(stderr, "%s %s\t: %s\n", timestamp, log_level_to_string(lvl), msg);
         return 0;
 }