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 sjg@chromium.org ---
Changes in v2: - Move the newline check into log_dispatch()
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 02f4cbe3fdb..1709c6ed192 100644 --- a/common/log.c +++ b/common/log.c @@ -217,8 +217,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); } @@ -247,6 +250,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 8776fd47039..76bc9524202 100644 --- a/common/log_console.c +++ b/common/log_console.c @@ -14,6 +14,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 @@ -25,18 +26,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 7fdd1132efe..482c17f7800 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -98,6 +98,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 46c7e16e91f..8e06843a58a 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -402,6 +402,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 da053b0a6e8..c0453d2f97c 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 68ca1d262c4..db36fbd1a7c 100644 --- a/test/log/cont_test.c +++ b/test/log/cont_test.c @@ -14,8 +14,6 @@
DECLARE_GLOBAL_DATA_PTR;
-#define BUFFSIZE 64 - static int log_test_cont(struct unit_test_state *uts) { int log_fmt; @@ -28,12 +26,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 */ @@ -47,6 +46,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);