Skip to content

Commit

Permalink
log: colorize log output
Browse files Browse the repository at this point in the history
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 <[email protected]>
Acked-by: Morten Brørup <[email protected]>
Acked-by: Bruce Richardson <[email protected]>
Acked-by: Chengwen Feng <[email protected]>
  • Loading branch information
shemminger authored and david-marchand committed Nov 7, 2024
1 parent 1125287 commit 132139a
Show file tree
Hide file tree
Showing 10 changed files with 307 additions and 4 deletions.
24 changes: 24 additions & 0 deletions app/test/test_eal_flags.c
Original file line number Diff line number Diff line change
Expand Up @@ -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 */

Expand Down Expand Up @@ -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=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);
Expand Down
24 changes: 24 additions & 0 deletions doc/guides/prog_guide/log_lib.rst
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,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
-------------------------------------------

Expand Down Expand Up @@ -140,3 +141,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.
11 changes: 11 additions & 0 deletions lib/eal/common/eal_common_options.c
Original file line number Diff line number Diff line change
Expand Up @@ -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 },
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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"
Expand Down
2 changes: 2 additions & 0 deletions lib/eal/common/eal_options.h
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
21 changes: 17 additions & 4 deletions lib/log/log.c
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
#include <regex.h>
#include <fnmatch.h>
#include <sys/queue.h>
#include <unistd.h>

#include <rte_common.h>
#include <rte_log.h>
Expand Down Expand Up @@ -520,10 +521,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
Expand Down
214 changes: 214 additions & 0 deletions lib/log/log_color.c
Original file line number Diff line number Diff line change
@@ -0,0 +1,214 @@
/* 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;
}

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;
}
5 changes: 5 additions & 0 deletions lib/log/log_internal.h
Original file line number Diff line number Diff line change
Expand Up @@ -56,5 +56,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 */
8 changes: 8 additions & 0 deletions lib/log/log_private.h
Original file line number Diff line number Diff line change
Expand Up @@ -42,4 +42,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 */
Loading

0 comments on commit 132139a

Please sign in to comment.