[U-Boot] [PATCH 06/13] log: Add an implemention of logging
Dr. Philipp Tomsich
philipp.tomsich at theobroma-systems.com
Wed Sep 20 14:37:23 UTC 2017
Masahiro & Simon,
> On 20 Sep 2017, at 15:49, Simon Glass <sjg at chromium.org> wrote:
>
> Hi Masahiro,
>
> On 19 September 2017 at 20:51, Masahiro Yamada
> <yamada.masahiro at socionext.com> wrote:
>> Hi Simon,
>>
>>
>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg at chromium.org>:
>>
>>>
>>> +menu "Logging"
>>> +
>>> +config LOG
>>> + bool "Enable logging support"
>>> + help
>>> + This enables support for logging of status and debug messages. These
>>> + can be displayed on the console, recorded in a memory buffer, or
>>> + discarded if not needed. Logging supports various categories and
>>> + levels of severity.
>>> +
>>> +config SPL_LOG
>>> + bool "Enable logging support in SPL"
>>> + help
>>> + This enables support for logging of status and debug messages. These
>>> + can be displayed on the console, recorded in a memory buffer, or
>>> + discarded if not needed. Logging supports various categories and
>>> + levels of severity.
>>
>>
>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
>>
>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9,
>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG
>> when building for TPL.
>>
>> Since that commit, if you add SPL_ prefixed option,
>> you need to add a TPL_ one as well.
>>
>> I cannot believe why such a commit was accepted.
>
> Well either way is strange. it is strange that SPL is enabled for TPL
> when really they are separate.
>
> We could revert that commit. But how do you think all of this SPL/TPL
> control should actually work? What is intended?
>
> But I'm OK with not having logging in TPL until we need it.
If we don’t differentiate between TPL_ and SPL_, we’ll eventually run into
size issues for TPL and the $(SPL_TPL_) mechanism will not match the
CONFIG_IS_ENABLED() mechanism.
I don’t think that anyone will miss this much in TPL and that this can be
safely left off for TPL (if space was not at a premium in TPL, then why
have a TPL at all…)
>
>>
>>
>>
>>
>>> +config LOG_MAX_LEVEL
>>> + int "Maximum log level to record"
>>> + depends on LOG
>>> + default 5
>>> + help
>>> + This selects the maximum log level that will be recorded. Any value
>>> + higher than this will be ignored. If possible log statements below
>>> + this level will be discarded at build time. Levels:
>>> +
>>> + 0 - panic
>>> + 1 - critical
>>> + 2 - error
>>> + 3 - warning
>>> + 4 - note
>>> + 5 - info
>>> + 6 - detail
>>> + 7 - debug
>>
>>
>> Please do not invent our own for U-Boot.
>> Just use Linux log level.
>>
>> 0 (KERN_EMERG) system is unusable
>> 1 (KERN_ALERT) action must be taken immediately
>> 2 (KERN_CRIT) critical conditions
>> 3 (KERN_ERR) error conditions
>> 4 (KERN_WARNING) warning conditions
>> 5 (KERN_NOTICE) normal but significant condition
>> 6 (KERN_INFO) informational
>> 7 (KERN_DEBUG) debug-level messages
>
> Yes I looked hard at that. The first three seem hard to distinguish in
> U-Boot, but we can keep them I suppose. But most of my problem is with
> the last two. INFO is what I plan to use for normal printf() output.
> DEBUG is obviously for debugging and often involves vaste amounts of
> stuff (e.g. logging every access to an MMC peripheral). We need
> something in between. It could list the accesses to device at a high
> level (e.g API calls) but not every little register access.
>
> So I don't think the Linux levels are suitable at the high end. We
> could go up to 8 I suppose, instead of trying to save one at the
> bottom?
I would expect KERN_NOTICE to be used for normal printf output, KERN_INFO
for more verbose output and DEBUG would be the granularity for tracing through
drivers (i.e. the MMC example given).
Regards,
Philipp.
>
>>
>>
>>
>>
>>> +config LOG_SPL_MAX_LEVEL
>>> + int "Maximum log level to record in SPL"
>>> + depends on SPL_LOG
>>> + default 3
>>> + help
>>> + This selects the maximum log level that will be recorded. Any value
>>> + higher than this will be ignored. If possible log statements below
>>> + this level will be discarded at build time. Levels:
>>> +
>>> + 0 - panic
>>> + 1 - critical
>>> + 2 - error
>>> + 3 - warning
>>> + 4 - note
>>> + 5 - info
>>> + 6 - detail
>>> + 7 - debug
>>>
>>
>>
>> If you want to use CONFIG_VAL(LOG_MAX_LEVEL),
>> this must be SPL_LOG_MAX_LEVEL.
>> (this coding mistake is now hidden by another mistake)
>
> Oops, yes.
>
>>
>> Again, you will probably end up with TPL_LOG_MAX_LEVEL.
>>
>>
>>
>>
>>> +
>>> +/**
>>> + * log_dispatch() - Send a log record to all log devices for processing
>>> + *
>>> + * The log record is sent to each log device in turn, skipping those which have
>>> + * filters which block the record
>>> + *
>>> + * @rec: Log record to dispatch
>>> + * @return 0 (meaning success)
>>> + */
>>> +static int log_dispatch(struct log_rec *rec)
>>> +{
>>> + struct log_device *ldev;
>>> +
>>> + list_for_each_entry(ldev, &gd->log_head, sibling_node) {
>>> + if (log_passes_filters(ldev, rec))
>>> + ldev->drv->emit(ldev, rec);
>>> + }
>>> +
>>> + return 0;
>>> +}
>>> +
>>> +int _log(enum log_category_t cat, enum log_level_t level, const char *file,
>>> + int line, const char *func, const char *fmt, ...)
>>> +{
>>> + char buf[CONFIG_SYS_CBSIZE];
>>> + struct log_rec rec;
>>> + va_list args;
>>> +
>>> + rec.cat = cat;
>>> + rec.level = level;
>>> + rec.file = file;
>>> + rec.line = line;
>>> + rec.func = func;
>>> + va_start(args, fmt);
>>> + vsnprintf(buf, sizeof(buf), fmt, args);
>>> + va_end(args);
>>> + rec.msg = buf;
>>> + if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {
>>> + if (gd)
>>> + gd->log_drop_count++;
>>> + return -ENOSYS;
>>> + }
>>> + log_dispatch(&rec);
>>> +
>>> + return 0;
>>> +}
>>> +
>>> +int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
>>> + enum log_level_t max_level, const char *file_list)
>>> +{
>>> + struct log_filter *filt;
>>> + struct log_device *ldev;
>>> + int i;
>>> +
>>> + ldev = log_device_find_by_name(drv_name);
>>> + if (!ldev)
>>> + return -ENOENT;
>>> + filt = (struct log_filter *)calloc(1, sizeof(*filt));
>>> + if (!filt)
>>> + return -ENOMEM;
>>> +
>>> + if (cat_list) {
>>> + filt->flags |= LOGFF_HAS_CAT;
>>> + for (i = 0; ; i++) {
>>> + if (i == ARRAY_SIZE(filt->cat_list))
>>> + return -ENOSPC;
>>> + filt->cat_list[i] = cat_list[i];
>>> + if (cat_list[i] == LOGC_END)
>>> + break;
>>> + }
>>> + }
>>> + filt->max_level = max_level;
>>> + if (file_list) {
>>> + filt->file_list = strdup(file_list);
>>> + if (!filt->file_list)
>>> + goto nomem;
>>> + }
>>> + filt->filter_num = ldev->next_filter_num++;
>>> + INIT_LIST_HEAD(&filt->sibling_node);
>>> + list_add_tail(&filt->sibling_node, &ldev->filter_head);
>>> +
>>> + return filt->filter_num;
>>> +
>>> +nomem:
>>> + free(filt);
>>> + return -ENOMEM;
>>> +}
>>> +
>>> +int log_remove_filter(const char *drv_name, int filter_num)
>>> +{
>>> + struct log_filter *filt;
>>> + struct log_device *ldev;
>>> +
>>> + ldev = log_device_find_by_name(drv_name);
>>> + if (!ldev)
>>> + return -ENOENT;
>>> +
>>> + list_for_each_entry(filt, &ldev->filter_head, sibling_node) {
>>> + if (filt->filter_num == filter_num) {
>>> + list_del(&filt->sibling_node);
>>> + free(filt);
>>> +
>>> + return 0;
>>> + }
>>> + }
>>> +
>>> + return -ENOENT;
>>> +}
>>
>>
>> I am not sure if this luxury filter is needed.
>> After all, the purpose is debugging.
>> The printf() debugging is useful, but only during testing.
>> Once quality code is established, most of debug message should
>> generally be removed from upstream code.
>
> But not logging, and this is the point. It is very useful to have
> basic logging information recorded for every boot, and the normal
> printf() output is not detailed enough. For example for verified boot
> I want to see details about boot failures and what went wrong (key
> verification, etc.). So I expect that at least INFO (and probably
> DETAIL) logging would be useful to record for such a system, even if
> it does not appear on the console (in fact the console would normally
> be disabled in such a system).
>
>>
>>
>>
>>> +int log_init(void)
>>> +{
>>> + struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);
>>> + const int count = ll_entry_count(struct log_driver, log_driver);
>>> + struct log_driver *end = drv + count;
>>> +
>>> + /*
>>> + * We cannot add runtime data to the driver since it is likely stored
>>> + * in rodata. Instead, set up a 'device' corresponding to each driver.
>>> + * We only support having a single device.
>>> + */
>>> + INIT_LIST_HEAD((struct list_head *)&gd->log_head);
>>> + while (drv < end) {
>>> + struct log_device *ldev;
>>> +
>>> + ldev = calloc(1, sizeof(*ldev));
>>> + if (!ldev) {
>>> + debug("%s: Cannot allocate memory\n", __func__);
>>> + return -ENOMEM;
>>> + }
>>> + INIT_LIST_HEAD(&ldev->sibling_node);
>>
>> This INIT_LIST_HEAD() is unneeded.
>
> How come? If I don't do that how will the list be set up?
>
>>
>>
>>
>>> + INIT_LIST_HEAD(&ldev->filter_head);
>>> + ldev->drv = drv;
>>> + list_add_tail(&ldev->sibling_node,
>>> + (struct list_head *)&gd->log_head);
>>
>> I know that this (struct list_head *) cast is needed,
>> but it is very unfortunate.
>> I believe gd_t is design mistake in the first place,
>> but U-Boot has gone to unfixable already...
>
> With driver model I added DM_ROOT_NON_CONST. I suppose we could use
> something like that.
>
> But perhaps we should start dropping the 'volatile' in gd? I'm not
> sure why it is needed.
>
>>
>>
>>
>>
>>
>>> +#if CONFIG_VAL(LOG_MAX_LEVEL)
>>> +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL)
>>> +#else
>>> +#define _LOG_MAX_LEVEL LOGL_INFO
>>> +#endif
>>
>>
>> I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL).
>> From your Kconfig entry,
>>
>> 0 - panic
>> 1 - critical
>> 2 - error
>> 3 - warning
>> 4 - note
>> 5 - info
>> 6 - detail
>> 7 - debug
>>
>> I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value
>> range 0 to 7.
>>
>> If the log level is 0 (= critial), the conditional is false, so
>> _LOG_MAX_LEVEL is set to "info" level.
>>
>> Why is this #if necessary?
>
> If we don't have CONFIG_LOG enabled then this value will not exist.
>
>>
>>
>>
>>
>>
>>
>>
>>
>>> +/* Emit a log record if the level is less that the maximum */
>>> +#define log(_cat, _level, _fmt, _args...) ({ \
>>> + int _l = _level; \
>>> + if (_l > _LOG_MAX_LEVEL) \
>>> + continue; \
>>> + _log(_cat, _l, __FILE__, __LINE__, __func__, \
>>> + pr_fmt(_fmt), ##_args); \
>>> + })
>>
>>
>> This is neither while() nor for().
>> The bare use of "continue" made me really surprised.
>
> Yes that may not be supported. I'll fix it.
>
> Regards,
> Simon
> _______________________________________________
> U-Boot mailing list
> U-Boot at lists.denx.de
> https://lists.denx.de/listinfo/u-boot
More information about the U-Boot
mailing list