From 93d5be6ffc6a564e512bcb79feaaa59d20548a9e Mon Sep 17 00:00:00 2001 From: Devaev Maxim Date: Fri, 6 Sep 2019 22:26:15 +0300 Subject: [PATCH] color logging --- src/encoders/omx/formatters.h | 10 +----- src/http/server.c | 2 +- src/logging.h | 63 +++++++++++++++++++++++------------ src/options.c | 27 ++++++++++----- src/stream.c | 2 +- 5 files changed, 64 insertions(+), 40 deletions(-) diff --git a/src/encoders/omx/formatters.h b/src/encoders/omx/formatters.h index 6f98f3a..f9ac460 100644 --- a/src/encoders/omx/formatters.h +++ b/src/encoders/omx/formatters.h @@ -22,23 +22,15 @@ #pragma once -#include - -#include - #include #include #include #include "../../logging.h" -#include "../../tools.h" #define LOG_OMX_ERROR(_error, _msg, ...) { \ - LOGGING_LOCK; \ - printf("-- ERROR [%.03Lf tid=%ld] -- " _msg ": %s\n", get_now_monotonic(), \ - syscall(SYS_gettid), ##__VA_ARGS__, omx_error_to_string(_error)); \ - LOGGING_UNLOCK; \ + LOG_ERROR(_msg ": %s", ##__VA_ARGS__, omx_error_to_string(_error)); \ } diff --git a/src/http/server.c b/src/http/server.c index b9b737a..331726f 100644 --- a/src/http/server.c +++ b/src/http/server.c @@ -895,7 +895,7 @@ static bool _expose_new_picture_unsafe(struct http_server_t *server) { EXPOSED(expose_cmp_time) = EXPOSED(expose_begin_time); EXPOSED(expose_end_time) = get_now_monotonic(); - LOG_VERBOSE("HTTP: exposed new frame; full exposition time = %.06Lf", + LOG_VERBOSE("HTTP: exposed new frame; full exposition time = %.06Lf", EXPOSED(expose_end_time) - EXPOSED(expose_begin_time)); # undef EXPOSED diff --git a/src/logging.h b/src/logging.h index 56698de..f368bb1 100644 --- a/src/logging.h +++ b/src/logging.h @@ -23,8 +23,10 @@ #pragma once #include +#include #include #include +#include #include #include #include @@ -41,11 +43,14 @@ enum { LOG_LEVEL_DEBUG, } log_level; +bool log_colored; + pthread_mutex_t log_mutex; #define LOGGING_INIT { \ log_level = LOG_LEVEL_INFO; \ + log_colored = isatty(1); \ assert(!pthread_mutex_init(&log_mutex, NULL)); \ } @@ -55,6 +60,15 @@ pthread_mutex_t log_mutex; #define LOGGING_UNLOCK assert(!pthread_mutex_unlock(&log_mutex)) +#define COLOR_GRAY "\x1b[30;1m" +#define COLOR_RED "\x1b[31;1m" +#define COLOR_GREEN "\x1b[32;1m" +#define COLOR_YELLOW "\x1b[33;1m" +#define COLOR_BLUE "\x1b[34;1m" +#define COLOR_CYAN "\x1b[36;1m" +#define COLOR_RESET "\x1b[0m" + + #define SEP_INFO(_ch) { \ LOGGING_LOCK; \ for (int _i = 0; _i < 80; ++_i) { \ @@ -71,57 +85,64 @@ pthread_mutex_t log_mutex; } \ } -#define LOG_PRINTF_NOLOCK(_label, _msg, ...) { \ - printf("-- " _label " [%.03Lf tid=%d] -- " _msg "\n", get_now_monotonic(), get_thread_id(), ##__VA_ARGS__); \ + +#define LOG_PRINTF_NOLOCK(_label_color, _label, _msg_color, _msg, ...) { \ + if (log_colored) { \ + printf(COLOR_GRAY "-- " _label_color _label COLOR_GRAY " [%.03Lf tid=%d]" " -- " COLOR_RESET _msg_color _msg COLOR_RESET, \ + get_now_monotonic(), get_thread_id(), ##__VA_ARGS__); \ + } else { \ + printf("-- " _label " [%.03Lf tid=%d] -- " _msg, \ + get_now_monotonic(), get_thread_id(), ##__VA_ARGS__); \ + } \ + putchar('\n'); \ fflush(stdout); \ } -#define LOG_ERROR(_msg, ...) { \ +#define LOG_PRINTF(_label_color, _label, _msg_color, _msg, ...) { \ LOGGING_LOCK; \ - LOG_PRINTF_NOLOCK("ERROR", _msg, ##__VA_ARGS__); \ + LOG_PRINTF_NOLOCK(_label_color, _label, _msg_color, _msg, ##__VA_ARGS__); \ LOGGING_UNLOCK; \ } +#define LOG_ERROR(_msg, ...) { \ + LOG_PRINTF(COLOR_RED, "ERROR", COLOR_RED, _msg, ##__VA_ARGS__); \ + } + #define LOG_PERROR(_msg, ...) { \ char _buf[1024] = ""; \ char *_ptr = errno_to_string(_buf, 1024); \ - LOGGING_LOCK; \ - printf("-- ERROR [%.03Lf tid=%d] -- " _msg ": %s\n", get_now_monotonic(), get_thread_id(), ##__VA_ARGS__, _ptr); \ - fflush(stdout); \ - LOGGING_UNLOCK; \ + LOG_ERROR(_msg ": %s", ##__VA_ARGS__, _ptr); \ } #define LOG_INFO(_msg, ...) { \ - LOGGING_LOCK; \ - LOG_PRINTF_NOLOCK("INFO ", _msg, ##__VA_ARGS__); \ - LOGGING_UNLOCK; \ + LOG_PRINTF(COLOR_GREEN, "INFO ", "", _msg, ##__VA_ARGS__); \ } #define LOG_INFO_NOLOCK(_msg, ...) { \ - LOG_PRINTF_NOLOCK("INFO ", _msg, ##__VA_ARGS__); \ + LOG_PRINTF_NOLOCK(COLOR_GREEN, "INFO ", "", _msg, ##__VA_ARGS__); \ } #define LOG_PERF(_msg, ...) { \ if (log_level >= LOG_LEVEL_PERF) { \ - LOGGING_LOCK; \ - LOG_PRINTF_NOLOCK("PERF ", _msg, ##__VA_ARGS__); \ - LOGGING_UNLOCK; \ + LOG_PRINTF(COLOR_CYAN, "PERF ", COLOR_CYAN, _msg, ##__VA_ARGS__); \ + } \ + } + +#define LOG_PERF_FPS(_msg, ...) { \ + if (log_level >= LOG_LEVEL_PERF) { \ + LOG_PRINTF(COLOR_YELLOW, "PERF ", COLOR_YELLOW, _msg, ##__VA_ARGS__); \ } \ } #define LOG_VERBOSE(_msg, ...) { \ if (log_level >= LOG_LEVEL_VERBOSE) { \ - LOGGING_LOCK; \ - LOG_PRINTF_NOLOCK("VERB ", _msg, ##__VA_ARGS__); \ - LOGGING_UNLOCK; \ + LOG_PRINTF(COLOR_BLUE, "VERB ", COLOR_BLUE, _msg, ##__VA_ARGS__); \ } \ } #define LOG_DEBUG(_msg, ...) { \ if (log_level >= LOG_LEVEL_DEBUG) { \ - LOGGING_LOCK; \ - LOG_PRINTF_NOLOCK("DEBUG", _msg, ##__VA_ARGS__); \ - LOGGING_UNLOCK; \ + LOG_PRINTF(COLOR_GRAY, "DEBUG", COLOR_GRAY, _msg, ##__VA_ARGS__); \ } \ } diff --git a/src/options.c b/src/options.c index 7de481f..a24f5ea 100644 --- a/src/options.c +++ b/src/options.c @@ -109,10 +109,12 @@ enum _OPT_VALUES { _O_GPIO_WORKERS_BUSY_AT, #endif + _O_LOG_LEVEL, _O_PERF, _O_VERBOSE, _O_DEBUG, - _O_LOG_LEVEL + _O_FORCE_COLORS, + _O_NO_COLORS, }; static const struct option _LONG_OPTS[] = { @@ -174,12 +176,16 @@ static const struct option _LONG_OPTS[] = { {"gpio-workers-busy-at", required_argument, NULL, _O_GPIO_WORKERS_BUSY_AT}, #endif + {"log-level", required_argument, NULL, _O_LOG_LEVEL}, {"perf", no_argument, NULL, _O_PERF}, {"verbose", no_argument, NULL, _O_VERBOSE}, {"debug", no_argument, NULL, _O_DEBUG}, - {"log-level", required_argument, NULL, _O_LOG_LEVEL}, + {"force-colors", no_argument, NULL, _O_FORCE_COLORS}, + {"no-colors", no_argument, NULL, _O_NO_COLORS}, + {"help", no_argument, NULL, _O_HELP}, {"version", no_argument, NULL, _O_VERSION}, + {NULL, 0, NULL, 0}, }; @@ -340,15 +346,18 @@ int parse_options(int argc, char *argv[], struct device_t *dev, struct encoder_t case _O_GPIO_WORKERS_BUSY_AT: OPT_NUMBER("--gpio-workers-busy-at", gpio_pin_workers_busy_at, 0, 256, 0); # endif - case _O_PERF: OPT_SET(log_level, LOG_LEVEL_PERF); - case _O_VERBOSE: OPT_SET(log_level, LOG_LEVEL_VERBOSE); - case _O_DEBUG: OPT_SET(log_level, LOG_LEVEL_DEBUG); - case _O_LOG_LEVEL: OPT_NUMBER("--log-level", log_level, LOG_LEVEL_INFO, LOG_LEVEL_DEBUG, 0); + case _O_LOG_LEVEL: OPT_NUMBER("--log-level", log_level, LOG_LEVEL_INFO, LOG_LEVEL_DEBUG, 0); + case _O_PERF: OPT_SET(log_level, LOG_LEVEL_PERF); + case _O_VERBOSE: OPT_SET(log_level, LOG_LEVEL_VERBOSE); + case _O_DEBUG: OPT_SET(log_level, LOG_LEVEL_DEBUG); + case _O_FORCE_COLORS: OPT_SET(log_colored, true); + case _O_NO_COLORS: OPT_SET(log_colored, false); case _O_HELP: _help(dev, encoder, server); return 1; case _O_VERSION: _version(true); return 1; - case 0: break; - default: _help(dev, encoder, server); return -1; + + case 0: break; + default: _help(dev, encoder, server); return -1; } } @@ -539,6 +548,8 @@ static void _help(struct device_t *dev, struct encoder_t *encoder, struct http_s printf(" --perf ────────── Enable performance messages (same as --log-level=1). Default: disabled.\n\n"); printf(" --verbose ─────── Enable verbose messages and lower (same as --log-level=2). Default: disabled.\n\n"); printf(" --debug ───────── Enable debug messages and lower (same as --log-level=3). Default: disabled.\n\n"); + printf(" --force-colors ── Force color logging. Default: colored if stdout is a TTY.\n\n"); + printf(" --no-colors ───── Disable color logging. Default: ditto.\n\n"); printf("Help options:\n"); printf("═════════════\n"); printf(" -h|--help ─────── Print this text and exit.\n\n"); diff --git a/src/stream.c b/src/stream.c index 45e0d6e..0886ce7 100644 --- a/src/stream.c +++ b/src/stream.c @@ -240,7 +240,7 @@ void stream_loop(struct stream_t *stream) { captured_fps = captured_fps_accum; captured_fps_accum = 0; captured_fps_second = now_second; - LOG_PERF("A new second has come; captured_fps=%u", captured_fps); + LOG_PERF_FPS("A new second has come; captured_fps=%u", captured_fps); } captured_fps_accum += 1;