[U-Boot] [PATCH v2 00/14] 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
Changes in v2: - Add a comment as to why CONFIG_LOG_MAX_LEVEL is not defined - Change log levels to match new header - Change sandbox log level to 6 - Drop MAINTAINERS entries for files not added by this patch - Drop the special log() functions from the README - Drop the use of 'continue' in the macro - Fix LOG_SPL_MAX_LEVEL typo (should be SPL_LOG_MAX_LEVEL) - Fix function called when test command is selected - Fix help output for 'log test' - Fix up bad use of #if CONFIG_VAL() - use #ifdef instead - Line up log levels with Linux - Only execute log tests if CONFIG_LOG is enabled - Rename LOGL_WARN to LOGL_WARNING - Split pre-console address change into a separate patch - Update commit message to explain that this is not just for serial output
Simon Glass (14): Revert "sandbox: remove os_putc() and os_puts()" sandbox: Adjust pre-console address to avoid conflict 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 | 245 ++++++++++++++++++++++++++++ common/log_console.c | 23 +++ common/stdio.c | 6 - configs/sandbox_defconfig | 5 +- doc/README.log | 214 +++++++++++++++++++++++++ include/asm-generic/global_data.h | 8 +- include/common.h | 64 +------- include/log.h | 316 ++++++++++++++++++++++++++++++++++++ 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 | 107 +++++++++++++ 30 files changed, 1320 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 ---
Changes in v2: None
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 *
We cannot use sandbox memory at 0 since other things use memory at that address. Move it up out of the way.
Note that the pre-console buffer is currently disabled with sandbox, but this change will avoid confusion if it is manually enabled.
Signed-off-by: Simon Glass sjg@chromium.org ---
Changes in v2: - Split pre-console address change into a separate patch
configs/sandbox_defconfig | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index 310b8acc29..93ea6889a0 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -15,7 +15,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
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 ---
Changes in v2: None
common/console.c | 7 +++++++ 1 file changed, 7 insertions(+)
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)) {
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 Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: None
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
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 Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: None
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;
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 Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: None
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 9220815441..1e8bf63ec1 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
Add the logging header file and implementation with some configuration options to control it.
Signed-off-by: Simon Glass sjg@chromium.org ---
Changes in v2: - Add a comment as to why CONFIG_LOG_MAX_LEVEL is not defined - Drop MAINTAINERS entries for files not added by this patch - Drop the use of 'continue' in the macro - Fix LOG_SPL_MAX_LEVEL typo (should be SPL_LOG_MAX_LEVEL) - Fix up bad use of #if CONFIG_VAL() - use #ifdef instead - Line up log levels with Linux
MAINTAINERS | 7 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 244 ++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 252 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 556 insertions(+), 9 deletions(-) create mode 100644 common/log.c
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..3ef97783c0 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,13 @@ 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 + MICROBLAZE M: Michal Simek monstr@monstr.eu S: Maintained diff --git a/common/Kconfig b/common/Kconfig index 540cc9999b..ca4a0f7f9b 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -382,6 +382,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 SPL_LOG_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 801ea3191f..9d52c9623c 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..a7d9a548f2 --- /dev/null +++ b/common/log.c @@ -0,0 +1,244 @@ +/* + * 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++; + 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->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..9488adc8cb 100644 --- a/include/log.h +++ b/include/log.h @@ -10,6 +10,87 @@ #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_EMERG = 0, /*U-Boot is unstable */ + LOGL_ALERT, /* Action must be taken immediately */ + LOGL_CRIT, /* Critical conditions */ + LOGL_ERR, /* Error that prevents something from working */ + LOGL_WARNING, /* Warning may prevent optimial operation */ + LOGL_NOTICE, /* Normal but significant condition, printf() */ + LOGL_INFO, /* General information message */ + LOGL_DEBUG, /* Basic debug-level message */ + LOGL_DEBUG_CONTENT, /* Debug message showing full message content */ + LOGL_DEBUG_IO, /* Debug message showing hardware I/O access */ + + LOGL_COUNT, + LOGL_FIRST = LOGL_EMERG, + 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 + +/* + * This header may be including when CONFIG_LOG is disabled, in which case + * CONFIG_LOG_MAX_LEVEL is not defined. Add a check for this. + */ +#if CONFIG_IS_ENABLED(LOG) +#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) \ + _log(_cat, _l, __FILE__, __LINE__, __func__, \ + pr_fmt(_fmt), ##_args); \ + }) + #ifdef DEBUG #define _DEBUG 1 #else @@ -22,10 +103,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 +128,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 +158,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 +168,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
It is useful to display log messages on the console. Add a simple driver to handle this.
Note that this driver outputs to the console, which may be serial or video. It does not specifically select serial output.
Signed-off-by: Simon Glass sjg@chromium.org Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: - Update commit message to explain that this is not just for serial output
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 ca4a0f7f9b..7fed04a5fb 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -436,6 +436,26 @@ config SPL_LOG_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 9d52c9623c..6405a4c299 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, +};
Add a command for adjusting the log level.
Signed-off-by: Simon Glass sjg@chromium.org Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: None
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 +);
Add a command which exercises the logging system.
Signed-off-by: Simon Glass sjg@chromium.org ---
Changes in v2: - Fix function called when test command is selected - Fix help output for 'log test' - Rename LOGL_WARN to LOGL_WARNING
MAINTAINERS | 1 + 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 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 8 files changed, 234 insertions(+), 1 deletion(-) create mode 100644 test/log/Makefile create mode 100644 test/log/log_test.c
diff --git a/MAINTAINERS b/MAINTAINERS index 3ef97783c0..ca5224341e 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -296,6 +296,7 @@ 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
MICROBLAZE M: Michal Simek monstr@monstr.eu 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..abc523b497 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_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 + "log test - run log tests\n" +#endif ; #endif
diff --git a/common/Kconfig b/common/Kconfig index 7fed04a5fb..55d73ad71f 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -456,6 +456,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 9488adc8cb..7f2e84a68b 100644 --- a/include/log.h +++ b/include/log.h @@ -268,6 +268,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..29bfe772f2 --- /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_WARNING, 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_WARNING, 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
Set up logging both before and after relocation.
Signed-off-by: Simon Glass sjg@chromium.org Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: None
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 1e8bf63ec1..e46eceda7d 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); #ifdef CONFIG_TIMER gd->timer = NULL; #endif 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 a7d9a548f2..c94a3c1759 100644 --- a/common/log.c +++ b/common/log.c @@ -238,6 +238,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 */
Enable all logging features on sandbox so that the tests can be run.
Signed-off-by: Simon Glass sjg@chromium.org Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: - Change sandbox log level to 6
configs/sandbox_defconfig | 3 +++ 1 file changed, 3 insertions(+)
diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index 93ea6889a0..9637d7098c 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -16,6 +16,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=6 CONFIG_CMD_CPU=y CONFIG_CMD_LICENSE=y CONFIG_CMD_BOOTZ=y @@ -64,6 +66,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
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 ---
Changes in v2: - Change log levels to match new header - Only execute log tests if CONFIG_LOG is enabled - Rename LOGL_WARN to LOGL_WARNING
MAINTAINERS | 1 + test/py/tests/test_log.py | 107 ++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 108 insertions(+) create mode 100644 test/py/tests/test_log.py
diff --git a/MAINTAINERS b/MAINTAINERS index ca5224341e..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -297,6 +297,7 @@ 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 diff --git a/test/py/tests/test_log.py b/test/py/tests/test_log.py new file mode 100644 index 0000000000..bed040b4d7 --- /dev/null +++ b/test/py/tests/test_log.py @@ -0,0 +1,107 @@ +# 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_WARNING, LOGL_INFO = (0, 4, 6) + +@pytest.mark.buildconfigspec('log') +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_WARNING) + + 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 Reviewed-by: Bin Meng bmeng.cn@gmail.com ---
Changes in v2: - Drop the special log() functions from the README
doc/README.log | 214 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 214 insertions(+) create mode 100644 doc/README.log
diff --git a/doc/README.log b/doc/README.log new file mode 100644 index 0000000000..f653fe7d79 --- /dev/null +++ b/doc/README.log @@ -0,0 +1,214 @@ +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_EMERG - Printed before U-Boot halts + LOGL_ALERT - Indicates action must be taken immediate or U-Boot will crash + LOGL_CRIT - Indicates a critical error that will cause boot failure + LOGL_ERR - Indicates an error that may cause boot failure + LOGL_WARNING - Warning about an unexpected condition + LOGL_NOTE - Important information about progress + LOGL_INFO - Information about normal boot progress + LOGL_DEBUG - Debug information (useful for debugging a driver or subsystem) + LOGL_DEBUG_CONTENT - Debug message showing full message content + LOGL_DEBUG_IO - Debug message showing hardware I/O access + + +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, ...) + +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
participants (1)
-
Simon Glass