From 9ad7a6c25c7142a46fe4b811c13bc3280c4bb27f Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Wed, 20 Jan 2021 20:10:53 -0700 Subject: [PATCH] log: Handle line continuation When multiple log() calls are used which don't end in newline, the log prefix is prepended multiple times in the same line. This makes the output look strange. Fix this by detecting when the previous log record did not end in newline. In that case, setting a flag. Drop the unused BUFFSIZE in the test while we are here. As an example implementation, update log_console to check the flag and produce the expected output. Signed-off-by: Simon Glass --- common/log.c | 7 ++++++- common/log_console.c | 26 +++++++++++++++----------- doc/develop/logging.rst | 16 ++++++++++++++++ include/asm-generic/global_data.h | 6 ++++++ include/log.h | 2 ++ test/log/cont_test.c | 19 +++++++++++++++---- 6 files changed, 60 insertions(+), 16 deletions(-) diff --git a/common/log.c b/common/log.c index f87e33a9ca..ea407c6db9 100644 --- a/common/log.c +++ b/common/log.c @@ -218,8 +218,11 @@ static int log_dispatch(struct log_rec *rec, const char *fmt, va_list args) if ((ldev->flags & LOGDF_ENABLE) && log_passes_filters(ldev, rec)) { if (!rec->msg) { - vsnprintf(buf, sizeof(buf), fmt, args); + int len; + + len = vsnprintf(buf, sizeof(buf), fmt, args); rec->msg = buf; + gd->log_cont = len && buf[len - 1] != '\n'; } ldev->drv->emit(ldev, rec); } @@ -248,6 +251,8 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file, rec.flags = 0; if (level & LOGL_FORCE_DEBUG) rec.flags |= LOGRECF_FORCE_DEBUG; + if (gd->log_cont) + rec.flags |= LOGRECF_CONT; rec.file = file; rec.line = line; rec.func = func; diff --git a/common/log_console.c b/common/log_console.c index 6abb13c93b..3f6177499e 100644 --- a/common/log_console.c +++ b/common/log_console.c @@ -15,6 +15,7 @@ DECLARE_GLOBAL_DATA_PTR; static int log_console_emit(struct log_device *ldev, struct log_rec *rec) { int fmt = gd->log_fmt; + bool add_space = false; /* * The output format is designed to give someone a fighting chance of @@ -26,18 +27,21 @@ static int log_console_emit(struct log_device *ldev, struct log_rec *rec) * - function is an identifier and ends with () * - message has a space before it unless it is on its own */ - if (fmt & BIT(LOGF_LEVEL)) - printf("%s.", log_get_level_name(rec->level)); - if (fmt & BIT(LOGF_CAT)) - printf("%s,", log_get_cat_name(rec->cat)); - if (fmt & BIT(LOGF_FILE)) - printf("%s:", rec->file); - if (fmt & BIT(LOGF_LINE)) - printf("%d-", rec->line); - if (fmt & BIT(LOGF_FUNC)) - printf("%s()", rec->func); + if (!(rec->flags & LOGRECF_CONT) && fmt != BIT(LOGF_MSG)) { + add_space = true; + if (fmt & BIT(LOGF_LEVEL)) + printf("%s.", log_get_level_name(rec->level)); + if (fmt & BIT(LOGF_CAT)) + printf("%s,", log_get_cat_name(rec->cat)); + if (fmt & BIT(LOGF_FILE)) + printf("%s:", rec->file); + if (fmt & BIT(LOGF_LINE)) + printf("%d-", rec->line); + if (fmt & BIT(LOGF_FUNC)) + printf("%s()", rec->func); + } if (fmt & BIT(LOGF_MSG)) - printf("%s%s", fmt != BIT(LOGF_MSG) ? " " : "", rec->msg); + printf("%s%s", add_space ? " " : "", rec->msg); return 0; } diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index 60c18c5b3a..622ad6ad1a 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -96,6 +96,22 @@ Also debug() and error() will generate log records - these use LOG_CATEGORY as the category, so you should #define this right at the top of the source file to ensure the category is correct. +Generally each log format_string ends with a newline. If it does not, then the +next log statement will have the LOGRECF_CONT flag set. This can be used to +continue the statement on the same line as the previous one without emitting +new header information (such as category/level). This behaviour is implemented +with log_console. Here is an example that prints a list all on one line with +the tags at the start: + +.. code-block:: c + + log_debug("Here is a list:"); + for (i = 0; i < count; i++) + log_debug(" item %d", i); + log_debug("\n"); + +Also see the special category LOGL_CONT and level LOGC_CONT. + You can also define CONFIG_LOG_ERROR_RETURN to enable the log_ret() macro. This can be used whenever your function returns an error value: diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h index b6a9991fc9..c24f5e0e97 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -410,6 +410,12 @@ struct global_data { * This value is used as logging level for continuation messages. */ int logl_prev; + /** + * @log_cont: Previous log line did not finished wtih \n + * + * This allows for chained log messages on the same line + */ + bool log_cont; #endif #if CONFIG_IS_ENABLED(BLOBLIST) /** diff --git a/include/log.h b/include/log.h index da053b0a6e..c0453d2f97 100644 --- a/include/log.h +++ b/include/log.h @@ -326,6 +326,8 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, enum log_rec_flags { /** @LOGRECF_FORCE_DEBUG: Force output of debug record */ LOGRECF_FORCE_DEBUG = BIT(0), + /** @LOGRECF_CONT: Continuation of previous log record */ + LOGRECF_CONT = BIT(1), }; /** diff --git a/test/log/cont_test.c b/test/log/cont_test.c index 16379a74be..de7b7f064c 100644 --- a/test/log/cont_test.c +++ b/test/log/cont_test.c @@ -15,8 +15,6 @@ DECLARE_GLOBAL_DATA_PTR; -#define BUFFSIZE 64 - static int log_test_cont(struct unit_test_state *uts) { int log_fmt; @@ -29,12 +27,13 @@ static int log_test_cont(struct unit_test_state *uts) gd->log_fmt = (1 << LOGF_CAT) | (1 << LOGF_LEVEL) | (1 << LOGF_MSG); gd->default_log_level = LOGL_INFO; console_record_reset_enable(); - log(LOGC_ARCH, LOGL_ERR, "ea%d ", 1); + log(LOGC_ARCH, LOGL_ERR, "ea%d\n", 1); log(LOGC_CONT, LOGL_CONT, "cc%d\n", 2); gd->default_log_level = log_level; gd->log_fmt = log_fmt; gd->flags &= ~GD_FLG_RECORD; - ut_assertok(ut_check_console_line(uts, "ERR.arch, ea1 ERR.arch, cc2")); + ut_assertok(ut_check_console_line(uts, "ERR.arch, ea1")); + ut_assertok(ut_check_console_line(uts, "ERR.arch, cc2")); ut_assertok(ut_check_console_end(uts)); /* Write a third message which is not a continuation */ @@ -48,6 +47,18 @@ static int log_test_cont(struct unit_test_state *uts) ut_assertok(ut_check_console_line(uts, "INFO.efi, ie3")); ut_assertok(ut_check_console_end(uts)); + /* Write two messages without a newline between them */ + gd->log_fmt = (1 << LOGF_CAT) | (1 << LOGF_LEVEL) | (1 << LOGF_MSG); + gd->default_log_level = LOGL_INFO; + console_record_reset_enable(); + log(LOGC_ARCH, LOGL_ERR, "ea%d ", 1); + log(LOGC_CONT, LOGL_CONT, "cc%d\n", 2); + gd->default_log_level = log_level; + gd->log_fmt = log_fmt; + gd->flags &= ~GD_FLG_RECORD; + ut_assertok(ut_check_console_line(uts, "ERR.arch, ea1 cc2")); + ut_assertok(ut_check_console_end(uts)); + return 0; } LOG_TEST(log_test_cont);