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 642A743D36; Sun, 24 Mar 2024 03:42:28 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id 1FE9C40A6D; Sun, 24 Mar 2024 03:41:35 +0100 (CET) Received: from mail-pl1-f180.google.com (mail-pl1-f180.google.com [209.85.214.180]) by mails.dpdk.org (Postfix) with ESMTP id 4966F4064A for ; Sun, 24 Mar 2024 03:41:28 +0100 (CET) Received: by mail-pl1-f180.google.com with SMTP id d9443c01a7336-1deffa23bb9so24371965ad.2 for ; Sat, 23 Mar 2024 19:41:28 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20230601.gappssmtp.com; s=20230601; t=1711248087; x=1711852887; 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=DmhxcTO2G7R7rt7pFjKteVsBa/8EY55YKFCvUAxoG4I=; b=NUEogCRp41zvGAHI/w9z0AfaT2gAH/4vCEZ9EAkjtfALEQFMgSGTugsh0R5oq6dBqC iEbcaf4/ReolRUCXao4/3mDGIRhmqVHBEpi7pCcYi9kgExU5Iln1Yy9FYyL/ZkBR5eJZ /K2l4c0d3aoGoSnz7Z36OMGwV7a/wofWeE2kuBYHQbJkX+kyy/ycCOhLnM/Gr0QrNRBD sPruzdbNImHuEwIUVJwLydTJIzvZ6tXAkTkMKb2+/DopOzA5oSCEZl1WP69oNmxKEPMs AkUhaGyCg4rpXzPfEhgf3gPKVYJi3tMopPl5zAljK5N8Dd16oDAZxVWNMbVWjpYJ9StQ GSxQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1711248087; x=1711852887; 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=DmhxcTO2G7R7rt7pFjKteVsBa/8EY55YKFCvUAxoG4I=; b=pkUp2NLaQtdIcacCDKCGbkDulMMwYlFg9lnDAf8S5qjnS6yYH7UcdyQ4CBUkWUlIUl EHUJHeVwq4G1jA/wc4vz2H50PlU/43iXlAnevDPj9/vSx26W9NQzeBo7i4jS3A8tbTCU EtFu2j4ivOCSNhPIYIqGM665aNJeyy1p+qUYNS+ULcD6FJk7eetU/5eShz26uh8i8QQT 83qtyl9wohX5Ee28AE1WuYt6k3qUxjCS5YBe1zEEnwU7J8JTpDB5cXOoC7wbc0mIxxS4 EoRMJhahVOfrqwLRuvcxzLjgktTggnv/9AFXns6halS4MRRonEKCvnaTLc8BjQD1crv1 hzgQ== X-Gm-Message-State: AOJu0YzuXIOGmlCcm9rEHZAW+TLIi9m3/YQIJpMnkY0sjhh6CUj1401U O1+gCi1kqUtUrouBnZCH/sWM2HmZRTB1mbb6fv2gyWm+lBfbxkUrU7+4cROZI+5XQmX0IMM3KrE n X-Google-Smtp-Source: AGHT+IFRH+nr4yLeqrH6sLgIz0L2ylLruCRo3j6KSUII6QJUqGDtXx9pL2n8jIkJaYX2vSAVUDWGLQ== X-Received: by 2002:a17:902:b48b:b0:1dc:abeb:22fe with SMTP id y11-20020a170902b48b00b001dcabeb22femr3227103plr.65.1711248087348; Sat, 23 Mar 2024 19:41:27 -0700 (PDT) Received: from hermes.local (204-195-123-203.wavecable.com. [204.195.123.203]) by smtp.gmail.com with ESMTPSA id q17-20020a17090311d100b001dc3c4e7a12sm2244980plh.14.2024.03.23.19.41.26 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sat, 23 Mar 2024 19:41:27 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger Subject: [PATCH v11 9/9] log: colorize log output Date: Sat, 23 Mar 2024 19:33:31 -0700 Message-ID: <20240324024109.306614-10-stephen@networkplumber.org> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240324024109.306614-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20240324024109.306614-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 --- doc/guides/prog_guide/log_lib.rst | 14 ++- lib/eal/common/eal_common_options.c | 1 + lib/eal/common/eal_options.h | 2 + lib/log/log.c | 153 +++++++++++++++++++++++++++- lib/log/log_internal.h | 5 + lib/log/version.map | 1 + 6 files changed, 173 insertions(+), 3 deletions(-) diff --git a/doc/guides/prog_guide/log_lib.rst b/doc/guides/prog_guide/log_lib.rst index 83949cce35..e0cb9bb9ed 100644 --- a/doc/guides/prog_guide/log_lib.rst +++ b/doc/guides/prog_guide/log_lib.rst @@ -58,6 +58,19 @@ 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 +~~~~~~~~~~~~ + +It is useful ot be able see important messages highlighted. This is controlled by the +``--log-color`` option. The 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 + + Console timestamp ~~~~~~~~~~~~~~~~~ @@ -83,7 +96,6 @@ To prefix all console messages with ISO format time the syntax is:: /path/to/app --log-timestamp=iso - 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 bc6d87266d..0da6729c64 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, 1, 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 }, diff --git a/lib/eal/common/eal_options.h b/lib/eal/common/eal_options.h index 197b7b25ef..c1696d75e5 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 4cfa160e3b..e75ed804ec 100644 --- a/lib/log/log.c +++ b/lib/log/log.c @@ -22,6 +22,7 @@ #include #endif +#include #include #include @@ -41,6 +42,12 @@ enum eal_log_time_format { EAL_LOG_TIMESTAMP_ISO, }; +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); @@ -53,6 +60,7 @@ static struct rte_logs { int journal_fd; /**< Journal file descriptor if using */ 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 */ @@ -665,6 +673,74 @@ 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 +}; + +static const char * const color_code[] = { + [COLOR_NONE] = "", + [COLOR_RED] = "\e[31m", + [COLOR_GREEN] = "\e[32m", + [COLOR_YELLOW] = "\e[33m", + [COLOR_BLUE] = "\e[34m", + [COLOR_MAGENTA] = "\e[35m", + [COLOR_CYAN] = "\e[36m", + [COLOR_WHITE] = "\e[37m", + [COLOR_BOLD] = "\e[1m", + [COLOR_CLEAR] = "\e[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]); + + 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 @@ -688,6 +764,70 @@ log_print_with_timestamp(FILE *f, uint32_t level, return log_print(f, level, format, ap); } +__rte_format_printf(3, 0) +static int +color_print(FILE *f, uint32_t level, const char *format, va_list ap) +{ + char *buf = NULL; + + /* need to make temporary buffer for color scan */ + if (vasprintf(&buf, format, ap) > 0) + return color_log_write(f, level, buf); + + /* 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 bool +use_color(int out_fd) +{ + 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 !!isatty(out_fd); + } + +} + #ifdef RTE_EXEC_ENV_LINUX /* * send message using journal protocol to journald @@ -817,10 +957,19 @@ eal_log_init(const char *id __rte_unused) rte_logs.print_func = journal_print; journal_send_id(jfd, id); } + } else #endif - if (rte_logs.time_format != EAL_LOG_TIMESTAMP_NONE) { - rte_logs.print_func = log_print_with_timestamp; + if (use_color(STDERR_FILENO)) { + if (rte_logs.time_format != EAL_LOG_TIMESTAMP_NONE) + rte_logs.print_func = color_print_with_timestamp; + else + rte_logs.print_func = color_print; + } else { + if (rte_logs.time_format != EAL_LOG_TIMESTAMP_NONE) + rte_logs.print_func = log_print_with_timestamp; + else + rte_logs.print_func = log_print; } #if RTE_LOG_DP_LEVEL >= RTE_LOG_DEBUG diff --git a/lib/log/log_internal.h b/lib/log/log_internal.h index 3544ae49ac..5b8bb6ffc9 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/version.map b/lib/log/version.map index 7fd5b39e3a..9ca561b05b 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