[v10,09/10] log: colorize log output

Message ID 20240321161146.340421-10-stephen@networkplumber.org (mailing list archive)
State Superseded, archived
Headers
Series eal: add option to put timestamp on console output |

Commit Message

Stephen Hemminger March 21, 2024, 4 p.m. UTC
  Like dmesg, colorize the log output (unless redirected to file).
Timestamp is green, the subsystem is in yellow and the message
is red if urgent, boldface if an error, and normal for info and
debug messages.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/eal/common/eal_common_options.c |  10 +++
 lib/eal/common/eal_options.h        |   2 +
 lib/log/log_internal.h              |   5 ++
 lib/log/log_unix.c                  | 132 +++++++++++++++++++++++++---
 lib/log/log_windows.c               |   6 ++
 lib/log/version.map                 |   1 +
 6 files changed, 146 insertions(+), 10 deletions(-)
  

Patch

diff --git a/lib/eal/common/eal_common_options.c b/lib/eal/common/eal_common_options.c
index 4e2c3d0f255c..522634f1dcfa 100644
--- a/lib/eal/common/eal_common_options.c
+++ b/lib/eal/common/eal_common_options.c
@@ -78,6 +78,7 @@  eal_long_options[] = {
 	{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_LOG_COLOR,		1, NULL, OPT_LOG_COLOR_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   },
@@ -1910,6 +1911,15 @@  eal_parse_common_option(int opt, const char *optarg,
 		}
 		break;
 
+
+	case OPT_LOG_COLOR_NUM:
+		if (eal_log_color(optarg) < 0) {
+			EAL_LOG(ERR, "invalid parameters for --"
+				OPT_LOG_COLOR);
+			return -1;
+		}
+		break;
+
 	case OPT_TRACE_NUM: {
 		if (eal_trace_args_save(optarg) < 0) {
 			EAL_LOG(ERR, "invalid parameters for --"
diff --git a/lib/eal/common/eal_options.h b/lib/eal/common/eal_options.h
index e24c9eca53ca..5a63c1dd3a32 100644
--- a/lib/eal/common/eal_options.h
+++ b/lib/eal/common/eal_options.h
@@ -37,6 +37,8 @@  enum {
 	OPT_LOG_LEVEL_NUM,
 #define OPT_LOG_TIMESTAMP     "log-timestamp"
 	OPT_LOG_TIMESTAMP_NUM,
+#define OPT_LOG_COLOR	      "log-color"
+	OPT_LOG_COLOR_NUM,
 #define OPT_TRACE             "trace"
 	OPT_TRACE_NUM,
 #define OPT_TRACE_DIR         "trace-dir"
diff --git a/lib/log/log_internal.h b/lib/log/log_internal.h
index 0e18d147cf98..b90c668f4668 100644
--- a/lib/log/log_internal.h
+++ b/lib/log/log_internal.h
@@ -52,5 +52,10 @@  void rte_eal_log_cleanup(void);
 __rte_internal
 int eal_log_timestamp(const char *fmt);
 
+/*
+ * Enable or disable color in log messages
+ */
+__rte_internal
+int eal_log_color(const char *mode);
 
 #endif /* LOG_INTERNAL_H */
diff --git a/lib/log/log_unix.c b/lib/log/log_unix.c
index cb8f17bc83ef..1af93795fec5 100644
--- a/lib/log/log_unix.c
+++ b/lib/log/log_unix.c
@@ -11,6 +11,7 @@ 
 #include <time.h>
 #include <unistd.h>
 
+#include <rte_common.h>
 #include <rte_log.h>
 
 #include "log_internal.h"
@@ -24,15 +25,113 @@  enum eal_log_time_format {
 	EAL_LOG_TIMESTAMP_ISO,
 };
 
+enum eal_log_color {
+	EAL_LOG_COLOR_AUTO = 0,	/* default */
+	EAL_LOG_COLOR_NEVER,
+	EAL_LOG_COLOR_ALWAYS,
+};
+
 static struct {
+	enum eal_log_color color_mode;
 	enum eal_log_time_format time_format;
+	bool show_color;
 	struct timespec start_time;
 	struct timespec last_time;
 	struct tm last_tm;
 } log = {
+	.color_mode = EAL_LOG_COLOR_AUTO,
 	.time_format = EAL_LOG_TIMESTAMP_NONE,
 };
 
+enum color {
+	COLOR_NONE,
+	COLOR_RED,
+	COLOR_GREEN,
+	COLOR_YELLOW,
+	COLOR_BLUE,
+	COLOR_MAGENTA,
+	COLOR_CYAN,
+	COLOR_WHITE,
+	COLOR_BOLD,
+	COLOR_CLEAR
+};
+
+static const char * const color_code[] = {
+	[COLOR_NONE]	= "",
+	[COLOR_RED]	= "\e[31m",
+	[COLOR_GREEN]	= "\e[32m",
+	[COLOR_YELLOW]	= "\e[33m",
+	[COLOR_BLUE]	= "\e[34m",
+	[COLOR_MAGENTA] = "\e[35m",
+	[COLOR_CYAN]    = "\e[36m",
+	[COLOR_WHITE]	= "\e[37m",
+	[COLOR_BOLD]	= "\e[1m",
+	[COLOR_CLEAR]	= "\e[0m",
+};
+
+__rte_format_printf(3, 4)
+static int color_fprintf(FILE *out, enum color color, const char *fmt, ...)
+{
+	va_list args;
+	int ret = 0;
+
+	va_start(args, fmt);
+	ret = fprintf(out, "%s", color_code[color]);
+	ret += vfprintf(out, fmt, args);
+	ret += fprintf(out, "%s", color_code[COLOR_CLEAR]);
+
+	return ret;
+}
+
+static ssize_t
+color_log_write(FILE *f, int level, const char *msg, size_t size)
+{
+	size_t i;
+	ssize_t ret = 0;
+
+	/* find first : delimiter in message */
+	for (i = 0; i < size; i++) {
+		if (msg[i] == ':') {
+			++i;  /* put colon in the color */
+			ret = color_fprintf(stderr, COLOR_YELLOW, "%.*s", (int)i, msg);
+			msg += i;
+			size -= i;
+			break;
+		}
+	}
+
+	if (level <= 0 || level >= (int)RTE_LOG_INFO)
+		ret += fprintf(f, "%.*s", (int)size, msg);
+	else if (level >= (int)RTE_LOG_ERR)
+		ret += color_fprintf(f, COLOR_BOLD, "%.*s", (int)size, msg);
+	else
+		ret += color_fprintf(f, COLOR_RED, "%.*s", (int)size, msg);
+
+	return ret;
+}
+
+/*
+ * Controls whether color is enabled:
+ * modes are:
+ *   always - enable color output regardless
+ *   auto - enable if stderr is a terminal
+ *   never - color output is disabled.
+ */
+int
+eal_log_color(const char *mode)
+{
+	if (mode == NULL || strcmp(mode, "always") == 0)
+		log.color_mode = EAL_LOG_COLOR_ALWAYS;
+	else if (strcmp(mode, "never") == 0)
+		log.color_mode = EAL_LOG_COLOR_NEVER;
+	else if (strcmp(mode, "auto") == 0)
+		log.color_mode = EAL_LOG_COLOR_AUTO;
+	else
+		return -1;
+
+	return 0;
+}
+
 int
 eal_log_timestamp(const char *str)
 {
@@ -153,18 +252,28 @@  console_log_timestamp(char *tsbuf, size_t tsbuflen)
 static ssize_t
 console_log_write(__rte_unused void *c, const char *msg, size_t size)
 {
-	char buf[128];
+	int level = rte_log_cur_msg_loglevel();
+	char tsbuf[128] = "";
 	ssize_t ret;
 
-	ret = console_log_timestamp(buf, sizeof(buf));
-	if (ret == 0)
-		ret = fwrite(msg, 1, size, stderr);
-	else
-		ret = fprintf(stderr, "[%s] %.*s", buf, (int)size, msg);
+	ret = console_log_timestamp(tsbuf, sizeof(tsbuf));
+	if (ret == 0) {
+		if (log.show_color)
+			ret = color_log_write(stderr, level, msg, size);
+		else
+			ret = fwrite(msg, 1, size, stderr);
+	} else {
+		if (log.show_color) {
+			color_fprintf(stderr, COLOR_GREEN, "[%s] ", tsbuf);
+			ret = color_log_write(stderr, level, msg, size);
+		} else {
+			ret = fprintf(stderr, "[%s] %.*s", tsbuf, (int)size, msg);
+		}
+	}
 	fflush(stderr);
 
 	/* Syslog error levels are from 0 to 7, so subtract 1 to convert */
-	syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, msg);
+	syslog(level - 1, "%.*s", (int)size, msg);
 
 	return ret;
 }
@@ -190,13 +299,16 @@  eal_log_init(const char *id, int facility)
 {
 	FILE *log_stream;
 
-	clock_gettime(CLOCK_MONOTONIC, &log.start_time);
-	log.last_time = log.start_time;
-
 	/* skip if user has already setup a log stream */
 	if (eal_log_get_default())
 		return 0;
 
+	log.show_color = (log.color_mode == EAL_LOG_COLOR_ALWAYS) ||
+		(log.color_mode == EAL_LOG_COLOR_AUTO && isatty(STDERR_FILENO));
+
+	clock_gettime(CLOCK_MONOTONIC, &log.start_time);
+	log.last_time = log.start_time;
+
 	log_stream = fopencookie(NULL, "w+", console_log_func);
 	if (log_stream == NULL)
 		return -1;
diff --git a/lib/log/log_windows.c b/lib/log/log_windows.c
index 8aa68a181bec..1cb72f519a91 100644
--- a/lib/log/log_windows.c
+++ b/lib/log/log_windows.c
@@ -12,6 +12,12 @@  eal_log_timestamp(__rte_unused const char *fmt)
 	return -1; /* not implemented */
 }
 
+int
+eal_log_color(__rte_unused const char *mode)
+{
+	return -1; /* not implemented */
+}
+
 /* set the log to default function, called during eal init process. */
 int
 eal_log_init(__rte_unused const char *id, __rte_unused int facility)
diff --git a/lib/log/version.map b/lib/log/version.map
index 697cdb3cb1b2..1fe6955427b7 100644
--- a/lib/log/version.map
+++ b/lib/log/version.map
@@ -25,6 +25,7 @@  DPDK_24 {
 INTERNAL {
 	global:
 
+	eal_log_color;
 	eal_log_get_default;
 	eal_log_init;
 	eal_log_level2str;