[PATCH v2 0/6] 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.
This mimics the behaviour for the log_...() macros like log_debug() and log_info(), so we can drop the special case for these.
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.
Changes in v2: - Move the newline check into log_dispatch() - Update commit message and cover letter to mention log_...() macros - Add a test for !CONFIG_LOG - Update log() to (effectively) call debug() for log_level == LOGL_DEBUG
Simon Glass (6): log: Set up a flag byte for log records log: Handle line continuation log: Add return-checking macros for 0 being success sandbox: log: Avoid build error with !CONFIG_LOG tpm: Don't select LOG log: Convert log values to printf() if not enabled
cmd/Kconfig | 1 - common/log.c | 16 +++++-- common/log_console.c | 26 +++++++----- configs/sandbox_defconfig | 15 ++++--- doc/develop/logging.rst | 37 +++++++++++++++-- include/asm-generic/global_data.h | 6 +++ include/log.h | 69 ++++++++++++++++++++----------- test/log/Makefile | 3 +- test/log/cont_test.c | 19 +++++++-- test/log/nolog_ndebug.c | 38 +++++++++++++++++ test/log/nolog_test.c | 3 ++ 11 files changed, 178 insertions(+), 55 deletions(-) create mode 100644 test/log/nolog_ndebug.c
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 ---
(no changes since v1)
common/log.c | 9 ++++++--- include/log.h | 14 ++++++++++---- 2 files changed, 16 insertions(+), 7 deletions(-)
diff --git a/common/log.c b/common/log.c index 767f0febc51..02f4cbe3fdb 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 */ @@ -244,7 +244,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; @@ -254,7 +256,8 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file, gd->log_drop_count++;
/* display dropped traces with console puts and DEBUG_UART */ - if (rec.level <= CONFIG_LOG_DEFAULT_LEVEL || rec.force_debug) { + if (rec.level <= CONFIG_LOG_DEFAULT_LEVEL || + rec.flags & LOGRECF_FORCE_DEBUG) { char buf[CONFIG_SYS_CBSIZE];
va_start(args, fmt); diff --git a/include/log.h b/include/log.h index 2d27f9f657e..da053b0a6e8 100644 --- a/include/log.h +++ b/include/log.h @@ -322,6 +322,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 * @@ -337,18 +343,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; };
On Wed, Jan 20, 2021 at 08:10:52PM -0700, Simon Glass wrote:
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
Applied to u-boot/next, thanks!
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);
On Wed, Jan 20, 2021 at 08:10:53PM -0700, Simon Glass wrote:
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
Applied to u-boot/next, thanks!
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 ---
(no changes since v1)
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 c0453d2f97c..6ef891d4d2d 100644 --- a/include/log.h +++ b/include/log.h @@ -316,10 +316,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 */
On Wed, Jan 20, 2021 at 08:10:54PM -0700, Simon Glass wrote:
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
Applied to u-boot/next, thanks!
The pr_cont_test.c test requires CONFIG_LOG since it directly accesses fields in global_data that require it. Move the test into the CONFIG_LOG condition to avoid build errors.
Enable CONFIG_LOG on sandbox (not sandbox_spl, etc.) so that we still run this test. This requires resyncing of the configs.
Signed-off-by: Simon Glass sjg@chromium.org ---
(no changes since v1)
configs/sandbox_defconfig | 15 +++++++-------- test/log/Makefile | 2 +- 2 files changed, 8 insertions(+), 9 deletions(-)
diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index 86dc603667c..788d22d56e6 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -20,8 +20,8 @@ CONFIG_BOOTSTAGE_STASH=y CONFIG_BOOTSTAGE_STASH_SIZE=0x4096 CONFIG_CONSOLE_RECORD=y CONFIG_CONSOLE_RECORD_OUT_SIZE=0x1000 -CONFIG_SILENT_CONSOLE=y CONFIG_PRE_CONSOLE_BUFFER=y +CONFIG_LOG=y CONFIG_LOG_SYSLOG=y CONFIG_LOG_ERROR_RETURN=y CONFIG_DISPLAY_BOARDINFO_LATE=y @@ -50,6 +50,7 @@ CONFIG_CMD_MEMTEST=y CONFIG_CMD_BIND=y CONFIG_CMD_DEMO=y CONFIG_CMD_GPIO=y +CONFIG_CMD_PWM=y CONFIG_CMD_GPT=y CONFIG_CMD_GPT_RENAME=y CONFIG_CMD_IDE=y @@ -58,7 +59,6 @@ CONFIG_CMD_LSBLK=y CONFIG_CMD_MUX=y CONFIG_CMD_OSD=y CONFIG_CMD_PCI=y -CONFIG_CMD_PWM=y CONFIG_CMD_READ=y CONFIG_CMD_REMOTEPROC=y CONFIG_CMD_SPI=y @@ -132,6 +132,7 @@ CONFIG_CPU=y CONFIG_DM_DEMO=y CONFIG_DM_DEMO_SIMPLE=y CONFIG_DM_DEMO_SHAPE=y +CONFIG_DFU_SF=y CONFIG_DMA=y CONFIG_DMA_CHANNELS=y CONFIG_SANDBOX_DMA=y @@ -270,14 +271,12 @@ CONFIG_CMD_DHRYSTONE=y CONFIG_TPM=y CONFIG_LZ4=y CONFIG_ERRNO_STR=y +CONFIG_EFI_RUNTIME_UPDATE_CAPSULE=y +CONFIG_EFI_CAPSULE_ON_DISK=y +CONFIG_EFI_CAPSULE_FIRMWARE_FIT=y +CONFIG_EFI_CAPSULE_FIRMWARE_RAW=y CONFIG_EFI_SECURE_BOOT=y CONFIG_TEST_FDTDEC=y CONFIG_UNIT_TEST=y CONFIG_UT_TIME=y CONFIG_UT_DM=y -# -CONFIG_DFU_SF=y -CONFIG_EFI_RUNTIME_UPDATE_CAPSULE=y -CONFIG_EFI_CAPSULE_ON_DISK=y -CONFIG_EFI_CAPSULE_FIRMWARE_FIT=y -CONFIG_EFI_CAPSULE_FIRMWARE_RAW=y diff --git a/test/log/Makefile b/test/log/Makefile index afdafa502ac..0e900363595 100644 --- a/test/log/Makefile +++ b/test/log/Makefile @@ -8,7 +8,6 @@ obj-$(CONFIG_CMD_LOG) += log_filter.o ifdef CONFIG_UT_LOG
obj-y += test-main.o -obj-y += pr_cont_test.o
ifdef CONFIG_SANDBOX obj-$(CONFIG_LOG_SYSLOG) += syslog_test.o @@ -17,6 +16,7 @@ endif
ifdef CONFIG_LOG obj-$(CONFIG_CONSOLE_RECORD) += cont_test.o +obj-y += pr_cont_test.o else obj-$(CONFIG_CONSOLE_RECORD) += nolog_test.o endif
We don't need to enable logging to run this command since the output will still appear. Drop the 'select'.
Signed-off-by: Simon Glass sjg@chromium.org ---
(no changes since v1)
cmd/Kconfig | 1 - 1 file changed, 1 deletion(-)
diff --git a/cmd/Kconfig b/cmd/Kconfig index 0625ee4050f..7097cc1a145 100644 --- a/cmd/Kconfig +++ b/cmd/Kconfig @@ -2025,7 +2025,6 @@ config CMD_TPM_V1
config CMD_TPM_V2 bool - select CMD_LOG
config CMD_TPM bool "Enable the 'tpm' command"
On Wed, Jan 20, 2021 at 08:10:56PM -0700, Simon Glass wrote:
We don't need to enable logging to run this command since the output will still appear. Drop the 'select'.
Signed-off-by: Simon Glass sjg@chromium.org
Applied to u-boot/next, thanks!
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.
This mimics the behaviour for the log_...() macros like log_debug() and log_info(), so we can drop the special case for these.
Add new tests to cover this case. Signed-off-by: Simon Glass sjg@chromium.org ---
Changes in v2: - Update commit message and cover letter to mention log_...() macros - Add a test for !CONFIG_LOG - Update log() to (effectively) call debug() for log_level == LOGL_DEBUG
doc/develop/logging.rst | 6 ++++-- include/log.h | 33 ++++++++++++++------------------- test/log/Makefile | 1 + test/log/nolog_ndebug.c | 38 ++++++++++++++++++++++++++++++++++++++ test/log/nolog_test.c | 3 +++ 5 files changed, 60 insertions(+), 21 deletions(-) create mode 100644 test/log/nolog_ndebug.c
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index b6c6b45049f..55cef42664d 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -54,6 +54,10 @@ 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. If logging is disabled and DEBUG is defined (at +the very top of a C file) then any message at LOGL_DEBUG will be written. + Temporary logging within a single file --------------------------------------
@@ -293,8 +297,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 6ef891d4d2d..748e34d5a26 100644 --- a/include/log.h +++ b/include/log.h @@ -156,6 +156,10 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, */ #if CONFIG_IS_ENABLED(LOG) #define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif + #define log_emer(_fmt...) log(LOG_CATEGORY, LOGL_EMERG, ##_fmt) #define log_alert(_fmt...) log(LOG_CATEGORY, LOGL_ALERT, ##_fmt) #define log_crit(_fmt...) log(LOG_CATEGORY, LOGL_CRIT, ##_fmt) @@ -167,41 +171,32 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, #define log_content(_fmt...) log(LOG_CATEGORY, LOGL_DEBUG_CONTENT, ##_fmt) #define log_io(_fmt...) log(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt) #define log_cont(_fmt...) log(LOGC_CONT, LOGL_CONT, ##_fmt) -#else -#define _LOG_MAX_LEVEL LOGL_INFO -#define log_emerg(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_alert(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_crit(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_err(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_warning(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_notice(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_info(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_cont(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_debug(_fmt, ...) debug(_fmt, ##__VA_ARGS__) -#define log_content(_fmt...) log_nop(LOG_CATEGORY, \ - LOGL_DEBUG_CONTENT, ##_fmt) -#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...) +/* Note: _LOG_DEBUG != 0 avoids a warning with clang */ +#define log(_cat, _level, _fmt, _args...) ({ \ + int _l = _level; \ + if (_LOG_DEBUG != 0 || _l <= LOGL_INFO || \ + (_DEBUG && _l == LOGL_DEBUG)) \ + printf(_fmt, ##_args); \ + }) #endif
#define log_nop(_cat, _level, _fmt, _args...) ({ \ diff --git a/test/log/Makefile b/test/log/Makefile index 0e900363595..b63064e8d02 100644 --- a/test/log/Makefile +++ b/test/log/Makefile @@ -19,6 +19,7 @@ obj-$(CONFIG_CONSOLE_RECORD) += cont_test.o obj-y += pr_cont_test.o else obj-$(CONFIG_CONSOLE_RECORD) += nolog_test.o +obj-$(CONFIG_CONSOLE_RECORD) += nolog_ndebug.o endif
endif # CONFIG_UT_LOG diff --git a/test/log/nolog_ndebug.c b/test/log/nolog_ndebug.c new file mode 100644 index 00000000000..5df353781d9 --- /dev/null +++ b/test/log/nolog_ndebug.c @@ -0,0 +1,38 @@ +// SPDX-License-Identifier: GPL-2.0+ +/* + * Copyright 2021 Google LLC + * + * Logging function tests for CONFIG_LOG=n without #define DEBUG + */ + +#include <common.h> +#include <console.h> +#include <log.h> +#include <test/log.h> +#include <test/ut.h> + +DECLARE_GLOBAL_DATA_PTR; + +#define BUFFSIZE 32 + +static int log_test_log_disabled_ndebug(struct unit_test_state *uts) +{ + char buf[BUFFSIZE]; + int i; + + memset(buf, 0, BUFFSIZE); + console_record_reset_enable(); + + /* Output a log record at every level */ + for (i = LOGL_EMERG; i < LOGL_COUNT; i++) + log(LOGC_NONE, i, "testing level %i\n", i); + gd->flags &= ~GD_FLG_RECORD; + + /* Since DEBUG is not defined, we expect to not get debug output */ + for (i = LOGL_EMERG; i < LOGL_DEBUG; i++) + ut_assertok(ut_check_console_line(uts, "testing level %d", i)); + ut_assertok(ut_check_console_end(uts)); + + return 0; +} +LOG_TEST(log_test_log_disabled_ndebug); diff --git a/test/log/nolog_test.c b/test/log/nolog_test.c index c418ed07c9a..dcf6b779bdc 100644 --- a/test/log/nolog_test.c +++ b/test/log/nolog_test.c @@ -10,6 +10,7 @@
#include <common.h> #include <console.h> +#include <log.h> #include <test/log.h> #include <test/test.h> #include <test/suites.h> @@ -127,8 +128,10 @@ static int log_test_nolog_debug(struct unit_test_state *uts) memset(buf, 0, BUFFSIZE); console_record_reset_enable(); log_debug("testing %s\n", "log_debug"); + log(LOGC_NONE, LOGL_DEBUG, "more %s\n", "log_debug"); gd->flags &= ~GD_FLG_RECORD; ut_assertok(ut_check_console_line(uts, "testing log_debug")); + ut_assertok(ut_check_console_line(uts, "more log_debug")); ut_assertok(ut_check_console_end(uts)); return 0; }
On 1/20/21 10:10 PM, 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.
This mimics the behaviour for the log_...() macros like log_debug() and log_info(), so we can drop the special case for these.
Add new tests to cover this case. Signed-off-by: Simon Glass sjg@chromium.org
Changes in v2:
Update commit message and cover letter to mention log_...() macros
Add a test for !CONFIG_LOG
Update log() to (effectively) call debug() for log_level == LOGL_DEBUG
doc/develop/logging.rst | 6 ++++-- include/log.h | 33 ++++++++++++++------------------- test/log/Makefile | 1 + test/log/nolog_ndebug.c | 38 ++++++++++++++++++++++++++++++++++++++ test/log/nolog_test.c | 3 +++ 5 files changed, 60 insertions(+), 21 deletions(-) create mode 100644 test/log/nolog_ndebug.c
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index b6c6b45049f..55cef42664d 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -54,6 +54,10 @@ 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. If logging is disabled and DEBUG is defined (at +the very top of a C file) then any message at LOGL_DEBUG will be written.
Temporary logging within a single file
@@ -293,8 +297,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 6ef891d4d2d..748e34d5a26 100644 --- a/include/log.h +++ b/include/log.h @@ -156,6 +156,10 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, */ #if CONFIG_IS_ENABLED(LOG) #define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
- #define log_emer(_fmt...) log(LOG_CATEGORY, LOGL_EMERG, ##_fmt) #define log_alert(_fmt...) log(LOG_CATEGORY, LOGL_ALERT, ##_fmt) #define log_crit(_fmt...) log(LOG_CATEGORY, LOGL_CRIT, ##_fmt)
@@ -167,41 +171,32 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, #define log_content(_fmt...) log(LOG_CATEGORY, LOGL_DEBUG_CONTENT, ##_fmt) #define log_io(_fmt...) log(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt) #define log_cont(_fmt...) log(LOGC_CONT, LOGL_CONT, ##_fmt) -#else -#define _LOG_MAX_LEVEL LOGL_INFO -#define log_emerg(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_alert(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_crit(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_err(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_warning(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_notice(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_info(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_cont(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_debug(_fmt, ...) debug(_fmt, ##__VA_ARGS__) -#define log_content(_fmt...) log_nop(LOG_CATEGORY, \
LOGL_DEBUG_CONTENT, ##_fmt)-#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...) +/* Note: _LOG_DEBUG != 0 avoids a warning with clang */ +#define log(_cat, _level, _fmt, _args...) ({ \
- int _l = _level; \
- if (_LOG_DEBUG != 0 || _l <= LOGL_INFO || \
Should this be < CONFIG_LOGLEVEL?
--Sean
(_DEBUG && _l == LOGL_DEBUG)) \printf(_fmt, ##_args); \}) #endif
#define log_nop(_cat, _level, _fmt, _args...) ({ \
diff --git a/test/log/Makefile b/test/log/Makefile index 0e900363595..b63064e8d02 100644 --- a/test/log/Makefile +++ b/test/log/Makefile @@ -19,6 +19,7 @@ obj-$(CONFIG_CONSOLE_RECORD) += cont_test.o obj-y += pr_cont_test.o else obj-$(CONFIG_CONSOLE_RECORD) += nolog_test.o +obj-$(CONFIG_CONSOLE_RECORD) += nolog_ndebug.o endif
endif # CONFIG_UT_LOG diff --git a/test/log/nolog_ndebug.c b/test/log/nolog_ndebug.c new file mode 100644 index 00000000000..5df353781d9 --- /dev/null +++ b/test/log/nolog_ndebug.c @@ -0,0 +1,38 @@ +// SPDX-License-Identifier: GPL-2.0+ +/*
- Copyright 2021 Google LLC
- Logging function tests for CONFIG_LOG=n without #define DEBUG
- */
+#include <common.h> +#include <console.h> +#include <log.h> +#include <test/log.h> +#include <test/ut.h>
+DECLARE_GLOBAL_DATA_PTR;
+#define BUFFSIZE 32
+static int log_test_log_disabled_ndebug(struct unit_test_state *uts) +{
- char buf[BUFFSIZE];
- int i;
- memset(buf, 0, BUFFSIZE);
- console_record_reset_enable();
- /* Output a log record at every level */
- for (i = LOGL_EMERG; i < LOGL_COUNT; i++)
log(LOGC_NONE, i, "testing level %i\n", i);- gd->flags &= ~GD_FLG_RECORD;
- /* Since DEBUG is not defined, we expect to not get debug output */
- for (i = LOGL_EMERG; i < LOGL_DEBUG; i++)
ut_assertok(ut_check_console_line(uts, "testing level %d", i));- ut_assertok(ut_check_console_end(uts));
- return 0;
+} +LOG_TEST(log_test_log_disabled_ndebug); diff --git a/test/log/nolog_test.c b/test/log/nolog_test.c index c418ed07c9a..dcf6b779bdc 100644 --- a/test/log/nolog_test.c +++ b/test/log/nolog_test.c @@ -10,6 +10,7 @@
#include <common.h> #include <console.h> +#include <log.h> #include <test/log.h> #include <test/test.h> #include <test/suites.h> @@ -127,8 +128,10 @@ static int log_test_nolog_debug(struct unit_test_state *uts) memset(buf, 0, BUFFSIZE); console_record_reset_enable(); log_debug("testing %s\n", "log_debug");
- log(LOGC_NONE, LOGL_DEBUG, "more %s\n", "log_debug"); gd->flags &= ~GD_FLG_RECORD; ut_assertok(ut_check_console_line(uts, "testing log_debug"));
- ut_assertok(ut_check_console_line(uts, "more log_debug")); ut_assertok(ut_check_console_end(uts)); return 0; }
Hi Sean,
On Thu, 4 Feb 2021 at 18:28, Sean Anderson seanga2@gmail.com wrote:
On 1/20/21 10:10 PM, 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.
This mimics the behaviour for the log_...() macros like log_debug() and log_info(), so we can drop the special case for these.
Add new tests to cover this case. Signed-off-by: Simon Glass sjg@chromium.org
Changes in v2:
Update commit message and cover letter to mention log_...() macros
Add a test for !CONFIG_LOG
Update log() to (effectively) call debug() for log_level == LOGL_DEBUG
doc/develop/logging.rst | 6 ++++-- include/log.h | 33 ++++++++++++++------------------- test/log/Makefile | 1 + test/log/nolog_ndebug.c | 38 ++++++++++++++++++++++++++++++++++++++ test/log/nolog_test.c | 3 +++ 5 files changed, 60 insertions(+), 21 deletions(-) create mode 100644 test/log/nolog_ndebug.c
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst index b6c6b45049f..55cef42664d 100644 --- a/doc/develop/logging.rst +++ b/doc/develop/logging.rst @@ -54,6 +54,10 @@ 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. If logging is disabled and DEBUG is defined (at +the very top of a C file) then any message at LOGL_DEBUG will be written.
Temporary logging within a single file
@@ -293,8 +297,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 6ef891d4d2d..748e34d5a26 100644 --- a/include/log.h +++ b/include/log.h @@ -156,6 +156,10 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, */ #if CONFIG_IS_ENABLED(LOG) #define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
- #define log_emer(_fmt...) log(LOG_CATEGORY, LOGL_EMERG, ##_fmt) #define log_alert(_fmt...) log(LOG_CATEGORY, LOGL_ALERT, ##_fmt) #define log_crit(_fmt...) log(LOG_CATEGORY, LOGL_CRIT, ##_fmt)
@@ -167,41 +171,32 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level, #define log_content(_fmt...) log(LOG_CATEGORY, LOGL_DEBUG_CONTENT, ##_fmt) #define log_io(_fmt...) log(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt) #define log_cont(_fmt...) log(LOGC_CONT, LOGL_CONT, ##_fmt) -#else -#define _LOG_MAX_LEVEL LOGL_INFO -#define log_emerg(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_alert(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_crit(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_err(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_warning(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_notice(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_info(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_cont(_fmt, ...) printf(_fmt, ##__VA_ARGS__) -#define log_debug(_fmt, ...) debug(_fmt, ##__VA_ARGS__) -#define log_content(_fmt...) log_nop(LOG_CATEGORY, \
LOGL_DEBUG_CONTENT, ##_fmt)-#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); \ })-#define log(_cat, _level, _fmt, _args...) +/* Note: _LOG_DEBUG != 0 avoids a warning with clang */ +#define log(_cat, _level, _fmt, _args...) ({ \
int _l = _level; \if (_LOG_DEBUG != 0 || _l <= LOGL_INFO || \Should this be < CONFIG_LOGLEVEL?
Well it could be, but in fact that value predates the log system and I've been wondering how to remove it, to reconcile the pr_...() stuff and the log subsystem.
CONFIG_LOGLEVEL should really go away in favour of CONFIG_LOG_MAX_LEVEL I think.
Regards, Simon
On Wed, Jan 20, 2021 at 08:10:57PM -0700, 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.
This mimics the behaviour for the log_...() macros like log_debug() and log_info(), so we can drop the special case for these.
Add new tests to cover this case. Signed-off-by: Simon Glass sjg@chromium.org
Changes in v2:
- Update commit message and cover letter to mention log_...() macros
- Add a test for !CONFIG_LOG
- Update log() to (effectively) call debug() for log_level == LOGL_DEBUG
As is, this last patch in the series causes tests to fail on sandbox. I'm re-testing 1-5 by themselves right now.
Hi Tom,
On Sun, 14 Mar 2021 at 12:33, Tom Rini trini@konsulko.com wrote:
On Wed, Jan 20, 2021 at 08:10:57PM -0700, 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.
This mimics the behaviour for the log_...() macros like log_debug() and log_info(), so we can drop the special case for these.
Add new tests to cover this case. Signed-off-by: Simon Glass sjg@chromium.org
Changes in v2:
- Update commit message and cover letter to mention log_...() macros
- Add a test for !CONFIG_LOG
- Update log() to (effectively) call debug() for log_level == LOGL_DEBUG
As is, this last patch in the series causes tests to fail on sandbox. I'm re-testing 1-5 by themselves right now.
OK thanks, great to see this. I'll revisit once things land.
Regrads, Simon
+Heinrich Schuchardt
Hi Heinrich,
On Wed, 20 Jan 2021 at 20:11, Simon Glass sjg@chromium.org wrote:
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 mimics the behaviour for the log_...() macros like log_debug() and log_info(), so we can drop the special case for these.
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.
Changes in v2:
- Move the newline check into log_dispatch()
- Update commit message and cover letter to mention log_...() macros
- Add a test for !CONFIG_LOG
- Update log() to (effectively) call debug() for log_level == LOGL_DEBUG
Simon Glass (6): log: Set up a flag byte for log records log: Handle line continuation log: Add return-checking macros for 0 being success sandbox: log: Avoid build error with !CONFIG_LOG tpm: Don't select LOG log: Convert log values to printf() if not enabled
I should have sent this series to you as well, since you had a comment on the original version.
It is at u-boot-dm/log-working if that is easier.
Regards, Simon
participants (3)
-
Sean Anderson -
Simon Glass -
Tom Rini