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 D7E1F45CB1; Fri, 8 Nov 2024 09:49:30 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id 97AE042F0A; Fri, 8 Nov 2024 09:49:14 +0100 (CET) Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.133.124]) by mails.dpdk.org (Postfix) with ESMTP id A4D4C42EDB for ; Fri, 8 Nov 2024 09:49:12 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1731055752; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=hq8+RYrRdpb844fqUotGN8SY7/XojUowcyskysP07UU=; b=fMBEmRBlaIfbofIBRQ6qJIXDrVVJ8EAOhbVmo+kvF6l4UFt2/wX8J2IW0hp1+DPU5yu3q8 IWr6gi3NEsqIsgdu4s5j0+kQWAaXQ1wWi8cjxyFukM/aO3mOk4sWtyLEV/dI+le3LrXKzT ZZei2NNUZgepkNLwxRPXGLRuy6PdI2g= Received: from mx-prod-mc-02.mail-002.prod.us-west-2.aws.redhat.com (ec2-54-186-198-63.us-west-2.compute.amazonaws.com [54.186.198.63]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384) id us-mta-682-BcRJ7OfONqaatddPFXmrfg-1; Fri, 08 Nov 2024 03:49:08 -0500 X-MC-Unique: BcRJ7OfONqaatddPFXmrfg-1 X-Mimecast-MFC-AGG-ID: BcRJ7OfONqaatddPFXmrfg Received: from mx-prod-int-05.mail-002.prod.us-west-2.aws.redhat.com (mx-prod-int-05.mail-002.prod.us-west-2.aws.redhat.com [10.30.177.17]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by mx-prod-mc-02.mail-002.prod.us-west-2.aws.redhat.com (Postfix) with ESMTPS id 0212E195395B; Fri, 8 Nov 2024 08:49:07 +0000 (UTC) Received: from dmarchan.redhat.com (unknown [10.45.224.57]) by mx-prod-int-05.mail-002.prod.us-west-2.aws.redhat.com (Postfix) with ESMTP id 4B2791953880; Fri, 8 Nov 2024 08:49:04 +0000 (UTC) From: David Marchand To: dev@dpdk.org Cc: Stephen Hemminger , =?UTF-8?q?Morten=20Br=C3=B8rup?= , Bruce Richardson , Chengwen Feng , Tyler Retzlaff , Dmitry Kozlyuk Subject: [PATCH v32 11/12] log: colorize log output Date: Fri, 8 Nov 2024 09:48:00 +0100 Message-ID: <20241108084802.2942435-12-david.marchand@redhat.com> In-Reply-To: <20241108084802.2942435-1-david.marchand@redhat.com> References: <20200814173441.23086-1-stephen@networkplumber.org> <20241108084802.2942435-1-david.marchand@redhat.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 3.0 on 10.30.177.17 X-Mimecast-Spam-Score: 0 X-Mimecast-MFC-PROC-ID: rVyfcdXhTHL8TL9HLGl_5n0rhZHEmgmNnE51xvI11B4_1731055747 X-Mimecast-Originator: redhat.com 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 From: Stephen Hemminger 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. Note: add fileno() and isatty() to the Windows wrapper. Signed-off-by: Stephen Hemminger Acked-by: Morten Brørup Acked-by: Bruce Richardson Acked-by: Chengwen Feng --- app/test/test_eal_flags.c | 24 +++ doc/guides/prog_guide/log_lib.rst | 24 +++ doc/guides/rel_notes/release_24_11.rst | 2 + lib/eal/common/eal_common_options.c | 11 ++ lib/eal/common/eal_options.h | 2 + lib/eal/windows/include/rte_os_shim.h | 2 + lib/log/log.c | 23 ++- lib/log/log_color.c | 214 +++++++++++++++++++++++++ lib/log/log_internal.h | 5 + lib/log/log_private.h | 8 + lib/log/meson.build | 1 + lib/log/version.map | 1 + 12 files changed, 312 insertions(+), 5 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 1a062fe0e8..d37d6b8627 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 */ if (launch_proc(argv0) == 0) { @@ -1186,6 +1198,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=never 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); rmdir(hugepath_dir2); diff --git a/doc/guides/prog_guide/log_lib.rst b/doc/guides/prog_guide/log_lib.rst index a2e95317f5..3e888b8965 100644 --- a/doc/guides/prog_guide/log_lib.rst +++ b/doc/guides/prog_guide/log_lib.rst @@ -59,6 +59,7 @@ 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. + Using Logging APIs to Generate Log Messages ------------------------------------------- @@ -138,3 +139,26 @@ To prefix all console messages with ISO format time the syntax is:: Timestamp option has no effect if using syslog because the ``syslog()`` service already does timestamping internally. + + +Color output +~~~~~~~~~~~~ + +The log library will highlight important messages. +This is controlled by the ``--log-color`` option. +The optional argument describes when color is enabled: + +:never: Do not enable color. This is the default behavior. + +:auto: Enable color only when printing to a terminal. + This is the same as ``--log-color`` with no argument. + +:always: Always print color. + +For example to enable color in logs if using terminal:: + + /path/to/app --log-color + +.. note:: + + Color output is never used for syslog or systemd journal logging. diff --git a/doc/guides/rel_notes/release_24_11.rst b/doc/guides/rel_notes/release_24_11.rst index 341606f541..543becba28 100644 --- a/doc/guides/rel_notes/release_24_11.rst +++ b/doc/guides/rel_notes/release_24_11.rst @@ -128,6 +128,8 @@ New Features * Log messages can be timestamped with ``--log-timestamp`` option. + * Log messages can be colorized with the ``--log-color`` 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 7de6a25e62..79db9a47dd 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_TIMESTAMP, 2, NULL, OPT_LOG_TIMESTAMP_NUM }, {OPT_TRACE, 1, NULL, OPT_TRACE_NUM }, @@ -1599,6 +1600,7 @@ bool eal_option_is_log(int opt) { switch (opt) { + case OPT_LOG_COLOR_NUM: case OPT_LOG_LEVEL_NUM: case OPT_LOG_TIMESTAMP_NUM: case OPT_SYSLOG_NUM: @@ -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) { @@ -2235,6 +2245,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 a1b52ae694..95fb4f6108 100644 --- a/lib/eal/common/eal_options.h +++ b/lib/eal/common/eal_options.h @@ -33,6 +33,8 @@ enum { OPT_HUGE_UNLINK_NUM, #define OPT_LCORES "lcores" OPT_LCORES_NUM, +#define OPT_LOG_COLOR "log-color" + OPT_LOG_COLOR_NUM, #define OPT_LOG_LEVEL "log-level" OPT_LOG_LEVEL_NUM, #define OPT_LOG_TIMESTAMP "log-timestamp" diff --git a/lib/eal/windows/include/rte_os_shim.h b/lib/eal/windows/include/rte_os_shim.h index 665c9ac93b..0e74eb19c7 100644 --- a/lib/eal/windows/include/rte_os_shim.h +++ b/lib/eal/windows/include/rte_os_shim.h @@ -30,6 +30,8 @@ #define write(fd, buf, n) _write(fd, buf, n) #define close(fd) _close(fd) #define unlink(path) _unlink(path) +#define fileno(f) _fileno(f) +#define isatty(fd) _isatty(fd) #define IPVERSION 4 diff --git a/lib/log/log.c b/lib/log/log.c index 0974adc81f..eb087d601e 100644 --- a/lib/log/log.c +++ b/lib/log/log.c @@ -12,6 +12,7 @@ #include #include #include +#include #include #include @@ -517,12 +518,24 @@ eal_log_init(const char *id) logf = log_syslog_open(id); /* if either syslog or journal is used, then no special handling */ - if (logf) + if (logf) { rte_openlog_stream(logf); - else if (log_timestamp_enabled()) - rte_logs.print_func = log_print_with_timestamp; - else - rte_logs.print_func = vfprintf; + } else { + bool is_terminal = isatty(fileno(stderr)); + bool use_color = log_color_enabled(is_terminal); + + if (log_timestamp_enabled()) { + if (use_color) + rte_logs.print_func = color_print_with_timestamp; + else + rte_logs.print_func = log_print_with_timestamp; + } else { + if (use_color) + rte_logs.print_func = color_print; + else + rte_logs.print_func = vfprintf; + } + } } #if RTE_LOG_DP_LEVEL >= RTE_LOG_DEBUG diff --git a/lib/log/log_color.c b/lib/log/log_color.c new file mode 100644 index 0000000000..04eb5aa485 --- /dev/null +++ b/lib/log/log_color.c @@ -0,0 +1,214 @@ +/* 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 ? "\033[1;%um" : "\033[%um", esc); + ret += vsnprintf(buf + ret, len - ret, fmt, args); + ret += snprintf(buf + ret, len - ret, "%s", "\033[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; + } + + if (log_color_mode == LOG_COLOR_ALWAYS) + return true; + else if (log_color_mode == LOG_COLOR_AUTO) + return is_terminal; + else + 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); + /* skip the first part */ + 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 1b66057fd6..f275346c7b 100644 --- a/lib/log/log_private.h +++ b/lib/log/log_private.h @@ -46,4 +46,12 @@ 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); +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.47.0