[U-Boot] [PATCH 00/13] log: Add a new logging feature
U-Boot currently has fairly rudimentary logging features. A basic printf() provides console output and debug() provides debug output which is activated if DEBUG is defined in the file containing the debug() statements.
It would be useful to have a few more features:
- control of debug output at runtime, so problems can potentially be debugged without recompiling U-Boot - control of which subsystems output debug information, so that (for example) it is possible to enable debugging for MMC or SATA at runtime - indication of severity with each message, so that the user can control whether just errors are displayed, warnings, or all debug messages - sending logging information to different destinations, such as console, memory, linux, etc,
At present U-Boot has a logbuffer feature which records output in a memory buffer for later display or storage. This is useful but is not at present enabled for any board.
This series introduced a new logging system which supports: - various log levels from panic to debug - log categories including all uclasses and a few others - log drivers to which all log records can be sent - log filters which control which log records make it to which drivers
Enabling logging with the default options does not add much to code size. By default the maximum recorded log level is LOGL_INFO, meaning that debug messages (and above) are discarded a build-time. Increasing this level provides more run-time flexibility to enable/disable logging at the cost of increased code size.
This feature is by no means finished. The README provides a long list of features and clean-ups that could be done. But hopefully this is a starting point for improving this important area in U-Boot.
The series is available at u-boot-dm/log-working
Simon Glass (13): Revert "sandbox: remove os_putc() and os_puts()" Revert "sandbox: Drop special case console code for sandbox" Move debug and logging support to a separate header mtdparts: Correct use of debug() Drop the log buffer log: Add an implemention of logging log: Add a console driver log: Add a 'log level' command log: Add a test command log: Plumb logging into the init sequence log: sandbox: Enable logging log: test: Add a pytest for logging log: Add documentation
MAINTAINERS | 9 ++ arch/sandbox/cpu/os.c | 11 ++ cmd/Kconfig | 8 + cmd/Makefile | 2 +- cmd/log.c | 326 +++++--------------------------------- cmd/mtdparts.c | 3 - common/Kconfig | 86 ++++++++++ common/Makefile | 2 + common/board_f.c | 23 +-- common/board_r.c | 27 +--- common/console.c | 7 + common/image.c | 9 -- common/log.c | 247 +++++++++++++++++++++++++++++ common/log_console.c | 23 +++ common/stdio.c | 6 - configs/sandbox_defconfig | 5 +- doc/README.log | 220 +++++++++++++++++++++++++ include/asm-generic/global_data.h | 8 +- include/common.h | 64 +------- include/log.h | 311 ++++++++++++++++++++++++++++++++++++ include/logbuff.h | 49 ------ include/os.h | 20 +++ include/post.h | 4 +- post/post.c | 9 -- post/tests.c | 4 - scripts/config_whitelist.txt | 1 - test/Makefile | 1 + test/log/Makefile | 7 + test/log/log_test.c | 204 ++++++++++++++++++++++++ test/py/tests/test_log.py | 106 +++++++++++++ 30 files changed, 1322 insertions(+), 480 deletions(-) create mode 100644 common/log.c create mode 100644 common/log_console.c create mode 100644 doc/README.log create mode 100644 include/log.h delete mode 100644 include/logbuff.h create mode 100644 test/log/Makefile create mode 100644 test/log/log_test.c create mode 100644 test/py/tests/test_log.py
While sandbox works OK without the special-case code, it does result in console output being stored in the pre-console buffer while sandbox starts up. If there is a crash or a problem then there is no indication of what is going on.
For ease of debugging it seems better to revert this change.
This reverts commit 47b98ad0f6779485d0f0c14f337c3eece273eb54.
Signed-off-by: Simon Glass sjg@chromium.org ---
arch/sandbox/cpu/os.c | 11 +++++++++++ include/os.h | 20 ++++++++++++++++++++ 2 files changed, 31 insertions(+)
diff --git a/arch/sandbox/cpu/os.c b/arch/sandbox/cpu/os.c index 22d6aab534..7243bfc1b1 100644 --- a/arch/sandbox/cpu/os.c +++ b/arch/sandbox/cpu/os.c @@ -413,6 +413,17 @@ int os_get_filesize(const char *fname, loff_t *size) return 0; }
+void os_putc(int ch) +{ + putchar(ch); +} + +void os_puts(const char *str) +{ + while (*str) + os_putc(*str++); +} + int os_write_ram_buf(const char *fname) { struct sandbox_state *state = state_get_current(); diff --git a/include/os.h b/include/os.h index 2bf4bdb1b8..049b248c5b 100644 --- a/include/os.h +++ b/include/os.h @@ -240,6 +240,26 @@ const char *os_dirent_get_typename(enum os_dirent_t type); */ int os_get_filesize(const char *fname, loff_t *size);
+/** + * Write a character to the controlling OS terminal + * + * This bypasses the U-Boot console support and writes directly to the OS + * stdout file descriptor. + * + * @param ch Character to write + */ +void os_putc(int ch); + +/** + * Write a string to the controlling OS terminal + * + * This bypasses the U-Boot console support and writes directly to the OS + * stdout file descriptor. + * + * @param str String to write (note that \n is not appended) + */ +void os_puts(const char *str); + /** * Write the sandbox RAM buffer to a existing file *
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
While sandbox works OK without the special-case code, it does result in console output being stored in the pre-console buffer while sandbox starts up. If there is a crash or a problem then there is no indication of what is going on.
I don't understand where the issue is. I built with current sandbox_defconfig w/ or w/o CONFIG_PRE_CONSOLE_BUFFER, both work fine.
For ease of debugging it seems better to revert this change.
This reverts commit 47b98ad0f6779485d0f0c14f337c3eece273eb54.
Signed-off-by: Simon Glass sjg@chromium.org
arch/sandbox/cpu/os.c | 11 +++++++++++ include/os.h | 20 ++++++++++++++++++++ 2 files changed, 31 insertions(+)
Regards, Bin
Hi Bin,
On 17 September 2017 at 06:48, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
While sandbox works OK without the special-case code, it does result in console output being stored in the pre-console buffer while sandbox starts up. If there is a crash or a problem then there is no indication of what is going on.
I don't understand where the issue is. I built with current sandbox_defconfig w/ or w/o CONFIG_PRE_CONSOLE_BUFFER, both work fine.
Did you try adding a crash before console_init_f()? The problem is that any early problems in sandbox are not reported. It just crashes with no output. With these two patches reverted you can see what is going on.
For ease of debugging it seems better to revert this change.
This reverts commit 47b98ad0f6779485d0f0c14f337c3eece273eb54.
Signed-off-by: Simon Glass sjg@chromium.org
arch/sandbox/cpu/os.c | 11 +++++++++++ include/os.h | 20 ++++++++++++++++++++ 2 files changed, 31 insertions(+)
REgards, Simon
While sandbox works OK without the special-case code, it does result in console output being stored in the pre-console buffer while sandbox starts up. If there is a crash or a problem then there is no indication of what is going on.
For ease of debugging it seems better to revert this change also.
This reverts commit d8c6fb8cedbc35eee27730a7fa544e499b3c81cc.
Signed-off-by: Simon Glass sjg@chromium.org ---
common/console.c | 7 +++++++ configs/sandbox_defconfig | 2 +- 2 files changed, 8 insertions(+), 1 deletion(-)
diff --git a/common/console.c b/common/console.c index f83528ca60..18457aab3c 100644 --- a/common/console.c +++ b/common/console.c @@ -482,6 +482,13 @@ static inline void print_pre_console_buffer(int flushpoint) {}
void putc(const char c) { +#ifdef CONFIG_SANDBOX + /* sandbox can send characters to stdout before it has a console */ + if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) { + os_putc(c); + return; + } +#endif #ifdef CONFIG_DEBUG_UART /* if we don't have a console yet, use the debug UART */ if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) { diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index e7a61bd61a..88ae98d312 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -16,7 +16,7 @@ CONFIG_CONSOLE_RECORD=y CONFIG_CONSOLE_RECORD_OUT_SIZE=0x1000 CONFIG_SILENT_CONSOLE=y CONFIG_PRE_CONSOLE_BUFFER=y -CONFIG_PRE_CON_BUF_ADDR=0 +CONFIG_PRE_CON_BUF_ADDR=0x100000 CONFIG_CMD_CPU=y CONFIG_CMD_LICENSE=y CONFIG_CMD_BOOTZ=y
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
While sandbox works OK without the special-case code, it does result in console output being stored in the pre-console buffer while sandbox starts up. If there is a crash or a problem then there is no indication of what is going on.
For ease of debugging it seems better to revert this change also.
This reverts commit d8c6fb8cedbc35eee27730a7fa544e499b3c81cc.
Signed-off-by: Simon Glass sjg@chromium.org
common/console.c | 7 +++++++ configs/sandbox_defconfig | 2 +- 2 files changed, 8 insertions(+), 1 deletion(-)
diff --git a/common/console.c b/common/console.c index f83528ca60..18457aab3c 100644 --- a/common/console.c +++ b/common/console.c @@ -482,6 +482,13 @@ static inline void print_pre_console_buffer(int flushpoint) {}
void putc(const char c) { +#ifdef CONFIG_SANDBOX
/* sandbox can send characters to stdout before it has a console */if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {os_putc(c);return;}+#endif #ifdef CONFIG_DEBUG_UART /* if we don't have a console yet, use the debug UART */ if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) { diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index e7a61bd61a..88ae98d312 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -16,7 +16,7 @@ CONFIG_CONSOLE_RECORD=y CONFIG_CONSOLE_RECORD_OUT_SIZE=0x1000 CONFIG_SILENT_CONSOLE=y CONFIG_PRE_CONSOLE_BUFFER=y -CONFIG_PRE_CON_BUF_ADDR=0 +CONFIG_PRE_CON_BUF_ADDR=0x100000
Looks commit d8c6fb8cedbc35eee27730a7fa544e499b3c81cc does not have this change. Why is the change from 0 to 0x100000?
CONFIG_CMD_CPU=y CONFIG_CMD_LICENSE=y CONFIG_CMD_BOOTZ=y --
And looks there is more changes in commit d8c6fb8cedbc35eee27730a7fa544e499b3c81cc that is not reverted? ie: puts()?
Regards, Bin
Hi Bin,
On 17 September 2017 at 06:50, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
While sandbox works OK without the special-case code, it does result in console output being stored in the pre-console buffer while sandbox starts up. If there is a crash or a problem then there is no indication of what is going on.
For ease of debugging it seems better to revert this change also.
This reverts commit d8c6fb8cedbc35eee27730a7fa544e499b3c81cc.
Signed-off-by: Simon Glass sjg@chromium.org
common/console.c | 7 +++++++ configs/sandbox_defconfig | 2 +- 2 files changed, 8 insertions(+), 1 deletion(-)
diff --git a/common/console.c b/common/console.c index f83528ca60..18457aab3c 100644 --- a/common/console.c +++ b/common/console.c @@ -482,6 +482,13 @@ static inline void print_pre_console_buffer(int flushpoint) {}
void putc(const char c) { +#ifdef CONFIG_SANDBOX
/* sandbox can send characters to stdout before it has a console */if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {os_putc(c);return;}+#endif #ifdef CONFIG_DEBUG_UART /* if we don't have a console yet, use the debug UART */ if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) { diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index e7a61bd61a..88ae98d312 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -16,7 +16,7 @@ CONFIG_CONSOLE_RECORD=y CONFIG_CONSOLE_RECORD_OUT_SIZE=0x1000 CONFIG_SILENT_CONSOLE=y CONFIG_PRE_CONSOLE_BUFFER=y -CONFIG_PRE_CON_BUF_ADDR=0 +CONFIG_PRE_CON_BUF_ADDR=0x100000
Looks commit d8c6fb8cedbc35eee27730a7fa544e499b3c81cc does not have this change. Why is the change from 0 to 0x100000?
It causes a conflict with other usage of memory in sandbox. I'll split it into a separate patch.
CONFIG_CMD_CPU=y CONFIG_CMD_LICENSE=y CONFIG_CMD_BOOTZ=y --
And looks there is more changes in commit d8c6fb8cedbc35eee27730a7fa544e499b3c81cc that is not reverted? ie: puts()?
That function doesn't have this code in it anymore. It just calls putc().
Regards, Simon
Before adding new features, move these definitions to a separate header to avoid further cluttering common.h.
Signed-off-by: Simon Glass sjg@chromium.org ---
include/common.h | 64 +-------------------------------------------- include/log.h | 79 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 80 insertions(+), 63 deletions(-) create mode 100644 include/log.h
diff --git a/include/common.h b/include/common.h index aaed131671..459d273389 100644 --- a/include/common.h +++ b/include/common.h @@ -42,69 +42,7 @@ typedef volatile unsigned char vu_char; #define CONFIG_SYS_SUPPORT_64BIT_DATA #endif
-#ifdef DEBUG -#define _DEBUG 1 -#else -#define _DEBUG 0 -#endif - -#ifdef CONFIG_SPL_BUILD -#define _SPL_BUILD 1 -#else -#define _SPL_BUILD 0 -#endif - -/* Define this at the top of a file to add a prefix to debug messages */ -#ifndef pr_fmt -#define pr_fmt(fmt) fmt -#endif - -/* - * Output a debug text when condition "cond" is met. The "cond" should be - * computed by a preprocessor in the best case, allowing for the best - * optimization. - */ -#define debug_cond(cond, fmt, args...) \ - do { \ - if (cond) \ - printf(pr_fmt(fmt), ##args); \ - } while (0) - -/* Show a message if DEBUG is defined in a file */ -#define debug(fmt, args...) \ - debug_cond(_DEBUG, fmt, ##args) - -/* Show a message if not in SPL */ -#define warn_non_spl(fmt, args...) \ - debug_cond(!_SPL_BUILD, fmt, ##args) - -/* - * An assertion is run-time check done in debug mode only. If DEBUG is not - * defined then it is skipped. If DEBUG is defined and the assertion fails, - * then it calls panic*( which may or may not reset/halt U-Boot (see - * CONFIG_PANIC_HANG), It is hoped that all failing assertions are found - * before release, and after release it is hoped that they don't matter. But - * in any case these failing assertions cannot be fixed with a reset (which - * may just do the same assertion again). - */ -void __assert_fail(const char *assertion, const char *file, unsigned line, - const char *function); -#define assert(x) \ - ({ if (!(x) && _DEBUG) \ - __assert_fail(#x, __FILE__, __LINE__, __func__); }) - -#define error(fmt, args...) do { \ - printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ - ##args, __FILE__, __LINE__, __func__); \ -} while (0) - -#ifndef BUG -#define BUG() do { \ - printf("BUG: failure at %s:%d/%s()!\n", __FILE__, __LINE__, __FUNCTION__); \ - panic("BUG!"); \ -} while (0) -#define BUG_ON(condition) do { if (unlikely((condition)!=0)) BUG(); } while(0) -#endif /* BUG */ +#include <log.h>
typedef void (interrupt_handler_t)(void *);
diff --git a/include/log.h b/include/log.h new file mode 100644 index 0000000000..4101a74161 --- /dev/null +++ b/include/log.h @@ -0,0 +1,79 @@ +/* + * Logging support + * + * Copyright (c) 2017 Google, Inc + * Written by Simon Glass sjg@chromium.org + * + * SPDX-License-Identifier: GPL-2.0+ + */ + +#ifndef __LOG_H +#define __LOG_H + +#ifdef DEBUG +#define _DEBUG 1 +#else +#define _DEBUG 0 +#endif + +#ifdef CONFIG_SPL_BUILD +#define _SPL_BUILD 1 +#else +#define _SPL_BUILD 0 +#endif + +/* Define this at the top of a file to add a prefix to debug messages */ +#ifndef pr_fmt +#define pr_fmt(fmt) fmt +#endif + +/* + * Output a debug text when condition "cond" is met. The "cond" should be + * computed by a preprocessor in the best case, allowing for the best + * optimization. + */ +#define debug_cond(cond, fmt, args...) \ + do { \ + if (cond) \ + printf(pr_fmt(fmt), ##args); \ + } while (0) + +/* Show a message if DEBUG is defined in a file */ +#define debug(fmt, args...) \ + debug_cond(_DEBUG, fmt, ##args) + +/* Show a message if not in SPL */ +#define warn_non_spl(fmt, args...) \ + debug_cond(!_SPL_BUILD, fmt, ##args) + +/* + * An assertion is run-time check done in debug mode only. If DEBUG is not + * defined then it is skipped. If DEBUG is defined and the assertion fails, + * then it calls panic*( which may or may not reset/halt U-Boot (see + * CONFIG_PANIC_HANG), It is hoped that all failing assertions are found + * before release, and after release it is hoped that they don't matter. But + * in any case these failing assertions cannot be fixed with a reset (which + * may just do the same assertion again). + */ +void __assert_fail(const char *assertion, const char *file, unsigned int line, + const char *function); +#define assert(x) \ + ({ if (!(x) && _DEBUG) \ + __assert_fail(#x, __FILE__, __LINE__, __func__); }) + +#define error(fmt, args...) do { \ + printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ + ##args, __FILE__, __LINE__, __func__); \ +} while (0) + +#ifndef BUG +#define BUG() do { \ + printf("BUG: failure at %s:%d/%s()!\n", __FILE__, __LINE__, \ + __func__); \ + panic("BUG!"); \ +} while (0) +#define BUG_ON(condition) do { if (unlikely((condition) != 0)) BUG(); } \ + while (0) +#endif /* BUG */ + +#endif
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Before adding new features, move these definitions to a separate header to avoid further cluttering common.h.
Signed-off-by: Simon Glass sjg@chromium.org
include/common.h | 64 +-------------------------------------------- include/log.h | 79 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 80 insertions(+), 63 deletions(-) create mode 100644 include/log.h
Reviewed-by: Bin Meng bmeng.cn@gmail.com
The debug() macro now evaluates its expression so does not need #ifdef protection. In fact the current code causes a warning with the new log implementation. Adjust the code to fix this.
Signed-off-by: Simon Glass sjg@chromium.org ---
cmd/mtdparts.c | 3 --- 1 file changed, 3 deletions(-)
diff --git a/cmd/mtdparts.c b/cmd/mtdparts.c index 3275eb919b..13677faf4b 100644 --- a/cmd/mtdparts.c +++ b/cmd/mtdparts.c @@ -873,15 +873,12 @@ static int device_parse(const char *const mtd_dev, const char **ret, struct mtd_ return 1; }
-#ifdef DEBUG pend = strchr(p, ';'); -#endif debug("dev type = %d (%s), dev num = %d, mtd-id = %s\n", id->type, MTD_DEV_TYPE(id->type), id->num, id->mtd_id); debug("parsing partitions %.*s\n", (int)(pend ? pend - p : strlen(p)), p);
- /* parse partitions */ num_parts = 0;
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
The debug() macro now evaluates its expression so does not need #ifdef protection. In fact the current code causes a warning with the new log implementation. Adjust the code to fix this.
Signed-off-by: Simon Glass sjg@chromium.org
cmd/mtdparts.c | 3 --- 1 file changed, 3 deletions(-)
Reviewed-by: Bin Meng bmeng.cn@gmail.com
This does not appear to be used by any boards. Before introducing a new log system, remove this old one.
Signed-off-by: Simon Glass sjg@chromium.org ---
cmd/Makefile | 1 - cmd/log.c | 313 -------------------------------------- common/board_f.c | 18 --- common/board_r.c | 25 +-- common/image.c | 9 -- common/stdio.c | 6 - include/asm-generic/global_data.h | 2 +- include/logbuff.h | 49 ------ include/post.h | 4 +- post/post.c | 9 -- post/tests.c | 4 - scripts/config_whitelist.txt | 1 - 12 files changed, 5 insertions(+), 436 deletions(-) delete mode 100644 cmd/log.c delete mode 100644 include/logbuff.h
diff --git a/cmd/Makefile b/cmd/Makefile index 2a5b8ce825..1b13d07901 100644 --- a/cmd/Makefile +++ b/cmd/Makefile @@ -75,7 +75,6 @@ obj-$(CONFIG_LED_STATUS_CMD) += legacy_led.o obj-$(CONFIG_CMD_LED) += led.o obj-$(CONFIG_CMD_LICENSE) += license.o obj-y += load.o -obj-$(CONFIG_LOGBUFFER) += log.o obj-$(CONFIG_ID_EEPROM) += mac.o obj-$(CONFIG_CMD_MD5SUM) += md5sum.o obj-$(CONFIG_CMD_MEMORY) += mem.o diff --git a/cmd/log.c b/cmd/log.c deleted file mode 100644 index 7a3bd5cd69..0000000000 --- a/cmd/log.c +++ /dev/null @@ -1,313 +0,0 @@ -/* - * (C) Copyright 2002-2007 - * Detlev Zundel, DENX Software Engineering, dzu@denx.de. - * - * Code used from linux/kernel/printk.c - * Copyright (C) 1991, 1992 Linus Torvalds - * - * SPDX-License-Identifier: GPL-2.0+ - * - * Comments: - * - * After relocating the code, the environment variable "loglevel" is - * copied to console_loglevel. The functionality is similar to the - * handling in the Linux kernel, i.e. messages logged with a priority - * less than console_loglevel are also output to stdout. - * - * If you want messages with the default level (e.g. POST messages) to - * appear on stdout also, make sure the environment variable - * "loglevel" is set at boot time to a number higher than - * default_message_loglevel below. - */ - -/* - * Logbuffer handling routines - */ - -#include <common.h> -#include <command.h> -#include <stdio_dev.h> -#include <post.h> -#include <logbuff.h> - -DECLARE_GLOBAL_DATA_PTR; - -/* Local prototypes */ -static void logbuff_putc(struct stdio_dev *dev, const char c); -static void logbuff_puts(struct stdio_dev *dev, const char *s); -static int logbuff_printk(const char *line); - -static char buf[1024]; - -/* This combination will not print messages with the default loglevel */ -static unsigned console_loglevel = 3; -static unsigned default_message_loglevel = 4; -static unsigned log_version = 1; -#ifdef CONFIG_ALT_LB_ADDR -static volatile logbuff_t *log; -#else -static logbuff_t *log; -#endif -static char *lbuf; - -unsigned long __logbuffer_base(void) -{ - return CONFIG_SYS_SDRAM_BASE + get_effective_memsize() - LOGBUFF_LEN; -} -unsigned long logbuffer_base(void) -__attribute__((weak, alias("__logbuffer_base"))); - -void logbuff_init_ptrs(void) -{ - unsigned long tag, post_word; - char *s; - -#ifdef CONFIG_ALT_LB_ADDR - log = (logbuff_t *)CONFIG_ALT_LH_ADDR; - lbuf = (char *)CONFIG_ALT_LB_ADDR; -#else - log = (logbuff_t *)(logbuffer_base()) - 1; - lbuf = (char *)log->buf; -#endif - - /* Set up log version */ - s = env_get("logversion"); - if (s) - log_version = (int)simple_strtoul(s, NULL, 10); - - if (log_version == 2) - tag = log->v2.tag; - else - tag = log->v1.tag; - post_word = post_word_load(); -#ifdef CONFIG_POST - /* The post routines have setup the word so we can simply test it */ - if (tag != LOGBUFF_MAGIC || (post_word & POST_COLDBOOT)) - logbuff_reset(); -#else - /* No post routines, so we do our own checking */ - if (tag != LOGBUFF_MAGIC || post_word != LOGBUFF_MAGIC) { - logbuff_reset (); - post_word_store (LOGBUFF_MAGIC); - } -#endif - if (log_version == 2 && (long)log->v2.start > (long)log->v2.con) - log->v2.start = log->v2.con; - - /* Initialize default loglevel if present */ - s = env_get("loglevel"); - if (s) - console_loglevel = (int)simple_strtoul(s, NULL, 10); - - gd->flags |= GD_FLG_LOGINIT; -} - -void logbuff_reset(void) -{ -#ifndef CONFIG_ALT_LB_ADDR - memset(log, 0, sizeof(logbuff_t)); -#endif - if (log_version == 2) { - log->v2.tag = LOGBUFF_MAGIC; -#ifdef CONFIG_ALT_LB_ADDR - log->v2.start = 0; - log->v2.con = 0; - log->v2.end = 0; - log->v2.chars = 0; -#endif - } else { - log->v1.tag = LOGBUFF_MAGIC; -#ifdef CONFIG_ALT_LB_ADDR - log->v1.dummy = 0; - log->v1.start = 0; - log->v1.size = 0; - log->v1.chars = 0; -#endif - } -} - -int drv_logbuff_init(void) -{ - struct stdio_dev logdev; - int rc; - - /* Device initialization */ - memset (&logdev, 0, sizeof (logdev)); - - strcpy (logdev.name, "logbuff"); - logdev.ext = 0; /* No extensions */ - logdev.flags = DEV_FLAGS_OUTPUT; /* Output only */ - logdev.putc = logbuff_putc; /* 'putc' function */ - logdev.puts = logbuff_puts; /* 'puts' function */ - - rc = stdio_register(&logdev); - - return (rc == 0) ? 1 : rc; -} - -static void logbuff_putc(struct stdio_dev *dev, const char c) -{ - char buf[2]; - buf[0] = c; - buf[1] = '\0'; - logbuff_printk(buf); -} - -static void logbuff_puts(struct stdio_dev *dev, const char *s) -{ - logbuff_printk (s); -} - -void logbuff_log(char *msg) -{ - if ((gd->flags & GD_FLG_LOGINIT)) { - logbuff_printk(msg); - } else { - /* - * Can happen only for pre-relocated errors as logging - * at that stage should be disabled - */ - puts (msg); - } -} - -/* - * Subroutine: do_log - * - * Description: Handler for 'log' command.. - * - * Inputs: argv[1] contains the subcommand - * - * Return: None - * - */ -int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) -{ - struct stdio_dev *sdev = NULL; - char *s; - unsigned long i, start, size; - - if (strcmp(argv[1], "append") == 0) { - /* Log concatenation of all arguments separated by spaces */ - for (i = 2; i < argc; i++) { - logbuff_printk(argv[i]); - logbuff_putc(sdev, (i < argc - 1) ? ' ' : '\n'); - } - return 0; - } - - switch (argc) { - - case 2: - if (strcmp(argv[1], "show") == 0) { - if (log_version == 2) { - start = log->v2.start; - size = log->v2.end - log->v2.start; - } else { - start = log->v1.start; - size = log->v1.size; - } - if (size > LOGBUFF_LEN) - size = LOGBUFF_LEN; - for (i = 0; i < size; i++) { - s = lbuf + ((start + i) & LOGBUFF_MASK); - putc(*s); - } - return 0; - } else if (strcmp(argv[1], "reset") == 0) { - logbuff_reset(); - return 0; - } else if (strcmp(argv[1], "info") == 0) { - printf("Logbuffer at %08lx\n", (unsigned long)lbuf); - if (log_version == 2) { - printf("log_start = %08lx\n", - log->v2.start); - printf("log_end = %08lx\n", log->v2.end); - printf("log_con = %08lx\n", log->v2.con); - printf("logged_chars = %08lx\n", - log->v2.chars); - } - else { - printf("log_start = %08lx\n", - log->v1.start); - printf("log_size = %08lx\n", - log->v1.size); - printf("logged_chars = %08lx\n", - log->v1.chars); - } - return 0; - } - return CMD_RET_USAGE; - - default: - return CMD_RET_USAGE; - } -} - -U_BOOT_CMD( - log, 255, 1, do_log, - "manipulate logbuffer", - "info - show pointer details\n" - "log reset - clear contents\n" - "log show - show contents\n" - "log append <msg> - append <msg> to the logbuffer" -); - -static int logbuff_printk(const char *line) -{ - int i; - char *msg, *p, *buf_end; - int line_feed; - static signed char msg_level = -1; - - strcpy(buf + 3, line); - i = strlen(line); - buf_end = buf + 3 + i; - for (p = buf + 3; p < buf_end; p++) { - msg = p; - if (msg_level < 0) { - if ( - p[0] != '<' || - p[1] < '0' || - p[1] > '7' || - p[2] != '>' - ) { - p -= 3; - p[0] = '<'; - p[1] = default_message_loglevel + '0'; - p[2] = '>'; - } else { - msg += 3; - } - msg_level = p[1] - '0'; - } - line_feed = 0; - for (; p < buf_end; p++) { - if (log_version == 2) { - lbuf[log->v2.end & LOGBUFF_MASK] = *p; - log->v2.end++; - if (log->v2.end - log->v2.start > LOGBUFF_LEN) - log->v2.start++; - log->v2.chars++; - } else { - lbuf[(log->v1.start + log->v1.size) & - LOGBUFF_MASK] = *p; - if (log->v1.size < LOGBUFF_LEN) - log->v1.size++; - else - log->v1.start++; - log->v1.chars++; - } - if (*p == '\n') { - line_feed = 1; - break; - } - } - if (msg_level < console_loglevel) { - printf("%s", msg); - } - if (line_feed) - msg_level = -1; - } - return i; -} diff --git a/common/board_f.c b/common/board_f.c index 104d144f41..d0b1a00175 100644 --- a/common/board_f.c +++ b/common/board_f.c @@ -19,7 +19,6 @@ #include <i2c.h> #include <initcall.h> #include <init_helpers.h> -#include <logbuff.h> #include <malloc.h> #include <mapmem.h> #include <os.h> @@ -296,20 +295,6 @@ static int setup_dest_addr(void) return 0; }
-#if defined(CONFIG_LOGBUFFER) -static int reserve_logbuffer(void) -{ -#ifndef CONFIG_ALT_LB_ADDR - /* reserve kernel log buffer */ - gd->relocaddr -= LOGBUFF_RESERVE; - debug("Reserving %dk for kernel logbuffer at %08lx\n", LOGBUFF_LEN, - gd->relocaddr); -#endif - - return 0; -} -#endif - #ifdef CONFIG_PRAM /* reserve protected RAM */ static int reserve_pram(void) @@ -846,9 +831,6 @@ static const init_fnc_t init_sequence_f[] = { * - board info struct */ setup_dest_addr, -#if defined(CONFIG_LOGBUFFER) - reserve_logbuffer, -#endif #ifdef CONFIG_PRAM reserve_pram, #endif diff --git a/common/board_r.c b/common/board_r.c index 94697e7bc1..02ac43d39c 100644 --- a/common/board_r.c +++ b/common/board_r.c @@ -33,7 +33,6 @@ #if defined(CONFIG_CMD_KGDB) #include <kgdb.h> #endif -#include <logbuff.h> #include <malloc.h> #include <mapmem.h> #ifdef CONFIG_BITBANGMII @@ -203,19 +202,6 @@ static int initr_addr_map(void) } #endif
-#ifdef CONFIG_LOGBUFFER -unsigned long logbuffer_base(void) -{ - return gd->ram_top - LOGBUFF_LEN; -} - -static int initr_logbuffer(void) -{ - logbuff_init_ptrs(); - return 0; -} -#endif - #ifdef CONFIG_POST static int initr_post_backlog(void) { @@ -640,7 +626,7 @@ static int initr_ide(void) } #endif
-#if defined(CONFIG_PRAM) || defined(CONFIG_LOGBUFFER) +#if defined(CONFIG_PRAM) /* * Export available size of memory for Linux, taking into account the * protected RAM at top of memory @@ -652,10 +638,6 @@ int initr_mem(void)
# ifdef CONFIG_PRAM pram = env_get_ulong("pram", 10, CONFIG_PRAM); -# endif -# if defined(CONFIG_LOGBUFFER) && !defined(CONFIG_ALT_LB_ADDR) - /* Also take the logbuffer into account (pram is in kB) */ - pram += (LOGBUFF_LEN + LOGBUFF_OVERHEAD) / 1024; # endif sprintf(memsz, "%ldk", (long int) ((gd->ram_size / 1024) - pram)); env_set("mem", memsz); @@ -765,9 +747,6 @@ static init_fnc_t init_sequence_r[] = { board_early_init_r, #endif INIT_FUNC_WATCHDOG_RESET -#ifdef CONFIG_LOGBUFFER - initr_logbuffer, -#endif #ifdef CONFIG_POST initr_post_backlog, #endif @@ -892,7 +871,7 @@ static init_fnc_t init_sequence_r[] = { INIT_FUNC_WATCHDOG_RESET initr_bedbug, #endif -#if defined(CONFIG_PRAM) || defined(CONFIG_LOGBUFFER) +#if defined(CONFIG_PRAM) initr_mem, #endif #ifdef CONFIG_PS2KBD diff --git a/common/image.c b/common/image.c index 332b5f2843..123b0fb75d 100644 --- a/common/image.c +++ b/common/image.c @@ -19,10 +19,6 @@ #include <dataflash.h> #endif
-#ifdef CONFIG_LOGBUFFER -#include <logbuff.h> -#endif - #include <rtc.h>
#include <environment.h> @@ -1238,11 +1234,6 @@ int boot_ramdisk_high(struct lmb *lmb, ulong rd_data, ulong rd_len, }
-#ifdef CONFIG_LOGBUFFER - /* Prevent initrd from overwriting logbuffer */ - lmb_reserve(lmb, logbuffer_base() - LOGBUFF_OVERHEAD, LOGBUFF_RESERVE); -#endif - debug("## initrd_high = 0x%08lx, copy_to_ram = %d\n", initrd_high, initrd_copy_to_ram);
diff --git a/common/stdio.c b/common/stdio.c index ee4f0bda9e..2e5143a025 100644 --- a/common/stdio.c +++ b/common/stdio.c @@ -17,9 +17,6 @@ #include <malloc.h> #include <stdio_dev.h> #include <serial.h> -#ifdef CONFIG_LOGBUFFER -#include <logbuff.h> -#endif
#if defined(CONFIG_SYS_I2C) #include <i2c.h> @@ -380,9 +377,6 @@ int stdio_add_devices(void) #endif /* CONFIG_DM_VIDEO */ #if defined(CONFIG_KEYBOARD) && !defined(CONFIG_DM_KEYBOARD) drv_keyboard_init (); -#endif -#ifdef CONFIG_LOGBUFFER - drv_logbuff_init (); #endif drv_system_init (); serial_stdio_init (); diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h index 944f58195c..79197acfa4 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -36,7 +36,7 @@ typedef struct global_data { #if defined(CONFIG_LCD) || defined(CONFIG_VIDEO) unsigned long fb_base; /* Base address of framebuffer mem */ #endif -#if defined(CONFIG_POST) || defined(CONFIG_LOGBUFFER) +#if defined(CONFIG_POST) unsigned long post_log_word; /* Record POST activities */ unsigned long post_log_res; /* success of POST test */ unsigned long post_init_f_time; /* When post_init_f started */ diff --git a/include/logbuff.h b/include/logbuff.h deleted file mode 100644 index 625feb9f95..0000000000 --- a/include/logbuff.h +++ /dev/null @@ -1,49 +0,0 @@ -/* - * (C) Copyright 2002-2007 - * Detlev Zundel, dzu@denx.de. - * - * SPDX-License-Identifier: GPL-2.0+ - */ -#ifndef _LOGBUFF_H -#define _LOGBUFF_H - -#ifdef CONFIG_LOGBUFFER - -#define LOGBUFF_MAGIC 0xc0de4ced /* Forced by code, eh! */ -#define LOGBUFF_LEN (16384) /* Must be 16k right now */ -#define LOGBUFF_MASK (LOGBUFF_LEN-1) -#define LOGBUFF_OVERHEAD (4096) /* Logbuffer overhead for extra info */ -#define LOGBUFF_RESERVE (LOGBUFF_LEN+LOGBUFF_OVERHEAD) - -/* The mapping used here has to be the same as in setup_ext_logbuff () - in linux/kernel/printk */ - -typedef struct { - union { - struct { - unsigned long tag; - unsigned long start; - unsigned long con; - unsigned long end; - unsigned long chars; - } v2; - struct { - unsigned long dummy; - unsigned long tag; - unsigned long start; - unsigned long size; - unsigned long chars; - } v1; - }; - unsigned char buf[0]; -} logbuff_t; - -int drv_logbuff_init (void); -void logbuff_init_ptrs (void); -void logbuff_log(char *msg); -void logbuff_reset (void); -unsigned long logbuffer_base (void); - -#endif /* CONFIG_LOGBUFFER */ - -#endif /* _LOGBUFF_H */ diff --git a/include/post.h b/include/post.h index d5278111e8..b41a6c8127 100644 --- a/include/post.h +++ b/include/post.h @@ -15,7 +15,7 @@ #include <common.h> #include <asm/io.h>
-#if defined(CONFIG_POST) || defined(CONFIG_LOGBUFFER) +#if defined(CONFIG_POST)
#ifndef CONFIG_POST_EXTERNAL_WORD_FUNCS #ifdef CONFIG_SYS_POST_WORD_ADDR @@ -58,7 +58,7 @@ extern ulong post_word_load(void); extern void post_word_store(ulong value);
#endif /* CONFIG_POST_EXTERNAL_WORD_FUNCS */ -#endif /* defined (CONFIG_POST) || defined(CONFIG_LOGBUFFER) */ +#endif /* defined (CONFIG_POST) */ #endif /* __ASSEMBLY__ */
#ifdef CONFIG_POST diff --git a/post/post.c b/post/post.c index 8fef0c3412..6c7902ad0c 100644 --- a/post/post.c +++ b/post/post.c @@ -15,10 +15,6 @@ #include <asm/gpio.h> #endif
-#ifdef CONFIG_LOGBUFFER -#include <logbuff.h> -#endif - DECLARE_GLOBAL_DATA_PTR;
#define POST_MAX_NUMBER 32 @@ -407,13 +403,8 @@ int post_log(char *format, ...) vsprintf(printbuffer, format, args); va_end(args);
-#ifdef CONFIG_LOGBUFFER - /* Send to the logbuffer */ - logbuff_log(printbuffer); -#else /* Send to the stdout file */ puts(printbuffer); -#endif
return 0; } diff --git a/post/tests.c b/post/tests.c index bc8e398051..473c0ea1e1 100644 --- a/post/tests.c +++ b/post/tests.c @@ -3,10 +3,6 @@ * Wolfgang Denk, DENX Software Engineering, wd@denx.de. * * SPDX-License-Identifier: GPL-2.0+ - * - * Be sure to mark tests to be run before relocation as such with the - * CONFIG_SYS_POST_PREREL flag so that logging is done correctly if the - * logbuffer support is enabled. */
#include <common.h> diff --git a/scripts/config_whitelist.txt b/scripts/config_whitelist.txt index 56bb639091..7689410243 100644 --- a/scripts/config_whitelist.txt +++ b/scripts/config_whitelist.txt @@ -1292,7 +1292,6 @@ CONFIG_LMS283GF05 CONFIG_LOADADDR CONFIG_LOADCMD CONFIG_LOADS_ECHO -CONFIG_LOGBUFFER CONFIG_LOWPOWER_ADDR CONFIG_LOWPOWER_FLAG CONFIG_LOW_MCFCLK
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
This does not appear to be used by any boards. Before introducing a new log system, remove this old one.
Signed-off-by: Simon Glass sjg@chromium.org
cmd/Makefile | 1 - cmd/log.c | 313 -------------------------------------- common/board_f.c | 18 --- common/board_r.c | 25 +-- common/image.c | 9 -- common/stdio.c | 6 - include/asm-generic/global_data.h | 2 +- include/logbuff.h | 49 ------ include/post.h | 4 +- post/post.c | 9 -- post/tests.c | 4 - scripts/config_whitelist.txt | 1 - 12 files changed, 5 insertions(+), 436 deletions(-) delete mode 100644 cmd/log.c delete mode 100644 include/logbuff.h
Reviewed-by: Bin Meng bmeng.cn@gmail.com
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org ---
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py + MICROBLAZE M: Michal Simek monstr@monstr.eu S: Maintained diff --git a/common/Kconfig b/common/Kconfig index 4d8cae9610..cbccc8ae26 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -384,6 +384,62 @@ config SYS_STDIO_DEREGISTER
endmenu
+menu "Logging" + +config LOG + bool "Enable logging support" + help + This enables support for logging of status and debug messages. These + can be displayed on the console, recorded in a memory buffer, or + discarded if not needed. Logging supports various categories and + levels of severity. + +config SPL_LOG + bool "Enable logging support in SPL" + help + This enables support for logging of status and debug messages. These + can be displayed on the console, recorded in a memory buffer, or + discarded if not needed. Logging supports various categories and + levels of severity. + +config LOG_MAX_LEVEL + int "Maximum log level to record" + depends on LOG + default 5 + help + This selects the maximum log level that will be recorded. Any value + higher than this will be ignored. If possible log statements below + this level will be discarded at build time. Levels: + + 0 - panic + 1 - critical + 2 - error + 3 - warning + 4 - note + 5 - info + 6 - detail + 7 - debug + +config LOG_SPL_MAX_LEVEL + int "Maximum log level to record in SPL" + depends on SPL_LOG + default 3 + help + This selects the maximum log level that will be recorded. Any value + higher than this will be ignored. If possible log statements below + this level will be discarded at build time. Levels: + + 0 - panic + 1 - critical + 2 - error + 3 - warning + 4 - note + 5 - info + 6 - detail + 7 - debug + +endmenu + config DTB_RESELECT bool "Support swapping dtbs at a later point in boot" depends on FIT_EMBED diff --git a/common/Makefile b/common/Makefile index 1b56cf9a70..d37c8d5636 100644 --- a/common/Makefile +++ b/common/Makefile @@ -128,5 +128,6 @@ obj-y += cli.o obj-$(CONFIG_FSL_DDR_INTERACTIVE) += cli_simple.o cli_readline.o obj-$(CONFIG_CMD_DFU) += dfu.o obj-y += command.o +obj-$(CONFIG_$(SPL_)LOG) += log.o obj-y += s_record.o obj-y += xyzModem.o diff --git a/common/log.c b/common/log.c new file mode 100644 index 0000000000..6bf2219d38 --- /dev/null +++ b/common/log.c @@ -0,0 +1,246 @@ +/* + * Logging support + * + * Copyright (c) 2017 Google, Inc + * Written by Simon Glass sjg@chromium.org + * + * SPDX-License-Identifier: GPL-2.0+ + */ + +#include <common.h> +#include <log.h> +#include <malloc.h> + +DECLARE_GLOBAL_DATA_PTR; + +static struct log_device *log_device_find_by_name(const char *drv_name) +{ + struct log_device *ldev; + + list_for_each_entry(ldev, &gd->log_head, sibling_node) { + if (!strcmp(drv_name, ldev->drv->name)) + return ldev; + } + + return NULL; +} + +/** + * log_has_cat() - check if a log category exists within a list + * + * @cat_list: List of categories to check, at most LOGF_MAX_CATEGORIES entries + * long, terminated by LC_END if fewer + * @cat: Category to search for + * @return true if @cat is in @cat_list, else false + */ +static bool log_has_cat(enum log_category_t cat_list[], enum log_category_t cat) +{ + int i; + + for (i = 0; i < LOGF_MAX_CATEGORIES && cat_list[i] != LOGC_END; i++) { + if (cat_list[i] == cat) + return true; + } + + return false; +} + +/** + * log_has_file() - check if a file is with a list + * + * @file_list: List of files to check, separated by comma + * @file: File to check for. This string is matched against the end of each + * file in the list, i.e. ignoring any preceeding path. The list is + * intended to consist of relative pathnames, e.g. common/main.c,cmd/log.c + * @return true if @file is in @file_list, else false + */ +static bool log_has_file(const char *file_list, const char *file) +{ + int file_len = strlen(file); + const char *s, *p; + int substr_len; + + for (s = file_list; *s; s = p + (*p != '\0')) { + p = strchrnul(s, ','); + substr_len = p - s; + if (file_len >= substr_len && + !strncmp(file + file_len - substr_len, s, substr_len)) + return true; + } + + return false; +} + +/** + * log_passes_filters() - check if a log record passes the filters for a device + * + * @ldev: Log device to check + * @rec: Log record to check + * @return true if @rec is not blocked by the filters in @ldev, false if it is + */ +static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec) +{ + struct log_filter *filt; + + /* If there are no filters, filter on the default log level */ + if (list_empty(&ldev->filter_head)) { + if (rec->level > gd->default_log_level) + return false; + return true; + } + + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { + if (rec->level > filt->max_level) + continue; + if ((filt->flags & LOGFF_HAS_CAT) && + !log_has_cat(filt->cat_list, rec->cat)) + continue; + if (filt->file_list && + !log_has_file(filt->file_list, rec->file)) + continue; + return true; + } + + return false; +} + +/** + * log_dispatch() - Send a log record to all log devices for processing + * + * The log record is sent to each log device in turn, skipping those which have + * filters which block the record + * + * @rec: Log record to dispatch + * @return 0 (meaning success) + */ +static int log_dispatch(struct log_rec *rec) +{ + struct log_device *ldev; + + list_for_each_entry(ldev, &gd->log_head, sibling_node) { + if (log_passes_filters(ldev, rec)) + ldev->drv->emit(ldev, rec); + } + + return 0; +} + +int _log(enum log_category_t cat, enum log_level_t level, const char *file, + int line, const char *func, const char *fmt, ...) +{ + char buf[CONFIG_SYS_CBSIZE]; + struct log_rec rec; + va_list args; + + rec.cat = cat; + rec.level = level; + rec.file = file; + rec.line = line; + rec.func = func; + va_start(args, fmt); + vsnprintf(buf, sizeof(buf), fmt, args); + va_end(args); + rec.msg = buf; + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { + if (gd) + gd->log_drop_count++; + return -ENOSYS; + } + log_dispatch(&rec); + + return 0; +} + +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], + enum log_level_t max_level, const char *file_list) +{ + struct log_filter *filt; + struct log_device *ldev; + int i; + + ldev = log_device_find_by_name(drv_name); + if (!ldev) + return -ENOENT; + filt = (struct log_filter *)calloc(1, sizeof(*filt)); + if (!filt) + return -ENOMEM; + + if (cat_list) { + filt->flags |= LOGFF_HAS_CAT; + for (i = 0; ; i++) { + if (i == ARRAY_SIZE(filt->cat_list)) + return -ENOSPC; + filt->cat_list[i] = cat_list[i]; + if (cat_list[i] == LOGC_END) + break; + } + } + filt->max_level = max_level; + if (file_list) { + filt->file_list = strdup(file_list); + if (!filt->file_list) + goto nomem; + } + filt->filter_num = ldev->next_filter_num++; + INIT_LIST_HEAD(&filt->sibling_node); + list_add_tail(&filt->sibling_node, &ldev->filter_head); + + return filt->filter_num; + +nomem: + free(filt); + return -ENOMEM; +} + +int log_remove_filter(const char *drv_name, int filter_num) +{ + struct log_filter *filt; + struct log_device *ldev; + + ldev = log_device_find_by_name(drv_name); + if (!ldev) + return -ENOENT; + + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { + if (filt->filter_num == filter_num) { + list_del(&filt->sibling_node); + free(filt); + + return 0; + } + } + + return -ENOENT; +} + +int log_init(void) +{ + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); + const int count = ll_entry_count(struct log_driver, log_driver); + struct log_driver *end = drv + count; + + /* + * We cannot add runtime data to the driver since it is likely stored + * in rodata. Instead, set up a 'device' corresponding to each driver. + * We only support having a single device. + */ + INIT_LIST_HEAD((struct list_head *)&gd->log_head); + while (drv < end) { + struct log_device *ldev; + + ldev = calloc(1, sizeof(*ldev)); + if (!ldev) { + debug("%s: Cannot allocate memory\n", __func__); + return -ENOMEM; + } + INIT_LIST_HEAD(&ldev->sibling_node); + INIT_LIST_HEAD(&ldev->filter_head); + ldev->drv = drv; + list_add_tail(&ldev->sibling_node, + (struct list_head *)&gd->log_head); + drv++; + } + gd->default_log_level = LOGL_INFO; + + return 0; +} diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h index 79197acfa4..77755dbb06 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -114,6 +114,11 @@ typedef struct global_data { struct bootstage_data *bootstage; /* Bootstage information */ struct bootstage_data *new_bootstage; /* Relocated bootstage info */ #endif +#ifdef CONFIG_LOG + int log_drop_count; /* Number of dropped log messages */ + int default_log_level; /* For devices with no filters */ + struct list_head log_head; /* List of struct log_device */ +#endif } gd_t; #endif
diff --git a/include/log.h b/include/log.h index 4101a74161..fb6a196202 100644 --- a/include/log.h +++ b/include/log.h @@ -10,6 +10,82 @@ #ifndef __LOG_H #define __LOG_H
+#include <dm/uclass-id.h> +#include <linux/list.h> + +/** Log levels supported, ranging from most to least important */ +enum log_level_t { + LOGL_PANIC = 0, + LOGL_CRIT, + LOGL_ERR, + LOGL_WARN, + LOGL_NOTE, + LOGL_INFO, + LOGL_DETAIL, + LOGL_DEBUG, + + LOGL_COUNT, + LOGL_FIRST = LOGL_PANIC, + LOGL_MAX = LOGL_DEBUG, +}; + +/** + * Log categories supported. Most of these correspond to uclasses (i.e. + * enum uclass_id) but there are also some more generic categories + */ +enum log_category_t { + LOGC_FIRST = 0, /* First part mirrors UCLASS_... */ + + LOGC_NONE = UCLASS_COUNT, + LOGC_ARCH, + LOGC_BOARD, + LOGC_CORE, + LOGC_DT, + + LOGC_COUNT, + LOGC_END, +}; + +/** + * _log() - Internal function to emit a new log record + * + * @cat: Category of log record (indicating which subsystem generated it) + * @level: Level of log record (indicating its severity) + * @file: File name of file where log record was generated + * @line: Line number in file where log record was generated + * @func: Function where log record was generated + * @fmt: printf() format string for log record + * @...: Optional parameters, according to the format string @fmt + * @return 0 if log record was emitted, -ve on error + */ +int _log(enum log_category_t cat, enum log_level_t level, const char *file, + int line, const char *func, const char *fmt, ...); + +/* Define this at the top of a file to add a prefix to debug messages */ +#ifndef pr_fmt +#define pr_fmt(fmt) fmt +#endif + +/* Use a default category if this file does not supply one */ +#ifndef LOG_CATEGORY +#define LOG_CATEGORY LOGC_NONE +#endif + +#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif + +/* Emit a log record if the level is less that the maximum */ +#define log(_cat, _level, _fmt, _args...) ({ \ + int _l = _level; \ + if (_l > _LOG_MAX_LEVEL) \ + continue; \ + _log(_cat, _l, __FILE__, __LINE__, __func__, \ + pr_fmt(_fmt), ##_args); \ + }) + #ifdef DEBUG #define _DEBUG 1 #else @@ -22,10 +98,19 @@ #define _SPL_BUILD 0 #endif
-/* Define this at the top of a file to add a prefix to debug messages */ -#ifndef pr_fmt -#define pr_fmt(fmt) fmt -#endif +#if !_DEBUG && CONFIG_IS_ENABLED(LOG) + +#define debug_cond(cond, fmt, args...) \ + do { \ + if (1) \ + log(LOG_CATEGORY, LOGL_DEBUG, fmt, ##args); \ + } while (0) + +#define error(fmt, args...) do { \ + log(LOG_CATEGORY, LOGL_ERR, fmt, ##args); \ +} while (0) + +#else /* _DEBUG */
/* * Output a debug text when condition "cond" is met. The "cond" should be @@ -38,6 +123,13 @@ printf(pr_fmt(fmt), ##args); \ } while (0)
+#define error(fmt, args...) do { \ + printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ + ##args, __FILE__, __LINE__, __func__); \ +} while (0) + +#endif /* _DEBUG */ + /* Show a message if DEBUG is defined in a file */ #define debug(fmt, args...) \ debug_cond(_DEBUG, fmt, ##args) @@ -61,11 +153,6 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, ({ if (!(x) && _DEBUG) \ __assert_fail(#x, __FILE__, __LINE__, __func__); })
-#define error(fmt, args...) do { \ - printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ - ##args, __FILE__, __LINE__, __func__); \ -} while (0) - #ifndef BUG #define BUG() do { \ printf("BUG: failure at %s:%d/%s()!\n", __FILE__, __LINE__, \ @@ -76,4 +163,146 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, while (0) #endif /* BUG */
+/** + * struct log_rec - a single log record + * + * Holds information about a single record in the log + * + * Members marked as 'not allocated' are stored as pointers and the caller is + * responsible for making sure that the data pointed to is not overwritten. + * Memebers marked as 'allocated' are allocated (e.g. via strdup()) by the log + * system. + * + * @cat: Category, representing a uclass or part of U-Boot + * @level: Severity level, less severe is higher + * @file: Name of file where the log record was generated (not allocated) + * @line: Line number where the log record was generated + * @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; + const char *file; + int line; + const char *func; + const char *msg; +}; + +struct log_device; + +/** + * struct log_driver - a driver which accepts and processes log records + * + * @name: Name of driver + */ +struct log_driver { + const char *name; + /** + * emit() - emit a log record + * + * Called by the log system to pass a log record to a particular driver + * for processing. The filter is checked before calling this function. + */ + int (*emit)(struct log_device *ldev, struct log_rec *rec); +}; + +/** + * struct log_device - an instance of a log driver + * + * Since drivers are set up at build-time we need to have a separate device for + * the run-time aspects of drivers (currently just a list of filters to apply + * to records send to this device). + * + * @next_filter_num: Seqence number of next filter filter added (0=no filters + * yet). This increments with each new filter on the device, but never + * decrements + * @drv: Pointer to driver for this device + * @filter_head: List of filters for this device + * @sibling_node: Next device in the list of all devices + */ +struct log_device { + int next_filter_num; + struct log_driver *drv; + struct list_head filter_head; + struct list_head sibling_node; +}; + +enum { + LOGF_MAX_CATEGORIES = 5, /* maximum categories per filter */ +}; + +enum log_filter_flags { + LOGFF_HAS_CAT = 1 << 0, /* Filter has a category list */ +}; + +/** + * struct log_filter - criterial to filter out log messages + * + * @filter_num: Sequence number of this filter. This is returned when adding a + * new filter, and must be provided when removing a previously added + * filter. + * @flags: Flags for this filter (LOGFF_...) + * @cat_list: List of categories to allow (terminated by LOGC_none). If empty + * then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries + * can be provided + * @max_level: Maximum log level to allow + * @file_list: List of files to allow, separated by comma. If NULL then all + * files are permitted + * @sibling_node: Next filter in the list of filters for this log device + */ +struct log_filter { + int filter_num; + int flags; + enum log_category_t cat_list[LOGF_MAX_CATEGORIES]; + enum log_level_t max_level; + const char *file_list; + struct list_head sibling_node; +}; + +#define LOG_DRIVER(_name) \ + ll_entry_declare(struct log_driver, _name, log_driver) + +/** + * log_add_filter() - Add a new filter to a log device + * + * @drv_name: Driver name to add the filter to (since each driver only has a + * single device) + * @cat_list: List of categories to allow (terminated by LOGC_none). If empty + * then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries + * can be provided + * @max_level: Maximum log level to allow + * @file_list: List of files to allow, separated by comma. If NULL then all + * files are permitted + * @return the sequence number of the new filter (>=0) if the filter was added, + * or a -ve value on error + */ +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], + enum log_level_t max_level, const char *file_list); + +/** + * log_remove_filter() - Remove a filter from a log device + * + * @drv_name: Driver name to remove the filter from (since each driver only has + * a single device) + * @filter_num: Filter number to remove (as returned by log_add_filter()) + * @return 0 if the filter was removed, -ENOENT if either the driver or the + * filter number was not found + */ +int log_remove_filter(const char *drv_name, int filter_num); + +#if CONFIG_IS_ENABLED(LOG) +/** + * log_init() - Set up the log system ready for use + * + * @return 0 if OK, -ENOMEM if out of memory + */ +int log_init(void); +#else +static inline int log_init(void) +{ + return 0; +} +#endif + #endif
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py
test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point.
MICROBLAZE M: Michal Simek monstr@monstr.eu S: Maintained diff --git a/common/Kconfig b/common/Kconfig index 4d8cae9610..cbccc8ae26 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -384,6 +384,62 @@ config SYS_STDIO_DEREGISTER
endmenu
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debug+config LOG_SPL_MAX_LEVEL
int "Maximum log level to record in SPL"depends on SPL_LOGdefault 3helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debug+endmenu
config DTB_RESELECT bool "Support swapping dtbs at a later point in boot" depends on FIT_EMBED diff --git a/common/Makefile b/common/Makefile index 1b56cf9a70..d37c8d5636 100644 --- a/common/Makefile +++ b/common/Makefile @@ -128,5 +128,6 @@ obj-y += cli.o obj-$(CONFIG_FSL_DDR_INTERACTIVE) += cli_simple.o cli_readline.o obj-$(CONFIG_CMD_DFU) += dfu.o obj-y += command.o +obj-$(CONFIG_$(SPL_)LOG) += log.o obj-y += s_record.o obj-y += xyzModem.o diff --git a/common/log.c b/common/log.c new file mode 100644 index 0000000000..6bf2219d38 --- /dev/null +++ b/common/log.c @@ -0,0 +1,246 @@ +/*
- Logging support
- Copyright (c) 2017 Google, Inc
- Written by Simon Glass sjg@chromium.org
- SPDX-License-Identifier: GPL-2.0+
- */
+#include <common.h> +#include <log.h> +#include <malloc.h>
+DECLARE_GLOBAL_DATA_PTR;
+static struct log_device *log_device_find_by_name(const char *drv_name) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (!strcmp(drv_name, ldev->drv->name))return ldev;}return NULL;+}
+/**
- log_has_cat() - check if a log category exists within a list
- @cat_list: List of categories to check, at most LOGF_MAX_CATEGORIES entries
long, terminated by LC_END if fewer
- @cat: Category to search for
- @return true if @cat is in @cat_list, else false
- */
+static bool log_has_cat(enum log_category_t cat_list[], enum log_category_t cat) +{
int i;for (i = 0; i < LOGF_MAX_CATEGORIES && cat_list[i] != LOGC_END; i++) {if (cat_list[i] == cat)return true;}return false;+}
+/**
- log_has_file() - check if a file is with a list
- @file_list: List of files to check, separated by comma
- @file: File to check for. This string is matched against the end of each
file in the list, i.e. ignoring any preceeding path. The list is
intended to consist of relative pathnames, e.g. common/main.c,cmd/log.c
- @return true if @file is in @file_list, else false
- */
+static bool log_has_file(const char *file_list, const char *file) +{
int file_len = strlen(file);const char *s, *p;int substr_len;for (s = file_list; *s; s = p + (*p != '\0')) {p = strchrnul(s, ',');substr_len = p - s;if (file_len >= substr_len &&!strncmp(file + file_len - substr_len, s, substr_len))return true;}return false;+}
+/**
- log_passes_filters() - check if a log record passes the filters for a device
- @ldev: Log device to check
- @rec: Log record to check
- @return true if @rec is not blocked by the filters in @ldev, false if it is
- */
+static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec) +{
struct log_filter *filt;/* If there are no filters, filter on the default log level */if (list_empty(&ldev->filter_head)) {if (rec->level > gd->default_log_level)return false;return true;}list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (rec->level > filt->max_level)continue;if ((filt->flags & LOGFF_HAS_CAT) &&!log_has_cat(filt->cat_list, rec->cat))continue;if (filt->file_list &&!log_has_file(filt->file_list, rec->file))continue;return true;}return false;+}
+/**
- log_dispatch() - Send a log record to all log devices for processing
- The log record is sent to each log device in turn, skipping those which have
- filters which block the record
- @rec: Log record to dispatch
- @return 0 (meaning success)
- */
+static int log_dispatch(struct log_rec *rec) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (log_passes_filters(ldev, rec))ldev->drv->emit(ldev, rec);}return 0;+}
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...)+{
char buf[CONFIG_SYS_CBSIZE];struct log_rec rec;va_list args;rec.cat = cat;rec.level = level;rec.file = file;rec.line = line;rec.func = func;va_start(args, fmt);vsnprintf(buf, sizeof(buf), fmt, args);va_end(args);rec.msg = buf;if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {if (gd)gd->log_drop_count++;return -ENOSYS;}log_dispatch(&rec);return 0;+}
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list)+{
struct log_filter *filt;struct log_device *ldev;int i;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;filt = (struct log_filter *)calloc(1, sizeof(*filt));if (!filt)return -ENOMEM;if (cat_list) {filt->flags |= LOGFF_HAS_CAT;for (i = 0; ; i++) {if (i == ARRAY_SIZE(filt->cat_list))return -ENOSPC;filt->cat_list[i] = cat_list[i];if (cat_list[i] == LOGC_END)break;}}filt->max_level = max_level;if (file_list) {filt->file_list = strdup(file_list);if (!filt->file_list)goto nomem;}filt->filter_num = ldev->next_filter_num++;INIT_LIST_HEAD(&filt->sibling_node);list_add_tail(&filt->sibling_node, &ldev->filter_head);return filt->filter_num;+nomem:
free(filt);return -ENOMEM;+}
+int log_remove_filter(const char *drv_name, int filter_num) +{
struct log_filter *filt;struct log_device *ldev;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (filt->filter_num == filter_num) {list_del(&filt->sibling_node);free(filt);return 0;}}return -ENOENT;+}
+int log_init(void) +{
struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);const int count = ll_entry_count(struct log_driver, log_driver);struct log_driver *end = drv + count;/** We cannot add runtime data to the driver since it is likely stored* in rodata. Instead, set up a 'device' corresponding to each driver.* We only support having a single device.*/INIT_LIST_HEAD((struct list_head *)&gd->log_head);while (drv < end) {struct log_device *ldev;ldev = calloc(1, sizeof(*ldev));if (!ldev) {debug("%s: Cannot allocate memory\n", __func__);return -ENOMEM;}INIT_LIST_HEAD(&ldev->sibling_node);INIT_LIST_HEAD(&ldev->filter_head);ldev->drv = drv;list_add_tail(&ldev->sibling_node,(struct list_head *)&gd->log_head);drv++;}gd->default_log_level = LOGL_INFO;
Shouldn't this be the Kconfig option CONFIG_LOG_MAX_LEVEL?
return 0;+} diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h index 79197acfa4..77755dbb06 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -114,6 +114,11 @@ typedef struct global_data { struct bootstage_data *bootstage; /* Bootstage information */ struct bootstage_data *new_bootstage; /* Relocated bootstage info */ #endif +#ifdef CONFIG_LOG
int log_drop_count; /* Number of dropped log messages */int default_log_level; /* For devices with no filters */struct list_head log_head; /* List of struct log_device */+#endif } gd_t; #endif
diff --git a/include/log.h b/include/log.h index 4101a74161..fb6a196202 100644 --- a/include/log.h +++ b/include/log.h @@ -10,6 +10,82 @@ #ifndef __LOG_H #define __LOG_H
+#include <dm/uclass-id.h> +#include <linux/list.h>
+/** Log levels supported, ranging from most to least important */ +enum log_level_t {
LOGL_PANIC = 0,LOGL_CRIT,LOGL_ERR,LOGL_WARN,LOGL_NOTE,LOGL_INFO,LOGL_DETAIL,LOGL_DEBUG,LOGL_COUNT,LOGL_FIRST = LOGL_PANIC,LOGL_MAX = LOGL_DEBUG,+};
+/**
- Log categories supported. Most of these correspond to uclasses (i.e.
- enum uclass_id) but there are also some more generic categories
- */
+enum log_category_t {
LOGC_FIRST = 0, /* First part mirrors UCLASS_... */LOGC_NONE = UCLASS_COUNT,LOGC_ARCH,LOGC_BOARD,LOGC_CORE,LOGC_DT,LOGC_COUNT,LOGC_END,+};
+/**
- _log() - Internal function to emit a new log record
- @cat: Category of log record (indicating which subsystem generated it)
- @level: Level of log record (indicating its severity)
- @file: File name of file where log record was generated
- @line: Line number in file where log record was generated
- @func: Function where log record was generated
- @fmt: printf() format string for log record
- @...: Optional parameters, according to the format string @fmt
- @return 0 if log record was emitted, -ve on error
- */
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...);+/* Define this at the top of a file to add a prefix to debug messages */ +#ifndef pr_fmt +#define pr_fmt(fmt) fmt +#endif
+/* Use a default category if this file does not supply one */ +#ifndef LOG_CATEGORY +#define LOG_CATEGORY LOGC_NONE +#endif
+#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
+/* Emit a log record if the level is less that the maximum */ +#define log(_cat, _level, _fmt, _args...) ({ \
int _l = _level; \if (_l > _LOG_MAX_LEVEL) \continue; \_log(_cat, _l, __FILE__, __LINE__, __func__, \pr_fmt(_fmt), ##_args); \})#ifdef DEBUG #define _DEBUG 1 #else @@ -22,10 +98,19 @@ #define _SPL_BUILD 0 #endif
-/* Define this at the top of a file to add a prefix to debug messages */ -#ifndef pr_fmt -#define pr_fmt(fmt) fmt -#endif +#if !_DEBUG && CONFIG_IS_ENABLED(LOG)
+#define debug_cond(cond, fmt, args...) \
do { \if (1) \log(LOG_CATEGORY, LOGL_DEBUG, fmt, ##args); \} while (0)+#define error(fmt, args...) do { \
log(LOG_CATEGORY, LOGL_ERR, fmt, ##args); \+} while (0)
+#else /* _DEBUG */
/*
- Output a debug text when condition "cond" is met. The "cond" should be
@@ -38,6 +123,13 @@ printf(pr_fmt(fmt), ##args); \ } while (0)
+#define error(fmt, args...) do { \
printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \##args, __FILE__, __LINE__, __func__); \+} while (0)
+#endif /* _DEBUG */
/* Show a message if DEBUG is defined in a file */ #define debug(fmt, args...) \ debug_cond(_DEBUG, fmt, ##args) @@ -61,11 +153,6 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, ({ if (!(x) && _DEBUG) \ __assert_fail(#x, __FILE__, __LINE__, __func__); })
-#define error(fmt, args...) do { \
printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \##args, __FILE__, __LINE__, __func__); \-} while (0)
#ifndef BUG #define BUG() do { \ printf("BUG: failure at %s:%d/%s()!\n", __FILE__, __LINE__, \ @@ -76,4 +163,146 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, while (0) #endif /* BUG */
+/**
- struct log_rec - a single log record
- Holds information about a single record in the log
- Members marked as 'not allocated' are stored as pointers and the caller is
- responsible for making sure that the data pointed to is not overwritten.
- Memebers marked as 'allocated' are allocated (e.g. via strdup()) by the log
- system.
- @cat: Category, representing a uclass or part of U-Boot
- @level: Severity level, less severe is higher
- @file: Name of file where the log record was generated (not allocated)
- @line: Line number where the log record was generated
- @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;const char *file;int line;const char *func;const char *msg;+};
+struct log_device;
+/**
- struct log_driver - a driver which accepts and processes log records
- @name: Name of driver
- */
+struct log_driver {
const char *name;/*** emit() - emit a log record** Called by the log system to pass a log record to a particular driver* for processing. The filter is checked before calling this function.*/int (*emit)(struct log_device *ldev, struct log_rec *rec);+};
So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?)
+/**
- struct log_device - an instance of a log driver
- Since drivers are set up at build-time we need to have a separate device for
- the run-time aspects of drivers (currently just a list of filters to apply
- to records send to this device).
- @next_filter_num: Seqence number of next filter filter added (0=no filters
yet). This increments with each new filter on the device, but never
decrements
- @drv: Pointer to driver for this device
- @filter_head: List of filters for this device
- @sibling_node: Next device in the list of all devices
- */
+struct log_device {
int next_filter_num;struct log_driver *drv;struct list_head filter_head;struct list_head sibling_node;+};
+enum {
LOGF_MAX_CATEGORIES = 5, /* maximum categories per filter */+};
+enum log_filter_flags {
LOGFF_HAS_CAT = 1 << 0, /* Filter has a category list */+};
+/**
- struct log_filter - criterial to filter out log messages
- @filter_num: Sequence number of this filter. This is returned when adding a
new filter, and must be provided when removing a previously added
filter.
- @flags: Flags for this filter (LOGFF_...)
- @cat_list: List of categories to allow (terminated by LOGC_none). If empty
then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries
can be provided
- @max_level: Maximum log level to allow
- @file_list: List of files to allow, separated by comma. If NULL then all
files are permitted
- @sibling_node: Next filter in the list of filters for this log device
- */
+struct log_filter {
int filter_num;int flags;enum log_category_t cat_list[LOGF_MAX_CATEGORIES];enum log_level_t max_level;const char *file_list;struct list_head sibling_node;+};
+#define LOG_DRIVER(_name) \
ll_entry_declare(struct log_driver, _name, log_driver)+/**
- log_add_filter() - Add a new filter to a log device
- @drv_name: Driver name to add the filter to (since each driver only has a
single device)
- @cat_list: List of categories to allow (terminated by LOGC_none). If empty
then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries
can be provided
- @max_level: Maximum log level to allow
- @file_list: List of files to allow, separated by comma. If NULL then all
files are permitted
- @return the sequence number of the new filter (>=0) if the filter was added,
or a -ve value on error- */
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list);+/**
- log_remove_filter() - Remove a filter from a log device
- @drv_name: Driver name to remove the filter from (since each driver only has
a single device)
- @filter_num: Filter number to remove (as returned by log_add_filter())
- @return 0 if the filter was removed, -ENOENT if either the driver or the
filter number was not found- */
+int log_remove_filter(const char *drv_name, int filter_num);
+#if CONFIG_IS_ENABLED(LOG) +/**
- log_init() - Set up the log system ready for use
- @return 0 if OK, -ENOMEM if out of memory
- */
+int log_init(void); +#else +static inline int log_init(void) +{
return 0;+} +#endif
#endif
Regards, Bin
Hi Bin,
On 17 September 2017 at 21:45, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py
test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point.
OK I can tweak that, [..]
+/**
- struct log_driver - a driver which accepts and processes log records
- @name: Name of driver
- */
+struct log_driver {
const char *name;/*** emit() - emit a log record** Called by the log system to pass a log record to a particular driver* for processing. The filter is checked before calling this function.*/int (*emit)(struct log_device *ldev, struct log_rec *rec);+};
So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?)
Yes that's right. I think I can link it to DM once it starts up, but a logging of DM start-up is useful.
Re your idea are you saying add an emit() method to UCLASS_BLK?
Regards, Simon
Hi Simon,
On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass sjg@chromium.org wrote:
Hi Bin,
On 17 September 2017 at 21:45, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py
test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point.
OK I can tweak that, [..]
+/**
- struct log_driver - a driver which accepts and processes log records
- @name: Name of driver
- */
+struct log_driver {
const char *name;/*** emit() - emit a log record** Called by the log system to pass a log record to a particular driver* for processing. The filter is checked before calling this function.*/int (*emit)(struct log_device *ldev, struct log_rec *rec);+};
So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?)
Yes that's right. I think I can link it to DM once it starts up, but a logging of DM start-up is useful.
Re your idea are you saying add an emit() method to UCLASS_BLK?
Yep, something like
#ifdef CONFIG_LOG .log_emit = xxx_log_emit, #endif
Probably we need a flag to find out which driver provides such log functionality.
Regards, Bin
On 20 Sep 2017, at 16:41, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass sjg@chromium.org wrote:
Hi Bin,
On 17 September 2017 at 21:45, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py
test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point.
OK I can tweak that, [..]
+/**
- struct log_driver - a driver which accepts and processes log records
- @name: Name of driver
- */
+struct log_driver {
const char *name;/*** emit() - emit a log record** Called by the log system to pass a log record to a particular driver* for processing. The filter is checked before calling this function.*/int (*emit)(struct log_device *ldev, struct log_rec *rec);+};
So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?)
Yes that's right. I think I can link it to DM once it starts up, but a logging of DM start-up is useful.
Re your idea are you saying add an emit() method to UCLASS_BLK?
Yep, something like
#ifdef CONFIG_LOG .log_emit = xxx_log_emit, #endif
Probably we need a flag to find out which driver provides such log functionality.
I had started to sketch (but have been able to fully flesh this out, due to other priorities intervening) a mechanism for MISC devices that might be a good fit for this.
My work centers around the idea of having devices comply to “protocols” and was aimed at distinguishing between an efuse-device and a GbE RGMII-control (one where we need to adjust the RGMII clock depending on the link rate the PHY negotiated) device.
I.e. I had started to implement something along the lines of:
/** * misc_supports - tests if a misc device complies to a given protocol * * protocols can either be ‘how data is processed after calling write()’, * ‘how data is presented for a read()’ or ‘what ioctl-values are supported’. * The assumption is that protocols can be versioned and higher versions * offer full backward compatibility (i.e. a client for “Ethernet PHY control, v1” * can work with a driver implementing v1 or any higher version). */ bool misc_supports(struct udevice *dev, const char *protocol, u32 version);
and a way to register a list of protocols as part of the misc uclass-priv for any given driver.
This would allow us to enumerate all MISC devices until we find one that complies to the ‘logging’-protocol and then invoke write or ioctl on it.
Regards, Philipp.
Hi Bin,
On 20 September 2017 at 08:41, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass sjg@chromium.org wrote:
Hi Bin,
On 17 September 2017 at 21:45, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py
test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point.
OK I can tweak that, [..]
+/**
- struct log_driver - a driver which accepts and processes log records
- @name: Name of driver
- */
+struct log_driver {
const char *name;/*** emit() - emit a log record** Called by the log system to pass a log record to a particular driver* for processing. The filter is checked before calling this function.*/int (*emit)(struct log_device *ldev, struct log_rec *rec);+};
So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?)
Yes that's right. I think I can link it to DM once it starts up, but a logging of DM start-up is useful.
Re your idea are you saying add an emit() method to UCLASS_BLK?
Yep, something like
#ifdef CONFIG_LOG .log_emit = xxx_log_emit, #endif
Probably we need a flag to find out which driver provides such log functionality.
So what would the block driver do in that function? I guess I don't understand what it is for. Can you please give me more information?
Regards, Simon
Hi Simon,
On Thu, Sep 21, 2017 at 12:58 PM, Simon Glass sjg@chromium.org wrote:
Hi Bin,
On 20 September 2017 at 08:41, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass sjg@chromium.org wrote:
Hi Bin,
On 17 September 2017 at 21:45, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py
test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point.
OK I can tweak that, [..]
+/**
- struct log_driver - a driver which accepts and processes log records
- @name: Name of driver
- */
+struct log_driver {
const char *name;/*** emit() - emit a log record** Called by the log system to pass a log record to a particular driver* for processing. The filter is checked before calling this function.*/int (*emit)(struct log_device *ldev, struct log_rec *rec);+};
So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?)
Yes that's right. I think I can link it to DM once it starts up, but a logging of DM start-up is useful.
Re your idea are you saying add an emit() method to UCLASS_BLK?
Yep, something like
#ifdef CONFIG_LOG .log_emit = xxx_log_emit, #endif
Probably we need a flag to find out which driver provides such log functionality.
So what would the block driver do in that function? I guess I don't understand what it is for. Can you please give me more information?
The blk driver can save the logs to a predefined block address for permanent storage. Or file system driver can send the logs to a file.
Regards, Bin
Hi Bin,
On 22 September 2017 at 07:37, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Thu, Sep 21, 2017 at 12:58 PM, Simon Glass sjg@chromium.org wrote:
Hi Bin,
On 20 September 2017 at 08:41, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass sjg@chromium.org wrote:
Hi Bin,
On 17 September 2017 at 21:45, Bin Meng bmeng.cn@gmail.com wrote:
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org
MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/
+LOGGING +M: Simon Glass sjg@chromium.org +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py
test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point.
OK I can tweak that, [..]
+/**
- struct log_driver - a driver which accepts and processes log records
- @name: Name of driver
- */
+struct log_driver {
const char *name;/*** emit() - emit a log record** Called by the log system to pass a log record to a particular driver* for processing. The filter is checked before calling this function.*/int (*emit)(struct log_device *ldev, struct log_rec *rec);+};
So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?)
Yes that's right. I think I can link it to DM once it starts up, but a logging of DM start-up is useful.
Re your idea are you saying add an emit() method to UCLASS_BLK?
Yep, something like
#ifdef CONFIG_LOG .log_emit = xxx_log_emit, #endif
Probably we need a flag to find out which driver provides such log functionality.
So what would the block driver do in that function? I guess I don't understand what it is for. Can you please give me more information?
The blk driver can save the logs to a predefined block address for permanent storage. Or file system driver can send the logs to a file.
OK I see. IMO this is not really a function of a block device. I don't see what an emit() method in a USB block device (for example) would do differently from one in a SATA block device.
We could have a single 'log_blk' driver which:
- allows configuration of what blocks are used for the log - writes blocks there (perhaps wrapping if it runs out of space)
For file systems we could have a 'log_fs' driver which:
- allows configuration of log file path - writes blocks into that file (perhaps starting a new file and rotating the log if things get over a limit
Regards, Simon
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.
Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debug
Please do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messages
+config LOG_SPL_MAX_LEVEL
int "Maximum log level to record in SPL"depends on SPL_LOGdefault 3helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debug
If you want to use CONFIG_VAL(LOG_MAX_LEVEL), this must be SPL_LOG_MAX_LEVEL. (this coding mistake is now hidden by another mistake)
Again, you will probably end up with TPL_LOG_MAX_LEVEL.
+/**
- log_dispatch() - Send a log record to all log devices for processing
- The log record is sent to each log device in turn, skipping those which have
- filters which block the record
- @rec: Log record to dispatch
- @return 0 (meaning success)
- */
+static int log_dispatch(struct log_rec *rec) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (log_passes_filters(ldev, rec))ldev->drv->emit(ldev, rec);}return 0;+}
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...)+{
char buf[CONFIG_SYS_CBSIZE];struct log_rec rec;va_list args;rec.cat = cat;rec.level = level;rec.file = file;rec.line = line;rec.func = func;va_start(args, fmt);vsnprintf(buf, sizeof(buf), fmt, args);va_end(args);rec.msg = buf;if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {if (gd)gd->log_drop_count++;return -ENOSYS;}log_dispatch(&rec);return 0;+}
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list)+{
struct log_filter *filt;struct log_device *ldev;int i;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;filt = (struct log_filter *)calloc(1, sizeof(*filt));if (!filt)return -ENOMEM;if (cat_list) {filt->flags |= LOGFF_HAS_CAT;for (i = 0; ; i++) {if (i == ARRAY_SIZE(filt->cat_list))return -ENOSPC;filt->cat_list[i] = cat_list[i];if (cat_list[i] == LOGC_END)break;}}filt->max_level = max_level;if (file_list) {filt->file_list = strdup(file_list);if (!filt->file_list)goto nomem;}filt->filter_num = ldev->next_filter_num++;INIT_LIST_HEAD(&filt->sibling_node);list_add_tail(&filt->sibling_node, &ldev->filter_head);return filt->filter_num;+nomem:
free(filt);return -ENOMEM;+}
+int log_remove_filter(const char *drv_name, int filter_num) +{
struct log_filter *filt;struct log_device *ldev;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (filt->filter_num == filter_num) {list_del(&filt->sibling_node);free(filt);return 0;}}return -ENOENT;+}
I am not sure if this luxury filter is needed. After all, the purpose is debugging. The printf() debugging is useful, but only during testing. Once quality code is established, most of debug message should generally be removed from upstream code.
+int log_init(void) +{
struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);const int count = ll_entry_count(struct log_driver, log_driver);struct log_driver *end = drv + count;/** We cannot add runtime data to the driver since it is likely stored* in rodata. Instead, set up a 'device' corresponding to each driver.* We only support having a single device.*/INIT_LIST_HEAD((struct list_head *)&gd->log_head);while (drv < end) {struct log_device *ldev;ldev = calloc(1, sizeof(*ldev));if (!ldev) {debug("%s: Cannot allocate memory\n", __func__);return -ENOMEM;}INIT_LIST_HEAD(&ldev->sibling_node);
This INIT_LIST_HEAD() is unneeded.
INIT_LIST_HEAD(&ldev->filter_head);ldev->drv = drv;list_add_tail(&ldev->sibling_node,(struct list_head *)&gd->log_head);
I know that this (struct list_head *) cast is needed, but it is very unfortunate. I believe gd_t is design mistake in the first place, but U-Boot has gone to unfixable already...
+#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL).
From your Kconfig entry,
0 - panic 1 - critical 2 - error 3 - warning 4 - note 5 - info 6 - detail 7 - debug
I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value range 0 to 7.
If the log level is 0 (= critial), the conditional is false, so _LOG_MAX_LEVEL is set to "info" level.
Why is this #if necessary?
+/* Emit a log record if the level is less that the maximum */ +#define log(_cat, _level, _fmt, _args...) ({ \
int _l = _level; \if (_l > _LOG_MAX_LEVEL) \continue; \_log(_cat, _l, __FILE__, __LINE__, __func__, \pr_fmt(_fmt), ##_args); \})
This is neither while() nor for(). The bare use of "continue" made me really surprised.
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugPlease do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messages
Yes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access.
So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom?
+config LOG_SPL_MAX_LEVEL
int "Maximum log level to record in SPL"depends on SPL_LOGdefault 3helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugIf you want to use CONFIG_VAL(LOG_MAX_LEVEL), this must be SPL_LOG_MAX_LEVEL. (this coding mistake is now hidden by another mistake)
Oops, yes.
Again, you will probably end up with TPL_LOG_MAX_LEVEL.
+/**
- log_dispatch() - Send a log record to all log devices for processing
- The log record is sent to each log device in turn, skipping those which have
- filters which block the record
- @rec: Log record to dispatch
- @return 0 (meaning success)
- */
+static int log_dispatch(struct log_rec *rec) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (log_passes_filters(ldev, rec))ldev->drv->emit(ldev, rec);}return 0;+}
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...)+{
char buf[CONFIG_SYS_CBSIZE];struct log_rec rec;va_list args;rec.cat = cat;rec.level = level;rec.file = file;rec.line = line;rec.func = func;va_start(args, fmt);vsnprintf(buf, sizeof(buf), fmt, args);va_end(args);rec.msg = buf;if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {if (gd)gd->log_drop_count++;return -ENOSYS;}log_dispatch(&rec);return 0;+}
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list)+{
struct log_filter *filt;struct log_device *ldev;int i;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;filt = (struct log_filter *)calloc(1, sizeof(*filt));if (!filt)return -ENOMEM;if (cat_list) {filt->flags |= LOGFF_HAS_CAT;for (i = 0; ; i++) {if (i == ARRAY_SIZE(filt->cat_list))return -ENOSPC;filt->cat_list[i] = cat_list[i];if (cat_list[i] == LOGC_END)break;}}filt->max_level = max_level;if (file_list) {filt->file_list = strdup(file_list);if (!filt->file_list)goto nomem;}filt->filter_num = ldev->next_filter_num++;INIT_LIST_HEAD(&filt->sibling_node);list_add_tail(&filt->sibling_node, &ldev->filter_head);return filt->filter_num;+nomem:
free(filt);return -ENOMEM;+}
+int log_remove_filter(const char *drv_name, int filter_num) +{
struct log_filter *filt;struct log_device *ldev;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (filt->filter_num == filter_num) {list_del(&filt->sibling_node);free(filt);return 0;}}return -ENOENT;+}
I am not sure if this luxury filter is needed. After all, the purpose is debugging. The printf() debugging is useful, but only during testing. Once quality code is established, most of debug message should generally be removed from upstream code.
But not logging, and this is the point. It is very useful to have basic logging information recorded for every boot, and the normal printf() output is not detailed enough. For example for verified boot I want to see details about boot failures and what went wrong (key verification, etc.). So I expect that at least INFO (and probably DETAIL) logging would be useful to record for such a system, even if it does not appear on the console (in fact the console would normally be disabled in such a system).
+int log_init(void) +{
struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);const int count = ll_entry_count(struct log_driver, log_driver);struct log_driver *end = drv + count;/** We cannot add runtime data to the driver since it is likely stored* in rodata. Instead, set up a 'device' corresponding to each driver.* We only support having a single device.*/INIT_LIST_HEAD((struct list_head *)&gd->log_head);while (drv < end) {struct log_device *ldev;ldev = calloc(1, sizeof(*ldev));if (!ldev) {debug("%s: Cannot allocate memory\n", __func__);return -ENOMEM;}INIT_LIST_HEAD(&ldev->sibling_node);This INIT_LIST_HEAD() is unneeded.
How come? If I don't do that how will the list be set up?
INIT_LIST_HEAD(&ldev->filter_head);ldev->drv = drv;list_add_tail(&ldev->sibling_node,(struct list_head *)&gd->log_head);I know that this (struct list_head *) cast is needed, but it is very unfortunate. I believe gd_t is design mistake in the first place, but U-Boot has gone to unfixable already...
With driver model I added DM_ROOT_NON_CONST. I suppose we could use something like that.
But perhaps we should start dropping the 'volatile' in gd? I'm not sure why it is needed.
+#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). From your Kconfig entry,
0 - panic 1 - critical 2 - error 3 - warning 4 - note 5 - info 6 - detail 7 - debug
I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value range 0 to 7.
If the log level is 0 (= critial), the conditional is false, so _LOG_MAX_LEVEL is set to "info" level.
Why is this #if necessary?
If we don't have CONFIG_LOG enabled then this value will not exist.
+/* Emit a log record if the level is less that the maximum */ +#define log(_cat, _level, _fmt, _args...) ({ \
int _l = _level; \if (_l > _LOG_MAX_LEVEL) \continue; \_log(_cat, _l, __FILE__, __LINE__, __func__, \pr_fmt(_fmt), ##_args); \})This is neither while() nor for(). The bare use of "continue" made me really surprised.
Yes that may not be supported. I'll fix it.
Regards, Simon
Masahiro & Simon,
On 20 Sep 2017, at 15:49, Simon Glass sjg@chromium.org wrote:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into size issues for TPL and the $(SPL_TPL_) mechanism will not match the CONFIG_IS_ENABLED() mechanism.
I don’t think that anyone will miss this much in TPL and that this can be safely left off for TPL (if space was not at a premium in TPL, then why have a TPL at all…)
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugPlease do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messagesYes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access.
So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom?
I would expect KERN_NOTICE to be used for normal printf output, KERN_INFO for more verbose output and DEBUG would be the granularity for tracing through drivers (i.e. the MMC example given).
Regards, Philipp.
+config LOG_SPL_MAX_LEVEL
int "Maximum log level to record in SPL"depends on SPL_LOGdefault 3helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugIf you want to use CONFIG_VAL(LOG_MAX_LEVEL), this must be SPL_LOG_MAX_LEVEL. (this coding mistake is now hidden by another mistake)
Oops, yes.
Again, you will probably end up with TPL_LOG_MAX_LEVEL.
+/**
- log_dispatch() - Send a log record to all log devices for processing
- The log record is sent to each log device in turn, skipping those which have
- filters which block the record
- @rec: Log record to dispatch
- @return 0 (meaning success)
- */
+static int log_dispatch(struct log_rec *rec) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (log_passes_filters(ldev, rec))ldev->drv->emit(ldev, rec);}return 0;+}
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...)+{
char buf[CONFIG_SYS_CBSIZE];struct log_rec rec;va_list args;rec.cat = cat;rec.level = level;rec.file = file;rec.line = line;rec.func = func;va_start(args, fmt);vsnprintf(buf, sizeof(buf), fmt, args);va_end(args);rec.msg = buf;if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {if (gd)gd->log_drop_count++;return -ENOSYS;}log_dispatch(&rec);return 0;+}
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list)+{
struct log_filter *filt;struct log_device *ldev;int i;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;filt = (struct log_filter *)calloc(1, sizeof(*filt));if (!filt)return -ENOMEM;if (cat_list) {filt->flags |= LOGFF_HAS_CAT;for (i = 0; ; i++) {if (i == ARRAY_SIZE(filt->cat_list))return -ENOSPC;filt->cat_list[i] = cat_list[i];if (cat_list[i] == LOGC_END)break;}}filt->max_level = max_level;if (file_list) {filt->file_list = strdup(file_list);if (!filt->file_list)goto nomem;}filt->filter_num = ldev->next_filter_num++;INIT_LIST_HEAD(&filt->sibling_node);list_add_tail(&filt->sibling_node, &ldev->filter_head);return filt->filter_num;+nomem:
free(filt);return -ENOMEM;+}
+int log_remove_filter(const char *drv_name, int filter_num) +{
struct log_filter *filt;struct log_device *ldev;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (filt->filter_num == filter_num) {list_del(&filt->sibling_node);free(filt);return 0;}}return -ENOENT;+}
I am not sure if this luxury filter is needed. After all, the purpose is debugging. The printf() debugging is useful, but only during testing. Once quality code is established, most of debug message should generally be removed from upstream code.
But not logging, and this is the point. It is very useful to have basic logging information recorded for every boot, and the normal printf() output is not detailed enough. For example for verified boot I want to see details about boot failures and what went wrong (key verification, etc.). So I expect that at least INFO (and probably DETAIL) logging would be useful to record for such a system, even if it does not appear on the console (in fact the console would normally be disabled in such a system).
+int log_init(void) +{
struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);const int count = ll_entry_count(struct log_driver, log_driver);struct log_driver *end = drv + count;/** We cannot add runtime data to the driver since it is likely stored* in rodata. Instead, set up a 'device' corresponding to each driver.* We only support having a single device.*/INIT_LIST_HEAD((struct list_head *)&gd->log_head);while (drv < end) {struct log_device *ldev;ldev = calloc(1, sizeof(*ldev));if (!ldev) {debug("%s: Cannot allocate memory\n", __func__);return -ENOMEM;}INIT_LIST_HEAD(&ldev->sibling_node);This INIT_LIST_HEAD() is unneeded.
How come? If I don't do that how will the list be set up?
INIT_LIST_HEAD(&ldev->filter_head);ldev->drv = drv;list_add_tail(&ldev->sibling_node,(struct list_head *)&gd->log_head);I know that this (struct list_head *) cast is needed, but it is very unfortunate. I believe gd_t is design mistake in the first place, but U-Boot has gone to unfixable already...
With driver model I added DM_ROOT_NON_CONST. I suppose we could use something like that.
But perhaps we should start dropping the 'volatile' in gd? I'm not sure why it is needed.
+#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). From your Kconfig entry,
0 - panic 1 - critical 2 - error 3 - warning 4 - note 5 - info 6 - detail 7 - debug
I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value range 0 to 7.
If the log level is 0 (= critial), the conditional is false, so _LOG_MAX_LEVEL is set to "info" level.
Why is this #if necessary?
If we don't have CONFIG_LOG enabled then this value will not exist.
+/* Emit a log record if the level is less that the maximum */ +#define log(_cat, _level, _fmt, _args...) ({ \
int _l = _level; \if (_l > _LOG_MAX_LEVEL) \continue; \_log(_cat, _l, __FILE__, __LINE__, __func__, \pr_fmt(_fmt), ##_args); \})This is neither while() nor for(). The bare use of "continue" made me really surprised.
Yes that may not be supported. I'll fix it.
Regards, Simon _______________________________________________ U-Boot mailing list U-Boot@lists.denx.de https://lists.denx.de/listinfo/u-boot
2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich philipp.tomsich@theobroma-systems.com:
Masahiro & Simon,
On 20 Sep 2017, at 15:49, Simon Glass sjg@chromium.org wrote:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into size issues for TPL and the $(SPL_TPL_) mechanism will not match the CONFIG_IS_ENABLED() mechanism.
I don’t think that anyone will miss this much in TPL and that this can be safely left off for TPL (if space was not at a premium in TPL, then why have a TPL at all…)
The motivation of TPL is the image size is really limited for the secondary boot loader in some cases.
Instead of: SPL -> TPL -> U-Boot full
I'd rather want to see: <something> -> SPL -> U-Boot full
<something> is implemented in an ad-hoc way under board or soc directory. If the space is premium, there is no room for DM, DT-ctrl in the <something>.
Then, remove the current TPL support.
It was only some old freescale boards that used TPL, so I was expecting they would die out sooner or later.
Recently, lion-rk3368_defconfig was added wit TPL.
Other rk3368 boards do not enable TPL.
Why does that board need TPL?
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugPlease do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messagesYes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access.
So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom?
I would expect KERN_NOTICE to be used for normal printf output, KERN_INFO for more verbose output and DEBUG would be the granularity for tracing through drivers (i.e. the MMC example given).
In my opinion, printf() and pr_*() should be different concept.
printf() (and puts(), putc(), etc.) should be turned on/off by CONFIG_SILENT_CONSOLE. These are direct access to console, so they should always and immediately print messages unless CONFIG_SILENT_CONSOLE is defined. We may want to use the command interface regardless of CONFIG_LOG / CONFIG_LOGLEVEL.
pr_*() are log functions that are controlled by CONFIG_LOGLEVEL. These can send the messages to the console directly, or to the ring buffer, or wherever implemented in the log device.
Masahiro,
On 20 Sep 2017, at 19:34, Masahiro Yamada yamada.masahiro@socionext.com wrote:
2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich philipp.tomsich@theobroma-systems.com:
Masahiro & Simon,
On 20 Sep 2017, at 15:49, Simon Glass sjg@chromium.org wrote:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into size issues for TPL and the $(SPL_TPL_) mechanism will not match the CONFIG_IS_ENABLED() mechanism.
I don’t think that anyone will miss this much in TPL and that this can be safely left off for TPL (if space was not at a premium in TPL, then why have a TPL at all…)
The motivation of TPL is the image size is really limited for the secondary boot loader in some cases.
Instead of: SPL -> TPL -> U-Boot full
Note that this was retro-actively defined to be TPL -> SPL -> U-Boot full by Tom at some point and reiterated in https://lists.denx.de/pipermail/u-boot/2017-July/299266.html
I'd rather want to see: <something> -> SPL -> U-Boot full
I would agree, that the stage before the SPL could be chip-specific. However, this is unlikely to happen quickly as some of the infrastructure (e.g. OF_PLATDATA) would have to be easily available to this new TPL framework.
<something> is implemented in an ad-hoc way under board or soc directory. If the space is premium, there is no room for DM, DT-ctrl in the <something>.
Then, remove the current TPL support.
It was only some old freescale boards that used TPL, so I was expecting they would die out sooner or later.
Recently, lion-rk3368_defconfig was added wit TPL.
Other rk3368 boards do not enable TPL.
Other RK3368 boards do not have DRAM init support yet (they still use the proprietary vendor blobs and then boot the full U-Boot stage). This is gated by the resource availability on Rockchip’s end to add support for those features of the DRAM controller that can not be tested on Lion.
Why does that board need TPL?
The RK3368’s boot-ROM loads only 0x7000 bytes as its first stage and requires this to (a) set up clocking and (b) initialise the DRAM controller. The SPL-stage on the RK3368 then runs out of DRAM (still loaded by the boot-ROM), but the size-limit is somewhat relaxed.
On the RK3368, we take the liberty of reusing as much framework code as possible in the TPL (resulting in 21k binary) and using OF_PLATDATA: the features reused include DM, DM_REGMAP, DM_SYSCON, DM_CLK, DM_RAM and DM_TIMER. With this, we can both use the same drivers as for SPL and full U-Boot and then have a SPL stage that does not rely of OF_PLATDATA (but has full OF_CONTROL).
Note that TPL is required for most of the Rockchip boards, if we want to do the DRAM initialisation in U-Boot… those chips that already have their DRAM controller drivers merged, usually have a TPL stage (with the exception of the RK3399, which supports 192kB for its first stage).
Regards, Philipp.
Hi Philipp,
2017-09-21 2:51 GMT+09:00 Dr. Philipp Tomsich philipp.tomsich@theobroma-systems.com:
Masahiro,
On 20 Sep 2017, at 19:34, Masahiro Yamada yamada.masahiro@socionext.com wrote:
2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich philipp.tomsich@theobroma-systems.com:
Masahiro & Simon,
On 20 Sep 2017, at 15:49, Simon Glass sjg@chromium.org wrote:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into size issues for TPL and the $(SPL_TPL_) mechanism will not match the CONFIG_IS_ENABLED() mechanism.
I don’t think that anyone will miss this much in TPL and that this can be safely left off for TPL (if space was not at a premium in TPL, then why have a TPL at all…)
The motivation of TPL is the image size is really limited for the secondary boot loader in some cases.
Instead of: SPL -> TPL -> U-Boot full
Note that this was retro-actively defined to be TPL -> SPL -> U-Boot full by Tom at some point and reiterated in https://lists.denx.de/pipermail/u-boot/2017-July/299266.html
Thanks. I did not know that this flip had already happened.
In fact, I am probably the first man who suggested it.
Here is the history.
1. Scott Wood introduced TPL to support some freescale chip, which had only 4KB memory footprint for the second loader https://www.denx.de/wiki/pub/U-Boot/MiniSummitELCE2013/tpl-presentation.pdf
At this point, the boot order was: SPL -> TPL -> U-Boot And TPL means "Tertiary Program Loader".
2. I imported Kbuild and Kconfig to U-Boot.
3. During the migration of Kconfig, I noticed switching the order of SPL / TPL has advantages.
The "Tiny Program Loader" was mentioned first in this mail: https://lists.denx.de/pipermail/u-boot/2015-August/222900.html
4. When Simon started to move CONFIG_TPL, I suggested it once again http://patchwork.ozlabs.org/patch/662396/
So, I'd like to make "TPL -> SPL" legitimate.
More ideally, I hope this is done outside of luxury frameworks. No DM, no OF_CONTROL, then CONFIG_TPL_* are all gone.
Hi Simon,
2017-09-20 22:49 GMT+09:00 Simon Glass sjg@chromium.org:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
I will explain it in another mail.
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugPlease do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messagesYes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access.
So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom?
In fact, Linux has one more for debug. dev_vdbg() is widely used in Linux.
If you like, we can add one more level:
8 (KERN_VDEBUG) verbose debug messages
Perhaps, logging every access to an MMC peripheral might belong to the vdbg level.
BTW, what do you mean "INFO is what I plan to use for normal printf() output"
Is that mean printf() is equivalent to pr_info()? If loglevel is 6 or smaller, will all print() be silent? If so, probably we can not use command line interface.
+/**
- log_dispatch() - Send a log record to all log devices for processing
- The log record is sent to each log device in turn, skipping those which have
- filters which block the record
- @rec: Log record to dispatch
- @return 0 (meaning success)
- */
+static int log_dispatch(struct log_rec *rec) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (log_passes_filters(ldev, rec))ldev->drv->emit(ldev, rec);}return 0;+}
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...)+{
char buf[CONFIG_SYS_CBSIZE];struct log_rec rec;va_list args;rec.cat = cat;rec.level = level;rec.file = file;rec.line = line;rec.func = func;va_start(args, fmt);vsnprintf(buf, sizeof(buf), fmt, args);va_end(args);rec.msg = buf;if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {if (gd)gd->log_drop_count++;return -ENOSYS;}log_dispatch(&rec);return 0;+}
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list)+{
struct log_filter *filt;struct log_device *ldev;int i;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;filt = (struct log_filter *)calloc(1, sizeof(*filt));if (!filt)return -ENOMEM;if (cat_list) {filt->flags |= LOGFF_HAS_CAT;for (i = 0; ; i++) {if (i == ARRAY_SIZE(filt->cat_list))return -ENOSPC;filt->cat_list[i] = cat_list[i];if (cat_list[i] == LOGC_END)break;}}filt->max_level = max_level;if (file_list) {filt->file_list = strdup(file_list);if (!filt->file_list)goto nomem;}filt->filter_num = ldev->next_filter_num++;INIT_LIST_HEAD(&filt->sibling_node);list_add_tail(&filt->sibling_node, &ldev->filter_head);return filt->filter_num;+nomem:
free(filt);return -ENOMEM;+}
+int log_remove_filter(const char *drv_name, int filter_num) +{
struct log_filter *filt;struct log_device *ldev;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (filt->filter_num == filter_num) {list_del(&filt->sibling_node);free(filt);return 0;}}return -ENOENT;+}
I am not sure if this luxury filter is needed. After all, the purpose is debugging. The printf() debugging is useful, but only during testing. Once quality code is established, most of debug message should generally be removed from upstream code.
But not logging, and this is the point. It is very useful to have basic logging information recorded for every boot, and the normal printf() output is not detailed enough. For example for verified boot I want to see details about boot failures and what went wrong (key verification, etc.).
This should be warn level, (or notice at least) not info.
So I expect that at least INFO (and probably DETAIL) logging would be useful to record for such a system, even if it does not appear on the console (in fact the console would normally be disabled in such a system).
OK. Logging is useful, but your example will be used with info level.
I still do not understand the necessity of category / file filtering.
+int log_init(void) +{
struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);const int count = ll_entry_count(struct log_driver, log_driver);struct log_driver *end = drv + count;/** We cannot add runtime data to the driver since it is likely stored* in rodata. Instead, set up a 'device' corresponding to each driver.* We only support having a single device.*/INIT_LIST_HEAD((struct list_head *)&gd->log_head);while (drv < end) {struct log_device *ldev;ldev = calloc(1, sizeof(*ldev));if (!ldev) {debug("%s: Cannot allocate memory\n", __func__);return -ENOMEM;}INIT_LIST_HEAD(&ldev->sibling_node);This INIT_LIST_HEAD() is unneeded.
How come? If I don't do that how will the list be set up?
Because ldev->sibling_node is not a list_head. It is used as a list node.
See include/linux/list.h for the implementation of list_add_tail().
The argument "head" must be initialized in advance, but "new" does not need initialization.
INIT_LIST_HEAD(&ldev->filter_head);ldev->drv = drv;list_add_tail(&ldev->sibling_node,(struct list_head *)&gd->log_head);
Here, gd->log_head is a head, so INIT_LIST_HEAD((struct list_head *)&gd->log_head); is correct.
INIT_LIST_HEAD(&ldev->sibling_node); is non-sense.
I know that this (struct list_head *) cast is needed, but it is very unfortunate. I believe gd_t is design mistake in the first place, but U-Boot has gone to unfixable already...
With driver model I added DM_ROOT_NON_CONST. I suppose we could use something like that.
But perhaps we should start dropping the 'volatile' in gd? I'm not sure why it is needed.
Me neither.
+#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). From your Kconfig entry,
0 - panic 1 - critical 2 - error 3 - warning 4 - note 5 - info 6 - detail 7 - debug
I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value range 0 to 7.
If the log level is 0 (= critial), the conditional is false, so _LOG_MAX_LEVEL is set to "info" level.
Why is this #if necessary?
If we don't have CONFIG_LOG enabled then this value will not exist.
This implementation is wrong.
You are abusing the fact that U-Boot does not specify -Wundef option.
--------------------->8----------------- -Wundef Warn if an undefined identifier is evaluated in an #if directive. Such identifiers are replaced with zero. --------------------->8-----------------
Right, U-Boot does not give -Wundef, but it is just because -Wundef causes too many warnings.
Ideally, we should fix the code, then enable the option like Linux.
We should use #ifdef for testing a option that may or may not be defined. Using #if for options that may not be defined is a bad coding way.
Hi Masahiro,
On 20 September 2017 at 11:19, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-20 22:49 GMT+09:00 Simon Glass sjg@chromium.org:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
I will explain it in another mail.
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugPlease do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messagesYes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access.
So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom?
In fact, Linux has one more for debug. dev_vdbg() is widely used in Linux.
If you like, we can add one more level:
8 (KERN_VDEBUG) verbose debug messagesPerhaps, logging every access to an MMC peripheral might belong to the vdbg level.
I like the idea of having a log level for message contents (bytes) and another for I/O access. So I will add two more in v2.
BTW, what do you mean "INFO is what I plan to use for normal printf() output"
Is that mean printf() is equivalent to pr_info()? If loglevel is 6 or smaller, will all print() be silent? If so, probably we can not use command line interface.
I mean that I want to (later) add a feature that logs normal printf() output. If the console is silent then it would still be logged. Maybe one day log functions will be used instead of printf(), but for now this provides a useful way to make things wok.
+/**
- log_dispatch() - Send a log record to all log devices for processing
- The log record is sent to each log device in turn, skipping those which have
- filters which block the record
- @rec: Log record to dispatch
- @return 0 (meaning success)
- */
+static int log_dispatch(struct log_rec *rec) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (log_passes_filters(ldev, rec))ldev->drv->emit(ldev, rec);}return 0;+}
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...)+{
char buf[CONFIG_SYS_CBSIZE];struct log_rec rec;va_list args;rec.cat = cat;rec.level = level;rec.file = file;rec.line = line;rec.func = func;va_start(args, fmt);vsnprintf(buf, sizeof(buf), fmt, args);va_end(args);rec.msg = buf;if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {if (gd)gd->log_drop_count++;return -ENOSYS;}log_dispatch(&rec);return 0;+}
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list)+{
struct log_filter *filt;struct log_device *ldev;int i;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;filt = (struct log_filter *)calloc(1, sizeof(*filt));if (!filt)return -ENOMEM;if (cat_list) {filt->flags |= LOGFF_HAS_CAT;for (i = 0; ; i++) {if (i == ARRAY_SIZE(filt->cat_list))return -ENOSPC;filt->cat_list[i] = cat_list[i];if (cat_list[i] == LOGC_END)break;}}filt->max_level = max_level;if (file_list) {filt->file_list = strdup(file_list);if (!filt->file_list)goto nomem;}filt->filter_num = ldev->next_filter_num++;INIT_LIST_HEAD(&filt->sibling_node);list_add_tail(&filt->sibling_node, &ldev->filter_head);return filt->filter_num;+nomem:
free(filt);return -ENOMEM;+}
+int log_remove_filter(const char *drv_name, int filter_num) +{
struct log_filter *filt;struct log_device *ldev;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (filt->filter_num == filter_num) {list_del(&filt->sibling_node);free(filt);return 0;}}return -ENOENT;+}
I am not sure if this luxury filter is needed. After all, the purpose is debugging. The printf() debugging is useful, but only during testing. Once quality code is established, most of debug message should generally be removed from upstream code.
But not logging, and this is the point. It is very useful to have basic logging information recorded for every boot, and the normal printf() output is not detailed enough. For example for verified boot I want to see details about boot failures and what went wrong (key verification, etc.).
This should be warn level, (or notice at least) not info.
Sure, but the the fact that it failed is not very useful. We know that. What is useful is the events leading up to that failure and those are probably not written to the console. For example if a key to verify was it because the key was invalid, the image was not found, the TPM had wrong data, ...?
So I expect that at least INFO (and probably DETAIL) logging would be useful to record for such a system, even if it does not appear on the console (in fact the console would normally be disabled in such a system).
OK. Logging is useful, but your example will be used with info level.
I still do not understand the necessity of category / file filtering.
Category is for knowing which subsystem generated the log message. It makes no sense to log MMC messages if you are hunting for an error in USB. It clutters up the log. Also, it allows a post-processing tool to filter log messages in a sensible, human-friendly way, even if both categories are recorded.
File filtering is useful I think in the interim, while nothing uses categories. We can filter on particular files to pick out the messages from those files. Even when we do have proper categories everywhere, it might still be useful. I am not sure yet.
+int log_init(void) +{
struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);const int count = ll_entry_count(struct log_driver, log_driver);struct log_driver *end = drv + count;/** We cannot add runtime data to the driver since it is likely stored* in rodata. Instead, set up a 'device' corresponding to each driver.* We only support having a single device.*/INIT_LIST_HEAD((struct list_head *)&gd->log_head);while (drv < end) {struct log_device *ldev;ldev = calloc(1, sizeof(*ldev));if (!ldev) {debug("%s: Cannot allocate memory\n", __func__);return -ENOMEM;}INIT_LIST_HEAD(&ldev->sibling_node);This INIT_LIST_HEAD() is unneeded.
How come? If I don't do that how will the list be set up?
Because ldev->sibling_node is not a list_head. It is used as a list node.
See include/linux/list.h for the implementation of list_add_tail().
The argument "head" must be initialized in advance, but "new" does not need initialization.
OK I see. Not at all obvious from reading the header file comments.
INIT_LIST_HEAD(&ldev->filter_head);ldev->drv = drv;list_add_tail(&ldev->sibling_node,(struct list_head *)&gd->log_head);Here, gd->log_head is a head, so INIT_LIST_HEAD((struct list_head *)&gd->log_head); is correct.
INIT_LIST_HEAD(&ldev->sibling_node); is non-sense.
I know that this (struct list_head *) cast is needed, but it is very unfortunate. I believe gd_t is design mistake in the first place, but U-Boot has gone to unfixable already...
With driver model I added DM_ROOT_NON_CONST. I suppose we could use something like that.
But perhaps we should start dropping the 'volatile' in gd? I'm not sure why it is needed.
Me neither.
OK well something to add to the list.
+#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif
I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). From your Kconfig entry,
0 - panic 1 - critical 2 - error 3 - warning 4 - note 5 - info 6 - detail 7 - debug
I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value range 0 to 7.
If the log level is 0 (= critial), the conditional is false, so _LOG_MAX_LEVEL is set to "info" level.
Why is this #if necessary?
If we don't have CONFIG_LOG enabled then this value will not exist.
This implementation is wrong.
You are abusing the fact that U-Boot does not specify -Wundef option.
--------------------->8----------------- -Wundef Warn if an undefined identifier is evaluated in an #if directive. Such identifiers are replaced with zero. --------------------->8-----------------
Right, U-Boot does not give -Wundef, but it is just because -Wundef causes too many warnings.
Ideally, we should fix the code, then enable the option like Linux.
We should use #ifdef for testing a option that may or may not be defined. Using #if for options that may not be defined is a bad coding way.
OK I see, will fix.
Regards, Simon
Hi Simon,
2017-09-27 4:10 GMT+09:00 Simon Glass sjg@chromium.org:
Hi Masahiro,
On 20 September 2017 at 11:19, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-20 22:49 GMT+09:00 Simon Glass sjg@chromium.org:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
I will explain it in another mail.
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugPlease do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messagesYes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access.
So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom?
In fact, Linux has one more for debug. dev_vdbg() is widely used in Linux.
If you like, we can add one more level:
8 (KERN_VDEBUG) verbose debug messagesPerhaps, logging every access to an MMC peripheral might belong to the vdbg level.
I like the idea of having a log level for message contents (bytes) and another for I/O access. So I will add two more in v2.
BTW, what do you mean "INFO is what I plan to use for normal printf() output"
Is that mean printf() is equivalent to pr_info()? If loglevel is 6 or smaller, will all print() be silent? If so, probably we can not use command line interface.
I mean that I want to (later) add a feature that logs normal printf() output. If the console is silent then it would still be logged. Maybe one day log functions will be used instead of printf(), but for now this provides a useful way to make things wok.
IMHO, printf() should be used for command line interface.
All SoC files, board files should use pr_*(), and drivers dev_*().
+/**
- log_dispatch() - Send a log record to all log devices for processing
- The log record is sent to each log device in turn, skipping those which have
- filters which block the record
- @rec: Log record to dispatch
- @return 0 (meaning success)
- */
+static int log_dispatch(struct log_rec *rec) +{
struct log_device *ldev;list_for_each_entry(ldev, &gd->log_head, sibling_node) {if (log_passes_filters(ldev, rec))ldev->drv->emit(ldev, rec);}return 0;+}
+int _log(enum log_category_t cat, enum log_level_t level, const char *file,
int line, const char *func, const char *fmt, ...)+{
char buf[CONFIG_SYS_CBSIZE];struct log_rec rec;va_list args;rec.cat = cat;rec.level = level;rec.file = file;rec.line = line;rec.func = func;va_start(args, fmt);vsnprintf(buf, sizeof(buf), fmt, args);va_end(args);rec.msg = buf;if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {if (gd)gd->log_drop_count++;return -ENOSYS;}log_dispatch(&rec);return 0;+}
+int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
enum log_level_t max_level, const char *file_list)+{
struct log_filter *filt;struct log_device *ldev;int i;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;filt = (struct log_filter *)calloc(1, sizeof(*filt));if (!filt)return -ENOMEM;if (cat_list) {filt->flags |= LOGFF_HAS_CAT;for (i = 0; ; i++) {if (i == ARRAY_SIZE(filt->cat_list))return -ENOSPC;filt->cat_list[i] = cat_list[i];if (cat_list[i] == LOGC_END)break;}}filt->max_level = max_level;if (file_list) {filt->file_list = strdup(file_list);if (!filt->file_list)goto nomem;}filt->filter_num = ldev->next_filter_num++;INIT_LIST_HEAD(&filt->sibling_node);list_add_tail(&filt->sibling_node, &ldev->filter_head);return filt->filter_num;+nomem:
free(filt);return -ENOMEM;+}
+int log_remove_filter(const char *drv_name, int filter_num) +{
struct log_filter *filt;struct log_device *ldev;ldev = log_device_find_by_name(drv_name);if (!ldev)return -ENOENT;list_for_each_entry(filt, &ldev->filter_head, sibling_node) {if (filt->filter_num == filter_num) {list_del(&filt->sibling_node);free(filt);return 0;}}return -ENOENT;+}
I am not sure if this luxury filter is needed. After all, the purpose is debugging. The printf() debugging is useful, but only during testing. Once quality code is established, most of debug message should generally be removed from upstream code.
But not logging, and this is the point. It is very useful to have basic logging information recorded for every boot, and the normal printf() output is not detailed enough. For example for verified boot I want to see details about boot failures and what went wrong (key verification, etc.).
This should be warn level, (or notice at least) not info.
Sure, but the the fact that it failed is not very useful. We know that. What is useful is the events leading up to that failure and those are probably not written to the console. For example if a key to verify was it because the key was invalid, the image was not found, the TPM had wrong data, ...?
So I expect that at least INFO (and probably DETAIL) logging would be useful to record for such a system, even if it does not appear on the console (in fact the console would normally be disabled in such a system).
OK. Logging is useful, but your example will be used with info level.
I still do not understand the necessity of category / file filtering.
Category is for knowing which subsystem generated the log message. It makes no sense to log MMC messages if you are hunting for an error in USB. It clutters up the log. Also, it allows a post-processing tool to filter log messages in a sensible, human-friendly way, even if both categories are recorded.
I do not think we have much volume for notice or lower loglevel.
The categorization is useful for debug level and you can see the right thing to do for example, in drivers/i2c/Makefile of Linux.
ccflags-$(CONFIG_I2C_DEBUG_CORE) := -DDEBUG
This is already established in Linux
[1] Create an entry for CONFIG_FOO_DEBUG in Kconfig [2] Add ccflags-$(CONFIG_FOO_DEBUG) := -DDEBUG
You can do likewise for DM-core, EFI, or whatever.
File filtering is useful I think in the interim, while nothing uses categories. We can filter on particular files to pick out the messages from those files. Even when we do have proper categories everywhere, it might still be useful. I am not sure yet.
File filter is pointless because we are generally supposed to add #define DEBUG to each file to make pr_dbg() effective.
Hi Masahiro,
On 27 September 2017 at 11:11, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-27 4:10 GMT+09:00 Simon Glass sjg@chromium.org:
Hi Masahiro,
On 20 September 2017 at 11:19, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-20 22:49 GMT+09:00 Simon Glass sjg@chromium.org:
Hi Masahiro,
On 19 September 2017 at 20:51, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+menu "Logging"
+config LOG
bool "Enable logging support"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.+config SPL_LOG
bool "Enable logging support in SPL"helpThis enables support for logging of status and debug messages. Thesecan be displayed on the console, recorded in a memory buffer, ordiscarded if not needed. Logging supports various categories andlevels of severity.Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL.
Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well.
I cannot believe why such a commit was accepted.
Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate.
We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended?
But I'm OK with not having logging in TPL until we need it.
I will explain it in another mail.
+config LOG_MAX_LEVEL
int "Maximum log level to record"depends on LOGdefault 5helpThis selects the maximum log level that will be recorded. Any valuehigher than this will be ignored. If possible log statements belowthis level will be discarded at build time. Levels:0 - panic1 - critical2 - error3 - warning4 - note5 - info6 - detail7 - debugPlease do not invent our own for U-Boot. Just use Linux log level.
0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messagesYes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access.
So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom?
In fact, Linux has one more for debug. dev_vdbg() is widely used in Linux.
If you like, we can add one more level:
8 (KERN_VDEBUG) verbose debug messagesPerhaps, logging every access to an MMC peripheral might belong to the vdbg level.
I like the idea of having a log level for message contents (bytes) and another for I/O access. So I will add two more in v2.
BTW, what do you mean "INFO is what I plan to use for normal printf() output"
Is that mean printf() is equivalent to pr_info()? If loglevel is 6 or smaller, will all print() be silent? If so, probably we can not use command line interface.
I mean that I want to (later) add a feature that logs normal printf() output. If the console is silent then it would still be logged. Maybe one day log functions will be used instead of printf(), but for now this provides a useful way to make things wok.
IMHO, printf() should be used for command line interface.
I suppose that makes sense, but in the interim we have a lot of printf() stuff printing errors / messages.
All SoC files, board files should use pr_*(), and drivers dev_*().
OK, for dev_*() we can generate the category automatically, but for pr_*() we cannot. So those would just get the default category for the file.
I do not think we have much volume for notice or lower loglevel.
We have loads and loads of debug() things. If you mean that they will normally be compiled out, yes. But I think we will see a trend to adding more debugging into the code for when things go wrong. I'd like to be able to do a 'debug' build and get all of that info recorded, even if it is not displayed on the console.
The categorization is useful for debug level and you can see the right thing to do for example, in drivers/i2c/Makefile of Linux.
ccflags-$(CONFIG_I2C_DEBUG_CORE) := -DDEBUG
That is a build-time thing, though.
This is already established in Linux
[1] Create an entry for CONFIG_FOO_DEBUG in Kconfig [2] Add ccflags-$(CONFIG_FOO_DEBUG) := -DDEBUG
You can do likewise for DM-core, EFI, or whatever.
That is not the (whole) use case for this log feature. Here you are suggesting that we add an option to debug each uclass at run-time. I think that might be quite useful to allow build-time control of what categories are logged, but I think it is not a core feature needed right now.
File filtering is useful I think in the interim, while nothing uses categories. We can filter on particular files to pick out the messages from those files. Even when we do have proper categories everywhere, it might still be useful. I am not sure yet.
File filter is pointless because we are generally supposed to add #define DEBUG to each file to make pr_dbg() effective.
With logging if you set the max level to DEBUG you don't need to do that. You can filter at run-time.
Regards, Simon
It is useful to display log messages on the console. Add a simple driver to handle this.
Signed-off-by: Simon Glass sjg@chromium.org ---
common/Kconfig | 20 ++++++++++++++++++++ common/Makefile | 1 + common/log_console.c | 23 +++++++++++++++++++++++ 3 files changed, 44 insertions(+) create mode 100644 common/log_console.c
diff --git a/common/Kconfig b/common/Kconfig index cbccc8ae26..ba4578e870 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -438,6 +438,26 @@ config LOG_SPL_MAX_LEVEL 6 - detail 7 - debug
+config LOG_CONSOLE + bool "Allow log output to the console" + depends on LOG + default y + help + Enables a log driver which writes log records to the console. + Generally the console is the serial port or LCD display. Only the + log message is shown - other details like level, category, file and + line number are omitted. + +config LOG_SPL_CONSOLE + bool "Allow log output to the console in SPL" + depends on LOG_SPL + default y + help + Enables a log driver which writes log records to the console. + Generally the console is the serial port or LCD display. Only the + log message is shown - other details like level, category, file and + line number are omitted. + endmenu
config DTB_RESELECT diff --git a/common/Makefile b/common/Makefile index d37c8d5636..9db0f4ca2d 100644 --- a/common/Makefile +++ b/common/Makefile @@ -129,5 +129,6 @@ obj-$(CONFIG_FSL_DDR_INTERACTIVE) += cli_simple.o cli_readline.o obj-$(CONFIG_CMD_DFU) += dfu.o obj-y += command.o obj-$(CONFIG_$(SPL_)LOG) += log.o +obj-$(CONFIG_$(SPL_)LOG_CONSOLE) += log_console.o obj-y += s_record.o obj-y += xyzModem.o diff --git a/common/log_console.c b/common/log_console.c new file mode 100644 index 0000000000..5af73bd8be --- /dev/null +++ b/common/log_console.c @@ -0,0 +1,23 @@ +/* + * Logging support + * + * Copyright (c) 2017 Google, Inc + * Written by Simon Glass sjg@chromium.org + * + * SPDX-License-Identifier: GPL-2.0+ + */ + +#include <common.h> +#include <log.h> + +static int log_console_emit(struct log_device *ldev, struct log_rec *rec) +{ + puts(rec->msg); + + return 0; +} + +LOG_DRIVER(console) = { + .name = "console", + .emit = log_console_emit, +};
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
It is useful to display log messages on the console. Add a simple driver to handle this.
Signed-off-by: Simon Glass sjg@chromium.org
common/Kconfig | 20 ++++++++++++++++++++ common/Makefile | 1 + common/log_console.c | 23 +++++++++++++++++++++++ 3 files changed, 44 insertions(+) create mode 100644 common/log_console.c
Reviewed-by: Bin Meng bmeng.cn@gmail.com
But isn't it possible to get this stuff into the serial-uclass driver?
Regards, Bin
Hi Bin,
On 17 September 2017 at 23:45, Bin Meng bmeng.cn@gmail.com wrote:
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
It is useful to display log messages on the console. Add a simple driver to handle this.
Signed-off-by: Simon Glass sjg@chromium.org
common/Kconfig | 20 ++++++++++++++++++++ common/Makefile | 1 + common/log_console.c | 23 +++++++++++++++++++++++ 3 files changed, 44 insertions(+) create mode 100644 common/log_console.c
Reviewed-by: Bin Meng bmeng.cn@gmail.com
But isn't it possible to get this stuff into the serial-uclass driver?
It could do but then it would not be the console. The console is controlled by stdout and might be set to output to an LCD, or perhaps both LCD and serial.
Regards, Simon
Add a command for adjusting the log level.
Signed-off-by: Simon Glass sjg@chromium.org ---
cmd/Kconfig | 7 +++++++ cmd/Makefile | 1 + cmd/log.c | 55 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 63 insertions(+) create mode 100644 cmd/log.c
diff --git a/cmd/Kconfig b/cmd/Kconfig index d6d130edfa..702d4f251f 100644 --- a/cmd/Kconfig +++ b/cmd/Kconfig @@ -1478,6 +1478,13 @@ config CMD_KGDB single-stepping, inspecting variables, etc. This is supported only on PowerPC at present.
+config CMD_LOG + bool "log - Generation, control and access to logging" + help + This provides access to logging features. It allows the output of + log data to be controlled to a limited extent (setting up the default + maximum log level for emitting of records). + config CMD_TRACE bool "trace - Support tracing of function calls and timing" help diff --git a/cmd/Makefile b/cmd/Makefile index 1b13d07901..f09278da24 100644 --- a/cmd/Makefile +++ b/cmd/Makefile @@ -75,6 +75,7 @@ obj-$(CONFIG_LED_STATUS_CMD) += legacy_led.o obj-$(CONFIG_CMD_LED) += led.o obj-$(CONFIG_CMD_LICENSE) += license.o obj-y += load.o +obj-$(CONFIG_CMD_LOG) += log.o obj-$(CONFIG_ID_EEPROM) += mac.o obj-$(CONFIG_CMD_MD5SUM) += md5sum.o obj-$(CONFIG_CMD_MEMORY) += mem.o diff --git a/cmd/log.c b/cmd/log.c new file mode 100644 index 0000000000..44e04ab16a --- /dev/null +++ b/cmd/log.c @@ -0,0 +1,55 @@ +/* + * Copyright (c) 2017 Google, Inc + * Written by Simon Glass sjg@chromium.org + * + * SPDX-License-Identifier: GPL-2.0+ + */ + +#include <common.h> +#include <command.h> +#include <dm.h> +#include <log.h> + +static int do_log_level(cmd_tbl_t *cmdtp, int flag, int argc, + char * const argv[]) +{ + if (argc > 1) + gd->default_log_level = simple_strtol(argv[1], NULL, 10); + else + printf("Default log level: %d\n", gd->default_log_level); + + return 0; +} + +static cmd_tbl_t log_sub[] = { + U_BOOT_CMD_MKENT(level, CONFIG_SYS_MAXARGS, 1, do_log_level, "", ""), +}; + +static int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) +{ + cmd_tbl_t *cp; + + if (argc < 2) + return CMD_RET_USAGE; + + /* drop initial "log" arg */ + argc--; + argv++; + + cp = find_cmd_tbl(argv[0], log_sub, ARRAY_SIZE(log_sub)); + if (cp) + return cp->cmd(cmdtp, flag, argc, argv); + + return CMD_RET_USAGE; +} + +#ifdef CONFIG_SYS_LONGHELP +static char log_help_text[] = + "level - get/set log level\n" + ; +#endif + +U_BOOT_CMD( + log, CONFIG_SYS_MAXARGS, 1, do_log, + "log system", log_help_text +);
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add a command for adjusting the log level.
Signed-off-by: Simon Glass sjg@chromium.org
cmd/Kconfig | 7 +++++++ cmd/Makefile | 1 + cmd/log.c | 55 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 63 insertions(+) create mode 100644 cmd/log.c
Reviewed-by: Bin Meng bmeng.cn@gmail.com
Add a command which exercises the logging system.
Signed-off-by: Simon Glass sjg@chromium.org ---
cmd/Kconfig | 3 +- cmd/log.c | 6 ++ common/Kconfig | 10 +++ include/log.h | 3 + test/Makefile | 1 + test/log/Makefile | 7 ++ test/log/log_test.c | 204 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 7 files changed, 233 insertions(+), 1 deletion(-) create mode 100644 test/log/Makefile create mode 100644 test/log/log_test.c
diff --git a/cmd/Kconfig b/cmd/Kconfig index 702d4f251f..9d52e4fecc 100644 --- a/cmd/Kconfig +++ b/cmd/Kconfig @@ -1483,7 +1483,8 @@ config CMD_LOG help This provides access to logging features. It allows the output of log data to be controlled to a limited extent (setting up the default - maximum log level for emitting of records). + maximum log level for emitting of records). It also provides access + to a command used for testing the log system.
config CMD_TRACE bool "trace - Support tracing of function calls and timing" diff --git a/cmd/log.c b/cmd/log.c index 44e04ab16a..1fc49c4cf2 100644 --- a/cmd/log.c +++ b/cmd/log.c @@ -23,6 +23,9 @@ static int do_log_level(cmd_tbl_t *cmdtp, int flag, int argc,
static cmd_tbl_t log_sub[] = { U_BOOT_CMD_MKENT(level, CONFIG_SYS_MAXARGS, 1, do_log_level, "", ""), +#ifdef CONFIG_LOG_TEST + U_BOOT_CMD_MKENT(test, 2, 1, do_log_level, "", ""), +#endif };
static int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) @@ -46,6 +49,9 @@ static int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) #ifdef CONFIG_SYS_LONGHELP static char log_help_text[] = "level - get/set log level\n" +#ifdef CONFIG_LOG_TEST + "test - run log tests\n" +#endif ; #endif
diff --git a/common/Kconfig b/common/Kconfig index ba4578e870..57ce2cbe9a 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -458,6 +458,16 @@ config LOG_SPL_CONSOLE log message is shown - other details like level, category, file and line number are omitted.
+config LOG_TEST + bool "Provide a test for logging" + depends on LOG + default y if SANDBOX + help + This enables a 'log test' command to test logging. It is normally + executed from a pytest and simply outputs logging information + in various different ways to test that the logging system works + correctly with varoius settings. + endmenu
config DTB_RESELECT diff --git a/include/log.h b/include/log.h index fb6a196202..f03ed94128 100644 --- a/include/log.h +++ b/include/log.h @@ -263,6 +263,9 @@ struct log_filter { #define LOG_DRIVER(_name) \ ll_entry_declare(struct log_driver, _name, log_driver)
+/* Handle the 'log test' command */ +int do_log_test(cmd_tbl_t *cmdtp, int flag, int argc, char *const argv[]); + /** * log_add_filter() - Add a new filter to a log device * diff --git a/test/Makefile b/test/Makefile index 6305afb211..40f2244b79 100644 --- a/test/Makefile +++ b/test/Makefile @@ -10,3 +10,4 @@ obj-$(CONFIG_SANDBOX) += command_ut.o obj-$(CONFIG_SANDBOX) += compression.o obj-$(CONFIG_SANDBOX) += print_ut.o obj-$(CONFIG_UT_TIME) += time_ut.o +obj-$(CONFIG_$(SPL_)LOG) += log/ diff --git a/test/log/Makefile b/test/log/Makefile new file mode 100644 index 0000000000..b0da8dee28 --- /dev/null +++ b/test/log/Makefile @@ -0,0 +1,7 @@ +# +# Copyright (c) 2017 Google, Inc +# +# SPDX-License-Identifier: GPL-2.0+ +# + +obj-$(CONFIG_LOG_TEST) += log_test.o diff --git a/test/log/log_test.c b/test/log/log_test.c new file mode 100644 index 0000000000..c3d076491f --- /dev/null +++ b/test/log/log_test.c @@ -0,0 +1,204 @@ +/* + * Logging support test program + * + * Copyright (c) 2017 Google, Inc + * Written by Simon Glass sjg@chromium.org + * + * SPDX-License-Identifier: GPL-2.0+ + */ + +#include <common.h> + +/* emit some sample log records in different ways, for testing */ +static int log_run(enum log_category_t cat, const char *file) +{ + int i; + + debug("debug\n"); + error("error\n"); + for (i = LOGL_FIRST; i < LOGL_COUNT; i++) { + log(cat, i, "log %d\n", i); + _log(cat, i, file, 100 + i, "func", "_log %d\n", i); + } + + return 0; +} + +static int log_test(int testnum) +{ + int ret; + + printf("test %d\n", testnum); + switch (testnum) { + case 0: { + /* Check a category filter using the first category */ + enum log_category_t cat_list[] = { + UCLASS_MMC, UCLASS_SPI, LOGC_NONE, LOGC_END + }; + + ret = log_add_filter("console", cat_list, LOGL_MAX, NULL); + if (ret < 0) + return ret; + log_run(UCLASS_MMC, "file"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 1: { + /* Check a category filter using the second category */ + enum log_category_t cat_list[] = { + UCLASS_MMC, UCLASS_SPI, LOGC_END + }; + + ret = log_add_filter("console", cat_list, LOGL_MAX, NULL); + if (ret < 0) + return ret; + log_run(UCLASS_SPI, "file"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 2: { + /* Check a category filter that should block log entries */ + enum log_category_t cat_list[] = { + UCLASS_MMC, LOGC_NONE, LOGC_END + }; + + ret = log_add_filter("console", cat_list, LOGL_MAX, NULL); + if (ret < 0) + return ret; + log_run(UCLASS_SPI, "file"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 3: { + /* Check a passing file filter */ + ret = log_add_filter("console", NULL, LOGL_MAX, "file"); + if (ret < 0) + return ret; + log_run(UCLASS_SPI, "file"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 4: { + /* Check a failing file filter */ + ret = log_add_filter("console", NULL, LOGL_MAX, "file"); + if (ret < 0) + return ret; + log_run(UCLASS_SPI, "file2"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 5: { + /* Check a passing file filter (second in list) */ + ret = log_add_filter("console", NULL, LOGL_MAX, "file,file2"); + if (ret < 0) + return ret; + log_run(UCLASS_SPI, "file2"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 6: { + /* Check a passing file filter (also passing error()) */ + ret = log_add_filter("console", NULL, LOGL_MAX, + "file,file2,log/log_test.c"); + if (ret < 0) + return ret; + log_run(UCLASS_SPI, "file2"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 7: { + /* Check a log level filter */ + ret = log_add_filter("console", NULL, LOGL_WARN, NULL); + if (ret < 0) + return ret; + log_run(UCLASS_SPI, "file"); + ret = log_remove_filter("console", ret); + if (ret < 0) + return ret; + break; + } + case 8: { + /* Check two filters, one of which passes everything */ + int filt1, filt2; + + ret = log_add_filter("console", NULL, LOGL_WARN, NULL); + if (ret < 0) + return ret; + filt1 = ret; + ret = log_add_filter("console", NULL, LOGL_MAX, NULL); + if (ret < 0) + return ret; + filt2 = ret; + log_run(UCLASS_SPI, "file"); + ret = log_remove_filter("console", filt1); + if (ret < 0) + return ret; + ret = log_remove_filter("console", filt2); + if (ret < 0) + return ret; + break; + } + case 9: { + /* Check three filters, which together pass everything */ + int filt1, filt2, filt3; + + ret = log_add_filter("console", NULL, LOGL_MAX, "file)"); + if (ret < 0) + return ret; + filt1 = ret; + ret = log_add_filter("console", NULL, LOGL_MAX, "file2"); + if (ret < 0) + return ret; + filt2 = ret; + ret = log_add_filter("console", NULL, LOGL_MAX, + "log/log_test.c"); + if (ret < 0) + return ret; + filt3 = ret; + log_run(UCLASS_SPI, "file2"); + ret = log_remove_filter("console", filt1); + if (ret < 0) + return ret; + ret = log_remove_filter("console", filt2); + if (ret < 0) + return ret; + ret = log_remove_filter("console", filt3); + if (ret < 0) + return ret; + break; + } + } + + return 0; +} + +#ifdef CONFIG_LOG_TEST +int do_log_test(cmd_tbl_t *cmdtp, int flag, int argc, char *const argv[]) +{ + int testnum = 0; + int ret; + + if (argc > 1) + testnum = simple_strtoul(argv[1], NULL, 10); + + ret = log_test(testnum); + if (ret) + printf("Test failure (err=%d)\n", ret); + + return ret ? CMD_RET_FAILURE : 0; +} +#endif
Hi Simon,
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add a command which exercises the logging system.
Signed-off-by: Simon Glass sjg@chromium.org
cmd/Kconfig | 3 +- cmd/log.c | 6 ++ common/Kconfig | 10 +++ include/log.h | 3 + test/Makefile | 1 + test/log/Makefile | 7 ++ test/log/log_test.c | 204 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 7 files changed, 233 insertions(+), 1 deletion(-) create mode 100644 test/log/Makefile create mode 100644 test/log/log_test.c
diff --git a/cmd/Kconfig b/cmd/Kconfig index 702d4f251f..9d52e4fecc 100644 --- a/cmd/Kconfig +++ b/cmd/Kconfig @@ -1483,7 +1483,8 @@ config CMD_LOG help This provides access to logging features. It allows the output of log data to be controlled to a limited extent (setting up the default
maximum log level for emitting of records).
maximum log level for emitting of records). It also provides accessto a command used for testing the log system.config CMD_TRACE bool "trace - Support tracing of function calls and timing" diff --git a/cmd/log.c b/cmd/log.c index 44e04ab16a..1fc49c4cf2 100644 --- a/cmd/log.c +++ b/cmd/log.c @@ -23,6 +23,9 @@ static int do_log_level(cmd_tbl_t *cmdtp, int flag, int argc,
static cmd_tbl_t log_sub[] = { U_BOOT_CMD_MKENT(level, CONFIG_SYS_MAXARGS, 1, do_log_level, "", ""), +#ifdef CONFIG_LOG_TEST
U_BOOT_CMD_MKENT(test, 2, 1, do_log_level, "", ""),
It should be "do_log_test".
+#endif };
static int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) @@ -46,6 +49,9 @@ static int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) #ifdef CONFIG_SYS_LONGHELP static char log_help_text[] = "level - get/set log level\n" +#ifdef CONFIG_LOG_TEST
"test - run log tests\n"
It should be "log test", as U-Boot's command line won't append the main command name except the first one.
+#endif ; #endif
diff --git a/common/Kconfig b/common/Kconfig index ba4578e870..57ce2cbe9a 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -458,6 +458,16 @@ config LOG_SPL_CONSOLE log message is shown - other details like level, category, file and line number are omitted.
+config LOG_TEST
bool "Provide a test for logging"depends on LOGdefault y if SANDBOXhelpThis enables a 'log test' command to test logging. It is normallyexecuted from a pytest and simply outputs logging informationin various different ways to test that the logging system workscorrectly with varoius settings.endmenu
config DTB_RESELECT diff --git a/include/log.h b/include/log.h index fb6a196202..f03ed94128 100644 --- a/include/log.h +++ b/include/log.h @@ -263,6 +263,9 @@ struct log_filter { #define LOG_DRIVER(_name) \ ll_entry_declare(struct log_driver, _name, log_driver)
+/* Handle the 'log test' command */ +int do_log_test(cmd_tbl_t *cmdtp, int flag, int argc, char *const argv[]);
/**
- log_add_filter() - Add a new filter to a log device
diff --git a/test/Makefile b/test/Makefile index 6305afb211..40f2244b79 100644 --- a/test/Makefile +++ b/test/Makefile @@ -10,3 +10,4 @@ obj-$(CONFIG_SANDBOX) += command_ut.o obj-$(CONFIG_SANDBOX) += compression.o obj-$(CONFIG_SANDBOX) += print_ut.o obj-$(CONFIG_UT_TIME) += time_ut.o +obj-$(CONFIG_$(SPL_)LOG) += log/ diff --git a/test/log/Makefile b/test/log/Makefile new file mode 100644 index 0000000000..b0da8dee28 --- /dev/null +++ b/test/log/Makefile @@ -0,0 +1,7 @@ +# +# Copyright (c) 2017 Google, Inc +# +# SPDX-License-Identifier: GPL-2.0+ +#
+obj-$(CONFIG_LOG_TEST) += log_test.o diff --git a/test/log/log_test.c b/test/log/log_test.c new file mode 100644 index 0000000000..c3d076491f --- /dev/null +++ b/test/log/log_test.c @@ -0,0 +1,204 @@ +/*
- Logging support test program
- Copyright (c) 2017 Google, Inc
- Written by Simon Glass sjg@chromium.org
- SPDX-License-Identifier: GPL-2.0+
- */
+#include <common.h>
+/* emit some sample log records in different ways, for testing */ +static int log_run(enum log_category_t cat, const char *file) +{
int i;debug("debug\n");error("error\n");for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {log(cat, i, "log %d\n", i);_log(cat, i, file, 100 + i, "func", "_log %d\n", i);}return 0;+}
+static int log_test(int testnum) +{
int ret;printf("test %d\n", testnum);switch (testnum) {case 0: {/* Check a category filter using the first category */enum log_category_t cat_list[] = {UCLASS_MMC, UCLASS_SPI, LOGC_NONE, LOGC_END};ret = log_add_filter("console", cat_list, LOGL_MAX, NULL);if (ret < 0)return ret;log_run(UCLASS_MMC, "file");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 1: {/* Check a category filter using the second category */enum log_category_t cat_list[] = {UCLASS_MMC, UCLASS_SPI, LOGC_END};ret = log_add_filter("console", cat_list, LOGL_MAX, NULL);if (ret < 0)return ret;log_run(UCLASS_SPI, "file");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 2: {/* Check a category filter that should block log entries */enum log_category_t cat_list[] = {UCLASS_MMC, LOGC_NONE, LOGC_END};ret = log_add_filter("console", cat_list, LOGL_MAX, NULL);if (ret < 0)return ret;log_run(UCLASS_SPI, "file");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 3: {/* Check a passing file filter */ret = log_add_filter("console", NULL, LOGL_MAX, "file");if (ret < 0)return ret;log_run(UCLASS_SPI, "file");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 4: {/* Check a failing file filter */ret = log_add_filter("console", NULL, LOGL_MAX, "file");if (ret < 0)return ret;log_run(UCLASS_SPI, "file2");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 5: {/* Check a passing file filter (second in list) */ret = log_add_filter("console", NULL, LOGL_MAX, "file,file2");if (ret < 0)return ret;log_run(UCLASS_SPI, "file2");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 6: {/* Check a passing file filter (also passing error()) */ret = log_add_filter("console", NULL, LOGL_MAX,"file,file2,log/log_test.c");if (ret < 0)return ret;log_run(UCLASS_SPI, "file2");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 7: {/* Check a log level filter */ret = log_add_filter("console", NULL, LOGL_WARN, NULL);if (ret < 0)return ret;log_run(UCLASS_SPI, "file");ret = log_remove_filter("console", ret);if (ret < 0)return ret;break;}case 8: {/* Check two filters, one of which passes everything */int filt1, filt2;ret = log_add_filter("console", NULL, LOGL_WARN, NULL);if (ret < 0)return ret;filt1 = ret;ret = log_add_filter("console", NULL, LOGL_MAX, NULL);if (ret < 0)return ret;filt2 = ret;log_run(UCLASS_SPI, "file");ret = log_remove_filter("console", filt1);if (ret < 0)return ret;ret = log_remove_filter("console", filt2);if (ret < 0)return ret;break;}case 9: {/* Check three filters, which together pass everything */int filt1, filt2, filt3;ret = log_add_filter("console", NULL, LOGL_MAX, "file)");if (ret < 0)return ret;filt1 = ret;ret = log_add_filter("console", NULL, LOGL_MAX, "file2");if (ret < 0)return ret;filt2 = ret;ret = log_add_filter("console", NULL, LOGL_MAX,"log/log_test.c");if (ret < 0)return ret;filt3 = ret;log_run(UCLASS_SPI, "file2");ret = log_remove_filter("console", filt1);if (ret < 0)return ret;ret = log_remove_filter("console", filt2);if (ret < 0)return ret;ret = log_remove_filter("console", filt3);if (ret < 0)return ret;break;}}return 0;+}
+#ifdef CONFIG_LOG_TEST +int do_log_test(cmd_tbl_t *cmdtp, int flag, int argc, char *const argv[]) +{
int testnum = 0;int ret;if (argc > 1)testnum = simple_strtoul(argv[1], NULL, 10);ret = log_test(testnum);if (ret)printf("Test failure (err=%d)\n", ret);return ret ? CMD_RET_FAILURE : 0;+}
+#endif
Regards, Bin
Set up logging both before and after relocation.
Signed-off-by: Simon Glass sjg@chromium.org ---
common/board_f.c | 5 ++++- common/board_r.c | 2 ++ common/log.c | 1 + include/asm-generic/global_data.h | 1 + 4 files changed, 8 insertions(+), 1 deletion(-)
diff --git a/common/board_f.c b/common/board_f.c index d0b1a00175..b22772d32c 100644 --- a/common/board_f.c +++ b/common/board_f.c @@ -751,6 +751,7 @@ static const init_fnc_t init_sequence_f[] = { trace_early_init, #endif initf_malloc, + log_init, initf_bootstage, /* uses its own timer, so does not need DM */ initf_console_record, #if defined(CONFIG_HAVE_FSP) @@ -932,8 +933,10 @@ void board_init_f_r(void) * The pre-relocation drivers may be using memory that has now gone * away. Mark serial as unavailable - this will fall back to the debug * UART if available. + * + * Do the same with log drivers since the memory may not be available. */ - gd->flags &= ~GD_FLG_SERIAL_READY; + gd->flags &= ~(GD_FLG_SERIAL_READY | GD_FLG_LOG_READY);
/* * U-Boot has been copied into SDRAM, the BSS has been cleared etc. diff --git a/common/board_r.c b/common/board_r.c index 02ac43d39c..fb56b7d997 100644 --- a/common/board_r.c +++ b/common/board_r.c @@ -703,6 +703,7 @@ static init_fnc_t init_sequence_r[] = { #endif initr_barrier, initr_malloc, + log_init, initr_bootstage, /* Needs malloc() but has its own timer */ initr_console_record, #ifdef CONFIG_SYS_NONCACHED_MEMORY @@ -899,6 +900,7 @@ void board_init_r(gd_t *new_gd, ulong dest_addr) #if !defined(CONFIG_X86) && !defined(CONFIG_ARM) && !defined(CONFIG_ARM64) gd = new_gd; #endif + gd->flags &= ~GD_FLG_LOG_READY;
#ifdef CONFIG_NEEDS_MANUAL_RELOC for (i = 0; i < ARRAY_SIZE(init_sequence_r); i++) diff --git a/common/log.c b/common/log.c index 6bf2219d38..917152b45a 100644 --- a/common/log.c +++ b/common/log.c @@ -240,6 +240,7 @@ int log_init(void) (struct list_head *)&gd->log_head); drv++; } + gd->flags |= GD_FLG_LOG_READY; gd->default_log_level = LOGL_INFO;
return 0; diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h index 77755dbb06..73e036d6fd 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -146,5 +146,6 @@ typedef struct global_data { #define GD_FLG_RECORD 0x01000 /* Record console */ #define GD_FLG_ENV_DEFAULT 0x02000 /* Default variable flag */ #define GD_FLG_SPL_EARLY_INIT 0x04000 /* Early SPL init is done */ +#define GD_FLG_LOG_READY 0x08000 /* Log system is ready for use */
#endif /* __ASM_GENERIC_GBL_DATA_H */
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Set up logging both before and after relocation.
Signed-off-by: Simon Glass sjg@chromium.org
common/board_f.c | 5 ++++- common/board_r.c | 2 ++ common/log.c | 1 + include/asm-generic/global_data.h | 1 + 4 files changed, 8 insertions(+), 1 deletion(-)
Reviewed-by: Bin Meng bmeng.cn@gmail.com
Enable all logging features on sandbox so that the tests can be run.
Signed-off-by: Simon Glass sjg@chromium.org ---
configs/sandbox_defconfig | 3 +++ 1 file changed, 3 insertions(+)
diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index 88ae98d312..0496ad49c8 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -17,6 +17,8 @@ CONFIG_CONSOLE_RECORD_OUT_SIZE=0x1000 CONFIG_SILENT_CONSOLE=y CONFIG_PRE_CONSOLE_BUFFER=y CONFIG_PRE_CON_BUF_ADDR=0x100000 +CONFIG_LOG=y +CONFIG_LOG_MAX_LEVEL=7 CONFIG_CMD_CPU=y CONFIG_CMD_LICENSE=y CONFIG_CMD_BOOTZ=y @@ -65,6 +67,7 @@ CONFIG_CMD_CBFS=y CONFIG_CMD_CRAMFS=y CONFIG_CMD_EXT4_WRITE=y CONFIG_CMD_MTDPARTS=y +CONFIG_CMD_LOG=y CONFIG_MAC_PARTITION=y CONFIG_AMIGA_PARTITION=y CONFIG_OF_CONTROL=y
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Enable all logging features on sandbox so that the tests can be run.
Signed-off-by: Simon Glass sjg@chromium.org
configs/sandbox_defconfig | 3 +++ 1 file changed, 3 insertions(+)
Reviewed-by: Bin Meng bmeng.cn@gmail.com
Add a test which tries out various filters and options to make sure that logging works as expected.
Signed-off-by: Simon Glass sjg@chromium.org ---
test/py/tests/test_log.py | 106 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 106 insertions(+) create mode 100644 test/py/tests/test_log.py
diff --git a/test/py/tests/test_log.py b/test/py/tests/test_log.py new file mode 100644 index 0000000000..d5a01df357 --- /dev/null +++ b/test/py/tests/test_log.py @@ -0,0 +1,106 @@ +# Copyright (c) 2016, Google Inc. +# +# SPDX-License-Identifier: GPL-2.0+ +# +# U-Boot Verified Boot Test + +""" +This tests U-Boot logging. It uses the 'log test' command with various options +and checks that the output is correct. +""" + +import pytest + +LOGL_FIRST, LOGL_WARN, LOGL_INFO = (0, 3, 5) + +def test_log(u_boot_console): + """Test that U-Boot logging works correctly.""" + def check_log_entries(lines, mask, max_level=LOGL_INFO): + """Check that the expected log records appear in the output + + Args: + lines: iterator containing lines to check + mask: bit mask to select which lines to check for: + bit 0: standard log line + bit 1: _log line + max_level: maximum log level to expect in the output + """ + for i in range(max_level): + if mask & 1: + assert 'log %d' % i == lines.next() + if mask & 3: + assert '_log %d' % i == lines.next() + + def run_test(testnum): + """Run a particular test number (the 'log test' command) + + Args: + testnum: Test number to run + Returns: + iterator containing the lines output from the command + """ + + with cons.log.section('basic'): + output = u_boot_console.run_command('log test %d' % testnum) + split = output.replace('\r', '').splitlines() + lines = iter(split) + assert 'test %d' % testnum == lines.next() + return lines + + def test0(): + lines = run_test(0) + assert 'error' == lines.next() + check_log_entries(lines, 3) + + def test1(): + lines = run_test(1) + check_log_entries(lines, 3) + + def test2(): + lines = run_test(2) + assert 'error' == lines.next() + + def test3(): + lines = run_test(3) + check_log_entries(lines, 2) + + def test4(): + lines = run_test(4) + assert next(lines, None) == None + + def test5(): + lines = run_test(5) + check_log_entries(lines, 2) + + def test6(): + lines = run_test(6) + assert 'error' == lines.next() + check_log_entries(lines, 3) + + def test7(): + lines = run_test(7) + assert 'error' == lines.next() + check_log_entries(lines, 3, LOGL_WARN) + + def test8(): + lines = run_test(8) + assert 'error' == lines.next() + check_log_entries(lines, 3) + + def test9(): + lines = run_test(8) + assert 'error' == lines.next() + check_log_entries(lines, 3) + + # TODO(sjg@chromium.org): Consider structuring this as separate tests + cons = u_boot_console + test0() + test1() + test2() + test3() + test4() + test5() + test6() + test7() + test8() + test9()
Add documentation for the log system.
Signed-off-by: Simon Glass sjg@chromium.org ---
doc/README.log | 220 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 220 insertions(+) create mode 100644 doc/README.log
diff --git a/doc/README.log b/doc/README.log new file mode 100644 index 0000000000..0f2d8b84dd --- /dev/null +++ b/doc/README.log @@ -0,0 +1,220 @@ +Logging in U-Boot +================= + +Introduction +------------ + +U-Boot's internal operation involves many different steps and actions. From +setting up the board to displaying a start-up screen to loading an Operating +System, there are many component parts each with many actions. + +Most of the time this internal detail is not useful. Displaying it on the +console would delay booting (U-Boot's primary purpose) and confuse users. + +But for digging into what is happening in a particular area, or for debugging +a problem it is often useful to see what U-Boot is doing in more detail than +is visible from the basic console output. + +U-Boot's logging feature aims to satisfy this goal for both users and +developers. + + +Logging levels +-------------- + +There are a number logging levels available, in increasing order of verbosity: + + LOGL_PANIC - Printed before U-Boot halts + LOGL_CRIT - Indicates a critical error that will cause boot failure + LOGL_ERR - Indicates an error that may cause boot failure + LOGL_WARN - Warning about an unexpected condition + LOGL_NOTE - Important information about progress + LOGL_INFO - Information about normal boot progress + LOGL_DETAIL - Detailed information (e.g. internal operation of drivers) + LOGL_DEBUG - Debug information (useful for debugging a driver or subsystem) + + +Logging category +---------------- + +Logging can come from a wide variety of places within U-Boot. Each log message +has a category which is intended to allow messages to be filtered according to +their source. + +The following main categories are defined: + + LOGC_NONE - Unknown category (e.g. a debug() statement) + UCLASS_... - Related to a particular uclass (e.g. UCLASS_USB) + LOGC_ARCH - Related to architecture-specific code + LOGC_BOARD - Related to board-specific code + LOGC_CORE - Related to core driver-model support + LOGC_DT - Related to device tree control + + +Enabling logging +---------------- + +The following options are used to enable logging at compile time: + + CONFIG_LOG - Enables the logging system + CONFIG_MAX_LOG_LEVEL - Max log level to build (anything higher is compiled + out) + CONFIG_LOG_CONSOLE - Enable writing log records to the console + +If CONFIG_LOG is not set, then no logging will be available. + +The above have SPL versions also, e.g. CONFIG_SPL_MAX_LOG_LEVEL. + + +Using DEBUG +----------- + +U-Boot has traditionally used a #define called DEBUG to enable debugging on a +file-by-file basis. The debug() macro compiles to a printf() statement if +DEBUG is enabled, and an empty statement if not. + +With logging enabled, debug() statements are interpreted as logging output +with a level of LOGL_DEBUG and a category of LOGC_NONE. + +The logging facilities are intended to replace DEBUG, but if DEBUG is defined +at the top of a file, then it takes precedence. This means that debug() +statements will result in output to the console and this output will not be +logged. + + +Logging destinations +-------------------- + +If logging information goes nowhere then it serves no purpose. U-Boot provides +several possible determinations for logging information, all of which can be +enabled or disabled independently: + + console - goes to stdout + + +Filters +------- + +Filters are attached to log drivers to control what those drivers emit. Only +records that pass through the filter make it to the driver. + +Filters can be based on several criteria: + + - maximum log level + - in a set of categories + - in a set of files + +If no filters are attached to a driver then a default filter is used, which +limits output to records with a level less than CONFIG_LOG_MAX_LEVEL. + + +Logging statements +------------------ + +The main logging function is: + + log(category, level, format_string, ...) + +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. + + +Code size +--------- + +Code size impact depends largely on what is enabled. The following numbers are +for snow, which is a Thumb-2 board: + +This series: adds bss +20.0 data +4.0 rodata +4.0 text +44.0 +CONFIG_LOG: bss -52.0 data +92.0 rodata -635.0 text +1048.0 +CONFIG_LOG_MAX_LEVEL=7: bss +188.0 data +4.0 rodata +49183.0 text +98124.0 + +The last option turns every debug() statement into a logging call, which +bloats the code hugely. The advantage is that it is then possible to enable +all logging within U-Boot. + + +To Do +----- + +There are lots of useful additions that could be made. None of the below is +implemented! If you do one, please add a test in test/py/tests/test_log.py + +Convenience functions to support setting the category: + + log_arch(level, format_string, ...) - category LOGC_ARCH + log_board(level, format_string, ...) - category LOGC_BOARD + log_core(level, format_string, ...) - category LOGC_CORE + log_dt(level, format_string, ...) - category LOGC_DT + +Convenience functions to support a category defined for a single file, for +example: + + #define LOG_CATEGORY UCLASS_USB + +all of these can use LOG_CATEGORY as the category, and a log level +corresponding to the function name: + + logc(level, format_string, ...) + pr_panic(format_string, ...) + pr_crit(format_string, ...) + pr_err(format_string, ...) + pr_warn(format_string, ...) + pr_note(format_string, ...) + pr_info(format_string, ...) + pr_detail(format_string, ...) + pr_debug(format_string, ...) + +More logging destinations: + + device - goes to a device (e.g. serial) + buffer - recorded in a memory buffer + +Convert debug() statements in the code to log() statements + +Support making printf() emit log statements a 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() + +Figure out what to do with assert() + +Add a way to browse log records + +Add a way to record log records for browsing using an external tool + +Add commands to add and remove filters + +Add commands to add and remove log devices + +Allow sharing of printf format strings in log records to reduce storage size +for large numbers of log records + +Add a command-line option to sandbox to set the default logging level + +Convert core driver model code to use logging + +Convert uclasses to use logging with the correct category + +Consider making log() calls emit an automatic newline, perhaps with a logn() + function to avoid that + +Passing log records through to linux (e.g. via device tree /chosen) + +Provide a command to access the number of log records generated, and the +number dropped due to them being generated before the log system was ready. + +Add a printf() format string pragma so that log statements are checked properly + +Enhance the log console driver to show level / category / file / line +information + +Add a command to add new log records and delete existing records. + +Provide additional log() functions - e.g. logc() to specify the category + +-- +Simon Glass sjg@chromium.org +15-Sep-17
On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass sjg@chromium.org wrote:
Add documentation for the log system.
Signed-off-by: Simon Glass sjg@chromium.org
doc/README.log | 220 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 220 insertions(+) create mode 100644 doc/README.log
Reviewed-by: Bin Meng bmeng.cn@gmail.com
Hi Simon
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+To Do +-----
+There are lots of useful additions that could be made. None of the below is +implemented! If you do one, please add a test in test/py/tests/test_log.py
+Convenience functions to support setting the category:
- log_arch(level, format_string, ...) - category LOGC_ARCH
- log_board(level, format_string, ...) - category LOGC_BOARD
- log_core(level, format_string, ...) - category LOGC_CORE
- log_dt(level, format_string, ...) - category LOGC_DT
I do not want to see any more proliferation of log functions...
+Convenience functions to support a category defined for a single file, for +example:
- #define LOG_CATEGORY UCLASS_USB
+all of these can use LOG_CATEGORY as the category, and a log level +corresponding to the function name:
- logc(level, format_string, ...)
- pr_panic(format_string, ...)
- pr_crit(format_string, ...)
- pr_err(format_string, ...)
- pr_warn(format_string, ...)
- pr_note(format_string, ...)
- pr_info(format_string, ...)
- pr_detail(format_string, ...)
- pr_debug(format_string, ...)
Linux uses:
pr_emerg(fmt, ...) pr_alert(fmt, ...) pr_crit(fmt, ...) pr_err(fmt, ...) pr_warn(fmt, ...) pr_notice(fmt, ...) pr_info(fmt, ...) pr_debug(fmt, ...)
Please do not invent similar, but different APIs.
Hi Masahiro,
On 19 September 2017 at 21:04, Masahiro Yamada yamada.masahiro@socionext.com wrote:
Hi Simon
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
+To Do +-----
+There are lots of useful additions that could be made. None of the below is +implemented! If you do one, please add a test in test/py/tests/test_log.py
+Convenience functions to support setting the category:
- log_arch(level, format_string, ...) - category LOGC_ARCH
- log_board(level, format_string, ...) - category LOGC_BOARD
- log_core(level, format_string, ...) - category LOGC_CORE
- log_dt(level, format_string, ...) - category LOGC_DT
I do not want to see any more proliferation of log functions...
So just a function where you specify the category?
+Convenience functions to support a category defined for a single file, for +example:
- #define LOG_CATEGORY UCLASS_USB
+all of these can use LOG_CATEGORY as the category, and a log level +corresponding to the function name:
- logc(level, format_string, ...)
- pr_panic(format_string, ...)
- pr_crit(format_string, ...)
- pr_err(format_string, ...)
- pr_warn(format_string, ...)
- pr_note(format_string, ...)
- pr_info(format_string, ...)
- pr_detail(format_string, ...)
- pr_debug(format_string, ...)
Linux uses:
pr_emerg(fmt, ...) pr_alert(fmt, ...) pr_crit(fmt, ...) pr_err(fmt, ...) pr_warn(fmt, ...) pr_notice(fmt, ...) pr_info(fmt, ...) pr_debug(fmt, ...)
Please do not invent similar, but different APIs.
See my comment about log levels in the previous patch. I can keep these all the same but want to add at least one more detail level.
Regards, Simon
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
U-Boot currently has fairly rudimentary logging features. A basic printf() provides console output and debug() provides debug output which is activated if DEBUG is defined in the file containing the debug() statements.
It would be useful to have a few more features:
- control of debug output at runtime, so problems can potentially be
debugged without recompiling U-Boot
- control of which subsystems output debug information, so that (for
example) it is possible to enable debugging for MMC or SATA at runtime
- indication of severity with each message, so that the user can control
whether just errors are displayed, warnings, or all debug messages
- sending logging information to different destinations, such as console,
memory, linux, etc,
At present U-Boot has a logbuffer feature which records output in a memory buffer for later display or storage. This is useful but is not at present enabled for any board.
This series introduced a new logging system which supports:
- various log levels from panic to debug
- log categories including all uclasses and a few others
- log drivers to which all log records can be sent
- log filters which control which log records make it to which drivers
Enabling logging with the default options does not add much to code size. By default the maximum recorded log level is LOGL_INFO, meaning that debug messages (and above) are discarded a build-time. Increasing this level provides more run-time flexibility to enable/disable logging at the cost of increased code size.
This feature is by no means finished. The README provides a long list of features and clean-ups that could be done. But hopefully this is a starting point for improving this important area in U-Boot.
The series is available at u-boot-dm/log-working
As you notice, this series has lots of conflicts with my clean-up works.
The lesson we leaned is we should prepare Linux-compatible APIs where possible, instead of inventing similar ones for our own. Otherwise, people would start to sprinkle compat macros/headers everywhere.
In this sense, this series introduce similar, but different interfaces.
If you want the log interface, could you implement it as a back-end of printk() (after my clean-ups) ? Users can use printk(), or more preferably pr_() to call the log API.
If CONFIG_LOG is disabled, printk() falls back to printf(), i.e. the log is immediately printed to the console.
If CONFIG_LOG is enabled, printk() sends the log message to the log facility you are implementing.
I am not sure how much demand exists for category/file filters. Having both of them (or even one of them) might be over-implementation.
I do not like the category filter because I do not want to see log(LOGC_BOARD, ...)
On 09/20/2017 04:32 AM, Masahiro Yamada wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
U-Boot currently has fairly rudimentary logging features. A basic printf() provides console output and debug() provides debug output which is activated if DEBUG is defined in the file containing the debug() statements.
It would be useful to have a few more features:
- control of debug output at runtime, so problems can potentially be
debugged without recompiling U-Boot
- control of which subsystems output debug information, so that (for
example) it is possible to enable debugging for MMC or SATA at runtime
- indication of severity with each message, so that the user can control
whether just errors are displayed, warnings, or all debug messages
- sending logging information to different destinations, such as console,
memory, linux, etc,
At present U-Boot has a logbuffer feature which records output in a memory buffer for later display or storage. This is useful but is not at present enabled for any board.
This series introduced a new logging system which supports:
- various log levels from panic to debug
- log categories including all uclasses and a few others
- log drivers to which all log records can be sent
- log filters which control which log records make it to which drivers
Enabling logging with the default options does not add much to code size. By default the maximum recorded log level is LOGL_INFO, meaning that debug messages (and above) are discarded a build-time. Increasing this level provides more run-time flexibility to enable/disable logging at the cost of increased code size.
This feature is by no means finished. The README provides a long list of features and clean-ups that could be done. But hopefully this is a starting point for improving this important area in U-Boot.
The series is available at u-boot-dm/log-working
As you notice, this series has lots of conflicts with my clean-up works.
The lesson we leaned is we should prepare Linux-compatible APIs where possible, instead of inventing similar ones for our own. Otherwise, people would start to sprinkle compat macros/headers everywhere.
In this sense, this series introduce similar, but different interfaces.
If you want the log interface, could you implement it as a back-end of printk() (after my clean-ups) ? Users can use printk(), or more preferably pr_() to call the log API.
If CONFIG_LOG is disabled, printk() falls back to printf(), i.e. the log is immediately printed to the console.
If CONFIG_LOG is enabled, printk() sends the log message to the log facility you are implementing.
I am not sure how much demand exists for category/file filters. Having both of them (or even one of them) might be over-implementation.
I do not like the category filter because I do not want to see log(LOGC_BOARD, ...)
Filtering by category is a good idea. I have been developing parts of the EFI API implementation. There it showed up to be a necessity to disable debug output for events (occuring dozens of times per millisecond). Network services will fail if timeouts occur due to too many log message passed over a slow serial console.
As fine grained control is currently missing I had to spray #undefine _DEBUG #define _DEBUG 0 ... #define _DEBUG 1 all over the code.
Other codes (e.g. iPXE) can enable debugging per module with different verbosity levels, cf. http://ipxe.org/download#debug_builds .
Regards
Heinrich
Hi Heinrich,
On 20 September 2017 at 14:20, Heinrich Schuchardt xypron.glpk@gmx.de wrote:
On 09/20/2017 04:32 AM, Masahiro Yamada wrote:
Hi Simon,
2017-09-17 6:23 GMT+09:00 Simon Glass sjg@chromium.org:
U-Boot currently has fairly rudimentary logging features. A basic printf() provides console output and debug() provides debug output which is activated if DEBUG is defined in the file containing the debug() statements.
It would be useful to have a few more features:
- control of debug output at runtime, so problems can potentially be
debugged without recompiling U-Boot
- control of which subsystems output debug information, so that (for
example) it is possible to enable debugging for MMC or SATA at runtime
- indication of severity with each message, so that the user can control
whether just errors are displayed, warnings, or all debug messages
- sending logging information to different destinations, such as console,
memory, linux, etc,
At present U-Boot has a logbuffer feature which records output in a memory buffer for later display or storage. This is useful but is not at present enabled for any board.
This series introduced a new logging system which supports:
- various log levels from panic to debug
- log categories including all uclasses and a few others
- log drivers to which all log records can be sent
- log filters which control which log records make it to which drivers
Enabling logging with the default options does not add much to code size. By default the maximum recorded log level is LOGL_INFO, meaning that debug messages (and above) are discarded a build-time. Increasing this level provides more run-time flexibility to enable/disable logging at the cost of increased code size.
This feature is by no means finished. The README provides a long list of features and clean-ups that could be done. But hopefully this is a starting point for improving this important area in U-Boot.
The series is available at u-boot-dm/log-working
As you notice, this series has lots of conflicts with my clean-up works.
The lesson we leaned is we should prepare Linux-compatible APIs where possible, instead of inventing similar ones for our own. Otherwise, people would start to sprinkle compat macros/headers everywhere.
In this sense, this series introduce similar, but different interfaces.
If you want the log interface, could you implement it as a back-end of printk() (after my clean-ups) ? Users can use printk(), or more preferably pr_() to call the log API.
If CONFIG_LOG is disabled, printk() falls back to printf(), i.e. the log is immediately printed to the console.
If CONFIG_LOG is enabled, printk() sends the log message to the log facility you are implementing.
I am not sure how much demand exists for category/file filters. Having both of them (or even one of them) might be over-implementation.
I do not like the category filter because I do not want to see log(LOGC_BOARD, ...)
Filtering by category is a good idea. I have been developing parts of the EFI API implementation. There it showed up to be a necessity to disable debug output for events (occuring dozens of times per millisecond). Network services will fail if timeouts occur due to too many log message passed over a slow serial console.
As fine grained control is currently missing I had to spray #undefine _DEBUG #define _DEBUG 0 ... #define _DEBUG 1 all over the code.
Other codes (e.g. iPXE) can enable debugging per module with different verbosity levels, cf. http://ipxe.org/download#debug_builds .
Actually I quite like those levels:
- Enable basic debug messages - Enable verbose debug messages (e.g. one message per event) - Enable extra-verbose debug messages (e.g. one message per byte) - Enable I/O tracing (e.g. one message per readl()/writel() call)
This seems a lot better than having just a 'debug' level.
Regards, Simon
Dear Simon,
sorry for jumping in so late...
In message 20170916212331.170463-1-sjg@chromium.org you wrote:
At present U-Boot has a logbuffer feature which records output in a memory buffer for later display or storage. This is useful but is not at present enabled for any board.
Background explanation: When this was implemented, the buffer handling was fully compatible with the Linux kernel logbuffer. And U-Boot was able to reserve memory (at the top of the RAM) that could be shared between U-Boot and Linux, so you could for example write U-Boot POST results into the log buffer, and read it using standard syslog tools in Linux. Or keep the panic messages of the previous crash and read it after reboot.
IIRC this was in production use only on Power architectre systems, and it broke (and nover got fixed) when the Linux log buffer was reworked.
This series introduced a new logging system which supports:
- various log levels from panic to debug
- log categories including all uclasses and a few others
- log drivers to which all log records can be sent
- log filters which control which log records make it to which drivers
You don't mention it here, but would it be possible to keep compatibility with the Linux logbuffer implementation in mind?
So we could re-implement this shared logbuffer thingy in case someone finds it useful?
Thanks!
Best regards,
Wolfgang Denk
Hi Wolfgang,
On 20 September 2017 at 13:55, Wolfgang Denk wd@denx.de wrote:
Dear Simon,
sorry for jumping in so late...
In message 20170916212331.170463-1-sjg@chromium.org you wrote:
At present U-Boot has a logbuffer feature which records output in a memory buffer for later display or storage. This is useful but is not at present enabled for any board.
Background explanation: When this was implemented, the buffer handling was fully compatible with the Linux kernel logbuffer. And U-Boot was able to reserve memory (at the top of the RAM) that could be shared between U-Boot and Linux, so you could for example write U-Boot POST results into the log buffer, and read it using standard syslog tools in Linux. Or keep the panic messages of the previous crash and read it after reboot.
IIRC this was in production use only on Power architectre systems, and it broke (and nover got fixed) when the Linux log buffer was reworked.
OK I see, i did not realise the Linux connection.
This series introduced a new logging system which supports:
- various log levels from panic to debug
- log categories including all uclasses and a few others
- log drivers to which all log records can be sent
- log filters which control which log records make it to which drivers
You don't mention it here, but would it be possible to keep compatibility with the Linux logbuffer implementation in mind?
So we could re-implement this shared logbuffer thingy in case someone finds it useful?
I think it would be fairly easy to do, yes. It just needs a driver which writes log records into memory at a given address. I certainly don't like removing useful features, will take a look.
Regards, Simon
participants (6)
-
Bin Meng -
Dr. Philipp Tomsich -
Heinrich Schuchardt -
Masahiro Yamada -
Simon Glass -
Wolfgang Denk