Re: [PATCH v27 13/14] log: colorize log output

[Baruch Even <baruch@weka.io>]

[-- Attachment #1: Type: text/plain, Size: 16983 bytes --]

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@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@networkplumber.org>
> Acked-by: Morten Brørup <mb@smartsharesystems.com>
> Acked-by: Bruce Richardson <bruce.richardson@intel.com>
> Acked-by: Chengwen Feng <fengchengwen@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@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>

[-- Attachment #2: Type: text/html, Size: 23752 bytes --]