[U-Boot] [PATCH 06/13] log: Add an implemention of logging
Simon Glass
sjg at chromium.org
Tue Sep 26 19:10:22 UTC 2017
Hi Masahiro,
On 20 September 2017 at 11:19, Masahiro Yamada
<yamada.masahiro at socionext.com> wrote:
> Hi Simon,
>
>
> 2017-09-20 22:49 GMT+09:00 Simon Glass <sjg at chromium.org>:
>> 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.
>
> 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
More information about the U-Boot
mailing list