From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mails.dpdk.org (mails.dpdk.org [217.70.189.124]) by inbox.dpdk.org (Postfix) with ESMTP id 7EA8445B56; Wed, 16 Oct 2024 22:25:22 +0200 (CEST) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id C1776406FF; Wed, 16 Oct 2024 22:24:16 +0200 (CEST) Received: from mail-pl1-f181.google.com (mail-pl1-f181.google.com [209.85.214.181]) by mails.dpdk.org (Postfix) with ESMTP id F350640653 for ; Wed, 16 Oct 2024 22:24:08 +0200 (CEST) Received: by mail-pl1-f181.google.com with SMTP id d9443c01a7336-207115e3056so1719655ad.2 for ; Wed, 16 Oct 2024 13:24:08 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20230601.gappssmtp.com; s=20230601; t=1729110248; x=1729715048; darn=dpdk.org; h=content-transfer-encoding:mime-version:references:in-reply-to :message-id:date:subject:cc:to:from:from:to:cc:subject:date :message-id:reply-to; bh=w2OQlt0prUPKkYDFOMJG/5pKB3cNn45g8cXvWXDruvY=; b=h+S9k5aWLPbd8v1zJ9M6oosfXK8ebnCQXr1JTF+4xBhbrHSToRSaGZHcUHzWmqLDJh mTpDClP2Mv4nCZWyMlO6g65+8ne5Pf/80fPwrkamTnMY6lt2WzJNqVHdUqVsG61TpahD 8xMaxmsdJt+1Gww1t3ZMb6Wy4ZqywRcTGMer1jJaWkAhiHUCvgUwEkZa/L5bwhZt+DF/ IfJL/cIlR/1OBlX06xJ4JlIZiNwl70DPTww+Ma/pz/5H6ib0XCAy5QPl0yEYAo3pHmce qfE4gc1fi07md49+s1CUlX+sQ/3haSIuvCaFAe+pXbsIrLz83/WpS2d6Lq7w5U+DXSA/ Qdcw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1729110248; x=1729715048; h=content-transfer-encoding:mime-version:references:in-reply-to :message-id:date:subject:cc:to:from:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=w2OQlt0prUPKkYDFOMJG/5pKB3cNn45g8cXvWXDruvY=; b=xNeEB13jKy9ndIBKcPUS3mUikrwfPMZEu4lScSTGRIeo+D/oV9/VLyb0D6rfu3r0Dt h3eVNXtftdnckLBiY9FbcSm30PQgAtyhr1OPvnuGhDHZU3cQZ3PVTgrQHcZBvQ4pTclg iSRevPG5gzt6aUnGfcYxzqQHovsB6cyteKmfaPeaKGcCOpGMIMGcCyF46qLPAd73qD84 puwFqsuPMeL6tyJ8Rb5hd/hDSSumWjewoKDNKt9dqU99lPSFieRVpa42+OSs/RDejv4v q29xS3Acd1FcyyVtqL6c53G4WNoctBBgL01FWMtpV1auQkvUTkiEnlRC/q53LB1Phojh G4Ew== X-Gm-Message-State: AOJu0YzNmxPU37+y7DG2AGQ8DwlvEJpMVXPvCSw1u2XtXsZHlE/XsRdh uSa2pDQASQXGhk/AVnmcskwXIxjAr4njaKkfUJP0loAJJlMWspkt2xSKfKmgFhnH6nvlCkdRvfZ D X-Google-Smtp-Source: AGHT+IFfDHWkRKWZyqhdKXRnItWm3O79oL+/B/sXMrQ/HKd6WgcYyTfiWvkAFKcSyUA+tGzdxE8Lew== X-Received: by 2002:a17:903:41d2:b0:20b:8776:4902 with SMTP id d9443c01a7336-20d27f1ccc2mr78932325ad.38.1729110248057; Wed, 16 Oct 2024 13:24:08 -0700 (PDT) Received: from hermes.local (204-195-96-226.wavecable.com. [204.195.96.226]) by smtp.gmail.com with ESMTPSA id d9443c01a7336-20d180361e5sm32308825ad.120.2024.10.16.13.24.07 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 16 Oct 2024 13:24:07 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger , =?UTF-8?q?Morten=20Br=C3=B8rup?= , Bruce Richardson , Chengwen Feng , Tyler Retzlaff Subject: [PATCH v26 14/15] log: colorize log output Date: Wed, 16 Oct 2024 13:20:41 -0700 Message-ID: <20241016202343.190653-15-stephen@networkplumber.org> X-Mailer: git-send-email 2.45.2 In-Reply-To: <20241016202343.190653-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20241016202343.190653-1-stephen@networkplumber.org> MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: dev@dpdk.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: DPDK patches and discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@dpdk.org 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. The default is to not use color since it may disturb automatic tests and other embedded usage. Signed-off-by: Stephen Hemminger Acked-by: Morten Brørup Acked-by: Bruce Richardson Acked-by: Chengwen Feng log dark --- app/test/test_eal_flags.c | 24 ++++ doc/guides/prog_guide/log_lib.rst | 15 ++ lib/eal/common/eal_common_options.c | 11 ++ lib/eal/common/eal_options.h | 6 +- lib/log/log.c | 19 ++- lib/log/log_color.c | 216 ++++++++++++++++++++++++++++ lib/log/log_internal.h | 5 + lib/log/log_private.h | 8 ++ lib/log/meson.build | 1 + lib/log/version.map | 1 + 10 files changed, 298 insertions(+), 8 deletions(-) create mode 100644 lib/log/log_color.c diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c index 06295030b2..6ee56ec97a 100644 --- a/app/test/test_eal_flags.c +++ b/app/test/test_eal_flags.c @@ -1067,6 +1067,18 @@ test_misc_flags(void) const char * const argv25[] = {prgname, prefix, mp_flag, "--log-timestamp=invalid" }; + /* Try running with --log-color */ + const char * const argv26[] = {prgname, prefix, mp_flag, + "--log-color" }; + + /* Try running with --log-color=never */ + const char * const argv27[] = {prgname, prefix, mp_flag, + "--log-color=never" }; + + /* Try running with --log-color=invalid */ + const char * const argv28[] = {prgname, prefix, mp_flag, + "--log-color=invalid" }; + /* run all tests also applicable to FreeBSD first */ @@ -1187,6 +1199,18 @@ test_misc_flags(void) printf("Error - process did run ok with --log-timestamp=invalid parameter\n"); goto fail; } + if (launch_proc(argv26) != 0) { + printf("Error - process did not run ok with --log-color parameter\n"); + goto fail; + } + if (launch_proc(argv27) != 0) { + printf("Error - process did not run ok with --log-color=none parameter\n"); + goto fail; + } + if (launch_proc(argv28) == 0) { + printf("Error - process did run ok with --log-timestamp=invalid parameter\n"); + goto fail; + } rmdir(hugepath_dir3); diff --git a/doc/guides/prog_guide/log_lib.rst b/doc/guides/prog_guide/log_lib.rst index 925bc70ede..b533e2d48e 100644 --- a/doc/guides/prog_guide/log_lib.rst +++ b/doc/guides/prog_guide/log_lib.rst @@ -57,6 +57,21 @@ For example:: Within an application, the same result can be got using the ``rte_log_set_level_pattern()`` or ``rte_log_set_level_regex()`` APIs. +Color output +~~~~~~~~~~~~ + +The log library will highlight important messages. +This is controlled by the ``--log-color`` option. +he optional argument ``when`` can be ``auto``, ``never``, or ``always``. +The default setting is ``auto`` which enables color when the output to +``stderr`` is a terminal. +If the ``when`` argument is omitted, it defaults to ``always``. + +For example to turn off all coloring:: + + /path/to/app --log-color=none + + Log timestamp ~~~~~~~~~~~~~ diff --git a/lib/eal/common/eal_common_options.c b/lib/eal/common/eal_common_options.c index 6184d27ad3..de19b1c258 100644 --- a/lib/eal/common/eal_common_options.c +++ b/lib/eal/common/eal_common_options.c @@ -73,6 +73,7 @@ eal_long_options[] = { {OPT_HUGE_UNLINK, 2, NULL, OPT_HUGE_UNLINK_NUM }, {OPT_IOVA_MODE, 1, NULL, OPT_IOVA_MODE_NUM }, {OPT_LCORES, 1, NULL, OPT_LCORES_NUM }, + {OPT_LOG_COLOR, 2, NULL, OPT_LOG_COLOR_NUM }, {OPT_LOG_LEVEL, 1, NULL, OPT_LOG_LEVEL_NUM }, {OPT_LOG_JOURNAL, 2, NULL, OPT_LOG_JOURNAL_NUM }, {OPT_LOG_TIMESTAMP, 2, NULL, OPT_LOG_TIMESTAMP_NUM }, @@ -1620,6 +1621,7 @@ eal_log_level_parse(int argc, char * const argv[]) case OPT_SYSLOG_NUM: case OPT_LOG_JOURNAL_NUM: case OPT_LOG_TIMESTAMP_NUM: + case OPT_LOG_COLOR_NUM: if (eal_parse_common_option(opt, optarg, internal_conf) < 0) return -1; break; @@ -1869,6 +1871,14 @@ 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; + #ifndef RTE_EXEC_ENV_WINDOWS case OPT_TRACE_NUM: { if (eal_trace_args_save(optarg) < 0) { @@ -2238,6 +2248,7 @@ eal_common_usage(void) " Set specific log level\n" " --"OPT_LOG_LEVEL"=help Show log types and levels\n" " --"OPT_LOG_TIMESTAMP"[=] Timestamp log output\n" + " --"OPT_LOG_COLOR"[=] Colorize log messages\n" #ifndef RTE_EXEC_ENV_WINDOWS " --"OPT_TRACE"=\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 c5a1c70288..c0686c2544 100644 --- a/lib/eal/common/eal_options.h +++ b/lib/eal/common/eal_options.h @@ -33,10 +33,12 @@ enum { OPT_HUGE_UNLINK_NUM, #define OPT_LCORES "lcores" OPT_LCORES_NUM, -#define OPT_LOG_LEVEL "log-level" - OPT_LOG_LEVEL_NUM, +#define OPT_LOG_COLOR "log-color" + OPT_LOG_COLOR_NUM, #define OPT_LOG_JOURNAL "log-journal" OPT_LOG_JOURNAL_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" diff --git a/lib/log/log.c b/lib/log/log.c index 96fa651e81..8b7b394f49 100644 --- a/lib/log/log.c +++ b/lib/log/log.c @@ -511,14 +511,21 @@ eal_log_init(const char *id) is_terminal = isatty(STDERR_FILENO); #endif - if (log_journal_enabled()) + if (log_journal_enabled()) { log_journal_open(id); - else if (log_syslog_enabled(is_terminal)) + } else if (log_syslog_enabled(is_terminal)) { log_syslog_open(id, is_terminal); - else if (log_timestamp_enabled()) - rte_logs.print_func = log_print_with_timestamp; - else - rte_logs.print_func = vfprintf; + } else if (log_timestamp_enabled()) { + if (log_color_enabled(is_terminal)) + rte_logs.print_func = color_print_with_timestamp; + else + rte_logs.print_func = log_print_with_timestamp; + } else { + if (log_color_enabled(is_terminal)) + rte_logs.print_func = color_print; + else + rte_logs.print_func = vfprintf; + } #if RTE_LOG_DP_LEVEL >= RTE_LOG_DEBUG RTE_LOG(NOTICE, EAL, diff --git a/lib/log/log_color.c b/lib/log/log_color.c new file mode 100644 index 0000000000..82a9ac8022 --- /dev/null +++ b/lib/log/log_color.c @@ -0,0 +1,216 @@ +/* SPDX-License-Identifier: BSD-3-Clause */ + +#include +#include +#include +#include +#include +#include +#include + +#include +#include + +#ifdef RTE_EXEC_ENV_WINDOWS +#include +#endif + +#include "log_internal.h" +#include "log_private.h" + +enum { + LOG_COLOR_AUTO = 0, + LOG_COLOR_NEVER, + LOG_COLOR_ALWAYS, +} log_color_mode = LOG_COLOR_NEVER; + +enum color { + COLOR_NONE, + COLOR_RED, + COLOR_GREEN, + COLOR_YELLOW, + COLOR_BLUE, + COLOR_MAGENTA, + COLOR_CYAN, + COLOR_WHITE, + COLOR_BOLD, + COLOR_CLEAR, +}; + +enum log_field { + LOG_FIELD_SUBSYS, + LOG_FIELD_TIME, + LOG_FIELD_ALERT, + LOG_FIELD_ERROR, + LOG_FIELD_INFO, +}; + +static const enum color field_colors[] = { + [LOG_FIELD_SUBSYS] = COLOR_YELLOW, + [LOG_FIELD_TIME] = COLOR_GREEN, + [LOG_FIELD_ALERT] = COLOR_RED, + [LOG_FIELD_ERROR] = COLOR_BOLD, + [LOG_FIELD_INFO] = COLOR_NONE, +}; + +/* If set all colors are bolder */ +static bool dark_mode; + +/* Standard terminal escape codes for colors and bold */ +static const uint8_t color_esc_code[] = { + [COLOR_RED] = 31, + [COLOR_GREEN] = 32, + [COLOR_YELLOW] = 33, + [COLOR_BLUE] = 34, + [COLOR_MAGENTA] = 35, + [COLOR_CYAN] = 36, + [COLOR_WHITE] = 37, + [COLOR_BOLD] = 1, +}; + +__rte_format_printf(4, 5) +static int +color_snprintf(char *buf, size_t len, enum log_field field, + const char *fmt, ...) +{ + enum color color = field_colors[field]; + uint8_t esc = color_esc_code[color]; + va_list args; + int ret = 0; + + va_start(args, fmt); + if (esc == 0) { + ret = vsnprintf(buf, len, fmt, args); + } else { + ret = snprintf(buf, len, + dark_mode ? "\e[1;%um" : "\e[%um", esc); + ret += vsnprintf(buf + ret, len - ret, fmt, args); + ret += snprintf(buf + ret, len - ret, "%s", "\e[0m"); + } + va_end(args); + + 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 = LOG_COLOR_ALWAYS; + else if (strcmp(mode, "never") == 0) + log_color_mode = LOG_COLOR_NEVER; + else if (strcmp(mode, "auto") == 0) + log_color_mode = LOG_COLOR_AUTO; + else + return -1; + + return 0; +} + +bool +log_color_enabled(bool is_terminal) +{ + char *env, *sep; + + /* Set dark mode using the defacto heuristics used by other programs */ + env = getenv("COLORFGBG"); + if (env) { + sep = strrchr(env, ';'); + if (sep && + ((sep[1] >= '0' && sep[1] <= '6') || sep[1] == '8') && + sep[2] == '\0') + dark_mode = true; + } + + switch (log_color_mode) { + case LOG_COLOR_ALWAYS: + return true; + case LOG_COLOR_AUTO: + return is_terminal; + default: + return false; + + } +} + +/* Look ast the current message level to determine color of field */ +static enum log_field +color_msg_field(void) +{ + const int level = rte_log_cur_msg_loglevel(); + + if (level <= 0 || level >= (int)RTE_LOG_INFO) + return LOG_FIELD_INFO; + else if (level >= (int)RTE_LOG_ERR) + return LOG_FIELD_ERROR; + else + return LOG_FIELD_ALERT; +} + +__rte_format_printf(3, 0) +static int +color_fmt_msg(char *out, size_t len, const char *format, va_list ap) +{ + enum log_field field = color_msg_field(); + char buf[LINE_MAX]; + int ret = 0; + + /* format raw message */ + vsnprintf(buf, sizeof(buf), format, ap); + const char *msg = buf; + + /* + * use convention that first part of message (up to the ':' character) + * is the subsystem id and should be highlighted. + */ + const char *cp = strchr(msg, ':'); + if (cp) { + /* print first part in yellow */ + ret = color_snprintf(out, len, LOG_FIELD_SUBSYS, + "%.*s", (int)(cp - msg + 1), msg); + msg = cp + 1; + } + + ret += color_snprintf(out + ret, len - ret, field, "%s", msg); + return ret; +} + +__rte_format_printf(2, 0) +int +color_print(FILE *f, const char *format, va_list ap) +{ + char out[LINE_MAX]; + + /* format raw message */ + int ret = color_fmt_msg(out, sizeof(out), format, ap); + if (fputs(out, f) < 0) + return -1; + + return ret; +} + +__rte_format_printf(2, 0) +int +color_print_with_timestamp(FILE *f, const char *format, va_list ap) +{ + char out[LINE_MAX]; + char tsbuf[128]; + int ret = 0; + + if (log_timestamp(tsbuf, sizeof(tsbuf)) > 0) + ret = color_snprintf(out, sizeof(out), + LOG_FIELD_TIME, "[%s] ", tsbuf); + + ret += color_fmt_msg(out + ret, sizeof(out) - ret, format, ap); + if (fputs(out, f) < 0) + return -1; + + return ret; +} diff --git a/lib/log/log_internal.h b/lib/log/log_internal.h index 82fdc21ac2..bba7041ea3 100644 --- a/lib/log/log_internal.h +++ b/lib/log/log_internal.h @@ -50,5 +50,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_private.h b/lib/log/log_private.h index d8602681b2..855e32db90 100644 --- a/lib/log/log_private.h +++ b/lib/log/log_private.h @@ -50,4 +50,12 @@ log_journal_open(const char *id __rte_unused) } #endif /* !RTE_EXEC_ENV_LINUX */ +bool log_color_enabled(bool is_tty); + +__rte_format_printf(2, 0) +int color_print(FILE *f, const char *format, va_list ap); + +__rte_format_printf(2, 0) +int color_print_with_timestamp(FILE *f, const char *format, va_list ap); + #endif /* LOG_PRIVATE_H */ diff --git a/lib/log/meson.build b/lib/log/meson.build index 86e4452b19..b3de57b9c7 100644 --- a/lib/log/meson.build +++ b/lib/log/meson.build @@ -4,6 +4,7 @@ includes += global_inc sources = files( 'log.c', + 'log_color.c', 'log_timestamp.c', ) diff --git a/lib/log/version.map b/lib/log/version.map index 800d3943bc..09d8a4289b 100644 --- a/lib/log/version.map +++ b/lib/log/version.map @@ -25,6 +25,7 @@ DPDK_25 { INTERNAL { global: + eal_log_color; eal_log_init; eal_log_journal; # WINDOWS_NO_EXPORT eal_log_level2str; -- 2.45.2