[PATCH v27 13/14] log: colorize log output
Baruch Even
baruch at weka.io
Fri Oct 25 17:49:08 CEST 2024
The code has some mentions of `--log-color=none` but only the `never`
option is parsed.
On Thu, Oct 24, 2024 at 6:22 AM Stephen Hemminger <
stephen at networkplumber.org> wrote:
> 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 <stephen at networkplumber.org>
> Acked-by: Morten Brørup <mb at smartsharesystems.com>
> Acked-by: Bruce Richardson <bruce.richardson at intel.com>
> Acked-by: Chengwen Feng <fengchengwen at huawei.com>
> ---
> app/test/test_eal_flags.c | 24 ++++
> doc/guides/prog_guide/log_lib.rst | 24 ++++
> lib/eal/common/eal_common_options.c | 11 ++
> lib/eal/common/eal_options.h | 2 +
> lib/log/log.c | 20 ++-
> 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, 308 insertions(+), 4 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 e24630edde..cd73711da6 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 82d3b7be2b..a4f880037b 100644
> --- a/doc/guides/prog_guide/log_lib.rst
> +++ b/doc/guides/prog_guide/log_lib.rst
> @@ -57,6 +57,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
> -------------------------------------------
>
> @@ -137,3 +138,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/lib/eal/common/eal_common_options.c
> b/lib/eal/common/eal_common_options.c
> index a70d63479a..6965666a7c 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 },
> @@ -1620,6 +1621,7 @@ eal_log_level_parse(int argc, char * const argv[])
> case OPT_LOG_LEVEL_NUM:
> case OPT_SYSLOG_NUM:
> case OPT_LOG_TIMESTAMP_NUM:
> + case OPT_LOG_COLOR_NUM:
> if (eal_parse_common_option(opt, optarg,
> internal_conf) < 0)
> return -1;
> break;
> @@ -1859,6 +1861,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) {
> @@ -2225,6 +2235,7 @@ eal_common_usage(void)
> " Set specific log level\n"
> " --"OPT_LOG_LEVEL"=help Show log types and levels\n"
> " --"OPT_LOG_TIMESTAMP"[=<format>] Timestamp log output\n"
> + " --"OPT_LOG_COLOR"[=<when>] Colorize log messages\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 e24c9eca53..87c3c32f86 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/log/log.c b/lib/log/log.c
> index 343f9d77b7..f1bd408bee 100644
> --- a/lib/log/log.c
> +++ b/lib/log/log.c
> @@ -515,10 +515,22 @@ eal_log_init(const char *id)
>
> 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
> 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 <limits.h>
> +#include <stdbool.h>
> +#include <stdio.h>
> +#include <stdint.h>
> +#include <stdarg.h>
> +#include <stdlib.h>
> +#include <string.h>
> +
> +#include <rte_common.h>
> +#include <rte_log.h>
> +
> +#ifdef RTE_EXEC_ENV_WINDOWS
> +#include <rte_os_shim.h>
> +#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 625f57c0cc..42babbcac1 100644
> --- a/lib/log/log_private.h
> +++ b/lib/log/log_private.h
> @@ -25,4 +25,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.45.2
>
>
--
Baruch Even
Platform Technical Lead at WEKA
E baruch at weka.io* *W https://www.weka.io* *
[image: App Banner Image]
<https://www.weka.io/trends-in-AI-emsig?utm_campaign=signature&utm_source=WiseStamp&utm_medium=email>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mails.dpdk.org/archives/dev/attachments/20241025/d3670545/attachment-0001.htm>
More information about the dev
mailing list