[PATCH v32 09/12] log: add timestamp option

[David Marchand <david.marchand@redhat.com>]

From: Stephen Hemminger <stephen@networkplumber.org>

When debugging driver or startup issues, it is useful to have a timestamp
on each message printed.
The messages in syslog already have a timestamp, but often syslog is not
available during testing.

There are multiple timestamp formats similar to Linux dmesg.
The default is time relative since startup (when first step of logging
initialization is done by constructor).
Other alternative formats are delta, ctime, reltime and iso formats.

Example:
$ dpdk-testpmd --log-timestamp -- -i
[     0.008610] EAL: Detected CPU lcores: 8
[     0.008634] EAL: Detected NUMA nodes: 1
[     0.008792] EAL: Detected static linkage of DPDK
[     0.010620] EAL: Multi-process socket /var/run/dpdk/rte/mp_socket
[     0.012618] EAL: Selected IOVA mode 'VA'
[     0.016675] testpmd: No probed ethernet devices
Interactive-mode selected

Note: Windows does not have localtime_r but it does have a similar
function that can be used instead. Add it to rte_os_shim.h.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Morten Brørup <mb@smartsharesystems.com>
Acked-by: Bruce Richardson <bruce.richardson@intel.com>
---
 app/test/test_eal_flags.c              |  24 +++
 doc/guides/prog_guide/log_lib.rst      |  28 +++
 doc/guides/rel_notes/release_24_11.rst |   2 +
 lib/eal/common/eal_common_options.c    |  14 +-
 lib/eal/common/eal_options.h           |   2 +
 lib/eal/windows/include/rte_os_shim.h  |  10 ++
 lib/log/log.c                          |  13 +-
 lib/log/log_internal.h                 |   9 +
 lib/log/log_private.h                  |   6 +
 lib/log/log_timestamp.c                | 240 +++++++++++++++++++++++++
 lib/log/meson.build                    |   1 +
 lib/log/version.map                    |   1 +
 12 files changed, 344 insertions(+), 6 deletions(-)
 create mode 100644 lib/log/log_timestamp.c

diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c
index 9fcf0d56e6..1a062fe0e8 100644
--- a/app/test/test_eal_flags.c
+++ b/app/test/test_eal_flags.c
@@ -1055,6 +1055,18 @@ test_misc_flags(void)
 	const char * const argv22[] = {prgname, prefix, mp_flag,
 				       "--huge-worker-stack=512"};
 
+	/* Try running with --log-timestamp */
+	const char * const argv23[] = {prgname, prefix, mp_flag,
+				       "--log-timestamp" };
+
+	/* Try running with --log-timestamp=iso */
+	const char * const argv24[] = {prgname, prefix, mp_flag,
+				       "--log-timestamp=iso" };
+
+	/* Try running with invalid timestamp */
+	const char * const argv25[] = {prgname, prefix, mp_flag,
+				       "--log-timestamp=invalid" };
+
 	/* run all tests also applicable to FreeBSD first */
 
 	if (launch_proc(argv0) == 0) {
@@ -1162,6 +1174,18 @@ test_misc_flags(void)
 		printf("Error - process did not run ok with --huge-worker-stack=size parameter\n");
 		goto fail;
 	}
+	if (launch_proc(argv23) != 0) {
+		printf("Error - process did not run ok with --log-timestamp parameter\n");
+		goto fail;
+	}
+	if (launch_proc(argv24) != 0) {
+		printf("Error - process did not run ok with --log-timestamp=iso parameter\n");
+		goto fail;
+	}
+	if (launch_proc(argv25) == 0) {
+		printf("Error - process did run ok with --log-timestamp=invalid parameter\n");
+		goto fail;
+	}
 
 	rmdir(hugepath_dir3);
 	rmdir(hugepath_dir2);
diff --git a/doc/guides/prog_guide/log_lib.rst b/doc/guides/prog_guide/log_lib.rst
index 9cee75b88c..a2e95317f5 100644
--- a/doc/guides/prog_guide/log_lib.rst
+++ b/doc/guides/prog_guide/log_lib.rst
@@ -110,3 +110,31 @@ Throughout the cfgfile library, all logging calls are therefore of the form:
 
 	CFG_LOG(ERR, "invalid comment characters %c",
 	       params->comment_character);
+
+Log timestamp
+~~~~~~~~~~~~~
+
+An optional timestamp can be added before each message by adding the ``--log-timestamp`` option.
+For example::
+
+	/path/to/app --log-level=lib.*:debug --log-timestamp
+
+Multiple alternative timestamp formats are available:
+
+.. csv-table:: Log time stamp format
+   :header: "Format", "Description", "Example"
+   :widths: 6, 30, 32
+
+   "ctime", "Unix ctime", "``[Wed Mar 20 07:26:12 2024]``"
+   "delta", "Offset since last", "``[<    3.162373>]``"
+   "reltime", "Seconds since last or time if minute changed", "``[  +3.001791]`` or ``[Mar20 07:26:12]``"
+   "iso", "ISO-8601", "``[2024-03-20T07:26:12−07:00]``"
+
+To prefix all console messages with ISO format time the syntax is::
+
+	/path/to/app --log-timestamp=iso
+
+.. note::
+
+   Timestamp option has no effect if using syslog
+   because the ``syslog()`` service already does timestamping internally.
diff --git a/doc/guides/rel_notes/release_24_11.rst b/doc/guides/rel_notes/release_24_11.rst
index 3853af2798..d1226c78d1 100644
--- a/doc/guides/rel_notes/release_24_11.rst
+++ b/doc/guides/rel_notes/release_24_11.rst
@@ -122,6 +122,8 @@ New Features
     By default, messages are no longer sent to syslog unless the ``--syslog`` option is specified.
     Syslog is also supported on FreeBSD (but not on Windows).
 
+  * Log messages can be timestamped with ``--log-timestamp`` option.
+
 * **Updated Marvell cnxk mempool driver.**
 
   * Added mempool driver support for CN20K SoC.
diff --git a/lib/eal/common/eal_common_options.c b/lib/eal/common/eal_common_options.c
index 9f4feb2611..7de6a25e62 100644
--- a/lib/eal/common/eal_common_options.c
+++ b/lib/eal/common/eal_common_options.c
@@ -74,6 +74,7 @@ eal_long_options[] = {
 	{OPT_IOVA_MODE,	        1, NULL, OPT_IOVA_MODE_NUM        },
 	{OPT_LCORES,            1, NULL, OPT_LCORES_NUM           },
 	{OPT_LOG_LEVEL,         1, NULL, OPT_LOG_LEVEL_NUM        },
+	{OPT_LOG_TIMESTAMP,     2, NULL, OPT_LOG_TIMESTAMP_NUM    },
 	{OPT_TRACE,             1, NULL, OPT_TRACE_NUM            },
 	{OPT_TRACE_DIR,         1, NULL, OPT_TRACE_DIR_NUM        },
 	{OPT_TRACE_BUF_SIZE,    1, NULL, OPT_TRACE_BUF_SIZE_NUM   },
@@ -1599,6 +1600,7 @@ eal_option_is_log(int opt)
 {
 	switch (opt) {
 	case OPT_LOG_LEVEL_NUM:
+	case OPT_LOG_TIMESTAMP_NUM:
 	case OPT_SYSLOG_NUM:
 		return true;
 	default:
@@ -1850,7 +1852,7 @@ eal_parse_common_option(int opt, const char *optarg,
 		break;
 #endif
 
-	case OPT_LOG_LEVEL_NUM: {
+	case OPT_LOG_LEVEL_NUM:
 		if (eal_parse_log_level(optarg) < 0) {
 			EAL_LOG(ERR,
 				"invalid parameters for --"
@@ -1858,7 +1860,14 @@ eal_parse_common_option(int opt, const char *optarg,
 			return -1;
 		}
 		break;
-	}
+
+	case OPT_LOG_TIMESTAMP_NUM:
+		if (eal_log_timestamp(optarg) < 0) {
+			EAL_LOG(ERR, "invalid parameters for --"
+				OPT_LOG_TIMESTAMP);
+			return -1;
+		}
+		break;
 
 #ifndef RTE_EXEC_ENV_WINDOWS
 	case OPT_TRACE_NUM: {
@@ -2225,6 +2234,7 @@ eal_common_usage(void)
 	       "  --"OPT_LOG_LEVEL"=<type-match>:<level>\n"
 	       "                      Set specific log level\n"
 	       "  --"OPT_LOG_LEVEL"=help    Show log types and levels\n"
+	       "  --"OPT_LOG_TIMESTAMP"[=<format>]  Timestamp log output\n"
 #ifndef RTE_EXEC_ENV_WINDOWS
 	       "  --"OPT_TRACE"=<regex-match>\n"
 	       "                      Enable trace based on regular expression trace name.\n"
diff --git a/lib/eal/common/eal_options.h b/lib/eal/common/eal_options.h
index 06ba023c5a..a1b52ae694 100644
--- a/lib/eal/common/eal_options.h
+++ b/lib/eal/common/eal_options.h
@@ -35,6 +35,8 @@ enum {
 	OPT_LCORES_NUM,
 #define OPT_LOG_LEVEL         "log-level"
 	OPT_LOG_LEVEL_NUM,
+#define OPT_LOG_TIMESTAMP     "log-timestamp"
+	OPT_LOG_TIMESTAMP_NUM,
 #define OPT_TRACE             "trace"
 	OPT_TRACE_NUM,
 #define OPT_TRACE_DIR         "trace-dir"
diff --git a/lib/eal/windows/include/rte_os_shim.h b/lib/eal/windows/include/rte_os_shim.h
index eda8113662..665c9ac93b 100644
--- a/lib/eal/windows/include/rte_os_shim.h
+++ b/lib/eal/windows/include/rte_os_shim.h
@@ -110,4 +110,14 @@ rte_clock_gettime(clockid_t clock_id, struct timespec *tp)
 }
 #define clock_gettime(clock_id, tp) rte_clock_gettime(clock_id, tp)
 
+static inline struct tm *
+rte_localtime_r(const time_t *timep, struct tm *result)
+{
+	if (localtime_s(result, timep) == 0)
+		return result;
+	else
+		return NULL;
+}
+#define localtime_r(timep, result) rte_localtime_r(timep, result)
+
 #endif /* _RTE_OS_SHIM_ */
diff --git a/lib/log/log.c b/lib/log/log.c
index dbff223108..854d77887b 100644
--- a/lib/log/log.c
+++ b/lib/log/log.c
@@ -17,13 +17,13 @@
 #include <rte_log.h>
 #include <rte_per_lcore.h>
 
-#include "log_internal.h"
-#include "log_private.h"
-
 #ifdef RTE_EXEC_ENV_WINDOWS
-#define strdup _strdup
+#include <rte_os_shim.h>
 #endif
 
+#include "log_internal.h"
+#include "log_private.h"
+
 struct rte_log_dynamic_type {
 	const char *name;
 	uint32_t loglevel;
@@ -513,6 +513,11 @@ eal_log_init(const char *id)
 	if (logf)
 		rte_openlog_stream(logf);
 
+	if (log_timestamp_enabled())
+		rte_logs.print_func = log_print_with_timestamp;
+	else
+		rte_logs.print_func = vfprintf;
+
 #if RTE_LOG_DP_LEVEL >= RTE_LOG_DEBUG
 	RTE_LOG(NOTICE, EAL,
 		"Debug dataplane logs available - lower performance\n");
diff --git a/lib/log/log_internal.h b/lib/log/log_internal.h
index 3c46328e7b..7c7d44eed2 100644
--- a/lib/log/log_internal.h
+++ b/lib/log/log_internal.h
@@ -5,8 +5,10 @@
 #ifndef LOG_INTERNAL_H
 #define LOG_INTERNAL_H
 
+#include <stdbool.h>
 #include <stdio.h>
 #include <stdint.h>
+#include <time.h>
 
 #include <rte_compat.h>
 
@@ -39,4 +41,11 @@ const char *eal_log_level2str(uint32_t level);
 __rte_internal
 void rte_eal_log_cleanup(void);
 
+/*
+ * Add timestamp to console logs
+ */
+__rte_internal
+int eal_log_timestamp(const char *fmt);
+
+
 #endif /* LOG_INTERNAL_H */
diff --git a/lib/log/log_private.h b/lib/log/log_private.h
index d5a8bf271a..5da9c9b438 100644
--- a/lib/log/log_private.h
+++ b/lib/log/log_private.h
@@ -24,4 +24,10 @@ bool log_syslog_enabled(void);
 FILE *log_syslog_open(const char *id);
 #endif
 
+bool log_timestamp_enabled(void);
+ssize_t log_timestamp(char *tsbuf, size_t tsbuflen);
+
+__rte_format_printf(2, 0)
+int log_print_with_timestamp(FILE *f, const char *format, va_list ap);
+
 #endif /* LOG_PRIVATE_H */
diff --git a/lib/log/log_timestamp.c b/lib/log/log_timestamp.c
new file mode 100644
index 0000000000..b4b0bca6a8
--- /dev/null
+++ b/lib/log/log_timestamp.c
@@ -0,0 +1,240 @@
+/* SPDX-License-Identifier: BSD-3-Clause */
+
+#include <limits.h>
+#include <stdarg.h>
+#include <stdbool.h>
+#include <stdint.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <time.h>
+
+#include <rte_common.h>
+#include <rte_stdatomic.h>
+#include <rte_time.h>
+
+#ifdef RTE_EXEC_ENV_WINDOWS
+#include <rte_os_shim.h>
+#endif
+
+#include "log_internal.h"
+#include "log_private.h"
+
+#ifndef NS_PER_SEC
+#define NS_PER_SEC 1E9
+#endif
+
+static enum {
+	LOG_TIMESTAMP_NONE = 0,
+	LOG_TIMESTAMP_TIME,	/* time since start */
+	LOG_TIMESTAMP_DELTA,	/* time since last message */
+	LOG_TIMESTAMP_RELTIME,  /* relative time since last message */
+	LOG_TIMESTAMP_CTIME,	/* Unix standard time format */
+	LOG_TIMESTAMP_ISO,	/* ISO8601 time format */
+} log_time_format;
+
+static struct {
+	struct timespec started;   /* when log was initialized */
+	RTE_ATOMIC(uint64_t) last_monotonic;
+	RTE_ATOMIC(uint64_t) last_realtime;
+} log_time;
+
+/* Set the log timestamp format */
+int
+eal_log_timestamp(const char *str)
+{
+	if (str == NULL)
+		log_time_format = LOG_TIMESTAMP_TIME;
+	else if (strcmp(str, "notime") == 0)
+		log_time_format = LOG_TIMESTAMP_NONE;
+	else if (strcmp(str, "reltime") == 0)
+		log_time_format = LOG_TIMESTAMP_RELTIME;
+	else if (strcmp(str, "delta") == 0)
+		log_time_format = LOG_TIMESTAMP_DELTA;
+	else if (strcmp(str, "ctime") == 0)
+		log_time_format =  LOG_TIMESTAMP_CTIME;
+	else if (strcmp(str, "iso") == 0)
+		log_time_format = LOG_TIMESTAMP_ISO;
+	else
+		return -1;
+
+	return 0;
+}
+
+bool
+log_timestamp_enabled(void)
+{
+	return log_time_format != LOG_TIMESTAMP_NONE;
+}
+
+/* Subtract two timespec values and handle wraparound */
+static struct timespec
+timespec_sub(const struct timespec *t0, const struct timespec *t1)
+{
+	struct timespec ts;
+
+	ts.tv_sec = t0->tv_sec - t1->tv_sec;
+	ts.tv_nsec = t0->tv_nsec - t1->tv_nsec;
+	if (ts.tv_nsec < 0) {
+		ts.tv_sec--;
+		ts.tv_nsec += 1000000000L;
+	}
+	return ts;
+}
+
+/*
+ * Format current timespec into ISO8601 format.
+ * Surprisingly, can't just use strftime() for this;
+ * since want microseconds and the timezone offset format differs.
+ */
+static ssize_t
+format_iso8601(char *tsbuf, size_t tsbuflen, const struct timespec *now)
+{
+	struct tm *tm, tbuf;
+	char dbuf[64]; /* "2024-05-01T22:11:00" */
+	char zbuf[16] = { }; /* "+0800" */
+
+	tm = localtime_r(&now->tv_sec, &tbuf);
+
+	/* make "2024-05-01T22:11:00,123456+0100" */
+	if (strftime(dbuf, sizeof(dbuf), "%Y-%m-%dT%H:%M:%S", tm) == 0)
+		return 0;
+
+	/* convert timezone to +hhmm */
+	if (strftime(zbuf, sizeof(zbuf), "%z", tm) == 0)
+		return 0;
+
+	/* the result for strftime is "+hhmm" but ISO wants "+hh:mm" */
+	return snprintf(tsbuf, tsbuflen, "%s,%06lu%.3s:%.2s",
+			dbuf, now->tv_nsec / 1000u,
+			zbuf, zbuf + 3);
+}
+
+/*
+ * Format a timestamp which shows time between messages.
+ */
+static ssize_t
+format_delta(char *tsbuf, size_t tsbuflen, const struct timespec *now)
+{
+	struct timespec delta;
+	uint64_t ns = rte_timespec_to_ns(now);
+	uint64_t previous;
+
+	previous = rte_atomic_exchange_explicit(&log_time.last_monotonic,
+						ns, rte_memory_order_seq_cst);
+	delta = rte_ns_to_timespec(ns - previous);
+
+	return snprintf(tsbuf, tsbuflen, "<%6lu.%06lu>",
+			(unsigned long)delta.tv_sec,
+			(unsigned long)delta.tv_nsec / 1000u);
+}
+
+/*
+ * Make a timestamp where if the minute, hour or day has
+ * changed from the last message, then print abbreviated
+ * "Month day hour:minute" format.
+ * Otherwise print delta from last printed message as +sec.usec
+ */
+static ssize_t
+format_reltime(char *tsbuf, size_t tsbuflen, const struct timespec *now)
+{
+	struct tm *tm, *last_tm, tbuf1, tbuf2;
+	time_t last_sec;
+	uint64_t ns = rte_timespec_to_ns(now);
+	uint64_t previous;
+
+	tm = localtime_r(&now->tv_sec, &tbuf1);
+
+	previous = rte_atomic_exchange_explicit(&log_time.last_realtime,
+						ns, rte_memory_order_seq_cst);
+	last_sec = previous / NS_PER_SEC;
+	last_tm = localtime_r(&last_sec, &tbuf2);
+	if (tm->tm_min == last_tm->tm_min &&
+	    tm->tm_hour == last_tm->tm_hour &&
+	    tm->tm_yday == last_tm->tm_yday) {
+		struct timespec elapsed;
+
+		elapsed = rte_ns_to_timespec(ns - previous);
+
+		return snprintf(tsbuf, tsbuflen, "+%3lu.%06lu",
+				(unsigned long)elapsed.tv_sec,
+				(unsigned long)elapsed.tv_nsec / 1000u);
+	} else {
+		return strftime(tsbuf, tsbuflen, "%b%d %H:%M", tm);
+	}
+}
+
+/* Format up a timestamp based on current format */
+ssize_t
+log_timestamp(char *tsbuf, size_t tsbuflen)
+{
+	struct timespec now, delta;
+
+	switch (log_time_format) {
+	case LOG_TIMESTAMP_NONE:
+		return 0;
+
+	case LOG_TIMESTAMP_TIME:
+		if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+			return 0;
+
+		delta = timespec_sub(&now, &log_time.started);
+
+		return snprintf(tsbuf, tsbuflen, "%6lu.%06lu",
+				(unsigned long)delta.tv_sec,
+				(unsigned long)delta.tv_nsec / 1000u);
+
+	case LOG_TIMESTAMP_DELTA:
+		if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+			return 0;
+
+		return format_delta(tsbuf, tsbuflen, &now);
+
+	case LOG_TIMESTAMP_RELTIME:
+		if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+			return 0;
+
+		return format_reltime(tsbuf, tsbuflen, &now);
+
+	case LOG_TIMESTAMP_CTIME:
+		if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+			return 0;
+
+		/* trncate to remove newline from ctime result */
+		return snprintf(tsbuf, tsbuflen, "%.24s", ctime(&now.tv_sec));
+
+	case LOG_TIMESTAMP_ISO:
+		if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+			return 0;
+
+		return format_iso8601(tsbuf, tsbuflen, &now);
+	}
+
+	return 0;
+}
+
+/* print timestamp before message */
+int
+log_print_with_timestamp(FILE *f, const char *format, va_list ap)
+{
+	char tsbuf[128];
+	char msgbuf[LINE_MAX];
+
+	if (log_timestamp(tsbuf, sizeof(tsbuf)) > 0) {
+		vsnprintf(msgbuf, sizeof(msgbuf), format, ap);
+		return fprintf(f, "[%s] %s", tsbuf, msgbuf);
+	}
+
+	/* fall back when timestamp is unavailable */
+	return vfprintf(f, format, ap);
+}
+
+RTE_INIT_PRIO(log_timestamp_init, LOG)
+{
+	struct timespec now;
+
+	clock_gettime(CLOCK_MONOTONIC, &now);
+	log_time.started = now;
+	rte_atomic_store_explicit(&log_time.last_monotonic, rte_timespec_to_ns(&now),
+				  rte_memory_order_seq_cst);
+}
diff --git a/lib/log/meson.build b/lib/log/meson.build
index 160cf34f50..4ac232786e 100644
--- a/lib/log/meson.build
+++ b/lib/log/meson.build
@@ -4,6 +4,7 @@
 includes += global_inc
 sources = files(
         'log.c',
+        'log_timestamp.c',
 )
 
 if not is_windows
diff --git a/lib/log/version.map b/lib/log/version.map
index 1637fba3b9..8be6907840 100644
--- a/lib/log/version.map
+++ b/lib/log/version.map
@@ -30,5 +30,6 @@ INTERNAL {
 	eal_log_save_pattern;
 	eal_log_save_regexp;
 	eal_log_syslog; # WINDOWS_NO_EXPORT
+	eal_log_timestamp;
 	rte_eal_log_cleanup;
 };
-- 
2.47.0