[U-Boot] [PATCH 00/13] log: Add a new logging feature

[U-Boot] [PATCH 00/13] log: Add a new logging feature

[Simon Glass]

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

-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 01/13] Revert "sandbox: remove os_putc() and os_puts()"

[Simon Glass]

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
  *
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 02/13] Revert "sandbox: Drop special case console code for sandbox"

[Simon Glass]

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
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 03/13] Move debug and logging support to a separate header

[Simon Glass]

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
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 04/13] mtdparts: Correct use of debug()

[Simon Glass]

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;
 
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 05/13] Drop the log buffer

[Simon Glass]

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 at 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  @ %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 at 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 at 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
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass]

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
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 07/13] log: Add a console driver

[Simon Glass]

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,
+};
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 08/13] log: Add a 'log level' command

[Simon Glass]

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
+);
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 09/13] log: Add a test command

[Simon Glass]

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
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 10/13] log: Plumb logging into the init sequence

[Simon Glass]

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 */
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 11/13] log: sandbox: Enable logging

[Simon Glass]

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
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 12/13] log: test: Add a pytest for logging

[Simon Glass]

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 at chromium.org): Consider structuring this as separate tests
+    cons = u_boot_console
+    test0()
+    test1()
+    test2()
+    test3()
+    test4()
+    test5()
+    test6()
+    test7()
+    test8()
+    test9()
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 13/13] log: Add documentation

[Simon Glass]

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
-- 
2.14.1.690.gbb1197296e-goog

[U-Boot] [PATCH 01/13] Revert "sandbox: remove os_putc() and os_puts()"

[Bin Meng]

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

[U-Boot] [PATCH 02/13] Revert "sandbox: Drop special case console code for sandbox"

[Bin Meng]

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

[U-Boot] [PATCH 03/13] Move debug and logging support to a separate header

[Bin Meng]

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>

[U-Boot] [PATCH 04/13] mtdparts: Correct use of debug()

[Bin Meng]

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>

[U-Boot] [PATCH 05/13] Drop the log buffer

[Bin Meng]

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>

[U-Boot] [PATCH 01/13] Revert "sandbox: remove os_putc() and os_puts()"

[Simon Glass]

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

[U-Boot] [PATCH 02/13] Revert "sandbox: Drop special case console code for sandbox"

[Simon Glass]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Bin Meng]

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"
> +       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;

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

[U-Boot] [PATCH 07/13] log: Add a console driver

[Bin Meng]

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

[U-Boot] [PATCH 08/13] log: Add a 'log level' command

[Bin Meng]

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>

[U-Boot] [PATCH 09/13] log: Add a test command

[Bin Meng]

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 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, "", ""),

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 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
> --

Regards,
Bin

[U-Boot] [PATCH 10/13] log: Plumb logging into the init sequence

[Bin Meng]

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>

[U-Boot] [PATCH 11/13] log: sandbox: Enable logging

[Bin Meng]

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>

[U-Boot] [PATCH 13/13] log: Add documentation

[Bin Meng]

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>

[U-Boot] [PATCH 00/13] log: Add a new logging feature

[Masahiro Yamada]

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, ...)




-- 
Best Regards
Masahiro Yamada

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Masahiro Yamada]

Hi Simon,


2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>:

>
> +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.


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 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


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_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
>


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.










-- 
Best Regards
Masahiro Yamada

[U-Boot] [PATCH 13/13] log: Add documentation

[Masahiro Yamada]

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.



-- 
Best Regards
Masahiro Yamada

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass]

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"
>> +       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.
>
>
> 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 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
>
>
> 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

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_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
>>
>
>
> 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)

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] [PATCH 13/13] log: Add documentation

[Simon Glass]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Dr. Philipp Tomsich]

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"
>>> +       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.
>> 
>> 
>> 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 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
>> 
>> 
>> 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
> 
> 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?

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_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
>>> 
>> 
>> 
>> 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)
> 
> 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 at lists.denx.de
> https://lists.denx.de/listinfo/u-boot

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Bin Meng]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Dr. Philipp Tomsich]

> 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.

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Masahiro Yamada]

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"
>>> +       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.
>>
>>
>> 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 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
>>
>>
>> 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
>
> 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?


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.




-- 
Best Regards
Masahiro Yamada

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Masahiro Yamada]

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"
>>>> +       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.
>>>
>>>
>>> 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 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
>>>
>>>
>>> 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
>>
>> 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?
>
> 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.




-- 
Best Regards
Masahiro Yamada

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Dr. Philipp Tomsich]

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"
>>>>> +       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.
>>>> 
>>>> 
>>>> 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.

[U-Boot] [PATCH 00/13] log: Add a new logging feature

[Wolfgang Denk]

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

-- 
DENX Software Engineering GmbH,      Managing Director: Wolfgang Denk
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de
The only thing necessary for the triumph of evil is for good  men  to
do nothing.                                            - Edmund Burke

[U-Boot] [PATCH 00/13] log: Add a new logging feature

[Heinrich Schuchardt]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass]

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

[U-Boot] [PATCH 00/13] log: Add a new logging feature

[Simon Glass]

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

[U-Boot] [PATCH 00/13] log: Add a new logging feature

[Simon Glass]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Bin Meng]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass]

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

[U-Boot] [PATCH 07/13] log: Add a console driver

[Simon Glass]

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass]

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"
>>>> +       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.
>>>
>>>
>>> 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 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
>>>
>>>
>>> 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
>>
>> 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?
>
>
> 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.

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

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Masahiro Yamada]

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"
>>>>>> +       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.
>>>>>
>>>>>
>>>>> 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.






-- 
Best Regards
Masahiro Yamada

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Masahiro Yamada]

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"
>>>>> +       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.
>>>>
>>>>
>>>> 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 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
>>>>
>>>>
>>>> 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
>>>
>>> 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?
>>
>>
>> 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.
>
> 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.




-- 
Best Regards
Masahiro Yamada

[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass]

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"
>>>>>> +       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.
>>>>>
>>>>>
>>>>> 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 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
>>>>>
>>>>>
>>>>> 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
>>>>
>>>> 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?
>>>
>>>
>>> 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.
>>
>> 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