log: Add a new logging feature

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 <[email protected]>

---

 arch/sandbox/cpu/os.c | 11 +++++++++++
 include/os.h          | 20 ++++++++++++++++++++
 2 files changed, 31 insertions(+)

Hi Simon,

Quoted 5 lines · 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.

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.

Quoted 11 lines

For ease of debugging it seems better to revert this change.

This reverts commit 47b98ad0f6779485d0f0c14f337c3eece273eb54.

Signed-off-by Simon Glass <[email protected]>

---

 arch/sandbox/cpu/os.c | 11 +++++++++++
 include/os.h          | 20 ++++++++++++++++++++
 2 files changed, 31 insertions(+)

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 <[email protected]>

---

 common/console.c          | 7 +++++++
 configs/sandbox_defconfig | 2 +-
 2 files changed, 8 insertions(+), 1 deletion(-)

common/console.c +7 -0

index f83528ca60..18457aab3c 100644
@@ -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)) {

configs/sandbox_defconfig +0 -0

index e7a61bd61a..88ae98d312 100644

Hi Simon,

Quoted 39 lines · 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 <[email protected]>

---

 common/console.c          | 7 +++++++
 configs/sandbox_defconfig | 2 +-
 2 files changed, 8 insertions(+), 1 deletion(-)

common/console.c +7 -0

index f83528ca60..18457aab3c 100644
@@ -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)) {

configs/sandbox_defconfig +0 -0

index e7a61bd61a..88ae98d312 100644
@@ -16,7 +16,7 @@ CONFIG_CONSOLE_RECORD=y

configs/sandbox_defconfig CONFIG_CONSOLE_RECORD=y · line 19

Quoted 5 lines

configs/sandbox_defconfig +1 -1

 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?

configs/sandbox_defconfig CONFIG_CONSOLE_RECORD=y

Quoted 4 lines

configs/sandbox_defconfig +0 -1

 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()?

Before adding new features, move these definitions to a separate header to avoid further cluttering common.h.

Signed-off-by Simon Glass <[email protected]>

---

 include/common.h | 64 +--------------------------------------------
 include/log.h    | 79 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 80 insertions(+), 63 deletions(-)
 create mode 100644 include/log.h

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 <[email protected]>

---

 cmd/mtdparts.c | 3 ---
 1 file changed, 3 deletions(-)

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 <[email protected]>

---

 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

Add the logging header file and implementation with some configuration options to control it.

Signed-off-by Simon Glass <[email protected]>

---

 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

MAINTAINERS +0 -0

index 04acf2b89d..eb420afa8d 100644
@@ -290,6 +290,15 @@ S: Maintained
 T:     git git://git.denx.de/u-boot-i2c.git

MAINTAINERS +1 -0

+
 MICROBLAZE
 M:     Michal Simek <[email protected]>
 S:     Maintained

common/Kconfig +56 -0

index 4d8cae9610..cbccc8ae26 100644
@@ -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

common/Makefile +1 -0

index 1b56cf9a70..d37c8d5636 100644
@@ -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

common/log.c new file +233 -0

new file mode 100644
index 0000000000..6bf2219d38
@@ -0,0 +1,246 @@
+/*
+ * Logging support
+ *
+ * Copyright (c) 2017 Google, Inc
+ * Written by Simon Glass <[email protected]>
+ *
+ * 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__);

common/log.c new file +3 -0

+
+       return 0;
+}

include/asm-generic/global_data.h +5 -0

index 79197acfa4..77755dbb06 100644
@@ -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
 

include/log.h +130 -9

index 4101a74161..fb6a196202 100644
@@ -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 {

include/log.h +90 -0

+/**
+ * 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
+ */

Hi Simon,

Quoted 23 lines · Simon Glass

Add the logging header file and implementation with some configuration options to control it.

Signed-off-by Simon Glass <[email protected]>

---

 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

MAINTAINERS +0 -0

index 04acf2b89d..eb420afa8d 100644
@@ -290,6 +290,15 @@ S: Maintained
 T:     git git://git.denx.de/u-boot-i2c.git
 F:     drivers/i2c/
 

MAINTAINERS S: Maintained · line 300

Quoted 8 lines

MAINTAINERS +8 -0

+LOGGING
+M:     Simon Glass <[email protected]>
+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.

Quoted 12 lines

MAINTAINERS +12 -0

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

MAINTAINERS

Quoted 4 lines

MAINTAINERS +4 -0

+        */
+       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?)

Hi Bin,

Quoted 26 lines · Bin Meng

Hi Simon,

Quoted 23 lines · Simon Glass

Add the logging header file and implementation with some configuration options to control it.

Signed-off-by Simon Glass <[email protected]>

---

 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

MAINTAINERS +0 -0

index 04acf2b89d..eb420afa8d 100644
@@ -290,6 +290,15 @@ S: Maintained
 T:     git git://git.denx.de/u-boot-i2c.git
 F:     drivers/i2c/
 

Quoted 11 lines

MAINTAINERS S: Maintained · line 300

Quoted 8 lines

MAINTAINERS +8 -0

+LOGGING
+M:     Simon Glass <[email protected]>
+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,
[..]

Quoted 12 lines

Quoted 12 lines

MAINTAINERS +12 -0

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

Quoted 8 lines

MAINTAINERS

Quoted 4 lines

MAINTAINERS +4 -0

+        */
+       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?

Hi Simon,

Quoted 65 lines · Simon Glass

Hi Bin,

Quoted 26 lines · Bin Meng

Hi Simon,

Quoted 23 lines · Simon Glass

Add the logging header file and implementation with some configuration options to control it.

Signed-off-by Simon Glass <[email protected]>

---

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

MAINTAINERS +0 -0

index 04acf2b89d..eb420afa8d 100644
@@ -290,6 +290,15 @@ S: Maintained

T:     git git://git.denx.de/u-boot-i2c.git
F:     drivers/i2c/

Quoted 11 lines

MAINTAINERS S: Maintained · line 300

Quoted 8 lines

MAINTAINERS +8 -0

+LOGGING
+M:     Simon Glass <[email protected]>
+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,
[..]

Quoted 12 lines

Quoted 12 lines

MAINTAINERS +12 -0

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

Quoted 8 lines

MAINTAINERS

Quoted 4 lines

MAINTAINERS +4 -0

+        */
+       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?)

Quoted 5 lines

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.

Hi Simon,

Quoted 65 lines · Simon Glass

Hi Bin,

Quoted 26 lines · Bin Meng

Hi Simon,

Quoted 23 lines · Simon Glass

Add the logging header file and implementation with some configuration options to control it.

Signed-off-by Simon Glass <[email protected]>

---

 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

MAINTAINERS +0 -0

index 04acf2b89d..eb420afa8d 100644
@@ -290,6 +290,15 @@ S: Maintained
 T:     git git://git.denx.de/u-boot-i2c.git
 F:     drivers/i2c/
 

Quoted 11 lines

MAINTAINERS S: Maintained · line 300

Quoted 8 lines

MAINTAINERS +8 -0

+LOGGING
+M:     Simon Glass <[email protected]>
+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,
[..]

Quoted 12 lines

Quoted 12 lines

MAINTAINERS +12 -0

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

Quoted 8 lines

MAINTAINERS

Quoted 4 lines

MAINTAINERS +4 -0

+        */
+       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?)

Quoted 5 lines

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.

Hi Bin,

Quoted 81 lines · Bin Meng

Hi Simon,

Quoted 65 lines · Simon Glass

Hi Bin,

Quoted 26 lines · Bin Meng

Hi Simon,

Quoted 23 lines · Simon Glass

Add the logging header file and implementation with some configuration options to control it.

Signed-off-by Simon Glass <[email protected]>

---

 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

MAINTAINERS +0 -0

index 04acf2b89d..eb420afa8d 100644
@@ -290,6 +290,15 @@ S: Maintained
 T:     git git://git.denx.de/u-boot-i2c.git
 F:     drivers/i2c/
 

Quoted 11 lines

MAINTAINERS S: Maintained · line 300

Quoted 8 lines

MAINTAINERS +8 -0

+LOGGING
+M:     Simon Glass <[email protected]>
+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,
[..]

Quoted 12 lines

Quoted 12 lines

MAINTAINERS +12 -0

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

Quoted 8 lines

MAINTAINERS

Quoted 4 lines

MAINTAINERS +4 -0

+        */
+       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?)

Quoted 5 lines

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

Quoted 2 lines

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?

Hi Simon,

Quoted 87 lines · Simon Glass

Hi Bin,

Quoted 83 lines · Bin Meng

Hi Simon,

Quoted 65 lines · Simon Glass

Hi Bin,

Quoted 26 lines · Bin Meng

Hi Simon,

Quoted 23 lines · Simon Glass

Add the logging header file and implementation with some configuration options to control it.

Signed-off-by Simon Glass <[email protected]>

---

 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

MAINTAINERS +0 -0

index 04acf2b89d..eb420afa8d 100644
@@ -290,6 +290,15 @@ S: Maintained
 T:     git git://git.denx.de/u-boot-i2c.git
 F:     drivers/i2c/
 

Quoted 11 lines

MAINTAINERS S: Maintained · line 300

Quoted 8 lines

MAINTAINERS +8 -0

+LOGGING
+M:     Simon Glass <[email protected]>
+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,
[..]

Quoted 12 lines

Quoted 12 lines

MAINTAINERS +12 -0

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

Quoted 8 lines

MAINTAINERS

Quoted 4 lines

MAINTAINERS +4 -0

+        */
+       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?)

Quoted 5 lines

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.

Quoted 3 lines

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.

common/Kconfig +7 -0

+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

common/Kconfig +7 -0

+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

common/Kconfig +7 -0

+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

common/log.c new file +99 -0

+
+/**
+ * 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) {

common/log.c new file +11 -0

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

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 11 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 421

Quoted 10 lines

common/Kconfig +10 -0

+         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

Quoted 19 lines

common/Kconfig +15 -0

+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

Review

Quoted 3 lines

(quoted diff) +2 -0

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

Quoted 108 lines

common/log.c new file +108 -0

+
+/**
+ * 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;

Quoted 1 line

+}

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.

Quoted 18 lines

common/log.c new file +15 -0

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

common/log.c line 236

Quoted 6 lines

common/log.c new file +6 -0

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

common/log.c line 240

Quoted 7 lines

common/log.c new file +4 -0

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

include/log.h line 78

Quoted 10 lines

include/log.h +5 -0

+#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?

include/log.h line 87

Quoted 8 lines

include/log.h +8 -0

+/* Emit a log record if the level is less that the maximum */
+#define log(_cat, _level, _fmt, _args...) ({ \
+       int _l = _level; \
+       if (_l > _LOG_MAX_LEVEL) \
+               continue; \
+       _log(_cat, _l, __FILE__, __LINE__, __func__, \
+            pr_fmt(_fmt), ##_args); \
+       })

This is neither while() nor for().
The bare use of "continue" made me really surprised.

Hi Masahiro,

Quoted 27 lines · Masahiro Yamada

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

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.

Quoted 27 lines

Quoted 12 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 421

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

                       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?

Quoted 20 lines

Quoted 20 lines

common/Kconfig +15 -0

+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

Quoted 8 lines

Review

Quoted 3 lines

(quoted diff) +2 -0

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

Quoted 114 lines

Again, you will probably end up with TPL_LOG_MAX_LEVEL.

Quoted 108 lines

common/log.c new file +108 -0

+
+/**
+ * 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;

Quoted 8 lines

Quoted 1 line

+}

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

Quoted 18 lines

Quoted 18 lines

common/log.c new file +15 -0

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

Quoted 8 lines

common/log.c line 236

Quoted 6 lines

common/log.c new file +6 -0

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

Quoted 8 lines

common/log.c line 240

Quoted 7 lines

common/log.c new file +4 -0

+               INIT_LIST_HEAD(&ldev->filter_head);
+               ldev->drv = drv;
+               list_add_tail(&ldev->sibling_node,
+                             (struct list_head *)&gd->log_head);

Quoted 4 lines

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.

Quoted 24 lines

include/log.h line 78

Quoted 10 lines

include/log.h +5 -0

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

Quoted 7 lines

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.

Quoted 8 lines

Quoted 12 lines

include/log.h line 87

Quoted 8 lines

include/log.h +8 -0

+/* 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

Masahiro & Simon,

Quoted 42 lines · Simon Glass

Hi Masahiro,

Quoted 27 lines · Masahiro Yamada

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

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.

Quoted 7 lines

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

Quoted 43 lines

Quoted 26 lines

Quoted 11 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 421

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

                       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.

Quoted 3 lines

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

2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich
<[email protected]>:

Quoted 52 lines

Masahiro & Simon,

Quoted 42 lines · Simon Glass

Hi Masahiro,

Quoted 27 lines · Masahiro Yamada

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

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.

Quoted 7 lines

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.

Quoted 7 lines

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?

Masahiro,

Quoted 70 lines · Masahiro Yamada

2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich
<[email protected]>:

Quoted 52 lines

Masahiro & Simon,

Quoted 42 lines · Simon Glass

Hi Masahiro,

Quoted 27 lines · Masahiro Yamada

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

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.

Quoted 7 lines

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.

Quoted 7 lines

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.

Quoted 2 lines

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

Hi Masahiro,

Quoted 27 lines · Masahiro Yamada

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

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.

Quoted 26 lines

Quoted 11 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 421

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

                        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?

Quoted 112 lines

Quoted 112 lines

common/log.c new file +108 -0

+
+/**
+ * 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;

Quoted 8 lines

Quoted 1 line

+}

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

Quoted 18 lines

Quoted 18 lines

common/log.c new file +15 -0

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

Quoted 8 lines

common/log.c line 236

Quoted 6 lines

common/log.c new file +6 -0

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

Quoted 7 lines

common/log.c line 240

Quoted 7 lines

common/log.c new file +4 -0

+               INIT_LIST_HEAD(&ldev->filter_head);
+               ldev->drv = drv;
+               list_add_tail(&ldev->sibling_node,
+                             (struct list_head *)&gd->log_head);

Quoted 4 lines

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.

Quoted 27 lines

include/log.h line 78

Quoted 10 lines

include/log.h +5 -0

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

Quoted 4 lines

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.

Hi Simon,

2017-09-20 22:49 GMT+09:00 Simon Glass <[email protected]>:

Quoted 40 lines

Hi Masahiro,

Quoted 27 lines · Masahiro Yamada

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

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.

Quoted 7 lines

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.

Quoted 43 lines

Quoted 26 lines

Quoted 11 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 421

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

                        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.

Quoted 3 lines

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.

Quoted 126 lines

Quoted 125 lines

Quoted 108 lines

common/log.c new file +99 -0

+
+/**
+ * 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) {

common/log.c line 214

Quoted 10 lines

common/log.c new file +10 -0

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

Quoted 5 lines

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.

Quoted 6 lines

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.

Quoted 29 lines

Quoted 20 lines

Quoted 20 lines

common/log.c new file +15 -0

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

Quoted 8 lines

common/log.c line 236

Quoted 6 lines

common/log.c new file +6 -0

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

Quoted 1 line

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.

Quoted 10 lines

Quoted 10 lines

common/log.c line 240

Quoted 10 lines

common/log.c new file +4 -0

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

Quoted 5 lines

Quoted 4 lines

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

Quoted 5 lines

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.

Quoted 29 lines

Quoted 29 lines

include/log.h line 78

Quoted 12 lines

include/log.h +5 -0

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

Quoted 7 lines

Quoted 4 lines

If the log level is 0 (= critial), the conditional is false, so _LOG_MAX_LEVEL is set to "info" level.

Why is this #if necessary?

If we don't have CONFIG_LOG enabled then this value will not exist.

This implementation is wrong.

You are abusing the fact that
U-Boot does not specify -Wundef option.

--------------------->8-----------------
-Wundef
Warn if an undefined identifier is evaluated in an #if directive.
Such identifiers are replaced with zero.
--------------------->8-----------------

Right, U-Boot does not give -Wundef,
but it is just because -Wundef causes too many warnings.

Ideally, we should fix the code,
then enable the option like Linux.

We should use #ifdef for testing a option that may or may not be defined. Using #if for options that may not be defined is a bad coding way.

Hi Masahiro,

Quoted 106 lines · Masahiro Yamada

Hi Simon,

2017-09-20 22:49 GMT+09:00 Simon Glass <[email protected]>:

Quoted 40 lines

Hi Masahiro,

Quoted 27 lines · Masahiro Yamada

Hi Simon,

2017-09-17 6:23 GMT+09:00 Simon Glass <[email protected]>:

Quoted 8 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 403

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

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.

Quoted 7 lines

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.

Quoted 43 lines

Quoted 26 lines

Quoted 11 lines

common/Kconfig +7 -0

+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

common/Kconfig config SYS_STDIO_DEREGISTER · line 421

Quoted 10 lines

common/Kconfig +10 -0

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

Quoted 8 lines

                        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.

Quoted 3 lines

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.

Quoted 7 lines

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.

Quoted 5 lines

BTW, what do you mean "INFO is what I plan to use for normal printf() output"