[PATCH 0/4] log: Allow multiple lines and conversion to printf()
At present when logging is not enabled, all log calls become nops. This does not seem right, since if the log level is high enough then there should be some sort of message. So in that case, this series updates it to print the message if the log level is above LOGL_INFO.
Also the current implementation does not support multiple log calls on the same line nicely. The tags are repeated so the line is very hard to read. This series adds that as a new feature.
Simon Glass (4): log: Set up a flag byte for log records log: Handle line continuation log: Add return-checking macros for 0 being success log: Convert log values to printf() if not enabled
common/log.c | 12 ++++++-- common/log_console.c | 26 ++++++++++------- doc/develop/logging.rst | 36 +++++++++++++++++++++-- include/asm-generic/global_data.h | 6 ++++ include/log.h | 48 +++++++++++++++++++++++++------ test/log/cont_test.c | 19 +++++++++--- 6 files changed, 118 insertions(+), 29 deletions(-)
At present only a single flag (force_debug) is used in log records. Before adding more, convert this into a bitfield, so more can be added without using more space.
To avoid expanding the log_record struct itself (which some drivers may wish to store in memory) reduce the line-number field to 16 bits. This provides for up to 64K lines which should be enough for anyone.
Signed-off-by: Simon Glass sjg@chromium.org ---
common/log.c | 6 ++++-- include/log.h | 14 ++++++++++---- 2 files changed, 14 insertions(+), 6 deletions(-)
diff --git a/common/log.c b/common/log.c index ce39918e045..d0abedaa05e 100644 --- a/common/log.c +++ b/common/log.c @@ -152,7 +152,7 @@ static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec) { struct log_filter *filt;
- if (rec->force_debug) + if (rec->flags & LOGRECF_FORCE_DEBUG) return true;
/* If there are no filters, filter on the default log level */ @@ -236,7 +236,9 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
rec.cat = cat; rec.level = level & LOGL_LEVEL_MASK; - rec.force_debug = level & LOGL_FORCE_DEBUG; + rec.flags = 0; + if (level & LOGL_FORCE_DEBUG) + rec.flags |= LOGRECF_FORCE_DEBUG; rec.file = file; rec.line = line; rec.func = func; diff --git a/include/log.h b/include/log.h index 6bce5606489..2416c3c8113 100644 --- a/include/log.h +++ b/include/log.h @@ -315,6 +315,12 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, #define log_msg_ret(_msg, _ret) ((void)(_msg), _ret) #endif
+/** * enum log_rec_flags - Flags for a log record */ +enum log_rec_flags { + /** @LOGRECF_FORCE_DEBUG: Force output of debug record */ + LOGRECF_FORCE_DEBUG = BIT(0), +}; + /** * struct log_rec - a single log record * @@ -330,18 +336,18 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, * * @cat: Category, representing a uclass or part of U-Boot * @level: Severity level, less severe is higher - * @force_debug: Force output of debug - * @file: Name of file where the log record was generated (not allocated) * @line: Line number where the log record was generated + * @flags: Flags for log record (enum log_rec_flags) + * @file: Name of file where the log record was generated (not allocated) * @func: Function where the log record was generated (not allocated) * @msg: Log message (allocated) */ struct log_rec { enum log_category_t cat; enum log_level_t level; - bool force_debug; + u16 line; + u8 flags; const char *file; - int line; const char *func; const char *msg; };
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 ---
common/log.c | 6 +++++- 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, 59 insertions(+), 16 deletions(-)
diff --git a/common/log.c b/common/log.c index d0abedaa05e..90c04c10a79 100644 --- a/common/log.c +++ b/common/log.c @@ -227,6 +227,7 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file, char buf[CONFIG_SYS_CBSIZE]; struct log_rec rec; va_list args; + int len;
/* Check for message continuation */ if (cat == LOGC_CONT) @@ -239,12 +240,15 @@ 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; va_start(args, fmt); - vsnprintf(buf, sizeof(buf), fmt, args); + len = vsnprintf(buf, sizeof(buf), fmt, args); va_end(args); + gd->log_cont = len && buf[len - 1] != '\n'; rec.msg = buf; if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { if (gd) 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 63bcf109d40..d0c93236b26 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -396,6 +396,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 2416c3c8113..b6b3c6b887e 100644 --- a/include/log.h +++ b/include/log.h @@ -319,6 +319,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);
The existing log_ret() and log_msg_ret() macros consider an error to be less than zero. But some function may return a positive number to indicate a different kind of failure. Add macros to check for that also.
Signed-off-by: Simon Glass sjg@chromium.org ---
doc/develop/logging.rst | 15 ++++++++++++++- include/log.h | 20 ++++++++++++++++++++ 2 files changed, 34 insertions(+), 1 deletion(-)
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index 482c17f7800..b6c6b45049f 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -119,11 +119,24 @@ can be used whenever your function returns an error value:
.. code-block:: c
- return log_ret(uclass_first_device(UCLASS_MMC, &dev)); + return log_ret(uclass_first_device_err(UCLASS_MMC, &dev));
This will write a log record when an error code is detected (a value < 0). This can make it easier to trace errors that are generated deep in the call stack.
+The log_msg_ret() variant will print a short string if CONFIG_LOG_ERROR_RETURN +is enabled. So long as the string is unique within the function you can normally +determine exactly which call failed: + +.. code-block:: c + + ret = gpio_request_by_name(dev, "cd-gpios", 0, &desc, GPIOD_IS_IN); + if (ret) + return log_msg_ret("gpio", ret); + +Some functions return 0 for success and any other value is an error. For these, +log_retz() and log_msg_retz() are available. + Convenience functions ~~~~~~~~~~~~~~~~~~~~~
diff --git a/include/log.h b/include/log.h index b6b3c6b887e..c5c1cf92356 100644 --- a/include/log.h +++ b/include/log.h @@ -309,10 +309,30 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, __ret); \ __ret; \ }) + +/* + * Similar to the above, but any non-zero value is consider an error, not just + * values less than 0. + */ +#define log_retz(_ret) ({ \ + int __ret = (_ret); \ + if (__ret) \ + log(LOG_CATEGORY, LOGL_ERR, "returning err=%d\n", __ret); \ + __ret; \ + }) +#define log_msg_retz(_msg, _ret) ({ \ + int __ret = (_ret); \ + if (__ret) \ + log(LOG_CATEGORY, LOGL_ERR, "%s: returning err=%d\n", _msg, \ + __ret); \ + __ret; \ + }) #else /* Non-logging versions of the above which just return the error code */ #define log_ret(_ret) (_ret) #define log_msg_ret(_msg, _ret) ((void)(_msg), _ret) +#define log_retz(_ret) (_ret) +#define log_msg_retz(_msg, _ret) ((void)(_msg), _ret) #endif
/** * enum log_rec_flags - Flags for a log record */
At present if logging not enabled, log_info() becomes a nop. But we want log output at the 'info' level to be akin to printf(). Update the macro to pass the output straight to printf() in this case.
Signed-off-by: Simon Glass sjg@chromium.org ---
doc/develop/logging.rst | 5 +++-- include/log.h | 12 ++++++++---- 2 files changed, 11 insertions(+), 6 deletions(-)
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index b6c6b45049f..fdc869204df 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -54,6 +54,9 @@ If CONFIG_LOG is not set, then no logging will be available. The above have SPL and TPL versions also, e.g. CONFIG_SPL_LOG_MAX_LEVEL and CONFIG_TPL_LOG_MAX_LEVEL.
+If logging is disabled, the default behaviour is to output any message at +level LOGL_INFO and below. + Temporary logging within a single file --------------------------------------
@@ -293,8 +296,6 @@ More logging destinations:
Convert debug() statements in the code to log() statements
-Support making printf() emit log statements at L_INFO level - Convert error() statements in the code to log() statements
Figure out what to do with BUG(), BUG_ON() and warn_non_spl() diff --git a/include/log.h b/include/log.h index c5c1cf92356..3d19f0448da 100644 --- a/include/log.h +++ b/include/log.h @@ -175,25 +175,29 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, #define log_io(_fmt...) log_nop(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt) #endif
-#if CONFIG_IS_ENABLED(LOG) #ifdef LOG_DEBUG #define _LOG_DEBUG LOGL_FORCE_DEBUG #else #define _LOG_DEBUG 0 #endif
+#if CONFIG_IS_ENABLED(LOG) + /* Emit a log record if the level is less that the maximum */ #define log(_cat, _level, _fmt, _args...) ({ \ int _l = _level; \ - if (CONFIG_IS_ENABLED(LOG) && \ - (_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \ + if ((_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \ _log((enum log_category_t)(_cat), \ (enum log_level_t)(_l | _LOG_DEBUG), __FILE__, \ __LINE__, __func__, \ pr_fmt(_fmt), ##_args); \ }) #else -#define log(_cat, _level, _fmt, _args...) +#define log(_cat, _level, _fmt, _args...) ({ \ + int _l = _level; \ + if ((_LOG_DEBUG != 0 || _l <= LOGL_INFO)) \ + printf(_fmt, ##_args); \ + }) #endif
#define log_nop(_cat, _level, _fmt, _args...) ({ \
Am 14. Januar 2021 04:30:51 MEZ schrieb Simon Glass sjg@chromium.org:
At present if logging not enabled, log_info() becomes a nop. But we want log output at the 'info' level to be akin to printf(). Update the macro to pass the output straight to printf() in this case.
Looking at
https://github.com/trini/u-boot/blob/master/include/log.h#L172
the commit message seems not to precisely describe in which cases printf() was not called.
We have a nolog unit test. Should that test be extended?
https://github.com/trini/u-boot/blob/master/test/log/nolog_test.c
For the naked log() is see the difference.
Is this patch fixing a recent change?
Best regards
Heinrich
Signed-off-by: Simon Glass sjg@chromium.org
doc/develop/logging.rst | 5 +++-- include/log.h | 12 ++++++++---- 2 files changed, 11 insertions(+), 6 deletions(-)
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index b6c6b45049f..fdc869204df 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -54,6 +54,9 @@ If CONFIG_LOG is not set, then no logging will be available. The above have SPL and TPL versions also, e.g. CONFIG_SPL_LOG_MAX_LEVEL and CONFIG_TPL_LOG_MAX_LEVEL.
+If logging is disabled, the default behaviour is to output any message at +level LOGL_INFO and below.
Temporary logging within a single file
@@ -293,8 +296,6 @@ More logging destinations:
Convert debug() statements in the code to log() statements
-Support making printf() emit log statements at L_INFO level
Convert error() statements in the code to log() statements
Figure out what to do with BUG(), BUG_ON() and warn_non_spl() diff --git a/include/log.h b/include/log.h index c5c1cf92356..3d19f0448da 100644 --- a/include/log.h +++ b/include/log.h @@ -175,25 +175,29 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, #define log_io(_fmt...) log_nop(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt) #endif
-#if CONFIG_IS_ENABLED(LOG) #ifdef LOG_DEBUG #define _LOG_DEBUG LOGL_FORCE_DEBUG #else #define _LOG_DEBUG 0 #endif
+#if CONFIG_IS_ENABLED(LOG)
/* Emit a log record if the level is less that the maximum */ #define log(_cat, _level, _fmt, _args...) ({ \ int _l = _level; \
- if (CONFIG_IS_ENABLED(LOG) && \
(_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \
- if ((_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \ _log((enum log_category_t)(_cat), \ (enum log_level_t)(_l | _LOG_DEBUG), __FILE__, \ __LINE__, __func__, \ pr_fmt(_fmt), ##_args); \ })
#else -#define log(_cat, _level, _fmt, _args...) +#define log(_cat, _level, _fmt, _args...) ({ \
- int _l = _level; \
- if ((_LOG_DEBUG != 0 || _l <= LOGL_INFO)) \
printf(_fmt, ##_args); \- })
#endif
#define log_nop(_cat, _level, _fmt, _args...) ({ \
On 1/14/21 4:30 AM, Simon Glass wrote:
At present if logging not enabled, log_info() becomes a nop. But we want log output at the 'info' level to be akin to printf(). Update the macro to pass the output straight to printf() in this case.
Signed-off-by: Simon Glass sjg@chromium.org
doc/develop/logging.rst | 5 +++-- include/log.h | 12 ++++++++---- 2 files changed, 11 insertions(+), 6 deletions(-)
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index b6c6b45049f..fdc869204df 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -54,6 +54,9 @@ If CONFIG_LOG is not set, then no logging will be available. The above have SPL and TPL versions also, e.g. CONFIG_SPL_LOG_MAX_LEVEL and CONFIG_TPL_LOG_MAX_LEVEL.
+If logging is disabled, the default behaviour is to output any message at +level LOGL_INFO and below.
Temporary logging within a single file
@@ -293,8 +296,6 @@ More logging destinations:
Convert debug() statements in the code to log() statements
-Support making printf() emit log statements at L_INFO level
Convert error() statements in the code to log() statements
Figure out what to do with BUG(), BUG_ON() and warn_non_spl()
diff --git a/include/log.h b/include/log.h index c5c1cf92356..3d19f0448da 100644 --- a/include/log.h +++ b/include/log.h @@ -175,25 +175,29 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, #define log_io(_fmt...) log_nop(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt) #endif
-#if CONFIG_IS_ENABLED(LOG) #ifdef LOG_DEBUG #define _LOG_DEBUG LOGL_FORCE_DEBUG #else #define _LOG_DEBUG 0 #endif
+#if CONFIG_IS_ENABLED(LOG)
- /* Emit a log record if the level is less that the maximum */ #define log(_cat, _level, _fmt, _args...) ({ \ int _l = _level; \
- if (CONFIG_IS_ENABLED(LOG) && \
(_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \
- if ((_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \ _log((enum log_category_t)(_cat), \ (enum log_level_t)(_l | _LOG_DEBUG), __FILE__, \ __LINE__, __func__, \ pr_fmt(_fmt), ##_args); \ }) #else
-#define log(_cat, _level, _fmt, _args...) +#define log(_cat, _level, _fmt, _args...) ({ \
- int _l = _level; \
- if ((_LOG_DEBUG != 0 || _l <= LOGL_INFO)) \
printf(_fmt, ##_args); \
log() should call debug() for log_level = LOGL_DEBUG.
Best regards
Heinrich
}) #endif
#define log_nop(_cat, _level, _fmt, _args...) ({ \
Am 14. Januar 2021 04:30:47 MEZ schrieb Simon Glass sjg@chromium.org:
At present when logging is not enabled, all log calls become nops. This does not seem right, since if the log level is high enough then there should be some sort of message. So in that case, this series updates it to print the message if the log level is above LOGL_INFO.
This is already current behavior. See
https://github.com/trini/u-boot/blob/master/include/log.h#L172
Best regards
Heinrich
Also the current implementation does not support multiple log calls on the same line nicely. The tags are repeated so the line is very hard to read. This series adds that as a new feature.
Simon Glass (4): log: Set up a flag byte for log records log: Handle line continuation log: Add return-checking macros for 0 being success log: Convert log values to printf() if not enabled
common/log.c | 12 ++++++-- common/log_console.c | 26 ++++++++++------- doc/develop/logging.rst | 36 +++++++++++++++++++++-- include/asm-generic/global_data.h | 6 ++++ include/log.h | 48 +++++++++++++++++++++++++------ test/log/cont_test.c | 19 +++++++++--- 6 files changed, 118 insertions(+), 29 deletions(-)
participants (2)
-
Heinrich Schuchardt -
Simon Glass