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 3D58B43D73; Fri, 29 Mar 2024 00:53:51 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id ABC7342DD5; Fri, 29 Mar 2024 00:52:34 +0100 (CET) Received: from mail-oo1-f45.google.com (mail-oo1-f45.google.com [209.85.161.45]) by mails.dpdk.org (Postfix) with ESMTP id 305E842D0C for ; Fri, 29 Mar 2024 00:52:20 +0100 (CET) Received: by mail-oo1-f45.google.com with SMTP id 006d021491bc7-5a4a102145fso756729eaf.3 for ; Thu, 28 Mar 2024 16:52:20 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20230601.gappssmtp.com; s=20230601; t=1711669939; x=1712274739; 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=8y4fO2IxafOGdKbX1uE26QnkEVjNCqSc9vkZoCMYRwo=; b=JE8sZVrL2PAykGsONTEQ57qO37dRcQP7Zp9i9jjtnur34xIC6Bp+FbgJISX7J4FWXO 1elG7fzYawIo94xQqqfrmQ1+9PMGch5ySvVWPWB2GfqE9uIMUcjCHevGN/D4acxZleLJ 0SMqGbhTZyooWzkq41t9sjiT0nDWNAg9teyFN9jIyZweIoQZ7p0bP4VPmw3PTb4DUrm8 crRf8XG5WG73r83AqMVMqCX38MaPdgsih3pVhxDP93gKRvO4dUAvFtZfm96Nx9bY2WgB yVFASa+kYWL6uWzX5D95aLq72xj8GIjFzvM95j2XpFOnnDoL5tXF3q1G182YuV3jEJii dvhw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1711669939; x=1712274739; 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=8y4fO2IxafOGdKbX1uE26QnkEVjNCqSc9vkZoCMYRwo=; b=SNt5VMAzyChz2X67eCjeISJb/qqch7/7Aaxn2po597NceB2/AkKrLYt8DnDVf1rBBQ DvPpYZ7mVueFzNkFu4U/WfqBHpaohr/NbRi18GCLXXNxWrwlwVPWbQcz2+lnYFpx363l JCJ8LT0qnxRYoPAhyX5CbcwoBdSBJiCIJuwjz8kp7UF94uH1+J15dvVjNYW76OXPOTwB ztSZiS26ovcYTONaljPotVeiKc208Hqn3QQexw+aH0BMzuF8HNE5KyzD0FErRMvUJ1mI vzSqzxbxo0DFVB9Eadn+KEvTM3/TxqPMLmrKmwU3YRFBxIZ+GkN6yNafc4VMTa2e61tG W3Hg== X-Gm-Message-State: AOJu0YwzdMRyuYnvqRWdjX9pO7vK4wR+ggyizZ9g8ygpV9xCvoj+IlpM HGe0EDr0FSHZxNVr+YdVyRg77dLNHpgz/mLTQWLNqpLkUCfZqJJT9uEsjoZgCsKOvtUYFVdt+eI 4 X-Google-Smtp-Source: AGHT+IHUHSdG4Mp8DjkFzplUhdqP7PuxwwTbuOrb3fmzbWek0toR5vkD23P/DVD4BzwMBFpSiH/afQ== X-Received: by 2002:a05:6359:4ca8:b0:17c:2ce0:f55 with SMTP id kk40-20020a0563594ca800b0017c2ce00f55mr808353rwc.19.1711669939304; Thu, 28 Mar 2024 16:52:19 -0700 (PDT) Received: from hermes.local (204-195-123-203.wavecable.com. [204.195.123.203]) by smtp.gmail.com with ESMTPSA id g21-20020a631115000000b005df58c83e89sm1875650pgl.84.2024.03.28.16.52.18 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 28 Mar 2024 16:52:18 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger Subject: [PATCH v18 15/15] log: colorize log output Date: Thu, 28 Mar 2024 16:49:45 -0700 Message-ID: <20240328235156.5768-16-stephen@networkplumber.org> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240328235156.5768-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20240328235156.5768-1-stephen@networkplumber.org> MIME-Version: 1.0 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. Signed-off-by: Stephen Hemminger --- app/test/test_eal_flags.c | 24 ++++ doc/guides/prog_guide/log_lib.rst | 16 ++- lib/eal/common/eal_common_options.c | 11 ++ lib/eal/common/eal_options.h | 2 + lib/log/log.c | 168 +++++++++++++++++++++++++++- lib/log/log_internal.h | 5 + lib/log/version.map | 1 + 7 files changed, 223 insertions(+), 4 deletions(-) diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c index 08f4866461..c6c05e2e1d 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 abaedc7212..40727ebaae 100644 --- a/doc/guides/prog_guide/log_lib.rst +++ b/doc/guides/prog_guide/log_lib.rst @@ -59,6 +59,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 ~~~~~~~~~~~~~ @@ -101,7 +116,6 @@ option. There are three possible settings for this option: If ``--syslog`` option is not specified, then only console (stderr) will be used. - Using Logging APIs to Generate Log Messages ------------------------------------------- diff --git a/lib/eal/common/eal_common_options.c b/lib/eal/common/eal_common_options.c index 9ca7db04aa..5e7ab29ae3 100644 --- a/lib/eal/common/eal_common_options.c +++ b/lib/eal/common/eal_common_options.c @@ -75,6 +75,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, 2, 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 }, @@ -1618,6 +1619,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; @@ -1862,6 +1864,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) { @@ -2229,6 +2239,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 e24c9eca53..5a63c1dd3a 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.c b/lib/log/log.c index 650d294120..75c5e2af78 100644 --- a/lib/log/log.c +++ b/lib/log/log.c @@ -23,6 +23,7 @@ #include #endif +#include #include #include @@ -49,6 +50,12 @@ enum eal_log_syslog { EAL_LOG_SYSLOG_BOTH, /* log to both syslog and stderr */ }; +enum eal_log_color { + EAL_LOG_COLOR_AUTO = 0, /* default */ + EAL_LOG_COLOR_NEVER, + EAL_LOG_COLOR_ALWAYS, +}; + typedef int (*log_print_t)(FILE *f, uint32_t level, const char *fmt, va_list ap); static int log_print(FILE *f, uint32_t level, const char *format, va_list ap); @@ -64,6 +71,7 @@ static struct rte_logs { #endif log_print_t print_func; + enum eal_log_color color_mode; enum eal_log_time_format time_format; struct timespec started; /* when log was initialized */ struct timespec previous; /* when last msg was printed */ @@ -715,6 +723,76 @@ format_timestamp(char *tsbuf, size_t tsbuflen) return 0; } +enum color { + COLOR_NONE, + COLOR_RED, + COLOR_GREEN, + COLOR_YELLOW, + COLOR_BLUE, + COLOR_MAGENTA, + COLOR_CYAN, + COLOR_WHITE, + COLOR_BOLD, + COLOR_CLEAR +}; + +/* Standard terminal escape codes for colors and bold */ +static const char * const color_code[] = { + [COLOR_NONE] = "", + [COLOR_RED] = "\033[31m", + [COLOR_GREEN] = "\033[32m", + [COLOR_YELLOW] = "\033[33m", + [COLOR_BLUE] = "\033[34m", + [COLOR_MAGENTA] = "\033[35m", + [COLOR_CYAN] = "\033[36m", + [COLOR_WHITE] = "\033[37m", + [COLOR_BOLD] = "\033[1m", + [COLOR_CLEAR] = "\033[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]); + va_end(args); + + return ret; +} + +static ssize_t +color_log_write(FILE *f, int level, char *msg) +{ + char *cp; + ssize_t ret = 0; + + /* + * use convention that first part of message (up to the ':' character) + * is the subsystem id and should be highlighted. + */ + cp = strchr(msg, ':'); + if (cp) { + /* print first part in yellow */ + ret = color_fprintf(stderr, COLOR_YELLOW, "%.*s", + (int)(cp - msg + 1), msg); + msg = cp + 1; + } + + if (level <= 0 || level >= (int)RTE_LOG_INFO) + ret += fprintf(f, "%s", msg); + else if (level >= (int)RTE_LOG_ERR) + ret += color_fprintf(f, COLOR_BOLD, "%s", msg); + else + ret += color_fprintf(f, COLOR_RED, "%s", msg); + + return ret; +} + /* default log print function */ __rte_format_printf(3, 0) static int @@ -930,14 +1008,87 @@ log_open_syslog(const char *id, bool is_terminal) } #endif +__rte_format_printf(3, 0) +static int +color_print(FILE *f, uint32_t level, const char *format, va_list ap) +{ + char *buf = NULL; + int ret; + + /* need to make temporary buffer for color scan */ + ret = vasprintf(&buf, format, ap); + if (ret > 0) { + ret = color_log_write(f, level, buf); + free(buf); + return ret; + } + + /* if vasprintf fails, print without color */ + return log_print(f, level, format, ap); +} + +__rte_format_printf(3, 0) +static int +color_print_with_timestamp(FILE *f, uint32_t level, + const char *format, va_list ap) +{ + char tsbuf[128]; + + if (format_timestamp(tsbuf, sizeof(tsbuf)) > 0) + color_fprintf(f, COLOR_GREEN, "[%s] ", tsbuf); + + return color_print(f, level, format, ap); +} + +/* + * 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) + rte_logs.color_mode = EAL_LOG_COLOR_ALWAYS; + else if (strcmp(mode, "never") == 0) + rte_logs.color_mode = EAL_LOG_COLOR_NEVER; + else if (strcmp(mode, "auto") == 0) + rte_logs.color_mode = EAL_LOG_COLOR_AUTO; + else + return -1; + + return 0; +} + +static inline bool +use_color(bool is_terminal) +{ + switch (rte_logs.color_mode) { + default: + case EAL_LOG_COLOR_NEVER: + return false; + case EAL_LOG_COLOR_ALWAYS: + return true; + case EAL_LOG_COLOR_AUTO: + return is_terminal; + } + +} + /* Choose how log output is directed */ static void log_output_selection(const char *id) { + bool is_terminal; + #ifdef RTE_EXEC_ENV_WINDOWS RTE_SET_USED(id); + + is_terminal = _isatty(_fileno(stderr)); #else - bool is_terminal = isatty(STDERR_FILENO); + is_terminal = isatty(STDERR_FILENO); /* If stderr is redirected to systemd journal then upgrade */ if (!is_terminal && is_journal(STDERR_FILENO)) { @@ -957,8 +1108,19 @@ log_output_selection(const char *id) return; } #endif - if (rte_logs.time_format != EAL_LOG_TIMESTAMP_NONE) - rte_logs.print_func = log_print_with_timestamp; + + if (use_color(is_terminal)) { + if (rte_logs.time_format == EAL_LOG_TIMESTAMP_NONE) + rte_logs.print_func = color_print; + else + rte_logs.print_func = color_print_with_timestamp; + } else { + if (rte_logs.time_format == EAL_LOG_TIMESTAMP_NONE) + rte_logs.print_func = log_print; + else + rte_logs.print_func = log_print_with_timestamp; + } + } /* diff --git a/lib/log/log_internal.h b/lib/log/log_internal.h index 7c7d44eed2..525e1397fd 100644 --- a/lib/log/log_internal.h +++ b/lib/log/log_internal.h @@ -47,5 +47,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/version.map b/lib/log/version.map index 14d6681a5f..7fa79b20ff 100644 --- a/lib/log/version.map +++ b/lib/log/version.map @@ -25,6 +25,7 @@ DPDK_24 { INTERNAL { global: + eal_log_color; eal_log_init; eal_log_level2str; eal_log_save_pattern; -- 2.43.0