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 <sjg@chromium.org>

diff --git a/common/log.c b/common/log.c
index f87e33a9ca1621e2e784a18caf15e5cda963950b..ea407c6db9e9dcdab4b12338c34a66a130e678e9 100644 (file)
--- 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 6abb13c93b80b418e1f35c481ee0d821d570ca57..3f6177499ef9394e0cc1b52b92eef27e46ac9f54 100644 (file)
--- 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 60c18c5b3a859d0e3fbb95e3dd702cd64d6c8370..622ad6ad1af2867e4f6f8f19b155d8247e8aaefa 100644 (file)
--- 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 b6a9991fc9a98ec1e67b3f66132b10b46103e993..c24f5e0e9735ba99d4c86fb1368d060325870478 100644 (file)
--- 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 da053b0a6e8934ca741f6fc20f6a317e8c656c1c..c0453d2f97c1ee9cc89c165799a10535dbd797b5 100644 (file)
--- 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 16379a74be626f713c8ce4c8d04e6e2d9d056561..de7b7f064cd597cfcbb74ca35f496e27d695f5f2 100644 (file)
--- 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);