| Message ID | 20170916212331.170463-7-sjg@chromium.org |
|---|---|
| State | Superseded |
| Delegated to: | Simon Glass |
| Headers | show |
| Series | log: Add a new logging feature | expand |
Hi Simon, On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass <sjg@chromium.org> wrote: > Add the logging header file and implementation with some configuration > options to control it. > > Signed-off-by: Simon Glass <sjg@chromium.org> > --- > > MAINTAINERS | 9 ++ > common/Kconfig | 56 +++++++++ > common/Makefile | 1 + > common/log.c | 246 +++++++++++++++++++++++++++++++++++++ > include/asm-generic/global_data.h | 5 + > include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- > 6 files changed, 555 insertions(+), 9 deletions(-) > create mode 100644 common/log.c > > diff --git a/MAINTAINERS b/MAINTAINERS > index 04acf2b89d..eb420afa8d 100644 > --- a/MAINTAINERS > +++ b/MAINTAINERS > @@ -290,6 +290,15 @@ S: Maintained > T: git git://git.denx.de/u-boot-i2c.git > F: drivers/i2c/ > > +LOGGING > +M: Simon Glass <sjg@chromium.org> > +S: Maintained > +T: git git://git.denx.de/u-boot.git > +F: common/log.c > +F: cmd/log.c > +F: test/log/log_test.c > +F: test/py/tests/test_log.py test/log/log_test.c and test/py/tests/test_log.py have not been introduced at this point. > + > MICROBLAZE > M: Michal Simek <monstr@monstr.eu> > S: Maintained > diff --git a/common/Kconfig b/common/Kconfig > index 4d8cae9610..cbccc8ae26 100644 > --- a/common/Kconfig > +++ b/common/Kconfig > @@ -384,6 +384,62 @@ config SYS_STDIO_DEREGISTER > > endmenu > > +menu "Logging" > + > +config LOG > + bool "Enable logging support" > + help > + This enables support for logging of status and debug messages. These > + can be displayed on the console, recorded in a memory buffer, or > + discarded if not needed. Logging supports various categories and > + levels of severity. > + > +config SPL_LOG > + bool "Enable logging support in SPL" > + help > + This enables support for logging of status and debug messages. These > + can be displayed on the console, recorded in a memory buffer, or > + discarded if not needed. Logging supports various categories and > + levels of severity. > + > +config LOG_MAX_LEVEL > + int "Maximum log level to record" > + depends on LOG > + default 5 > + help > + This selects the maximum log level that will be recorded. Any value > + higher than this will be ignored. If possible log statements below > + this level will be discarded at build time. Levels: > + > + 0 - panic > + 1 - critical > + 2 - error > + 3 - warning > + 4 - note > + 5 - info > + 6 - detail > + 7 - debug > + > +config LOG_SPL_MAX_LEVEL > + int "Maximum log level to record in SPL" > + depends on SPL_LOG > + default 3 > + help > + This selects the maximum log level that will be recorded. Any value > + higher than this will be ignored. If possible log statements below > + this level will be discarded at build time. Levels: > + > + 0 - panic > + 1 - critical > + 2 - error > + 3 - warning > + 4 - note > + 5 - info > + 6 - detail > + 7 - debug > + > +endmenu > + > config DTB_RESELECT > bool "Support swapping dtbs at a later point in boot" > depends on FIT_EMBED > diff --git a/common/Makefile b/common/Makefile > index 1b56cf9a70..d37c8d5636 100644 > --- a/common/Makefile > +++ b/common/Makefile > @@ -128,5 +128,6 @@ obj-y += cli.o > obj-$(CONFIG_FSL_DDR_INTERACTIVE) += cli_simple.o cli_readline.o > obj-$(CONFIG_CMD_DFU) += dfu.o > obj-y += command.o > +obj-$(CONFIG_$(SPL_)LOG) += log.o > obj-y += s_record.o > obj-y += xyzModem.o > diff --git a/common/log.c b/common/log.c > new file mode 100644 > index 0000000000..6bf2219d38 > --- /dev/null > +++ b/common/log.c > @@ -0,0 +1,246 @@ > +/* > + * Logging support > + * > + * Copyright (c) 2017 Google, Inc > + * Written by Simon Glass <sjg@chromium.org> > + * > + * SPDX-License-Identifier: GPL-2.0+ > + */ > + > +#include <common.h> > +#include <log.h> > +#include <malloc.h> > + > +DECLARE_GLOBAL_DATA_PTR; > + > +static struct log_device *log_device_find_by_name(const char *drv_name) > +{ > + struct log_device *ldev; > + > + list_for_each_entry(ldev, &gd->log_head, sibling_node) { > + if (!strcmp(drv_name, ldev->drv->name)) > + return ldev; > + } > + > + return NULL; > +} > + > +/** > + * log_has_cat() - check if a log category exists within a list > + * > + * @cat_list: List of categories to check, at most LOGF_MAX_CATEGORIES entries > + * long, terminated by LC_END if fewer > + * @cat: Category to search for > + * @return true if @cat is in @cat_list, else false > + */ > +static bool log_has_cat(enum log_category_t cat_list[], enum log_category_t cat) > +{ > + int i; > + > + for (i = 0; i < LOGF_MAX_CATEGORIES && cat_list[i] != LOGC_END; i++) { > + if (cat_list[i] == cat) > + return true; > + } > + > + return false; > +} > + > +/** > + * log_has_file() - check if a file is with a list > + * > + * @file_list: List of files to check, separated by comma > + * @file: File to check for. This string is matched against the end of each > + * file in the list, i.e. ignoring any preceeding path. The list is > + * intended to consist of relative pathnames, e.g. common/main.c,cmd/log.c > + * @return true if @file is in @file_list, else false > + */ > +static bool log_has_file(const char *file_list, const char *file) > +{ > + int file_len = strlen(file); > + const char *s, *p; > + int substr_len; > + > + for (s = file_list; *s; s = p + (*p != '\0')) { > + p = strchrnul(s, ','); > + substr_len = p - s; > + if (file_len >= substr_len && > + !strncmp(file + file_len - substr_len, s, substr_len)) > + return true; > + } > + > + return false; > +} > + > +/** > + * log_passes_filters() - check if a log record passes the filters for a device > + * > + * @ldev: Log device to check > + * @rec: Log record to check > + * @return true if @rec is not blocked by the filters in @ldev, false if it is > + */ > +static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec) > +{ > + struct log_filter *filt; > + > + /* If there are no filters, filter on the default log level */ > + if (list_empty(&ldev->filter_head)) { > + if (rec->level > gd->default_log_level) > + return false; > + return true; > + } > + > + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { > + if (rec->level > filt->max_level) > + continue; > + if ((filt->flags & LOGFF_HAS_CAT) && > + !log_has_cat(filt->cat_list, rec->cat)) > + continue; > + if (filt->file_list && > + !log_has_file(filt->file_list, rec->file)) > + continue; > + return true; > + } > + > + return false; > +} > + > +/** > + * log_dispatch() - Send a log record to all log devices for processing > + * > + * The log record is sent to each log device in turn, skipping those which have > + * filters which block the record > + * > + * @rec: Log record to dispatch > + * @return 0 (meaning success) > + */ > +static int log_dispatch(struct log_rec *rec) > +{ > + struct log_device *ldev; > + > + list_for_each_entry(ldev, &gd->log_head, sibling_node) { > + if (log_passes_filters(ldev, rec)) > + ldev->drv->emit(ldev, rec); > + } > + > + return 0; > +} > + > +int _log(enum log_category_t cat, enum log_level_t level, const char *file, > + int line, const char *func, const char *fmt, ...) > +{ > + char buf[CONFIG_SYS_CBSIZE]; > + struct log_rec rec; > + va_list args; > + > + rec.cat = cat; > + rec.level = level; > + rec.file = file; > + rec.line = line; > + rec.func = func; > + va_start(args, fmt); > + vsnprintf(buf, sizeof(buf), fmt, args); > + va_end(args); > + rec.msg = buf; > + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { > + if (gd) > + gd->log_drop_count++; > + return -ENOSYS; > + } > + log_dispatch(&rec); > + > + return 0; > +} > + > +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], > + enum log_level_t max_level, const char *file_list) > +{ > + struct log_filter *filt; > + struct log_device *ldev; > + int i; > + > + ldev = log_device_find_by_name(drv_name); > + if (!ldev) > + return -ENOENT; > + filt = (struct log_filter *)calloc(1, sizeof(*filt)); > + if (!filt) > + return -ENOMEM; > + > + if (cat_list) { > + filt->flags |= LOGFF_HAS_CAT; > + for (i = 0; ; i++) { > + if (i == ARRAY_SIZE(filt->cat_list)) > + return -ENOSPC; > + filt->cat_list[i] = cat_list[i]; > + if (cat_list[i] == LOGC_END) > + break; > + } > + } > + filt->max_level = max_level; > + if (file_list) { > + filt->file_list = strdup(file_list); > + if (!filt->file_list) > + goto nomem; > + } > + filt->filter_num = ldev->next_filter_num++; > + INIT_LIST_HEAD(&filt->sibling_node); > + list_add_tail(&filt->sibling_node, &ldev->filter_head); > + > + return filt->filter_num; > + > +nomem: > + free(filt); > + return -ENOMEM; > +} > + > +int log_remove_filter(const char *drv_name, int filter_num) > +{ > + struct log_filter *filt; > + struct log_device *ldev; > + > + ldev = log_device_find_by_name(drv_name); > + if (!ldev) > + return -ENOENT; > + > + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { > + if (filt->filter_num == filter_num) { > + list_del(&filt->sibling_node); > + free(filt); > + > + return 0; > + } > + } > + > + return -ENOENT; > +} > + > +int log_init(void) > +{ > + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); > + const int count = ll_entry_count(struct log_driver, log_driver); > + struct log_driver *end = drv + count; > + > + /* > + * We cannot add runtime data to the driver since it is likely stored > + * in rodata. Instead, set up a 'device' corresponding to each driver. > + * We only support having a single device. > + */ > + INIT_LIST_HEAD((struct list_head *)&gd->log_head); > + while (drv < end) { > + struct log_device *ldev; > + > + ldev = calloc(1, sizeof(*ldev)); > + if (!ldev) { > + debug("%s: Cannot allocate memory\n", __func__); > + return -ENOMEM; > + } > + INIT_LIST_HEAD(&ldev->sibling_node); > + INIT_LIST_HEAD(&ldev->filter_head); > + ldev->drv = drv; > + list_add_tail(&ldev->sibling_node, > + (struct list_head *)&gd->log_head); > + drv++; > + } > + gd->default_log_level = LOGL_INFO; Shouldn't this be the Kconfig option CONFIG_LOG_MAX_LEVEL? > + > + return 0; > +} > diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h > index 79197acfa4..77755dbb06 100644 > --- a/include/asm-generic/global_data.h > +++ b/include/asm-generic/global_data.h > @@ -114,6 +114,11 @@ typedef struct global_data { > struct bootstage_data *bootstage; /* Bootstage information */ > struct bootstage_data *new_bootstage; /* Relocated bootstage info */ > #endif > +#ifdef CONFIG_LOG > + int log_drop_count; /* Number of dropped log messages */ > + int default_log_level; /* For devices with no filters */ > + struct list_head log_head; /* List of struct log_device */ > +#endif > } gd_t; > #endif > > diff --git a/include/log.h b/include/log.h > index 4101a74161..fb6a196202 100644 > --- a/include/log.h > +++ b/include/log.h > @@ -10,6 +10,82 @@ > #ifndef __LOG_H > #define __LOG_H > > +#include <dm/uclass-id.h> > +#include <linux/list.h> > + > +/** Log levels supported, ranging from most to least important */ > +enum log_level_t { > + LOGL_PANIC = 0, > + LOGL_CRIT, > + LOGL_ERR, > + LOGL_WARN, > + LOGL_NOTE, > + LOGL_INFO, > + LOGL_DETAIL, > + LOGL_DEBUG, > + > + LOGL_COUNT, > + LOGL_FIRST = LOGL_PANIC, > + LOGL_MAX = LOGL_DEBUG, > +}; > + > +/** > + * Log categories supported. Most of these correspond to uclasses (i.e. > + * enum uclass_id) but there are also some more generic categories > + */ > +enum log_category_t { > + LOGC_FIRST = 0, /* First part mirrors UCLASS_... */ > + > + LOGC_NONE = UCLASS_COUNT, > + LOGC_ARCH, > + LOGC_BOARD, > + LOGC_CORE, > + LOGC_DT, > + > + LOGC_COUNT, > + LOGC_END, > +}; > + > +/** > + * _log() - Internal function to emit a new log record > + * > + * @cat: Category of log record (indicating which subsystem generated it) > + * @level: Level of log record (indicating its severity) > + * @file: File name of file where log record was generated > + * @line: Line number in file where log record was generated > + * @func: Function where log record was generated > + * @fmt: printf() format string for log record > + * @...: Optional parameters, according to the format string @fmt > + * @return 0 if log record was emitted, -ve on error > + */ > +int _log(enum log_category_t cat, enum log_level_t level, const char *file, > + int line, const char *func, const char *fmt, ...); > + > +/* Define this at the top of a file to add a prefix to debug messages */ > +#ifndef pr_fmt > +#define pr_fmt(fmt) fmt > +#endif > + > +/* Use a default category if this file does not supply one */ > +#ifndef LOG_CATEGORY > +#define LOG_CATEGORY LOGC_NONE > +#endif > + > +#if CONFIG_VAL(LOG_MAX_LEVEL) > +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) > +#else > +#define _LOG_MAX_LEVEL LOGL_INFO > +#endif > + > +/* Emit a log record if the level is less that the maximum */ > +#define log(_cat, _level, _fmt, _args...) ({ \ > + int _l = _level; \ > + if (_l > _LOG_MAX_LEVEL) \ > + continue; \ > + _log(_cat, _l, __FILE__, __LINE__, __func__, \ > + pr_fmt(_fmt), ##_args); \ > + }) > + > #ifdef DEBUG > #define _DEBUG 1 > #else > @@ -22,10 +98,19 @@ > #define _SPL_BUILD 0 > #endif > > -/* Define this at the top of a file to add a prefix to debug messages */ > -#ifndef pr_fmt > -#define pr_fmt(fmt) fmt > -#endif > +#if !_DEBUG && CONFIG_IS_ENABLED(LOG) > + > +#define debug_cond(cond, fmt, args...) \ > + do { \ > + if (1) \ > + log(LOG_CATEGORY, LOGL_DEBUG, fmt, ##args); \ > + } while (0) > + > +#define error(fmt, args...) do { \ > + log(LOG_CATEGORY, LOGL_ERR, fmt, ##args); \ > +} while (0) > + > +#else /* _DEBUG */ > > /* > * Output a debug text when condition "cond" is met. The "cond" should be > @@ -38,6 +123,13 @@ > printf(pr_fmt(fmt), ##args); \ > } while (0) > > +#define error(fmt, args...) do { \ > + printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ > + ##args, __FILE__, __LINE__, __func__); \ > +} while (0) > + > +#endif /* _DEBUG */ > + > /* Show a message if DEBUG is defined in a file */ > #define debug(fmt, args...) \ > debug_cond(_DEBUG, fmt, ##args) > @@ -61,11 +153,6 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, > ({ if (!(x) && _DEBUG) \ > __assert_fail(#x, __FILE__, __LINE__, __func__); }) > > -#define error(fmt, args...) do { \ > - printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ > - ##args, __FILE__, __LINE__, __func__); \ > -} while (0) > - > #ifndef BUG > #define BUG() do { \ > printf("BUG: failure at %s:%d/%s()!\n", __FILE__, __LINE__, \ > @@ -76,4 +163,146 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, > while (0) > #endif /* BUG */ > > +/** > + * struct log_rec - a single log record > + * > + * Holds information about a single record in the log > + * > + * Members marked as 'not allocated' are stored as pointers and the caller is > + * responsible for making sure that the data pointed to is not overwritten. > + * Memebers marked as 'allocated' are allocated (e.g. via strdup()) by the log > + * system. > + * > + * @cat: Category, representing a uclass or part of U-Boot > + * @level: Severity level, less severe is higher > + * @file: Name of file where the log record was generated (not allocated) > + * @line: Line number where the log record was generated > + * @func: Function where the log record was generated (not allocated) > + * @msg: Log message (allocated) > + */ > +struct log_rec { > + enum log_category_t cat; > + enum log_level_t level; > + const char *file; > + int line; > + const char *func; > + const char *msg; > +}; > + > +struct log_device; > + > +/** > + * struct log_driver - a driver which accepts and processes log records > + * > + * @name: Name of driver > + */ > +struct log_driver { > + const char *name; > + /** > + * emit() - emit a log record > + * > + * Called by the log system to pass a log record to a particular driver > + * for processing. The filter is checked before calling this function. > + */ > + int (*emit)(struct log_device *ldev, struct log_rec *rec); > +}; > + So we are creating a new type of non-DM driver which is log-specific? How about we add this emit to the existing uclass driver that can be used as the log driver? (eg: blk devices with file system?) > +/** > + * struct log_device - an instance of a log driver > + * > + * Since drivers are set up at build-time we need to have a separate device for > + * the run-time aspects of drivers (currently just a list of filters to apply > + * to records send to this device). > + * > + * @next_filter_num: Seqence number of next filter filter added (0=no filters > + * yet). This increments with each new filter on the device, but never > + * decrements > + * @drv: Pointer to driver for this device > + * @filter_head: List of filters for this device > + * @sibling_node: Next device in the list of all devices > + */ > +struct log_device { > + int next_filter_num; > + struct log_driver *drv; > + struct list_head filter_head; > + struct list_head sibling_node; > +}; > + > +enum { > + LOGF_MAX_CATEGORIES = 5, /* maximum categories per filter */ > +}; > + > +enum log_filter_flags { > + LOGFF_HAS_CAT = 1 << 0, /* Filter has a category list */ > +}; > + > +/** > + * struct log_filter - criterial to filter out log messages > + * > + * @filter_num: Sequence number of this filter. This is returned when adding a > + * new filter, and must be provided when removing a previously added > + * filter. > + * @flags: Flags for this filter (LOGFF_...) > + * @cat_list: List of categories to allow (terminated by LOGC_none). If empty > + * then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries > + * can be provided > + * @max_level: Maximum log level to allow > + * @file_list: List of files to allow, separated by comma. If NULL then all > + * files are permitted > + * @sibling_node: Next filter in the list of filters for this log device > + */ > +struct log_filter { > + int filter_num; > + int flags; > + enum log_category_t cat_list[LOGF_MAX_CATEGORIES]; > + enum log_level_t max_level; > + const char *file_list; > + struct list_head sibling_node; > +}; > + > +#define LOG_DRIVER(_name) \ > + ll_entry_declare(struct log_driver, _name, log_driver) > + > +/** > + * log_add_filter() - Add a new filter to a log device > + * > + * @drv_name: Driver name to add the filter to (since each driver only has a > + * single device) > + * @cat_list: List of categories to allow (terminated by LOGC_none). If empty > + * then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries > + * can be provided > + * @max_level: Maximum log level to allow > + * @file_list: List of files to allow, separated by comma. If NULL then all > + * files are permitted > + * @return the sequence number of the new filter (>=0) if the filter was added, > + * or a -ve value on error > + */ > +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], > + enum log_level_t max_level, const char *file_list); > + > +/** > + * log_remove_filter() - Remove a filter from a log device > + * > + * @drv_name: Driver name to remove the filter from (since each driver only has > + * a single device) > + * @filter_num: Filter number to remove (as returned by log_add_filter()) > + * @return 0 if the filter was removed, -ENOENT if either the driver or the > + * filter number was not found > + */ > +int log_remove_filter(const char *drv_name, int filter_num); > + > +#if CONFIG_IS_ENABLED(LOG) > +/** > + * log_init() - Set up the log system ready for use > + * > + * @return 0 if OK, -ENOMEM if out of memory > + */ > +int log_init(void); > +#else > +static inline int log_init(void) > +{ > + return 0; > +} > +#endif > + > #endif > -- Regards, Bin
Hi Simon, 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: > > +menu "Logging" > + > +config LOG > + bool "Enable logging support" > + help > + This enables support for logging of status and debug messages. These > + can be displayed on the console, recorded in a memory buffer, or > + discarded if not needed. Logging supports various categories and > + levels of severity. > + > +config SPL_LOG > + bool "Enable logging support in SPL" > + help > + This enables support for logging of status and debug messages. These > + can be displayed on the console, recorded in a memory buffer, or > + discarded if not needed. Logging supports various categories and > + levels of severity. Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG when building for TPL. Since that commit, if you add SPL_ prefixed option, you need to add a TPL_ one as well. I cannot believe why such a commit was accepted. > +config LOG_MAX_LEVEL > + int "Maximum log level to record" > + depends on LOG > + default 5 > + help > + This selects the maximum log level that will be recorded. Any value > + higher than this will be ignored. If possible log statements below > + this level will be discarded at build time. Levels: > + > + 0 - panic > + 1 - critical > + 2 - error > + 3 - warning > + 4 - note > + 5 - info > + 6 - detail > + 7 - debug Please do not invent our own for U-Boot. Just use Linux log level. 0 (KERN_EMERG) system is unusable 1 (KERN_ALERT) action must be taken immediately 2 (KERN_CRIT) critical conditions 3 (KERN_ERR) error conditions 4 (KERN_WARNING) warning conditions 5 (KERN_NOTICE) normal but significant condition 6 (KERN_INFO) informational 7 (KERN_DEBUG) debug-level messages > +config LOG_SPL_MAX_LEVEL > + int "Maximum log level to record in SPL" > + depends on SPL_LOG > + default 3 > + help > + This selects the maximum log level that will be recorded. Any value > + higher than this will be ignored. If possible log statements below > + this level will be discarded at build time. Levels: > + > + 0 - panic > + 1 - critical > + 2 - error > + 3 - warning > + 4 - note > + 5 - info > + 6 - detail > + 7 - debug > If you want to use CONFIG_VAL(LOG_MAX_LEVEL), this must be SPL_LOG_MAX_LEVEL. (this coding mistake is now hidden by another mistake) Again, you will probably end up with TPL_LOG_MAX_LEVEL. > + > +/** > + * log_dispatch() - Send a log record to all log devices for processing > + * > + * The log record is sent to each log device in turn, skipping those which have > + * filters which block the record > + * > + * @rec: Log record to dispatch > + * @return 0 (meaning success) > + */ > +static int log_dispatch(struct log_rec *rec) > +{ > + struct log_device *ldev; > + > + list_for_each_entry(ldev, &gd->log_head, sibling_node) { > + if (log_passes_filters(ldev, rec)) > + ldev->drv->emit(ldev, rec); > + } > + > + return 0; > +} > + > +int _log(enum log_category_t cat, enum log_level_t level, const char *file, > + int line, const char *func, const char *fmt, ...) > +{ > + char buf[CONFIG_SYS_CBSIZE]; > + struct log_rec rec; > + va_list args; > + > + rec.cat = cat; > + rec.level = level; > + rec.file = file; > + rec.line = line; > + rec.func = func; > + va_start(args, fmt); > + vsnprintf(buf, sizeof(buf), fmt, args); > + va_end(args); > + rec.msg = buf; > + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { > + if (gd) > + gd->log_drop_count++; > + return -ENOSYS; > + } > + log_dispatch(&rec); > + > + return 0; > +} > + > +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], > + enum log_level_t max_level, const char *file_list) > +{ > + struct log_filter *filt; > + struct log_device *ldev; > + int i; > + > + ldev = log_device_find_by_name(drv_name); > + if (!ldev) > + return -ENOENT; > + filt = (struct log_filter *)calloc(1, sizeof(*filt)); > + if (!filt) > + return -ENOMEM; > + > + if (cat_list) { > + filt->flags |= LOGFF_HAS_CAT; > + for (i = 0; ; i++) { > + if (i == ARRAY_SIZE(filt->cat_list)) > + return -ENOSPC; > + filt->cat_list[i] = cat_list[i]; > + if (cat_list[i] == LOGC_END) > + break; > + } > + } > + filt->max_level = max_level; > + if (file_list) { > + filt->file_list = strdup(file_list); > + if (!filt->file_list) > + goto nomem; > + } > + filt->filter_num = ldev->next_filter_num++; > + INIT_LIST_HEAD(&filt->sibling_node); > + list_add_tail(&filt->sibling_node, &ldev->filter_head); > + > + return filt->filter_num; > + > +nomem: > + free(filt); > + return -ENOMEM; > +} > + > +int log_remove_filter(const char *drv_name, int filter_num) > +{ > + struct log_filter *filt; > + struct log_device *ldev; > + > + ldev = log_device_find_by_name(drv_name); > + if (!ldev) > + return -ENOENT; > + > + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { > + if (filt->filter_num == filter_num) { > + list_del(&filt->sibling_node); > + free(filt); > + > + return 0; > + } > + } > + > + return -ENOENT; > +} I am not sure if this luxury filter is needed. After all, the purpose is debugging. The printf() debugging is useful, but only during testing. Once quality code is established, most of debug message should generally be removed from upstream code. > +int log_init(void) > +{ > + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); > + const int count = ll_entry_count(struct log_driver, log_driver); > + struct log_driver *end = drv + count; > + > + /* > + * We cannot add runtime data to the driver since it is likely stored > + * in rodata. Instead, set up a 'device' corresponding to each driver. > + * We only support having a single device. > + */ > + INIT_LIST_HEAD((struct list_head *)&gd->log_head); > + while (drv < end) { > + struct log_device *ldev; > + > + ldev = calloc(1, sizeof(*ldev)); > + if (!ldev) { > + debug("%s: Cannot allocate memory\n", __func__); > + return -ENOMEM; > + } > + INIT_LIST_HEAD(&ldev->sibling_node); This INIT_LIST_HEAD() is unneeded. > + INIT_LIST_HEAD(&ldev->filter_head); > + ldev->drv = drv; > + list_add_tail(&ldev->sibling_node, > + (struct list_head *)&gd->log_head); I know that this (struct list_head *) cast is needed, but it is very unfortunate. I believe gd_t is design mistake in the first place, but U-Boot has gone to unfixable already... > +#if CONFIG_VAL(LOG_MAX_LEVEL) > +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) > +#else > +#define _LOG_MAX_LEVEL LOGL_INFO > +#endif I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). From your Kconfig entry, 0 - panic 1 - critical 2 - error 3 - warning 4 - note 5 - info 6 - detail 7 - debug I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value range 0 to 7. If the log level is 0 (= critial), the conditional is false, so _LOG_MAX_LEVEL is set to "info" level. Why is this #if necessary? > +/* Emit a log record if the level is less that the maximum */ > +#define log(_cat, _level, _fmt, _args...) ({ \ > + int _l = _level; \ > + if (_l > _LOG_MAX_LEVEL) \ > + continue; \ > + _log(_cat, _l, __FILE__, __LINE__, __func__, \ > + pr_fmt(_fmt), ##_args); \ > + }) This is neither while() nor for(). The bare use of "continue" made me really surprised.
Hi Masahiro, On 19 September 2017 at 20:51, Masahiro Yamada <yamada.masahiro@socionext.com> wrote: > Hi Simon, > > > 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: > >> >> +menu "Logging" >> + >> +config LOG >> + bool "Enable logging support" >> + help >> + This enables support for logging of status and debug messages. These >> + can be displayed on the console, recorded in a memory buffer, or >> + discarded if not needed. Logging supports various categories and >> + levels of severity. >> + >> +config SPL_LOG >> + bool "Enable logging support in SPL" >> + help >> + This enables support for logging of status and debug messages. These >> + can be displayed on the console, recorded in a memory buffer, or >> + discarded if not needed. Logging supports various categories and >> + levels of severity. > > > Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. > > Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, > CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG > when building for TPL. > > Since that commit, if you add SPL_ prefixed option, > you need to add a TPL_ one as well. > > I cannot believe why such a commit was accepted. Well either way is strange. it is strange that SPL is enabled for TPL when really they are separate. We could revert that commit. But how do you think all of this SPL/TPL control should actually work? What is intended? But I'm OK with not having logging in TPL until we need it. > > > > >> +config LOG_MAX_LEVEL >> + int "Maximum log level to record" >> + depends on LOG >> + default 5 >> + help >> + This selects the maximum log level that will be recorded. Any value >> + higher than this will be ignored. If possible log statements below >> + this level will be discarded at build time. Levels: >> + >> + 0 - panic >> + 1 - critical >> + 2 - error >> + 3 - warning >> + 4 - note >> + 5 - info >> + 6 - detail >> + 7 - debug > > > Please do not invent our own for U-Boot. > Just use Linux log level. > > 0 (KERN_EMERG) system is unusable > 1 (KERN_ALERT) action must be taken immediately > 2 (KERN_CRIT) critical conditions > 3 (KERN_ERR) error conditions > 4 (KERN_WARNING) warning conditions > 5 (KERN_NOTICE) normal but significant condition > 6 (KERN_INFO) informational > 7 (KERN_DEBUG) debug-level messages Yes I looked hard at that. The first three seem hard to distinguish in U-Boot, but we can keep them I suppose. But most of my problem is with the last two. INFO is what I plan to use for normal printf() output. DEBUG is obviously for debugging and often involves vaste amounts of stuff (e.g. logging every access to an MMC peripheral). We need something in between. It could list the accesses to device at a high level (e.g API calls) but not every little register access. So I don't think the Linux levels are suitable at the high end. We could go up to 8 I suppose, instead of trying to save one at the bottom? > > > > >> +config LOG_SPL_MAX_LEVEL >> + int "Maximum log level to record in SPL" >> + depends on SPL_LOG >> + default 3 >> + help >> + This selects the maximum log level that will be recorded. Any value >> + higher than this will be ignored. If possible log statements below >> + this level will be discarded at build time. Levels: >> + >> + 0 - panic >> + 1 - critical >> + 2 - error >> + 3 - warning >> + 4 - note >> + 5 - info >> + 6 - detail >> + 7 - debug >> > > > If you want to use CONFIG_VAL(LOG_MAX_LEVEL), > this must be SPL_LOG_MAX_LEVEL. > (this coding mistake is now hidden by another mistake) Oops, yes. > > Again, you will probably end up with TPL_LOG_MAX_LEVEL. > > > > >> + >> +/** >> + * log_dispatch() - Send a log record to all log devices for processing >> + * >> + * The log record is sent to each log device in turn, skipping those which have >> + * filters which block the record >> + * >> + * @rec: Log record to dispatch >> + * @return 0 (meaning success) >> + */ >> +static int log_dispatch(struct log_rec *rec) >> +{ >> + struct log_device *ldev; >> + >> + list_for_each_entry(ldev, &gd->log_head, sibling_node) { >> + if (log_passes_filters(ldev, rec)) >> + ldev->drv->emit(ldev, rec); >> + } >> + >> + return 0; >> +} >> + >> +int _log(enum log_category_t cat, enum log_level_t level, const char *file, >> + int line, const char *func, const char *fmt, ...) >> +{ >> + char buf[CONFIG_SYS_CBSIZE]; >> + struct log_rec rec; >> + va_list args; >> + >> + rec.cat = cat; >> + rec.level = level; >> + rec.file = file; >> + rec.line = line; >> + rec.func = func; >> + va_start(args, fmt); >> + vsnprintf(buf, sizeof(buf), fmt, args); >> + va_end(args); >> + rec.msg = buf; >> + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { >> + if (gd) >> + gd->log_drop_count++; >> + return -ENOSYS; >> + } >> + log_dispatch(&rec); >> + >> + return 0; >> +} >> + >> +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], >> + enum log_level_t max_level, const char *file_list) >> +{ >> + struct log_filter *filt; >> + struct log_device *ldev; >> + int i; >> + >> + ldev = log_device_find_by_name(drv_name); >> + if (!ldev) >> + return -ENOENT; >> + filt = (struct log_filter *)calloc(1, sizeof(*filt)); >> + if (!filt) >> + return -ENOMEM; >> + >> + if (cat_list) { >> + filt->flags |= LOGFF_HAS_CAT; >> + for (i = 0; ; i++) { >> + if (i == ARRAY_SIZE(filt->cat_list)) >> + return -ENOSPC; >> + filt->cat_list[i] = cat_list[i]; >> + if (cat_list[i] == LOGC_END) >> + break; >> + } >> + } >> + filt->max_level = max_level; >> + if (file_list) { >> + filt->file_list = strdup(file_list); >> + if (!filt->file_list) >> + goto nomem; >> + } >> + filt->filter_num = ldev->next_filter_num++; >> + INIT_LIST_HEAD(&filt->sibling_node); >> + list_add_tail(&filt->sibling_node, &ldev->filter_head); >> + >> + return filt->filter_num; >> + >> +nomem: >> + free(filt); >> + return -ENOMEM; >> +} >> + >> +int log_remove_filter(const char *drv_name, int filter_num) >> +{ >> + struct log_filter *filt; >> + struct log_device *ldev; >> + >> + ldev = log_device_find_by_name(drv_name); >> + if (!ldev) >> + return -ENOENT; >> + >> + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { >> + if (filt->filter_num == filter_num) { >> + list_del(&filt->sibling_node); >> + free(filt); >> + >> + return 0; >> + } >> + } >> + >> + return -ENOENT; >> +} > > > I am not sure if this luxury filter is needed. > After all, the purpose is debugging. > The printf() debugging is useful, but only during testing. > Once quality code is established, most of debug message should > generally be removed from upstream code. But not logging, and this is the point. It is very useful to have basic logging information recorded for every boot, and the normal printf() output is not detailed enough. For example for verified boot I want to see details about boot failures and what went wrong (key verification, etc.). So I expect that at least INFO (and probably DETAIL) logging would be useful to record for such a system, even if it does not appear on the console (in fact the console would normally be disabled in such a system). > > > >> +int log_init(void) >> +{ >> + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); >> + const int count = ll_entry_count(struct log_driver, log_driver); >> + struct log_driver *end = drv + count; >> + >> + /* >> + * We cannot add runtime data to the driver since it is likely stored >> + * in rodata. Instead, set up a 'device' corresponding to each driver. >> + * We only support having a single device. >> + */ >> + INIT_LIST_HEAD((struct list_head *)&gd->log_head); >> + while (drv < end) { >> + struct log_device *ldev; >> + >> + ldev = calloc(1, sizeof(*ldev)); >> + if (!ldev) { >> + debug("%s: Cannot allocate memory\n", __func__); >> + return -ENOMEM; >> + } >> + INIT_LIST_HEAD(&ldev->sibling_node); > > This INIT_LIST_HEAD() is unneeded. How come? If I don't do that how will the list be set up? > > > >> + INIT_LIST_HEAD(&ldev->filter_head); >> + ldev->drv = drv; >> + list_add_tail(&ldev->sibling_node, >> + (struct list_head *)&gd->log_head); > > I know that this (struct list_head *) cast is needed, > but it is very unfortunate. > I believe gd_t is design mistake in the first place, > but U-Boot has gone to unfixable already... With driver model I added DM_ROOT_NON_CONST. I suppose we could use something like that. But perhaps we should start dropping the 'volatile' in gd? I'm not sure why it is needed. > > > > > >> +#if CONFIG_VAL(LOG_MAX_LEVEL) >> +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) >> +#else >> +#define _LOG_MAX_LEVEL LOGL_INFO >> +#endif > > > I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). > From your Kconfig entry, > > 0 - panic > 1 - critical > 2 - error > 3 - warning > 4 - note > 5 - info > 6 - detail > 7 - debug > > I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value > range 0 to 7. > > If the log level is 0 (= critial), the conditional is false, so > _LOG_MAX_LEVEL is set to "info" level. > > Why is this #if necessary? If we don't have CONFIG_LOG enabled then this value will not exist. > > > > > > > > >> +/* Emit a log record if the level is less that the maximum */ >> +#define log(_cat, _level, _fmt, _args...) ({ \ >> + int _l = _level; \ >> + if (_l > _LOG_MAX_LEVEL) \ >> + continue; \ >> + _log(_cat, _l, __FILE__, __LINE__, __func__, \ >> + pr_fmt(_fmt), ##_args); \ >> + }) > > > This is neither while() nor for(). > The bare use of "continue" made me really surprised. Yes that may not be supported. I'll fix it. Regards, Simon
Hi Bin, On 17 September 2017 at 21:45, Bin Meng <bmeng.cn@gmail.com> wrote: > Hi Simon, > > On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass <sjg@chromium.org> wrote: >> Add the logging header file and implementation with some configuration >> options to control it. >> >> Signed-off-by: Simon Glass <sjg@chromium.org> >> --- >> >> MAINTAINERS | 9 ++ >> common/Kconfig | 56 +++++++++ >> common/Makefile | 1 + >> common/log.c | 246 +++++++++++++++++++++++++++++++++++++ >> include/asm-generic/global_data.h | 5 + >> include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- >> 6 files changed, 555 insertions(+), 9 deletions(-) >> create mode 100644 common/log.c >> >> diff --git a/MAINTAINERS b/MAINTAINERS >> index 04acf2b89d..eb420afa8d 100644 >> --- a/MAINTAINERS >> +++ b/MAINTAINERS >> @@ -290,6 +290,15 @@ S: Maintained >> T: git git://git.denx.de/u-boot-i2c.git >> F: drivers/i2c/ >> >> +LOGGING >> +M: Simon Glass <sjg@chromium.org> >> +S: Maintained >> +T: git git://git.denx.de/u-boot.git >> +F: common/log.c >> +F: cmd/log.c >> +F: test/log/log_test.c >> +F: test/py/tests/test_log.py > > test/log/log_test.c and test/py/tests/test_log.py have not been > introduced at this point. OK I can tweak that, [..] >> +/** >> + * struct log_driver - a driver which accepts and processes log records >> + * >> + * @name: Name of driver >> + */ >> +struct log_driver { >> + const char *name; >> + /** >> + * emit() - emit a log record >> + * >> + * Called by the log system to pass a log record to a particular driver >> + * for processing. The filter is checked before calling this function. >> + */ >> + int (*emit)(struct log_device *ldev, struct log_rec *rec); >> +}; >> + > > So we are creating a new type of non-DM driver which is log-specific? > How about we add this emit to the existing uclass driver that can be > used as the log driver? (eg: blk devices with file system?) Yes that's right. I think I can link it to DM once it starts up, but a logging of DM start-up is useful. Re your idea are you saying add an emit() method to UCLASS_BLK? Regards, Simon
Masahiro & Simon, > On 20 Sep 2017, at 15:49, Simon Glass <sjg@chromium.org> wrote: > > Hi Masahiro, > > On 19 September 2017 at 20:51, Masahiro Yamada > <yamada.masahiro@socionext.com> wrote: >> Hi Simon, >> >> >> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >> >>> >>> +menu "Logging" >>> + >>> +config LOG >>> + bool "Enable logging support" >>> + help >>> + This enables support for logging of status and debug messages. These >>> + can be displayed on the console, recorded in a memory buffer, or >>> + discarded if not needed. Logging supports various categories and >>> + levels of severity. >>> + >>> +config SPL_LOG >>> + bool "Enable logging support in SPL" >>> + help >>> + This enables support for logging of status and debug messages. These >>> + can be displayed on the console, recorded in a memory buffer, or >>> + discarded if not needed. Logging supports various categories and >>> + levels of severity. >> >> >> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >> >> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >> when building for TPL. >> >> Since that commit, if you add SPL_ prefixed option, >> you need to add a TPL_ one as well. >> >> I cannot believe why such a commit was accepted. > > Well either way is strange. it is strange that SPL is enabled for TPL > when really they are separate. > > We could revert that commit. But how do you think all of this SPL/TPL > control should actually work? What is intended? > > But I'm OK with not having logging in TPL until we need it. If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into size issues for TPL and the $(SPL_TPL_) mechanism will not match the CONFIG_IS_ENABLED() mechanism. I don’t think that anyone will miss this much in TPL and that this can be safely left off for TPL (if space was not at a premium in TPL, then why have a TPL at all…) > >> >> >> >> >>> +config LOG_MAX_LEVEL >>> + int "Maximum log level to record" >>> + depends on LOG >>> + default 5 >>> + help >>> + This selects the maximum log level that will be recorded. Any value >>> + higher than this will be ignored. If possible log statements below >>> + this level will be discarded at build time. Levels: >>> + >>> + 0 - panic >>> + 1 - critical >>> + 2 - error >>> + 3 - warning >>> + 4 - note >>> + 5 - info >>> + 6 - detail >>> + 7 - debug >> >> >> Please do not invent our own for U-Boot. >> Just use Linux log level. >> >> 0 (KERN_EMERG) system is unusable >> 1 (KERN_ALERT) action must be taken immediately >> 2 (KERN_CRIT) critical conditions >> 3 (KERN_ERR) error conditions >> 4 (KERN_WARNING) warning conditions >> 5 (KERN_NOTICE) normal but significant condition >> 6 (KERN_INFO) informational >> 7 (KERN_DEBUG) debug-level messages > > Yes I looked hard at that. The first three seem hard to distinguish in > U-Boot, but we can keep them I suppose. But most of my problem is with > the last two. INFO is what I plan to use for normal printf() output. > DEBUG is obviously for debugging and often involves vaste amounts of > stuff (e.g. logging every access to an MMC peripheral). We need > something in between. It could list the accesses to device at a high > level (e.g API calls) but not every little register access. > > So I don't think the Linux levels are suitable at the high end. We > could go up to 8 I suppose, instead of trying to save one at the > bottom? I would expect KERN_NOTICE to be used for normal printf output, KERN_INFO for more verbose output and DEBUG would be the granularity for tracing through drivers (i.e. the MMC example given). Regards, Philipp. > >> >> >> >> >>> +config LOG_SPL_MAX_LEVEL >>> + int "Maximum log level to record in SPL" >>> + depends on SPL_LOG >>> + default 3 >>> + help >>> + This selects the maximum log level that will be recorded. Any value >>> + higher than this will be ignored. If possible log statements below >>> + this level will be discarded at build time. Levels: >>> + >>> + 0 - panic >>> + 1 - critical >>> + 2 - error >>> + 3 - warning >>> + 4 - note >>> + 5 - info >>> + 6 - detail >>> + 7 - debug >>> >> >> >> If you want to use CONFIG_VAL(LOG_MAX_LEVEL), >> this must be SPL_LOG_MAX_LEVEL. >> (this coding mistake is now hidden by another mistake) > > Oops, yes. > >> >> Again, you will probably end up with TPL_LOG_MAX_LEVEL. >> >> >> >> >>> + >>> +/** >>> + * log_dispatch() - Send a log record to all log devices for processing >>> + * >>> + * The log record is sent to each log device in turn, skipping those which have >>> + * filters which block the record >>> + * >>> + * @rec: Log record to dispatch >>> + * @return 0 (meaning success) >>> + */ >>> +static int log_dispatch(struct log_rec *rec) >>> +{ >>> + struct log_device *ldev; >>> + >>> + list_for_each_entry(ldev, &gd->log_head, sibling_node) { >>> + if (log_passes_filters(ldev, rec)) >>> + ldev->drv->emit(ldev, rec); >>> + } >>> + >>> + return 0; >>> +} >>> + >>> +int _log(enum log_category_t cat, enum log_level_t level, const char *file, >>> + int line, const char *func, const char *fmt, ...) >>> +{ >>> + char buf[CONFIG_SYS_CBSIZE]; >>> + struct log_rec rec; >>> + va_list args; >>> + >>> + rec.cat = cat; >>> + rec.level = level; >>> + rec.file = file; >>> + rec.line = line; >>> + rec.func = func; >>> + va_start(args, fmt); >>> + vsnprintf(buf, sizeof(buf), fmt, args); >>> + va_end(args); >>> + rec.msg = buf; >>> + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { >>> + if (gd) >>> + gd->log_drop_count++; >>> + return -ENOSYS; >>> + } >>> + log_dispatch(&rec); >>> + >>> + return 0; >>> +} >>> + >>> +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], >>> + enum log_level_t max_level, const char *file_list) >>> +{ >>> + struct log_filter *filt; >>> + struct log_device *ldev; >>> + int i; >>> + >>> + ldev = log_device_find_by_name(drv_name); >>> + if (!ldev) >>> + return -ENOENT; >>> + filt = (struct log_filter *)calloc(1, sizeof(*filt)); >>> + if (!filt) >>> + return -ENOMEM; >>> + >>> + if (cat_list) { >>> + filt->flags |= LOGFF_HAS_CAT; >>> + for (i = 0; ; i++) { >>> + if (i == ARRAY_SIZE(filt->cat_list)) >>> + return -ENOSPC; >>> + filt->cat_list[i] = cat_list[i]; >>> + if (cat_list[i] == LOGC_END) >>> + break; >>> + } >>> + } >>> + filt->max_level = max_level; >>> + if (file_list) { >>> + filt->file_list = strdup(file_list); >>> + if (!filt->file_list) >>> + goto nomem; >>> + } >>> + filt->filter_num = ldev->next_filter_num++; >>> + INIT_LIST_HEAD(&filt->sibling_node); >>> + list_add_tail(&filt->sibling_node, &ldev->filter_head); >>> + >>> + return filt->filter_num; >>> + >>> +nomem: >>> + free(filt); >>> + return -ENOMEM; >>> +} >>> + >>> +int log_remove_filter(const char *drv_name, int filter_num) >>> +{ >>> + struct log_filter *filt; >>> + struct log_device *ldev; >>> + >>> + ldev = log_device_find_by_name(drv_name); >>> + if (!ldev) >>> + return -ENOENT; >>> + >>> + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { >>> + if (filt->filter_num == filter_num) { >>> + list_del(&filt->sibling_node); >>> + free(filt); >>> + >>> + return 0; >>> + } >>> + } >>> + >>> + return -ENOENT; >>> +} >> >> >> I am not sure if this luxury filter is needed. >> After all, the purpose is debugging. >> The printf() debugging is useful, but only during testing. >> Once quality code is established, most of debug message should >> generally be removed from upstream code. > > But not logging, and this is the point. It is very useful to have > basic logging information recorded for every boot, and the normal > printf() output is not detailed enough. For example for verified boot > I want to see details about boot failures and what went wrong (key > verification, etc.). So I expect that at least INFO (and probably > DETAIL) logging would be useful to record for such a system, even if > it does not appear on the console (in fact the console would normally > be disabled in such a system). > >> >> >> >>> +int log_init(void) >>> +{ >>> + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); >>> + const int count = ll_entry_count(struct log_driver, log_driver); >>> + struct log_driver *end = drv + count; >>> + >>> + /* >>> + * We cannot add runtime data to the driver since it is likely stored >>> + * in rodata. Instead, set up a 'device' corresponding to each driver. >>> + * We only support having a single device. >>> + */ >>> + INIT_LIST_HEAD((struct list_head *)&gd->log_head); >>> + while (drv < end) { >>> + struct log_device *ldev; >>> + >>> + ldev = calloc(1, sizeof(*ldev)); >>> + if (!ldev) { >>> + debug("%s: Cannot allocate memory\n", __func__); >>> + return -ENOMEM; >>> + } >>> + INIT_LIST_HEAD(&ldev->sibling_node); >> >> This INIT_LIST_HEAD() is unneeded. > > How come? If I don't do that how will the list be set up? > >> >> >> >>> + INIT_LIST_HEAD(&ldev->filter_head); >>> + ldev->drv = drv; >>> + list_add_tail(&ldev->sibling_node, >>> + (struct list_head *)&gd->log_head); >> >> I know that this (struct list_head *) cast is needed, >> but it is very unfortunate. >> I believe gd_t is design mistake in the first place, >> but U-Boot has gone to unfixable already... > > With driver model I added DM_ROOT_NON_CONST. I suppose we could use > something like that. > > But perhaps we should start dropping the 'volatile' in gd? I'm not > sure why it is needed. > >> >> >> >> >> >>> +#if CONFIG_VAL(LOG_MAX_LEVEL) >>> +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) >>> +#else >>> +#define _LOG_MAX_LEVEL LOGL_INFO >>> +#endif >> >> >> I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). >> From your Kconfig entry, >> >> 0 - panic >> 1 - critical >> 2 - error >> 3 - warning >> 4 - note >> 5 - info >> 6 - detail >> 7 - debug >> >> I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value >> range 0 to 7. >> >> If the log level is 0 (= critial), the conditional is false, so >> _LOG_MAX_LEVEL is set to "info" level. >> >> Why is this #if necessary? > > If we don't have CONFIG_LOG enabled then this value will not exist. > >> >> >> >> >> >> >> >> >>> +/* Emit a log record if the level is less that the maximum */ >>> +#define log(_cat, _level, _fmt, _args...) ({ \ >>> + int _l = _level; \ >>> + if (_l > _LOG_MAX_LEVEL) \ >>> + continue; \ >>> + _log(_cat, _l, __FILE__, __LINE__, __func__, \ >>> + pr_fmt(_fmt), ##_args); \ >>> + }) >> >> >> This is neither while() nor for(). >> The bare use of "continue" made me really surprised. > > Yes that may not be supported. I'll fix it. > > Regards, > Simon > _______________________________________________ > U-Boot mailing list > U-Boot@lists.denx.de > https://lists.denx.de/listinfo/u-boot
Hi Simon, On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass <sjg@chromium.org> wrote: > Hi Bin, > > On 17 September 2017 at 21:45, Bin Meng <bmeng.cn@gmail.com> wrote: >> Hi Simon, >> >> On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass <sjg@chromium.org> wrote: >>> Add the logging header file and implementation with some configuration >>> options to control it. >>> >>> Signed-off-by: Simon Glass <sjg@chromium.org> >>> --- >>> >>> MAINTAINERS | 9 ++ >>> common/Kconfig | 56 +++++++++ >>> common/Makefile | 1 + >>> common/log.c | 246 +++++++++++++++++++++++++++++++++++++ >>> include/asm-generic/global_data.h | 5 + >>> include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- >>> 6 files changed, 555 insertions(+), 9 deletions(-) >>> create mode 100644 common/log.c >>> >>> diff --git a/MAINTAINERS b/MAINTAINERS >>> index 04acf2b89d..eb420afa8d 100644 >>> --- a/MAINTAINERS >>> +++ b/MAINTAINERS >>> @@ -290,6 +290,15 @@ S: Maintained >>> T: git git://git.denx.de/u-boot-i2c.git >>> F: drivers/i2c/ >>> >>> +LOGGING >>> +M: Simon Glass <sjg@chromium.org> >>> +S: Maintained >>> +T: git git://git.denx.de/u-boot.git >>> +F: common/log.c >>> +F: cmd/log.c >>> +F: test/log/log_test.c >>> +F: test/py/tests/test_log.py >> >> test/log/log_test.c and test/py/tests/test_log.py have not been >> introduced at this point. > > OK I can tweak that, > [..] > >>> +/** >>> + * struct log_driver - a driver which accepts and processes log records >>> + * >>> + * @name: Name of driver >>> + */ >>> +struct log_driver { >>> + const char *name; >>> + /** >>> + * emit() - emit a log record >>> + * >>> + * Called by the log system to pass a log record to a particular driver >>> + * for processing. The filter is checked before calling this function. >>> + */ >>> + int (*emit)(struct log_device *ldev, struct log_rec *rec); >>> +}; >>> + >> >> So we are creating a new type of non-DM driver which is log-specific? >> How about we add this emit to the existing uclass driver that can be >> used as the log driver? (eg: blk devices with file system?) > > Yes that's right. I think I can link it to DM once it starts up, but a > logging of DM start-up is useful. > > Re your idea are you saying add an emit() method to UCLASS_BLK? > Yep, something like #ifdef CONFIG_LOG .log_emit = xxx_log_emit, #endif Probably we need a flag to find out which driver provides such log functionality. Regards, Bin
> On 20 Sep 2017, at 16:41, Bin Meng <bmeng.cn@gmail.com> wrote: > > Hi Simon, > > On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass <sjg@chromium.org> wrote: >> Hi Bin, >> >> On 17 September 2017 at 21:45, Bin Meng <bmeng.cn@gmail.com> wrote: >>> Hi Simon, >>> >>> On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass <sjg@chromium.org> wrote: >>>> Add the logging header file and implementation with some configuration >>>> options to control it. >>>> >>>> Signed-off-by: Simon Glass <sjg@chromium.org> >>>> --- >>>> >>>> MAINTAINERS | 9 ++ >>>> common/Kconfig | 56 +++++++++ >>>> common/Makefile | 1 + >>>> common/log.c | 246 +++++++++++++++++++++++++++++++++++++ >>>> include/asm-generic/global_data.h | 5 + >>>> include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- >>>> 6 files changed, 555 insertions(+), 9 deletions(-) >>>> create mode 100644 common/log.c >>>> >>>> diff --git a/MAINTAINERS b/MAINTAINERS >>>> index 04acf2b89d..eb420afa8d 100644 >>>> --- a/MAINTAINERS >>>> +++ b/MAINTAINERS >>>> @@ -290,6 +290,15 @@ S: Maintained >>>> T: git git://git.denx.de/u-boot-i2c.git >>>> F: drivers/i2c/ >>>> >>>> +LOGGING >>>> +M: Simon Glass <sjg@chromium.org> >>>> +S: Maintained >>>> +T: git git://git.denx.de/u-boot.git >>>> +F: common/log.c >>>> +F: cmd/log.c >>>> +F: test/log/log_test.c >>>> +F: test/py/tests/test_log.py >>> >>> test/log/log_test.c and test/py/tests/test_log.py have not been >>> introduced at this point. >> >> OK I can tweak that, >> [..] >> >>>> +/** >>>> + * struct log_driver - a driver which accepts and processes log records >>>> + * >>>> + * @name: Name of driver >>>> + */ >>>> +struct log_driver { >>>> + const char *name; >>>> + /** >>>> + * emit() - emit a log record >>>> + * >>>> + * Called by the log system to pass a log record to a particular driver >>>> + * for processing. The filter is checked before calling this function. >>>> + */ >>>> + int (*emit)(struct log_device *ldev, struct log_rec *rec); >>>> +}; >>>> + >>> >>> So we are creating a new type of non-DM driver which is log-specific? >>> How about we add this emit to the existing uclass driver that can be >>> used as the log driver? (eg: blk devices with file system?) >> >> Yes that's right. I think I can link it to DM once it starts up, but a >> logging of DM start-up is useful. >> >> Re your idea are you saying add an emit() method to UCLASS_BLK? >> > > Yep, something like > > #ifdef CONFIG_LOG > .log_emit = xxx_log_emit, > #endif > > Probably we need a flag to find out which driver provides such log > functionality. I had started to sketch (but have been able to fully flesh this out, due to other priorities intervening) a mechanism for MISC devices that might be a good fit for this. My work centers around the idea of having devices comply to “protocols” and was aimed at distinguishing between an efuse-device and a GbE RGMII-control (one where we need to adjust the RGMII clock depending on the link rate the PHY negotiated) device. I.e. I had started to implement something along the lines of: /** * misc_supports - tests if a misc device complies to a given protocol * * protocols can either be ‘how data is processed after calling write()’, * ‘how data is presented for a read()’ or ‘what ioctl-values are supported’. * The assumption is that protocols can be versioned and higher versions * offer full backward compatibility (i.e. a client for “Ethernet PHY control, v1” * can work with a driver implementing v1 or any higher version). */ bool misc_supports(struct udevice *dev, const char *protocol, u32 version); and a way to register a list of protocols as part of the misc uclass-priv for any given driver. This would allow us to enumerate all MISC devices until we find one that complies to the ‘logging’-protocol and then invoke write or ioctl on it. Regards, Philipp.
Hi Simon, 2017-09-20 22:49 GMT+09:00 Simon Glass <sjg@chromium.org>: > Hi Masahiro, > > On 19 September 2017 at 20:51, Masahiro Yamada > <yamada.masahiro@socionext.com> wrote: >> Hi Simon, >> >> >> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >> >>> >>> +menu "Logging" >>> + >>> +config LOG >>> + bool "Enable logging support" >>> + help >>> + This enables support for logging of status and debug messages. These >>> + can be displayed on the console, recorded in a memory buffer, or >>> + discarded if not needed. Logging supports various categories and >>> + levels of severity. >>> + >>> +config SPL_LOG >>> + bool "Enable logging support in SPL" >>> + help >>> + This enables support for logging of status and debug messages. These >>> + can be displayed on the console, recorded in a memory buffer, or >>> + discarded if not needed. Logging supports various categories and >>> + levels of severity. >> >> >> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >> >> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >> when building for TPL. >> >> Since that commit, if you add SPL_ prefixed option, >> you need to add a TPL_ one as well. >> >> I cannot believe why such a commit was accepted. > > Well either way is strange. it is strange that SPL is enabled for TPL > when really they are separate. > > We could revert that commit. But how do you think all of this SPL/TPL > control should actually work? What is intended? > > But I'm OK with not having logging in TPL until we need it. I will explain it in another mail. >> >> >> >> >>> +config LOG_MAX_LEVEL >>> + int "Maximum log level to record" >>> + depends on LOG >>> + default 5 >>> + help >>> + This selects the maximum log level that will be recorded. Any value >>> + higher than this will be ignored. If possible log statements below >>> + this level will be discarded at build time. Levels: >>> + >>> + 0 - panic >>> + 1 - critical >>> + 2 - error >>> + 3 - warning >>> + 4 - note >>> + 5 - info >>> + 6 - detail >>> + 7 - debug >> >> >> Please do not invent our own for U-Boot. >> Just use Linux log level. >> >> 0 (KERN_EMERG) system is unusable >> 1 (KERN_ALERT) action must be taken immediately >> 2 (KERN_CRIT) critical conditions >> 3 (KERN_ERR) error conditions >> 4 (KERN_WARNING) warning conditions >> 5 (KERN_NOTICE) normal but significant condition >> 6 (KERN_INFO) informational >> 7 (KERN_DEBUG) debug-level messages > > Yes I looked hard at that. The first three seem hard to distinguish in > U-Boot, but we can keep them I suppose. But most of my problem is with > the last two. INFO is what I plan to use for normal printf() output. > DEBUG is obviously for debugging and often involves vaste amounts of > stuff (e.g. logging every access to an MMC peripheral). We need > something in between. It could list the accesses to device at a high > level (e.g API calls) but not every little register access. > > So I don't think the Linux levels are suitable at the high end. We > could go up to 8 I suppose, instead of trying to save one at the > bottom? In fact, Linux has one more for debug. dev_vdbg() is widely used in Linux. If you like, we can add one more level: 8 (KERN_VDEBUG) verbose debug messages Perhaps, logging every access to an MMC peripheral might belong to the vdbg level. BTW, what do you mean "INFO is what I plan to use for normal printf() output" Is that mean printf() is equivalent to pr_info()? If loglevel is 6 or smaller, will all print() be silent? If so, probably we can not use command line interface. >> >> >> >> >>> + >>> +/** >>> + * log_dispatch() - Send a log record to all log devices for processing >>> + * >>> + * The log record is sent to each log device in turn, skipping those which have >>> + * filters which block the record >>> + * >>> + * @rec: Log record to dispatch >>> + * @return 0 (meaning success) >>> + */ >>> +static int log_dispatch(struct log_rec *rec) >>> +{ >>> + struct log_device *ldev; >>> + >>> + list_for_each_entry(ldev, &gd->log_head, sibling_node) { >>> + if (log_passes_filters(ldev, rec)) >>> + ldev->drv->emit(ldev, rec); >>> + } >>> + >>> + return 0; >>> +} >>> + >>> +int _log(enum log_category_t cat, enum log_level_t level, const char *file, >>> + int line, const char *func, const char *fmt, ...) >>> +{ >>> + char buf[CONFIG_SYS_CBSIZE]; >>> + struct log_rec rec; >>> + va_list args; >>> + >>> + rec.cat = cat; >>> + rec.level = level; >>> + rec.file = file; >>> + rec.line = line; >>> + rec.func = func; >>> + va_start(args, fmt); >>> + vsnprintf(buf, sizeof(buf), fmt, args); >>> + va_end(args); >>> + rec.msg = buf; >>> + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { >>> + if (gd) >>> + gd->log_drop_count++; >>> + return -ENOSYS; >>> + } >>> + log_dispatch(&rec); >>> + >>> + return 0; >>> +} >>> + >>> +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], >>> + enum log_level_t max_level, const char *file_list) >>> +{ >>> + struct log_filter *filt; >>> + struct log_device *ldev; >>> + int i; >>> + >>> + ldev = log_device_find_by_name(drv_name); >>> + if (!ldev) >>> + return -ENOENT; >>> + filt = (struct log_filter *)calloc(1, sizeof(*filt)); >>> + if (!filt) >>> + return -ENOMEM; >>> + >>> + if (cat_list) { >>> + filt->flags |= LOGFF_HAS_CAT; >>> + for (i = 0; ; i++) { >>> + if (i == ARRAY_SIZE(filt->cat_list)) >>> + return -ENOSPC; >>> + filt->cat_list[i] = cat_list[i]; >>> + if (cat_list[i] == LOGC_END) >>> + break; >>> + } >>> + } >>> + filt->max_level = max_level; >>> + if (file_list) { >>> + filt->file_list = strdup(file_list); >>> + if (!filt->file_list) >>> + goto nomem; >>> + } >>> + filt->filter_num = ldev->next_filter_num++; >>> + INIT_LIST_HEAD(&filt->sibling_node); >>> + list_add_tail(&filt->sibling_node, &ldev->filter_head); >>> + >>> + return filt->filter_num; >>> + >>> +nomem: >>> + free(filt); >>> + return -ENOMEM; >>> +} >>> + >>> +int log_remove_filter(const char *drv_name, int filter_num) >>> +{ >>> + struct log_filter *filt; >>> + struct log_device *ldev; >>> + >>> + ldev = log_device_find_by_name(drv_name); >>> + if (!ldev) >>> + return -ENOENT; >>> + >>> + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { >>> + if (filt->filter_num == filter_num) { >>> + list_del(&filt->sibling_node); >>> + free(filt); >>> + >>> + return 0; >>> + } >>> + } >>> + >>> + return -ENOENT; >>> +} >> >> >> I am not sure if this luxury filter is needed. >> After all, the purpose is debugging. >> The printf() debugging is useful, but only during testing. >> Once quality code is established, most of debug message should >> generally be removed from upstream code. > > But not logging, and this is the point. It is very useful to have > basic logging information recorded for every boot, and the normal > printf() output is not detailed enough. For example for verified boot > I want to see details about boot failures and what went wrong (key > verification, etc.). This should be warn level, (or notice at least) not info. > So I expect that at least INFO (and probably > DETAIL) logging would be useful to record for such a system, even if > it does not appear on the console (in fact the console would normally > be disabled in such a system). OK. Logging is useful, but your example will be used with info level. I still do not understand the necessity of category / file filtering. >> >> >> >>> +int log_init(void) >>> +{ >>> + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); >>> + const int count = ll_entry_count(struct log_driver, log_driver); >>> + struct log_driver *end = drv + count; >>> + >>> + /* >>> + * We cannot add runtime data to the driver since it is likely stored >>> + * in rodata. Instead, set up a 'device' corresponding to each driver. >>> + * We only support having a single device. >>> + */ >>> + INIT_LIST_HEAD((struct list_head *)&gd->log_head); >>> + while (drv < end) { >>> + struct log_device *ldev; >>> + >>> + ldev = calloc(1, sizeof(*ldev)); >>> + if (!ldev) { >>> + debug("%s: Cannot allocate memory\n", __func__); >>> + return -ENOMEM; >>> + } >>> + INIT_LIST_HEAD(&ldev->sibling_node); >> >> This INIT_LIST_HEAD() is unneeded. > > How come? If I don't do that how will the list be set up? Because ldev->sibling_node is not a list_head. It is used as a list node. See include/linux/list.h for the implementation of list_add_tail(). The argument "head" must be initialized in advance, but "new" does not need initialization. >> >> >> >>> + INIT_LIST_HEAD(&ldev->filter_head); >>> + ldev->drv = drv; >>> + list_add_tail(&ldev->sibling_node, >>> + (struct list_head *)&gd->log_head); Here, gd->log_head is a head, so INIT_LIST_HEAD((struct list_head *)&gd->log_head); is correct. INIT_LIST_HEAD(&ldev->sibling_node); is non-sense. >> I know that this (struct list_head *) cast is needed, >> but it is very unfortunate. >> I believe gd_t is design mistake in the first place, >> but U-Boot has gone to unfixable already... > > With driver model I added DM_ROOT_NON_CONST. I suppose we could use > something like that. > > But perhaps we should start dropping the 'volatile' in gd? I'm not > sure why it is needed. Me neither. >> >> >> >> >> >>> +#if CONFIG_VAL(LOG_MAX_LEVEL) >>> +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) >>> +#else >>> +#define _LOG_MAX_LEVEL LOGL_INFO >>> +#endif >> >> >> I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). >> From your Kconfig entry, >> >> 0 - panic >> 1 - critical >> 2 - error >> 3 - warning >> 4 - note >> 5 - info >> 6 - detail >> 7 - debug >> >> I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value >> range 0 to 7. >> >> If the log level is 0 (= critial), the conditional is false, so >> _LOG_MAX_LEVEL is set to "info" level. >> >> Why is this #if necessary? > > If we don't have CONFIG_LOG enabled then this value will not exist. > This implementation is wrong. You are abusing the fact that U-Boot does not specify -Wundef option. --------------------->8----------------- -Wundef Warn if an undefined identifier is evaluated in an #if directive. Such identifiers are replaced with zero. --------------------->8----------------- Right, U-Boot does not give -Wundef, but it is just because -Wundef causes too many warnings. Ideally, we should fix the code, then enable the option like Linux. We should use #ifdef for testing a option that may or may not be defined. Using #if for options that may not be defined is a bad coding way.
2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich <philipp.tomsich@theobroma-systems.com>: > Masahiro & Simon, > >> On 20 Sep 2017, at 15:49, Simon Glass <sjg@chromium.org> wrote: >> >> Hi Masahiro, >> >> On 19 September 2017 at 20:51, Masahiro Yamada >> <yamada.masahiro@socionext.com> wrote: >>> Hi Simon, >>> >>> >>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >>> >>>> >>>> +menu "Logging" >>>> + >>>> +config LOG >>>> + bool "Enable logging support" >>>> + help >>>> + This enables support for logging of status and debug messages. These >>>> + can be displayed on the console, recorded in a memory buffer, or >>>> + discarded if not needed. Logging supports various categories and >>>> + levels of severity. >>>> + >>>> +config SPL_LOG >>>> + bool "Enable logging support in SPL" >>>> + help >>>> + This enables support for logging of status and debug messages. These >>>> + can be displayed on the console, recorded in a memory buffer, or >>>> + discarded if not needed. Logging supports various categories and >>>> + levels of severity. >>> >>> >>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >>> >>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >>> when building for TPL. >>> >>> Since that commit, if you add SPL_ prefixed option, >>> you need to add a TPL_ one as well. >>> >>> I cannot believe why such a commit was accepted. >> >> Well either way is strange. it is strange that SPL is enabled for TPL >> when really they are separate. >> >> We could revert that commit. But how do you think all of this SPL/TPL >> control should actually work? What is intended? >> >> But I'm OK with not having logging in TPL until we need it. > > If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into > size issues for TPL and the $(SPL_TPL_) mechanism will not match the > CONFIG_IS_ENABLED() mechanism. > > I don’t think that anyone will miss this much in TPL and that this can be > safely left off for TPL (if space was not at a premium in TPL, then why > have a TPL at all…) The motivation of TPL is the image size is really limited for the secondary boot loader in some cases. Instead of: SPL -> TPL -> U-Boot full I'd rather want to see: <something> -> SPL -> U-Boot full <something> is implemented in an ad-hoc way under board or soc directory. If the space is premium, there is no room for DM, DT-ctrl in the <something>. Then, remove the current TPL support. It was only some old freescale boards that used TPL, so I was expecting they would die out sooner or later. Recently, lion-rk3368_defconfig was added wit TPL. Other rk3368 boards do not enable TPL. Why does that board need TPL? >>> >>> >>> >>> >>>> +config LOG_MAX_LEVEL >>>> + int "Maximum log level to record" >>>> + depends on LOG >>>> + default 5 >>>> + help >>>> + This selects the maximum log level that will be recorded. Any value >>>> + higher than this will be ignored. If possible log statements below >>>> + this level will be discarded at build time. Levels: >>>> + >>>> + 0 - panic >>>> + 1 - critical >>>> + 2 - error >>>> + 3 - warning >>>> + 4 - note >>>> + 5 - info >>>> + 6 - detail >>>> + 7 - debug >>> >>> >>> Please do not invent our own for U-Boot. >>> Just use Linux log level. >>> >>> 0 (KERN_EMERG) system is unusable >>> 1 (KERN_ALERT) action must be taken immediately >>> 2 (KERN_CRIT) critical conditions >>> 3 (KERN_ERR) error conditions >>> 4 (KERN_WARNING) warning conditions >>> 5 (KERN_NOTICE) normal but significant condition >>> 6 (KERN_INFO) informational >>> 7 (KERN_DEBUG) debug-level messages >> >> Yes I looked hard at that. The first three seem hard to distinguish in >> U-Boot, but we can keep them I suppose. But most of my problem is with >> the last two. INFO is what I plan to use for normal printf() output. >> DEBUG is obviously for debugging and often involves vaste amounts of >> stuff (e.g. logging every access to an MMC peripheral). We need >> something in between. It could list the accesses to device at a high >> level (e.g API calls) but not every little register access. >> >> So I don't think the Linux levels are suitable at the high end. We >> could go up to 8 I suppose, instead of trying to save one at the >> bottom? > > I would expect KERN_NOTICE to be used for normal printf output, KERN_INFO > for more verbose output and DEBUG would be the granularity for tracing through > drivers (i.e. the MMC example given). > In my opinion, printf() and pr_*() should be different concept. printf() (and puts(), putc(), etc.) should be turned on/off by CONFIG_SILENT_CONSOLE. These are direct access to console, so they should always and immediately print messages unless CONFIG_SILENT_CONSOLE is defined. We may want to use the command interface regardless of CONFIG_LOG / CONFIG_LOGLEVEL. pr_*() are log functions that are controlled by CONFIG_LOGLEVEL. These can send the messages to the console directly, or to the ring buffer, or wherever implemented in the log device.
Masahiro, > On 20 Sep 2017, at 19:34, Masahiro Yamada <yamada.masahiro@socionext.com> wrote: > > 2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich > <philipp.tomsich@theobroma-systems.com>: >> Masahiro & Simon, >> >>> On 20 Sep 2017, at 15:49, Simon Glass <sjg@chromium.org> wrote: >>> >>> Hi Masahiro, >>> >>> On 19 September 2017 at 20:51, Masahiro Yamada >>> <yamada.masahiro@socionext.com> wrote: >>>> Hi Simon, >>>> >>>> >>>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >>>> >>>>> >>>>> +menu "Logging" >>>>> + >>>>> +config LOG >>>>> + bool "Enable logging support" >>>>> + help >>>>> + This enables support for logging of status and debug messages. These >>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>> + discarded if not needed. Logging supports various categories and >>>>> + levels of severity. >>>>> + >>>>> +config SPL_LOG >>>>> + bool "Enable logging support in SPL" >>>>> + help >>>>> + This enables support for logging of status and debug messages. These >>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>> + discarded if not needed. Logging supports various categories and >>>>> + levels of severity. >>>> >>>> >>>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >>>> >>>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >>>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >>>> when building for TPL. >>>> >>>> Since that commit, if you add SPL_ prefixed option, >>>> you need to add a TPL_ one as well. >>>> >>>> I cannot believe why such a commit was accepted. >>> >>> Well either way is strange. it is strange that SPL is enabled for TPL >>> when really they are separate. >>> >>> We could revert that commit. But how do you think all of this SPL/TPL >>> control should actually work? What is intended? >>> >>> But I'm OK with not having logging in TPL until we need it. >> >> If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into >> size issues for TPL and the $(SPL_TPL_) mechanism will not match the >> CONFIG_IS_ENABLED() mechanism. >> >> I don’t think that anyone will miss this much in TPL and that this can be >> safely left off for TPL (if space was not at a premium in TPL, then why >> have a TPL at all…) > > > The motivation of TPL is > the image size is really limited > for the secondary boot loader in some cases. > > > Instead of: > SPL -> TPL -> U-Boot full Note that this was retro-actively defined to be TPL -> SPL -> U-Boot full by Tom at some point and reiterated in https://lists.denx.de/pipermail/u-boot/2017-July/299266.html > I'd rather want to see: > <something> -> SPL -> U-Boot full I would agree, that the stage before the SPL could be chip-specific. However, this is unlikely to happen quickly as some of the infrastructure (e.g. OF_PLATDATA) would have to be easily available to this new TPL framework. > <something> is implemented in an ad-hoc way under board or soc directory. > If the space is premium, there is no room for DM, DT-ctrl in the <something>. > > Then, remove the current TPL support. > > > > It was only some old freescale boards that used TPL, > so I was expecting they would die out sooner or later. > > Recently, lion-rk3368_defconfig was added wit TPL. > > Other rk3368 boards do not enable TPL. Other RK3368 boards do not have DRAM init support yet (they still use the proprietary vendor blobs and then boot the full U-Boot stage). This is gated by the resource availability on Rockchip’s end to add support for those features of the DRAM controller that can not be tested on Lion. > Why does that board need TPL? The RK3368’s boot-ROM loads only 0x7000 bytes as its first stage and requires this to (a) set up clocking and (b) initialise the DRAM controller. The SPL-stage on the RK3368 then runs out of DRAM (still loaded by the boot-ROM), but the size-limit is somewhat relaxed. On the RK3368, we take the liberty of reusing as much framework code as possible in the TPL (resulting in 21k binary) and using OF_PLATDATA: the features reused include DM, DM_REGMAP, DM_SYSCON, DM_CLK, DM_RAM and DM_TIMER. With this, we can both use the same drivers as for SPL and full U-Boot and then have a SPL stage that does not rely of OF_PLATDATA (but has full OF_CONTROL). Note that TPL is required for most of the Rockchip boards, if we want to do the DRAM initialisation in U-Boot… those chips that already have their DRAM controller drivers merged, usually have a TPL stage (with the exception of the RK3399, which supports 192kB for its first stage). Regards, Philipp.
Hi Bin, On 20 September 2017 at 08:41, Bin Meng <bmeng.cn@gmail.com> wrote: > > Hi Simon, > > On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass <sjg@chromium.org> wrote: > > Hi Bin, > > > > On 17 September 2017 at 21:45, Bin Meng <bmeng.cn@gmail.com> wrote: > >> Hi Simon, > >> > >> On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass <sjg@chromium.org> wrote: > >>> Add the logging header file and implementation with some configuration > >>> options to control it. > >>> > >>> Signed-off-by: Simon Glass <sjg@chromium.org> > >>> --- > >>> > >>> MAINTAINERS | 9 ++ > >>> common/Kconfig | 56 +++++++++ > >>> common/Makefile | 1 + > >>> common/log.c | 246 +++++++++++++++++++++++++++++++++++++ > >>> include/asm-generic/global_data.h | 5 + > >>> include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- > >>> 6 files changed, 555 insertions(+), 9 deletions(-) > >>> create mode 100644 common/log.c > >>> > >>> diff --git a/MAINTAINERS b/MAINTAINERS > >>> index 04acf2b89d..eb420afa8d 100644 > >>> --- a/MAINTAINERS > >>> +++ b/MAINTAINERS > >>> @@ -290,6 +290,15 @@ S: Maintained > >>> T: git git://git.denx.de/u-boot-i2c.git > >>> F: drivers/i2c/ > >>> > >>> +LOGGING > >>> +M: Simon Glass <sjg@chromium.org> > >>> +S: Maintained > >>> +T: git git://git.denx.de/u-boot.git > >>> +F: common/log.c > >>> +F: cmd/log.c > >>> +F: test/log/log_test.c > >>> +F: test/py/tests/test_log.py > >> > >> test/log/log_test.c and test/py/tests/test_log.py have not been > >> introduced at this point. > > > > OK I can tweak that, > > [..] > > > >>> +/** > >>> + * struct log_driver - a driver which accepts and processes log records > >>> + * > >>> + * @name: Name of driver > >>> + */ > >>> +struct log_driver { > >>> + const char *name; > >>> + /** > >>> + * emit() - emit a log record > >>> + * > >>> + * Called by the log system to pass a log record to a particular driver > >>> + * for processing. The filter is checked before calling this function. > >>> + */ > >>> + int (*emit)(struct log_device *ldev, struct log_rec *rec); > >>> +}; > >>> + > >> > >> So we are creating a new type of non-DM driver which is log-specific? > >> How about we add this emit to the existing uclass driver that can be > >> used as the log driver? (eg: blk devices with file system?) > > > > Yes that's right. I think I can link it to DM once it starts up, but a > > logging of DM start-up is useful. > > > > Re your idea are you saying add an emit() method to UCLASS_BLK? > > > > Yep, something like > > #ifdef CONFIG_LOG > .log_emit = xxx_log_emit, > #endif > > Probably we need a flag to find out which driver provides such log > functionality. So what would the block driver do in that function? I guess I don't understand what it is for. Can you please give me more information? Regards, Simon
Hi Simon, On Thu, Sep 21, 2017 at 12:58 PM, Simon Glass <sjg@chromium.org> wrote: > Hi Bin, > > On 20 September 2017 at 08:41, Bin Meng <bmeng.cn@gmail.com> wrote: >> >> Hi Simon, >> >> On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass <sjg@chromium.org> wrote: >> > Hi Bin, >> > >> > On 17 September 2017 at 21:45, Bin Meng <bmeng.cn@gmail.com> wrote: >> >> Hi Simon, >> >> >> >> On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass <sjg@chromium.org> wrote: >> >>> Add the logging header file and implementation with some configuration >> >>> options to control it. >> >>> >> >>> Signed-off-by: Simon Glass <sjg@chromium.org> >> >>> --- >> >>> >> >>> MAINTAINERS | 9 ++ >> >>> common/Kconfig | 56 +++++++++ >> >>> common/Makefile | 1 + >> >>> common/log.c | 246 +++++++++++++++++++++++++++++++++++++ >> >>> include/asm-generic/global_data.h | 5 + >> >>> include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- >> >>> 6 files changed, 555 insertions(+), 9 deletions(-) >> >>> create mode 100644 common/log.c >> >>> >> >>> diff --git a/MAINTAINERS b/MAINTAINERS >> >>> index 04acf2b89d..eb420afa8d 100644 >> >>> --- a/MAINTAINERS >> >>> +++ b/MAINTAINERS >> >>> @@ -290,6 +290,15 @@ S: Maintained >> >>> T: git git://git.denx.de/u-boot-i2c.git >> >>> F: drivers/i2c/ >> >>> >> >>> +LOGGING >> >>> +M: Simon Glass <sjg@chromium.org> >> >>> +S: Maintained >> >>> +T: git git://git.denx.de/u-boot.git >> >>> +F: common/log.c >> >>> +F: cmd/log.c >> >>> +F: test/log/log_test.c >> >>> +F: test/py/tests/test_log.py >> >> >> >> test/log/log_test.c and test/py/tests/test_log.py have not been >> >> introduced at this point. >> > >> > OK I can tweak that, >> > [..] >> > >> >>> +/** >> >>> + * struct log_driver - a driver which accepts and processes log records >> >>> + * >> >>> + * @name: Name of driver >> >>> + */ >> >>> +struct log_driver { >> >>> + const char *name; >> >>> + /** >> >>> + * emit() - emit a log record >> >>> + * >> >>> + * Called by the log system to pass a log record to a particular driver >> >>> + * for processing. The filter is checked before calling this function. >> >>> + */ >> >>> + int (*emit)(struct log_device *ldev, struct log_rec *rec); >> >>> +}; >> >>> + >> >> >> >> So we are creating a new type of non-DM driver which is log-specific? >> >> How about we add this emit to the existing uclass driver that can be >> >> used as the log driver? (eg: blk devices with file system?) >> > >> > Yes that's right. I think I can link it to DM once it starts up, but a >> > logging of DM start-up is useful. >> > >> > Re your idea are you saying add an emit() method to UCLASS_BLK? >> > >> >> Yep, something like >> >> #ifdef CONFIG_LOG >> .log_emit = xxx_log_emit, >> #endif >> >> Probably we need a flag to find out which driver provides such log >> functionality. > > So what would the block driver do in that function? I guess I don't > understand what it is for. Can you please give me more information? > The blk driver can save the logs to a predefined block address for permanent storage. Or file system driver can send the logs to a file. Regards, Bin
Hi Bin, On 22 September 2017 at 07:37, Bin Meng <bmeng.cn@gmail.com> wrote: > Hi Simon, > > On Thu, Sep 21, 2017 at 12:58 PM, Simon Glass <sjg@chromium.org> wrote: >> Hi Bin, >> >> On 20 September 2017 at 08:41, Bin Meng <bmeng.cn@gmail.com> wrote: >>> >>> Hi Simon, >>> >>> On Wed, Sep 20, 2017 at 9:50 PM, Simon Glass <sjg@chromium.org> wrote: >>> > Hi Bin, >>> > >>> > On 17 September 2017 at 21:45, Bin Meng <bmeng.cn@gmail.com> wrote: >>> >> Hi Simon, >>> >> >>> >> On Sun, Sep 17, 2017 at 5:23 AM, Simon Glass <sjg@chromium.org> wrote: >>> >>> Add the logging header file and implementation with some configuration >>> >>> options to control it. >>> >>> >>> >>> Signed-off-by: Simon Glass <sjg@chromium.org> >>> >>> --- >>> >>> >>> >>> MAINTAINERS | 9 ++ >>> >>> common/Kconfig | 56 +++++++++ >>> >>> common/Makefile | 1 + >>> >>> common/log.c | 246 +++++++++++++++++++++++++++++++++++++ >>> >>> include/asm-generic/global_data.h | 5 + >>> >>> include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- >>> >>> 6 files changed, 555 insertions(+), 9 deletions(-) >>> >>> create mode 100644 common/log.c >>> >>> >>> >>> diff --git a/MAINTAINERS b/MAINTAINERS >>> >>> index 04acf2b89d..eb420afa8d 100644 >>> >>> --- a/MAINTAINERS >>> >>> +++ b/MAINTAINERS >>> >>> @@ -290,6 +290,15 @@ S: Maintained >>> >>> T: git git://git.denx.de/u-boot-i2c.git >>> >>> F: drivers/i2c/ >>> >>> >>> >>> +LOGGING >>> >>> +M: Simon Glass <sjg@chromium.org> >>> >>> +S: Maintained >>> >>> +T: git git://git.denx.de/u-boot.git >>> >>> +F: common/log.c >>> >>> +F: cmd/log.c >>> >>> +F: test/log/log_test.c >>> >>> +F: test/py/tests/test_log.py >>> >> >>> >> test/log/log_test.c and test/py/tests/test_log.py have not been >>> >> introduced at this point. >>> > >>> > OK I can tweak that, >>> > [..] >>> > >>> >>> +/** >>> >>> + * struct log_driver - a driver which accepts and processes log records >>> >>> + * >>> >>> + * @name: Name of driver >>> >>> + */ >>> >>> +struct log_driver { >>> >>> + const char *name; >>> >>> + /** >>> >>> + * emit() - emit a log record >>> >>> + * >>> >>> + * Called by the log system to pass a log record to a particular driver >>> >>> + * for processing. The filter is checked before calling this function. >>> >>> + */ >>> >>> + int (*emit)(struct log_device *ldev, struct log_rec *rec); >>> >>> +}; >>> >>> + >>> >> >>> >> So we are creating a new type of non-DM driver which is log-specific? >>> >> How about we add this emit to the existing uclass driver that can be >>> >> used as the log driver? (eg: blk devices with file system?) >>> > >>> > Yes that's right. I think I can link it to DM once it starts up, but a >>> > logging of DM start-up is useful. >>> > >>> > Re your idea are you saying add an emit() method to UCLASS_BLK? >>> > >>> >>> Yep, something like >>> >>> #ifdef CONFIG_LOG >>> .log_emit = xxx_log_emit, >>> #endif >>> >>> Probably we need a flag to find out which driver provides such log >>> functionality. >> >> So what would the block driver do in that function? I guess I don't >> understand what it is for. Can you please give me more information? >> > > The blk driver can save the logs to a predefined block address for > permanent storage. Or file system driver can send the logs to a file. OK I see. IMO this is not really a function of a block device. I don't see what an emit() method in a USB block device (for example) would do differently from one in a SATA block device. We could have a single 'log_blk' driver which: - allows configuration of what blocks are used for the log - writes blocks there (perhaps wrapping if it runs out of space) For file systems we could have a 'log_fs' driver which: - allows configuration of log file path - writes blocks into that file (perhaps starting a new file and rotating the log if things get over a limit Regards, Simon
Hi Masahiro, On 20 September 2017 at 11:19, Masahiro Yamada <yamada.masahiro@socionext.com> wrote: > Hi Simon, > > > 2017-09-20 22:49 GMT+09:00 Simon Glass <sjg@chromium.org>: >> Hi Masahiro, >> >> On 19 September 2017 at 20:51, Masahiro Yamada >> <yamada.masahiro@socionext.com> wrote: >>> Hi Simon, >>> >>> >>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >>> >>>> >>>> +menu "Logging" >>>> + >>>> +config LOG >>>> + bool "Enable logging support" >>>> + help >>>> + This enables support for logging of status and debug messages. These >>>> + can be displayed on the console, recorded in a memory buffer, or >>>> + discarded if not needed. Logging supports various categories and >>>> + levels of severity. >>>> + >>>> +config SPL_LOG >>>> + bool "Enable logging support in SPL" >>>> + help >>>> + This enables support for logging of status and debug messages. These >>>> + can be displayed on the console, recorded in a memory buffer, or >>>> + discarded if not needed. Logging supports various categories and >>>> + levels of severity. >>> >>> >>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >>> >>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >>> when building for TPL. >>> >>> Since that commit, if you add SPL_ prefixed option, >>> you need to add a TPL_ one as well. >>> >>> I cannot believe why such a commit was accepted. >> >> Well either way is strange. it is strange that SPL is enabled for TPL >> when really they are separate. >> >> We could revert that commit. But how do you think all of this SPL/TPL >> control should actually work? What is intended? >> >> But I'm OK with not having logging in TPL until we need it. > > I will explain it in another mail. > > >>> >>> >>> >>> >>>> +config LOG_MAX_LEVEL >>>> + int "Maximum log level to record" >>>> + depends on LOG >>>> + default 5 >>>> + help >>>> + This selects the maximum log level that will be recorded. Any value >>>> + higher than this will be ignored. If possible log statements below >>>> + this level will be discarded at build time. Levels: >>>> + >>>> + 0 - panic >>>> + 1 - critical >>>> + 2 - error >>>> + 3 - warning >>>> + 4 - note >>>> + 5 - info >>>> + 6 - detail >>>> + 7 - debug >>> >>> >>> Please do not invent our own for U-Boot. >>> Just use Linux log level. >>> >>> 0 (KERN_EMERG) system is unusable >>> 1 (KERN_ALERT) action must be taken immediately >>> 2 (KERN_CRIT) critical conditions >>> 3 (KERN_ERR) error conditions >>> 4 (KERN_WARNING) warning conditions >>> 5 (KERN_NOTICE) normal but significant condition >>> 6 (KERN_INFO) informational >>> 7 (KERN_DEBUG) debug-level messages >> >> Yes I looked hard at that. The first three seem hard to distinguish in >> U-Boot, but we can keep them I suppose. But most of my problem is with >> the last two. INFO is what I plan to use for normal printf() output. >> DEBUG is obviously for debugging and often involves vaste amounts of >> stuff (e.g. logging every access to an MMC peripheral). We need >> something in between. It could list the accesses to device at a high >> level (e.g API calls) but not every little register access. >> >> So I don't think the Linux levels are suitable at the high end. We >> could go up to 8 I suppose, instead of trying to save one at the >> bottom? > > > In fact, Linux has one more for debug. > dev_vdbg() is widely used in Linux. > > If you like, we can add one more level: > > 8 (KERN_VDEBUG) verbose debug messages > > > Perhaps, logging every access to an MMC peripheral > might belong to the vdbg level. I like the idea of having a log level for message contents (bytes) and another for I/O access. So I will add two more in v2. > > > > BTW, what do you mean "INFO is what I plan to use for normal printf() output" > > Is that mean printf() is equivalent to pr_info()? > If loglevel is 6 or smaller, will all print() be silent? > If so, probably we can not use command line interface. I mean that I want to (later) add a feature that logs normal printf() output. If the console is silent then it would still be logged. Maybe one day log functions will be used instead of printf(), but for now this provides a useful way to make things wok. > > > > > >>> >>> >>> >>> >>>> + >>>> +/** >>>> + * log_dispatch() - Send a log record to all log devices for processing >>>> + * >>>> + * The log record is sent to each log device in turn, skipping those which have >>>> + * filters which block the record >>>> + * >>>> + * @rec: Log record to dispatch >>>> + * @return 0 (meaning success) >>>> + */ >>>> +static int log_dispatch(struct log_rec *rec) >>>> +{ >>>> + struct log_device *ldev; >>>> + >>>> + list_for_each_entry(ldev, &gd->log_head, sibling_node) { >>>> + if (log_passes_filters(ldev, rec)) >>>> + ldev->drv->emit(ldev, rec); >>>> + } >>>> + >>>> + return 0; >>>> +} >>>> + >>>> +int _log(enum log_category_t cat, enum log_level_t level, const char *file, >>>> + int line, const char *func, const char *fmt, ...) >>>> +{ >>>> + char buf[CONFIG_SYS_CBSIZE]; >>>> + struct log_rec rec; >>>> + va_list args; >>>> + >>>> + rec.cat = cat; >>>> + rec.level = level; >>>> + rec.file = file; >>>> + rec.line = line; >>>> + rec.func = func; >>>> + va_start(args, fmt); >>>> + vsnprintf(buf, sizeof(buf), fmt, args); >>>> + va_end(args); >>>> + rec.msg = buf; >>>> + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { >>>> + if (gd) >>>> + gd->log_drop_count++; >>>> + return -ENOSYS; >>>> + } >>>> + log_dispatch(&rec); >>>> + >>>> + return 0; >>>> +} >>>> + >>>> +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], >>>> + enum log_level_t max_level, const char *file_list) >>>> +{ >>>> + struct log_filter *filt; >>>> + struct log_device *ldev; >>>> + int i; >>>> + >>>> + ldev = log_device_find_by_name(drv_name); >>>> + if (!ldev) >>>> + return -ENOENT; >>>> + filt = (struct log_filter *)calloc(1, sizeof(*filt)); >>>> + if (!filt) >>>> + return -ENOMEM; >>>> + >>>> + if (cat_list) { >>>> + filt->flags |= LOGFF_HAS_CAT; >>>> + for (i = 0; ; i++) { >>>> + if (i == ARRAY_SIZE(filt->cat_list)) >>>> + return -ENOSPC; >>>> + filt->cat_list[i] = cat_list[i]; >>>> + if (cat_list[i] == LOGC_END) >>>> + break; >>>> + } >>>> + } >>>> + filt->max_level = max_level; >>>> + if (file_list) { >>>> + filt->file_list = strdup(file_list); >>>> + if (!filt->file_list) >>>> + goto nomem; >>>> + } >>>> + filt->filter_num = ldev->next_filter_num++; >>>> + INIT_LIST_HEAD(&filt->sibling_node); >>>> + list_add_tail(&filt->sibling_node, &ldev->filter_head); >>>> + >>>> + return filt->filter_num; >>>> + >>>> +nomem: >>>> + free(filt); >>>> + return -ENOMEM; >>>> +} >>>> + >>>> +int log_remove_filter(const char *drv_name, int filter_num) >>>> +{ >>>> + struct log_filter *filt; >>>> + struct log_device *ldev; >>>> + >>>> + ldev = log_device_find_by_name(drv_name); >>>> + if (!ldev) >>>> + return -ENOENT; >>>> + >>>> + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { >>>> + if (filt->filter_num == filter_num) { >>>> + list_del(&filt->sibling_node); >>>> + free(filt); >>>> + >>>> + return 0; >>>> + } >>>> + } >>>> + >>>> + return -ENOENT; >>>> +} >>> >>> >>> I am not sure if this luxury filter is needed. >>> After all, the purpose is debugging. >>> The printf() debugging is useful, but only during testing. >>> Once quality code is established, most of debug message should >>> generally be removed from upstream code. >> >> But not logging, and this is the point. It is very useful to have >> basic logging information recorded for every boot, and the normal >> printf() output is not detailed enough. For example for verified boot >> I want to see details about boot failures and what went wrong (key >> verification, etc.). > > This should be warn level, (or notice at least) > not info. Sure, but the the fact that it failed is not very useful. We know that. What is useful is the events leading up to that failure and those are probably not written to the console. For example if a key to verify was it because the key was invalid, the image was not found, the TPM had wrong data, ...? > > >> So I expect that at least INFO (and probably >> DETAIL) logging would be useful to record for such a system, even if >> it does not appear on the console (in fact the console would normally >> be disabled in such a system). > > OK. Logging is useful, but your example will be used > with info level. > > I still do not understand the necessity of > category / file filtering. Category is for knowing which subsystem generated the log message. It makes no sense to log MMC messages if you are hunting for an error in USB. It clutters up the log. Also, it allows a post-processing tool to filter log messages in a sensible, human-friendly way, even if both categories are recorded. File filtering is useful I think in the interim, while nothing uses categories. We can filter on particular files to pick out the messages from those files. Even when we do have proper categories everywhere, it might still be useful. I am not sure yet. > > >>> >>> >>> >>>> +int log_init(void) >>>> +{ >>>> + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); >>>> + const int count = ll_entry_count(struct log_driver, log_driver); >>>> + struct log_driver *end = drv + count; >>>> + >>>> + /* >>>> + * We cannot add runtime data to the driver since it is likely stored >>>> + * in rodata. Instead, set up a 'device' corresponding to each driver. >>>> + * We only support having a single device. >>>> + */ >>>> + INIT_LIST_HEAD((struct list_head *)&gd->log_head); >>>> + while (drv < end) { >>>> + struct log_device *ldev; >>>> + >>>> + ldev = calloc(1, sizeof(*ldev)); >>>> + if (!ldev) { >>>> + debug("%s: Cannot allocate memory\n", __func__); >>>> + return -ENOMEM; >>>> + } >>>> + INIT_LIST_HEAD(&ldev->sibling_node); >>> >>> This INIT_LIST_HEAD() is unneeded. >> >> How come? If I don't do that how will the list be set up? > > Because ldev->sibling_node is not a list_head. > It is used as a list node. > > > See include/linux/list.h > for the implementation of list_add_tail(). > > The argument "head" must be initialized in advance, > but "new" does not need initialization. OK I see. Not at all obvious from reading the header file comments. > > > >>> >>> >>> >>>> + INIT_LIST_HEAD(&ldev->filter_head); >>>> + ldev->drv = drv; >>>> + list_add_tail(&ldev->sibling_node, >>>> + (struct list_head *)&gd->log_head); > > Here, gd->log_head is a head, so > INIT_LIST_HEAD((struct list_head *)&gd->log_head); > is correct. > > INIT_LIST_HEAD(&ldev->sibling_node); > is non-sense. > > > > > >>> I know that this (struct list_head *) cast is needed, >>> but it is very unfortunate. >>> I believe gd_t is design mistake in the first place, >>> but U-Boot has gone to unfixable already... >> >> With driver model I added DM_ROOT_NON_CONST. I suppose we could use >> something like that. >> >> But perhaps we should start dropping the 'volatile' in gd? I'm not >> sure why it is needed. > > Me neither. OK well something to add to the list. > > >>> >>> >>> >>> >>> >>>> +#if CONFIG_VAL(LOG_MAX_LEVEL) >>>> +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) >>>> +#else >>>> +#define _LOG_MAX_LEVEL LOGL_INFO >>>> +#endif >>> >>> >>> I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL). >>> From your Kconfig entry, >>> >>> 0 - panic >>> 1 - critical >>> 2 - error >>> 3 - warning >>> 4 - note >>> 5 - info >>> 6 - detail >>> 7 - debug >>> >>> I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value >>> range 0 to 7. >>> >>> If the log level is 0 (= critial), the conditional is false, so >>> _LOG_MAX_LEVEL is set to "info" level. >>> >>> Why is this #if necessary? >> >> If we don't have CONFIG_LOG enabled then this value will not exist. >> > > This implementation is wrong. > > You are abusing the fact that > U-Boot does not specify -Wundef option. > > > --------------------->8----------------- > -Wundef > Warn if an undefined identifier is evaluated in an #if directive. > Such identifiers are replaced with zero. > --------------------->8----------------- > > > > Right, U-Boot does not give -Wundef, > but it is just because -Wundef causes too many warnings. > > Ideally, we should fix the code, > then enable the option like Linux. > > We should use #ifdef for testing a option that may or may not be defined. > Using #if for options that may not be defined is a bad coding way. > OK I see, will fix. Regards, Simon
Hi Philipp, 2017-09-21 2:51 GMT+09:00 Dr. Philipp Tomsich <philipp.tomsich@theobroma-systems.com>: > Masahiro, > >> On 20 Sep 2017, at 19:34, Masahiro Yamada <yamada.masahiro@socionext.com> wrote: >> >> 2017-09-20 23:37 GMT+09:00 Dr. Philipp Tomsich >> <philipp.tomsich@theobroma-systems.com>: >>> Masahiro & Simon, >>> >>>> On 20 Sep 2017, at 15:49, Simon Glass <sjg@chromium.org> wrote: >>>> >>>> Hi Masahiro, >>>> >>>> On 19 September 2017 at 20:51, Masahiro Yamada >>>> <yamada.masahiro@socionext.com> wrote: >>>>> Hi Simon, >>>>> >>>>> >>>>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >>>>> >>>>>> >>>>>> +menu "Logging" >>>>>> + >>>>>> +config LOG >>>>>> + bool "Enable logging support" >>>>>> + help >>>>>> + This enables support for logging of status and debug messages. These >>>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>>> + discarded if not needed. Logging supports various categories and >>>>>> + levels of severity. >>>>>> + >>>>>> +config SPL_LOG >>>>>> + bool "Enable logging support in SPL" >>>>>> + help >>>>>> + This enables support for logging of status and debug messages. These >>>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>>> + discarded if not needed. Logging supports various categories and >>>>>> + levels of severity. >>>>> >>>>> >>>>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >>>>> >>>>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >>>>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >>>>> when building for TPL. >>>>> >>>>> Since that commit, if you add SPL_ prefixed option, >>>>> you need to add a TPL_ one as well. >>>>> >>>>> I cannot believe why such a commit was accepted. >>>> >>>> Well either way is strange. it is strange that SPL is enabled for TPL >>>> when really they are separate. >>>> >>>> We could revert that commit. But how do you think all of this SPL/TPL >>>> control should actually work? What is intended? >>>> >>>> But I'm OK with not having logging in TPL until we need it. >>> >>> If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into >>> size issues for TPL and the $(SPL_TPL_) mechanism will not match the >>> CONFIG_IS_ENABLED() mechanism. >>> >>> I don’t think that anyone will miss this much in TPL and that this can be >>> safely left off for TPL (if space was not at a premium in TPL, then why >>> have a TPL at all…) >> >> >> The motivation of TPL is >> the image size is really limited >> for the secondary boot loader in some cases. >> >> >> Instead of: >> SPL -> TPL -> U-Boot full > > Note that this was retro-actively defined to be > TPL -> SPL -> U-Boot full > by Tom at some point and reiterated in > https://lists.denx.de/pipermail/u-boot/2017-July/299266.html Thanks. I did not know that this flip had already happened. In fact, I am probably the first man who suggested it. Here is the history. 1. Scott Wood introduced TPL to support some freescale chip, which had only 4KB memory footprint for the second loader https://www.denx.de/wiki/pub/U-Boot/MiniSummitELCE2013/tpl-presentation.pdf At this point, the boot order was: SPL -> TPL -> U-Boot And TPL means "Tertiary Program Loader". 2. I imported Kbuild and Kconfig to U-Boot. 3. During the migration of Kconfig, I noticed switching the order of SPL / TPL has advantages. The "Tiny Program Loader" was mentioned first in this mail: https://lists.denx.de/pipermail/u-boot/2015-August/222900.html 4. When Simon started to move CONFIG_TPL, I suggested it once again http://patchwork.ozlabs.org/patch/662396/ So, I'd like to make "TPL -> SPL" legitimate. More ideally, I hope this is done outside of luxury frameworks. No DM, no OF_CONTROL, then CONFIG_TPL_* are all gone.
Hi Simon, 2017-09-27 4:10 GMT+09:00 Simon Glass <sjg@chromium.org>: > Hi Masahiro, > > On 20 September 2017 at 11:19, Masahiro Yamada > <yamada.masahiro@socionext.com> wrote: >> Hi Simon, >> >> >> 2017-09-20 22:49 GMT+09:00 Simon Glass <sjg@chromium.org>: >>> Hi Masahiro, >>> >>> On 19 September 2017 at 20:51, Masahiro Yamada >>> <yamada.masahiro@socionext.com> wrote: >>>> Hi Simon, >>>> >>>> >>>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >>>> >>>>> >>>>> +menu "Logging" >>>>> + >>>>> +config LOG >>>>> + bool "Enable logging support" >>>>> + help >>>>> + This enables support for logging of status and debug messages. These >>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>> + discarded if not needed. Logging supports various categories and >>>>> + levels of severity. >>>>> + >>>>> +config SPL_LOG >>>>> + bool "Enable logging support in SPL" >>>>> + help >>>>> + This enables support for logging of status and debug messages. These >>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>> + discarded if not needed. Logging supports various categories and >>>>> + levels of severity. >>>> >>>> >>>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >>>> >>>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >>>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >>>> when building for TPL. >>>> >>>> Since that commit, if you add SPL_ prefixed option, >>>> you need to add a TPL_ one as well. >>>> >>>> I cannot believe why such a commit was accepted. >>> >>> Well either way is strange. it is strange that SPL is enabled for TPL >>> when really they are separate. >>> >>> We could revert that commit. But how do you think all of this SPL/TPL >>> control should actually work? What is intended? >>> >>> But I'm OK with not having logging in TPL until we need it. >> >> I will explain it in another mail. >> >> >>>> >>>> >>>> >>>> >>>>> +config LOG_MAX_LEVEL >>>>> + int "Maximum log level to record" >>>>> + depends on LOG >>>>> + default 5 >>>>> + help >>>>> + This selects the maximum log level that will be recorded. Any value >>>>> + higher than this will be ignored. If possible log statements below >>>>> + this level will be discarded at build time. Levels: >>>>> + >>>>> + 0 - panic >>>>> + 1 - critical >>>>> + 2 - error >>>>> + 3 - warning >>>>> + 4 - note >>>>> + 5 - info >>>>> + 6 - detail >>>>> + 7 - debug >>>> >>>> >>>> Please do not invent our own for U-Boot. >>>> Just use Linux log level. >>>> >>>> 0 (KERN_EMERG) system is unusable >>>> 1 (KERN_ALERT) action must be taken immediately >>>> 2 (KERN_CRIT) critical conditions >>>> 3 (KERN_ERR) error conditions >>>> 4 (KERN_WARNING) warning conditions >>>> 5 (KERN_NOTICE) normal but significant condition >>>> 6 (KERN_INFO) informational >>>> 7 (KERN_DEBUG) debug-level messages >>> >>> Yes I looked hard at that. The first three seem hard to distinguish in >>> U-Boot, but we can keep them I suppose. But most of my problem is with >>> the last two. INFO is what I plan to use for normal printf() output. >>> DEBUG is obviously for debugging and often involves vaste amounts of >>> stuff (e.g. logging every access to an MMC peripheral). We need >>> something in between. It could list the accesses to device at a high >>> level (e.g API calls) but not every little register access. >>> >>> So I don't think the Linux levels are suitable at the high end. We >>> could go up to 8 I suppose, instead of trying to save one at the >>> bottom? >> >> >> In fact, Linux has one more for debug. >> dev_vdbg() is widely used in Linux. >> >> If you like, we can add one more level: >> >> 8 (KERN_VDEBUG) verbose debug messages >> >> >> Perhaps, logging every access to an MMC peripheral >> might belong to the vdbg level. > > I like the idea of having a log level for message contents (bytes) and > another for I/O access. So I will add two more in v2. > >> >> >> >> BTW, what do you mean "INFO is what I plan to use for normal printf() output" >> >> Is that mean printf() is equivalent to pr_info()? >> If loglevel is 6 or smaller, will all print() be silent? >> If so, probably we can not use command line interface. > > I mean that I want to (later) add a feature that logs normal printf() > output. If the console is silent then it would still be logged. Maybe > one day log functions will be used instead of printf(), but for now > this provides a useful way to make things wok. IMHO, printf() should be used for command line interface. All SoC files, board files should use pr_*(), and drivers dev_*(). >> >> >> >> >> >>>> >>>> >>>> >>>> >>>>> + >>>>> +/** >>>>> + * log_dispatch() - Send a log record to all log devices for processing >>>>> + * >>>>> + * The log record is sent to each log device in turn, skipping those which have >>>>> + * filters which block the record >>>>> + * >>>>> + * @rec: Log record to dispatch >>>>> + * @return 0 (meaning success) >>>>> + */ >>>>> +static int log_dispatch(struct log_rec *rec) >>>>> +{ >>>>> + struct log_device *ldev; >>>>> + >>>>> + list_for_each_entry(ldev, &gd->log_head, sibling_node) { >>>>> + if (log_passes_filters(ldev, rec)) >>>>> + ldev->drv->emit(ldev, rec); >>>>> + } >>>>> + >>>>> + return 0; >>>>> +} >>>>> + >>>>> +int _log(enum log_category_t cat, enum log_level_t level, const char *file, >>>>> + int line, const char *func, const char *fmt, ...) >>>>> +{ >>>>> + char buf[CONFIG_SYS_CBSIZE]; >>>>> + struct log_rec rec; >>>>> + va_list args; >>>>> + >>>>> + rec.cat = cat; >>>>> + rec.level = level; >>>>> + rec.file = file; >>>>> + rec.line = line; >>>>> + rec.func = func; >>>>> + va_start(args, fmt); >>>>> + vsnprintf(buf, sizeof(buf), fmt, args); >>>>> + va_end(args); >>>>> + rec.msg = buf; >>>>> + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { >>>>> + if (gd) >>>>> + gd->log_drop_count++; >>>>> + return -ENOSYS; >>>>> + } >>>>> + log_dispatch(&rec); >>>>> + >>>>> + return 0; >>>>> +} >>>>> + >>>>> +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], >>>>> + enum log_level_t max_level, const char *file_list) >>>>> +{ >>>>> + struct log_filter *filt; >>>>> + struct log_device *ldev; >>>>> + int i; >>>>> + >>>>> + ldev = log_device_find_by_name(drv_name); >>>>> + if (!ldev) >>>>> + return -ENOENT; >>>>> + filt = (struct log_filter *)calloc(1, sizeof(*filt)); >>>>> + if (!filt) >>>>> + return -ENOMEM; >>>>> + >>>>> + if (cat_list) { >>>>> + filt->flags |= LOGFF_HAS_CAT; >>>>> + for (i = 0; ; i++) { >>>>> + if (i == ARRAY_SIZE(filt->cat_list)) >>>>> + return -ENOSPC; >>>>> + filt->cat_list[i] = cat_list[i]; >>>>> + if (cat_list[i] == LOGC_END) >>>>> + break; >>>>> + } >>>>> + } >>>>> + filt->max_level = max_level; >>>>> + if (file_list) { >>>>> + filt->file_list = strdup(file_list); >>>>> + if (!filt->file_list) >>>>> + goto nomem; >>>>> + } >>>>> + filt->filter_num = ldev->next_filter_num++; >>>>> + INIT_LIST_HEAD(&filt->sibling_node); >>>>> + list_add_tail(&filt->sibling_node, &ldev->filter_head); >>>>> + >>>>> + return filt->filter_num; >>>>> + >>>>> +nomem: >>>>> + free(filt); >>>>> + return -ENOMEM; >>>>> +} >>>>> + >>>>> +int log_remove_filter(const char *drv_name, int filter_num) >>>>> +{ >>>>> + struct log_filter *filt; >>>>> + struct log_device *ldev; >>>>> + >>>>> + ldev = log_device_find_by_name(drv_name); >>>>> + if (!ldev) >>>>> + return -ENOENT; >>>>> + >>>>> + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { >>>>> + if (filt->filter_num == filter_num) { >>>>> + list_del(&filt->sibling_node); >>>>> + free(filt); >>>>> + >>>>> + return 0; >>>>> + } >>>>> + } >>>>> + >>>>> + return -ENOENT; >>>>> +} >>>> >>>> >>>> I am not sure if this luxury filter is needed. >>>> After all, the purpose is debugging. >>>> The printf() debugging is useful, but only during testing. >>>> Once quality code is established, most of debug message should >>>> generally be removed from upstream code. >>> >>> But not logging, and this is the point. It is very useful to have >>> basic logging information recorded for every boot, and the normal >>> printf() output is not detailed enough. For example for verified boot >>> I want to see details about boot failures and what went wrong (key >>> verification, etc.). >> >> This should be warn level, (or notice at least) >> not info. > > Sure, but the the fact that it failed is not very useful. We know > that. What is useful is the events leading up to that failure and > those are probably not written to the console. For example if a key to > verify was it because the key was invalid, the image was not found, > the TPM had wrong data, ...? > >> >> >>> So I expect that at least INFO (and probably >>> DETAIL) logging would be useful to record for such a system, even if >>> it does not appear on the console (in fact the console would normally >>> be disabled in such a system). >> >> OK. Logging is useful, but your example will be used >> with info level. >> >> I still do not understand the necessity of >> category / file filtering. > > Category is for knowing which subsystem generated the log message. It > makes no sense to log MMC messages if you are hunting for an error in > USB. It clutters up the log. Also, it allows a post-processing tool to > filter log messages in a sensible, human-friendly way, even if both > categories are recorded. I do not think we have much volume for notice or lower loglevel. The categorization is useful for debug level and you can see the right thing to do for example, in drivers/i2c/Makefile of Linux. ccflags-$(CONFIG_I2C_DEBUG_CORE) := -DDEBUG This is already established in Linux [1] Create an entry for CONFIG_FOO_DEBUG in Kconfig [2] Add ccflags-$(CONFIG_FOO_DEBUG) := -DDEBUG You can do likewise for DM-core, EFI, or whatever. > File filtering is useful I think in the interim, while nothing uses > categories. We can filter on particular files to pick out the messages > from those files. Even when we do have proper categories everywhere, > it might still be useful. I am not sure yet. File filter is pointless because we are generally supposed to add #define DEBUG to each file to make pr_dbg() effective.
Hi Masahiro, On 27 September 2017 at 11:11, Masahiro Yamada <yamada.masahiro@socionext.com> wrote: > Hi Simon, > > > 2017-09-27 4:10 GMT+09:00 Simon Glass <sjg@chromium.org>: >> Hi Masahiro, >> >> On 20 September 2017 at 11:19, Masahiro Yamada >> <yamada.masahiro@socionext.com> wrote: >>> Hi Simon, >>> >>> >>> 2017-09-20 22:49 GMT+09:00 Simon Glass <sjg@chromium.org>: >>>> Hi Masahiro, >>>> >>>> On 19 September 2017 at 20:51, Masahiro Yamada >>>> <yamada.masahiro@socionext.com> wrote: >>>>> Hi Simon, >>>>> >>>>> >>>>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>: >>>>> >>>>>> >>>>>> +menu "Logging" >>>>>> + >>>>>> +config LOG >>>>>> + bool "Enable logging support" >>>>>> + help >>>>>> + This enables support for logging of status and debug messages. These >>>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>>> + discarded if not needed. Logging supports various categories and >>>>>> + levels of severity. >>>>>> + >>>>>> +config SPL_LOG >>>>>> + bool "Enable logging support in SPL" >>>>>> + help >>>>>> + This enables support for logging of status and debug messages. These >>>>>> + can be displayed on the console, recorded in a memory buffer, or >>>>>> + discarded if not needed. Logging supports various categories and >>>>>> + levels of severity. >>>>> >>>>> >>>>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD. >>>>> >>>>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9, >>>>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG >>>>> when building for TPL. >>>>> >>>>> Since that commit, if you add SPL_ prefixed option, >>>>> you need to add a TPL_ one as well. >>>>> >>>>> I cannot believe why such a commit was accepted. >>>> >>>> Well either way is strange. it is strange that SPL is enabled for TPL >>>> when really they are separate. >>>> >>>> We could revert that commit. But how do you think all of this SPL/TPL >>>> control should actually work? What is intended? >>>> >>>> But I'm OK with not having logging in TPL until we need it. >>> >>> I will explain it in another mail. >>> >>> >>>>> >>>>> >>>>> >>>>> >>>>>> +config LOG_MAX_LEVEL >>>>>> + int "Maximum log level to record" >>>>>> + depends on LOG >>>>>> + default 5 >>>>>> + help >>>>>> + This selects the maximum log level that will be recorded. Any value >>>>>> + higher than this will be ignored. If possible log statements below >>>>>> + this level will be discarded at build time. Levels: >>>>>> + >>>>>> + 0 - panic >>>>>> + 1 - critical >>>>>> + 2 - error >>>>>> + 3 - warning >>>>>> + 4 - note >>>>>> + 5 - info >>>>>> + 6 - detail >>>>>> + 7 - debug >>>>> >>>>> >>>>> Please do not invent our own for U-Boot. >>>>> Just use Linux log level. >>>>> >>>>> 0 (KERN_EMERG) system is unusable >>>>> 1 (KERN_ALERT) action must be taken immediately >>>>> 2 (KERN_CRIT) critical conditions >>>>> 3 (KERN_ERR) error conditions >>>>> 4 (KERN_WARNING) warning conditions >>>>> 5 (KERN_NOTICE) normal but significant condition >>>>> 6 (KERN_INFO) informational >>>>> 7 (KERN_DEBUG) debug-level messages >>>> >>>> Yes I looked hard at that. The first three seem hard to distinguish in >>>> U-Boot, but we can keep them I suppose. But most of my problem is with >>>> the last two. INFO is what I plan to use for normal printf() output. >>>> DEBUG is obviously for debugging and often involves vaste amounts of >>>> stuff (e.g. logging every access to an MMC peripheral). We need >>>> something in between. It could list the accesses to device at a high >>>> level (e.g API calls) but not every little register access. >>>> >>>> So I don't think the Linux levels are suitable at the high end. We >>>> could go up to 8 I suppose, instead of trying to save one at the >>>> bottom? >>> >>> >>> In fact, Linux has one more for debug. >>> dev_vdbg() is widely used in Linux. >>> >>> If you like, we can add one more level: >>> >>> 8 (KERN_VDEBUG) verbose debug messages >>> >>> >>> Perhaps, logging every access to an MMC peripheral >>> might belong to the vdbg level. >> >> I like the idea of having a log level for message contents (bytes) and >> another for I/O access. So I will add two more in v2. >> >>> >>> >>> >>> BTW, what do you mean "INFO is what I plan to use for normal printf() output" >>> >>> Is that mean printf() is equivalent to pr_info()? >>> If loglevel is 6 or smaller, will all print() be silent? >>> If so, probably we can not use command line interface. >> >> I mean that I want to (later) add a feature that logs normal printf() >> output. If the console is silent then it would still be logged. Maybe >> one day log functions will be used instead of printf(), but for now >> this provides a useful way to make things wok. > > > IMHO, printf() should be used for command line interface. I suppose that makes sense, but in the interim we have a lot of printf() stuff printing errors / messages. > > All SoC files, board files should use pr_*(), > and drivers dev_*(). OK, for dev_*() we can generate the category automatically, but for pr_*() we cannot. So those would just get the default category for the file. > I do not think we have much volume for notice or lower loglevel. We have loads and loads of debug() things. If you mean that they will normally be compiled out, yes. But I think we will see a trend to adding more debugging into the code for when things go wrong. I'd like to be able to do a 'debug' build and get all of that info recorded, even if it is not displayed on the console. > > The categorization is useful for debug level > and you can see the right thing to do > for example, in drivers/i2c/Makefile of Linux. > > ccflags-$(CONFIG_I2C_DEBUG_CORE) := -DDEBUG That is a build-time thing, though. > > > > This is already established in Linux > > [1] Create an entry for CONFIG_FOO_DEBUG in Kconfig > [2] Add ccflags-$(CONFIG_FOO_DEBUG) := -DDEBUG > > You can do likewise for DM-core, EFI, or whatever. That is not the (whole) use case for this log feature. Here you are suggesting that we add an option to debug each uclass at run-time. I think that might be quite useful to allow build-time control of what categories are logged, but I think it is not a core feature needed right now. > > > > >> File filtering is useful I think in the interim, while nothing uses >> categories. We can filter on particular files to pick out the messages >> from those files. Even when we do have proper categories everywhere, >> it might still be useful. I am not sure yet. > > > File filter is pointless because we are generally > supposed to add #define DEBUG to each file > to make pr_dbg() effective. With logging if you set the max level to DEBUG you don't need to do that. You can filter at run-time. Regards, Simon
diff --git a/MAINTAINERS b/MAINTAINERS index 04acf2b89d..eb420afa8d 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -290,6 +290,15 @@ S: Maintained T: git git://git.denx.de/u-boot-i2c.git F: drivers/i2c/ +LOGGING +M: Simon Glass <sjg@chromium.org> +S: Maintained +T: git git://git.denx.de/u-boot.git +F: common/log.c +F: cmd/log.c +F: test/log/log_test.c +F: test/py/tests/test_log.py + MICROBLAZE M: Michal Simek <monstr@monstr.eu> S: Maintained diff --git a/common/Kconfig b/common/Kconfig index 4d8cae9610..cbccc8ae26 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -384,6 +384,62 @@ config SYS_STDIO_DEREGISTER endmenu +menu "Logging" + +config LOG + bool "Enable logging support" + help + This enables support for logging of status and debug messages. These + can be displayed on the console, recorded in a memory buffer, or + discarded if not needed. Logging supports various categories and + levels of severity. + +config SPL_LOG + bool "Enable logging support in SPL" + help + This enables support for logging of status and debug messages. These + can be displayed on the console, recorded in a memory buffer, or + discarded if not needed. Logging supports various categories and + levels of severity. + +config LOG_MAX_LEVEL + int "Maximum log level to record" + depends on LOG + default 5 + help + This selects the maximum log level that will be recorded. Any value + higher than this will be ignored. If possible log statements below + this level will be discarded at build time. Levels: + + 0 - panic + 1 - critical + 2 - error + 3 - warning + 4 - note + 5 - info + 6 - detail + 7 - debug + +config LOG_SPL_MAX_LEVEL + int "Maximum log level to record in SPL" + depends on SPL_LOG + default 3 + help + This selects the maximum log level that will be recorded. Any value + higher than this will be ignored. If possible log statements below + this level will be discarded at build time. Levels: + + 0 - panic + 1 - critical + 2 - error + 3 - warning + 4 - note + 5 - info + 6 - detail + 7 - debug + +endmenu + config DTB_RESELECT bool "Support swapping dtbs at a later point in boot" depends on FIT_EMBED diff --git a/common/Makefile b/common/Makefile index 1b56cf9a70..d37c8d5636 100644 --- a/common/Makefile +++ b/common/Makefile @@ -128,5 +128,6 @@ obj-y += cli.o obj-$(CONFIG_FSL_DDR_INTERACTIVE) += cli_simple.o cli_readline.o obj-$(CONFIG_CMD_DFU) += dfu.o obj-y += command.o +obj-$(CONFIG_$(SPL_)LOG) += log.o obj-y += s_record.o obj-y += xyzModem.o diff --git a/common/log.c b/common/log.c new file mode 100644 index 0000000000..6bf2219d38 --- /dev/null +++ b/common/log.c @@ -0,0 +1,246 @@ +/* + * Logging support + * + * Copyright (c) 2017 Google, Inc + * Written by Simon Glass <sjg@chromium.org> + * + * SPDX-License-Identifier: GPL-2.0+ + */ + +#include <common.h> +#include <log.h> +#include <malloc.h> + +DECLARE_GLOBAL_DATA_PTR; + +static struct log_device *log_device_find_by_name(const char *drv_name) +{ + struct log_device *ldev; + + list_for_each_entry(ldev, &gd->log_head, sibling_node) { + if (!strcmp(drv_name, ldev->drv->name)) + return ldev; + } + + return NULL; +} + +/** + * log_has_cat() - check if a log category exists within a list + * + * @cat_list: List of categories to check, at most LOGF_MAX_CATEGORIES entries + * long, terminated by LC_END if fewer + * @cat: Category to search for + * @return true if @cat is in @cat_list, else false + */ +static bool log_has_cat(enum log_category_t cat_list[], enum log_category_t cat) +{ + int i; + + for (i = 0; i < LOGF_MAX_CATEGORIES && cat_list[i] != LOGC_END; i++) { + if (cat_list[i] == cat) + return true; + } + + return false; +} + +/** + * log_has_file() - check if a file is with a list + * + * @file_list: List of files to check, separated by comma + * @file: File to check for. This string is matched against the end of each + * file in the list, i.e. ignoring any preceeding path. The list is + * intended to consist of relative pathnames, e.g. common/main.c,cmd/log.c + * @return true if @file is in @file_list, else false + */ +static bool log_has_file(const char *file_list, const char *file) +{ + int file_len = strlen(file); + const char *s, *p; + int substr_len; + + for (s = file_list; *s; s = p + (*p != '\0')) { + p = strchrnul(s, ','); + substr_len = p - s; + if (file_len >= substr_len && + !strncmp(file + file_len - substr_len, s, substr_len)) + return true; + } + + return false; +} + +/** + * log_passes_filters() - check if a log record passes the filters for a device + * + * @ldev: Log device to check + * @rec: Log record to check + * @return true if @rec is not blocked by the filters in @ldev, false if it is + */ +static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec) +{ + struct log_filter *filt; + + /* If there are no filters, filter on the default log level */ + if (list_empty(&ldev->filter_head)) { + if (rec->level > gd->default_log_level) + return false; + return true; + } + + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { + if (rec->level > filt->max_level) + continue; + if ((filt->flags & LOGFF_HAS_CAT) && + !log_has_cat(filt->cat_list, rec->cat)) + continue; + if (filt->file_list && + !log_has_file(filt->file_list, rec->file)) + continue; + return true; + } + + return false; +} + +/** + * log_dispatch() - Send a log record to all log devices for processing + * + * The log record is sent to each log device in turn, skipping those which have + * filters which block the record + * + * @rec: Log record to dispatch + * @return 0 (meaning success) + */ +static int log_dispatch(struct log_rec *rec) +{ + struct log_device *ldev; + + list_for_each_entry(ldev, &gd->log_head, sibling_node) { + if (log_passes_filters(ldev, rec)) + ldev->drv->emit(ldev, rec); + } + + return 0; +} + +int _log(enum log_category_t cat, enum log_level_t level, const char *file, + int line, const char *func, const char *fmt, ...) +{ + char buf[CONFIG_SYS_CBSIZE]; + struct log_rec rec; + va_list args; + + rec.cat = cat; + rec.level = level; + rec.file = file; + rec.line = line; + rec.func = func; + va_start(args, fmt); + vsnprintf(buf, sizeof(buf), fmt, args); + va_end(args); + rec.msg = buf; + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) { + if (gd) + gd->log_drop_count++; + return -ENOSYS; + } + log_dispatch(&rec); + + return 0; +} + +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], + enum log_level_t max_level, const char *file_list) +{ + struct log_filter *filt; + struct log_device *ldev; + int i; + + ldev = log_device_find_by_name(drv_name); + if (!ldev) + return -ENOENT; + filt = (struct log_filter *)calloc(1, sizeof(*filt)); + if (!filt) + return -ENOMEM; + + if (cat_list) { + filt->flags |= LOGFF_HAS_CAT; + for (i = 0; ; i++) { + if (i == ARRAY_SIZE(filt->cat_list)) + return -ENOSPC; + filt->cat_list[i] = cat_list[i]; + if (cat_list[i] == LOGC_END) + break; + } + } + filt->max_level = max_level; + if (file_list) { + filt->file_list = strdup(file_list); + if (!filt->file_list) + goto nomem; + } + filt->filter_num = ldev->next_filter_num++; + INIT_LIST_HEAD(&filt->sibling_node); + list_add_tail(&filt->sibling_node, &ldev->filter_head); + + return filt->filter_num; + +nomem: + free(filt); + return -ENOMEM; +} + +int log_remove_filter(const char *drv_name, int filter_num) +{ + struct log_filter *filt; + struct log_device *ldev; + + ldev = log_device_find_by_name(drv_name); + if (!ldev) + return -ENOENT; + + list_for_each_entry(filt, &ldev->filter_head, sibling_node) { + if (filt->filter_num == filter_num) { + list_del(&filt->sibling_node); + free(filt); + + return 0; + } + } + + return -ENOENT; +} + +int log_init(void) +{ + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver); + const int count = ll_entry_count(struct log_driver, log_driver); + struct log_driver *end = drv + count; + + /* + * We cannot add runtime data to the driver since it is likely stored + * in rodata. Instead, set up a 'device' corresponding to each driver. + * We only support having a single device. + */ + INIT_LIST_HEAD((struct list_head *)&gd->log_head); + while (drv < end) { + struct log_device *ldev; + + ldev = calloc(1, sizeof(*ldev)); + if (!ldev) { + debug("%s: Cannot allocate memory\n", __func__); + return -ENOMEM; + } + INIT_LIST_HEAD(&ldev->sibling_node); + INIT_LIST_HEAD(&ldev->filter_head); + ldev->drv = drv; + list_add_tail(&ldev->sibling_node, + (struct list_head *)&gd->log_head); + drv++; + } + gd->default_log_level = LOGL_INFO; + + return 0; +} diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h index 79197acfa4..77755dbb06 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -114,6 +114,11 @@ typedef struct global_data { struct bootstage_data *bootstage; /* Bootstage information */ struct bootstage_data *new_bootstage; /* Relocated bootstage info */ #endif +#ifdef CONFIG_LOG + int log_drop_count; /* Number of dropped log messages */ + int default_log_level; /* For devices with no filters */ + struct list_head log_head; /* List of struct log_device */ +#endif } gd_t; #endif diff --git a/include/log.h b/include/log.h index 4101a74161..fb6a196202 100644 --- a/include/log.h +++ b/include/log.h @@ -10,6 +10,82 @@ #ifndef __LOG_H #define __LOG_H +#include <dm/uclass-id.h> +#include <linux/list.h> + +/** Log levels supported, ranging from most to least important */ +enum log_level_t { + LOGL_PANIC = 0, + LOGL_CRIT, + LOGL_ERR, + LOGL_WARN, + LOGL_NOTE, + LOGL_INFO, + LOGL_DETAIL, + LOGL_DEBUG, + + LOGL_COUNT, + LOGL_FIRST = LOGL_PANIC, + LOGL_MAX = LOGL_DEBUG, +}; + +/** + * Log categories supported. Most of these correspond to uclasses (i.e. + * enum uclass_id) but there are also some more generic categories + */ +enum log_category_t { + LOGC_FIRST = 0, /* First part mirrors UCLASS_... */ + + LOGC_NONE = UCLASS_COUNT, + LOGC_ARCH, + LOGC_BOARD, + LOGC_CORE, + LOGC_DT, + + LOGC_COUNT, + LOGC_END, +}; + +/** + * _log() - Internal function to emit a new log record + * + * @cat: Category of log record (indicating which subsystem generated it) + * @level: Level of log record (indicating its severity) + * @file: File name of file where log record was generated + * @line: Line number in file where log record was generated + * @func: Function where log record was generated + * @fmt: printf() format string for log record + * @...: Optional parameters, according to the format string @fmt + * @return 0 if log record was emitted, -ve on error + */ +int _log(enum log_category_t cat, enum log_level_t level, const char *file, + int line, const char *func, const char *fmt, ...); + +/* Define this at the top of a file to add a prefix to debug messages */ +#ifndef pr_fmt +#define pr_fmt(fmt) fmt +#endif + +/* Use a default category if this file does not supply one */ +#ifndef LOG_CATEGORY +#define LOG_CATEGORY LOGC_NONE +#endif + +#if CONFIG_VAL(LOG_MAX_LEVEL) +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL) +#else +#define _LOG_MAX_LEVEL LOGL_INFO +#endif + +/* Emit a log record if the level is less that the maximum */ +#define log(_cat, _level, _fmt, _args...) ({ \ + int _l = _level; \ + if (_l > _LOG_MAX_LEVEL) \ + continue; \ + _log(_cat, _l, __FILE__, __LINE__, __func__, \ + pr_fmt(_fmt), ##_args); \ + }) + #ifdef DEBUG #define _DEBUG 1 #else @@ -22,10 +98,19 @@ #define _SPL_BUILD 0 #endif -/* Define this at the top of a file to add a prefix to debug messages */ -#ifndef pr_fmt -#define pr_fmt(fmt) fmt -#endif +#if !_DEBUG && CONFIG_IS_ENABLED(LOG) + +#define debug_cond(cond, fmt, args...) \ + do { \ + if (1) \ + log(LOG_CATEGORY, LOGL_DEBUG, fmt, ##args); \ + } while (0) + +#define error(fmt, args...) do { \ + log(LOG_CATEGORY, LOGL_ERR, fmt, ##args); \ +} while (0) + +#else /* _DEBUG */ /* * Output a debug text when condition "cond" is met. The "cond" should be @@ -38,6 +123,13 @@ printf(pr_fmt(fmt), ##args); \ } while (0) +#define error(fmt, args...) do { \ + printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ + ##args, __FILE__, __LINE__, __func__); \ +} while (0) + +#endif /* _DEBUG */ + /* Show a message if DEBUG is defined in a file */ #define debug(fmt, args...) \ debug_cond(_DEBUG, fmt, ##args) @@ -61,11 +153,6 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, ({ if (!(x) && _DEBUG) \ __assert_fail(#x, __FILE__, __LINE__, __func__); }) -#define error(fmt, args...) do { \ - printf("ERROR: " pr_fmt(fmt) "\nat %s:%d/%s()\n", \ - ##args, __FILE__, __LINE__, __func__); \ -} while (0) - #ifndef BUG #define BUG() do { \ printf("BUG: failure at %s:%d/%s()!\n", __FILE__, __LINE__, \ @@ -76,4 +163,146 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, while (0) #endif /* BUG */ +/** + * struct log_rec - a single log record + * + * Holds information about a single record in the log + * + * Members marked as 'not allocated' are stored as pointers and the caller is + * responsible for making sure that the data pointed to is not overwritten. + * Memebers marked as 'allocated' are allocated (e.g. via strdup()) by the log + * system. + * + * @cat: Category, representing a uclass or part of U-Boot + * @level: Severity level, less severe is higher + * @file: Name of file where the log record was generated (not allocated) + * @line: Line number where the log record was generated + * @func: Function where the log record was generated (not allocated) + * @msg: Log message (allocated) + */ +struct log_rec { + enum log_category_t cat; + enum log_level_t level; + const char *file; + int line; + const char *func; + const char *msg; +}; + +struct log_device; + +/** + * struct log_driver - a driver which accepts and processes log records + * + * @name: Name of driver + */ +struct log_driver { + const char *name; + /** + * emit() - emit a log record + * + * Called by the log system to pass a log record to a particular driver + * for processing. The filter is checked before calling this function. + */ + int (*emit)(struct log_device *ldev, struct log_rec *rec); +}; + +/** + * struct log_device - an instance of a log driver + * + * Since drivers are set up at build-time we need to have a separate device for + * the run-time aspects of drivers (currently just a list of filters to apply + * to records send to this device). + * + * @next_filter_num: Seqence number of next filter filter added (0=no filters + * yet). This increments with each new filter on the device, but never + * decrements + * @drv: Pointer to driver for this device + * @filter_head: List of filters for this device + * @sibling_node: Next device in the list of all devices + */ +struct log_device { + int next_filter_num; + struct log_driver *drv; + struct list_head filter_head; + struct list_head sibling_node; +}; + +enum { + LOGF_MAX_CATEGORIES = 5, /* maximum categories per filter */ +}; + +enum log_filter_flags { + LOGFF_HAS_CAT = 1 << 0, /* Filter has a category list */ +}; + +/** + * struct log_filter - criterial to filter out log messages + * + * @filter_num: Sequence number of this filter. This is returned when adding a + * new filter, and must be provided when removing a previously added + * filter. + * @flags: Flags for this filter (LOGFF_...) + * @cat_list: List of categories to allow (terminated by LOGC_none). If empty + * then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries + * can be provided + * @max_level: Maximum log level to allow + * @file_list: List of files to allow, separated by comma. If NULL then all + * files are permitted + * @sibling_node: Next filter in the list of filters for this log device + */ +struct log_filter { + int filter_num; + int flags; + enum log_category_t cat_list[LOGF_MAX_CATEGORIES]; + enum log_level_t max_level; + const char *file_list; + struct list_head sibling_node; +}; + +#define LOG_DRIVER(_name) \ + ll_entry_declare(struct log_driver, _name, log_driver) + +/** + * log_add_filter() - Add a new filter to a log device + * + * @drv_name: Driver name to add the filter to (since each driver only has a + * single device) + * @cat_list: List of categories to allow (terminated by LOGC_none). If empty + * then all categories are permitted. Up to LOGF_MAX_CATEGORIES entries + * can be provided + * @max_level: Maximum log level to allow + * @file_list: List of files to allow, separated by comma. If NULL then all + * files are permitted + * @return the sequence number of the new filter (>=0) if the filter was added, + * or a -ve value on error + */ +int log_add_filter(const char *drv_name, enum log_category_t cat_list[], + enum log_level_t max_level, const char *file_list); + +/** + * log_remove_filter() - Remove a filter from a log device + * + * @drv_name: Driver name to remove the filter from (since each driver only has + * a single device) + * @filter_num: Filter number to remove (as returned by log_add_filter()) + * @return 0 if the filter was removed, -ENOENT if either the driver or the + * filter number was not found + */ +int log_remove_filter(const char *drv_name, int filter_num); + +#if CONFIG_IS_ENABLED(LOG) +/** + * log_init() - Set up the log system ready for use + * + * @return 0 if OK, -ENOMEM if out of memory + */ +int log_init(void); +#else +static inline int log_init(void) +{ + return 0; +} +#endif + #endif
Add the logging header file and implementation with some configuration options to control it. Signed-off-by: Simon Glass <sjg@chromium.org> --- MAINTAINERS | 9 ++ common/Kconfig | 56 +++++++++ common/Makefile | 1 + common/log.c | 246 +++++++++++++++++++++++++++++++++++++ include/asm-generic/global_data.h | 5 + include/log.h | 247 ++++++++++++++++++++++++++++++++++++-- 6 files changed, 555 insertions(+), 9 deletions(-) create mode 100644 common/log.c