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

Masahiro Yamada yamada.masahiro at socionext.com
Wed Sep 20 17:19:58 UTC 2017


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.



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

Is that mean printf() is equivalent to pr_info()?
If loglevel is 6 or smaller, will all print() be silent?
If so, probably we can not use command line interface.





>>
>>
>>
>>
>>> +
>>> +/**
>>> + * log_dispatch() - Send a log record to all log devices for processing
>>> + *
>>> + * The log record is sent to each log device in turn, skipping those which have
>>> + * filters which block the record
>>> + *
>>> + * @rec: Log record to dispatch
>>> + * @return 0 (meaning success)
>>> + */
>>> +static int log_dispatch(struct log_rec *rec)
>>> +{
>>> +       struct log_device *ldev;
>>> +
>>> +       list_for_each_entry(ldev, &gd->log_head, sibling_node) {
>>> +               if (log_passes_filters(ldev, rec))
>>> +                       ldev->drv->emit(ldev, rec);
>>> +       }
>>> +
>>> +       return 0;
>>> +}
>>> +
>>> +int _log(enum log_category_t cat, enum log_level_t level, const char *file,
>>> +        int line, const char *func, const char *fmt, ...)
>>> +{
>>> +       char buf[CONFIG_SYS_CBSIZE];
>>> +       struct log_rec rec;
>>> +       va_list args;
>>> +
>>> +       rec.cat = cat;
>>> +       rec.level = level;
>>> +       rec.file = file;
>>> +       rec.line = line;
>>> +       rec.func = func;
>>> +       va_start(args, fmt);
>>> +       vsnprintf(buf, sizeof(buf), fmt, args);
>>> +       va_end(args);
>>> +       rec.msg = buf;
>>> +       if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {
>>> +               if (gd)
>>> +                       gd->log_drop_count++;
>>> +               return -ENOSYS;
>>> +       }
>>> +       log_dispatch(&rec);
>>> +
>>> +       return 0;
>>> +}
>>> +
>>> +int log_add_filter(const char *drv_name, enum log_category_t cat_list[],
>>> +                  enum log_level_t max_level, const char *file_list)
>>> +{
>>> +       struct log_filter *filt;
>>> +       struct log_device *ldev;
>>> +       int i;
>>> +
>>> +       ldev = log_device_find_by_name(drv_name);
>>> +       if (!ldev)
>>> +               return -ENOENT;
>>> +       filt = (struct log_filter *)calloc(1, sizeof(*filt));
>>> +       if (!filt)
>>> +               return -ENOMEM;
>>> +
>>> +       if (cat_list) {
>>> +               filt->flags |= LOGFF_HAS_CAT;
>>> +               for (i = 0; ; i++) {
>>> +                       if (i == ARRAY_SIZE(filt->cat_list))
>>> +                               return -ENOSPC;
>>> +                       filt->cat_list[i] = cat_list[i];
>>> +                       if (cat_list[i] == LOGC_END)
>>> +                               break;
>>> +               }
>>> +       }
>>> +       filt->max_level = max_level;
>>> +       if (file_list) {
>>> +               filt->file_list = strdup(file_list);
>>> +               if (!filt->file_list)
>>> +                       goto nomem;
>>> +       }
>>> +       filt->filter_num = ldev->next_filter_num++;
>>> +       INIT_LIST_HEAD(&filt->sibling_node);
>>> +       list_add_tail(&filt->sibling_node, &ldev->filter_head);
>>> +
>>> +       return filt->filter_num;
>>> +
>>> +nomem:
>>> +       free(filt);
>>> +       return -ENOMEM;
>>> +}
>>> +
>>> +int log_remove_filter(const char *drv_name, int filter_num)
>>> +{
>>> +       struct log_filter *filt;
>>> +       struct log_device *ldev;
>>> +
>>> +       ldev = log_device_find_by_name(drv_name);
>>> +       if (!ldev)
>>> +               return -ENOENT;
>>> +
>>> +       list_for_each_entry(filt, &ldev->filter_head, sibling_node) {
>>> +               if (filt->filter_num == filter_num) {
>>> +                       list_del(&filt->sibling_node);
>>> +                       free(filt);
>>> +
>>> +                       return 0;
>>> +               }
>>> +       }
>>> +
>>> +       return -ENOENT;
>>> +}
>>
>>
>> I am not sure if this luxury filter is needed.
>> After all, the purpose is debugging.
>> The printf() debugging is useful, but only during testing.
>> Once quality code is established, most of debug message should
>> generally be removed from upstream code.
>
> But not logging, and this is the point. It is very useful to have
> basic logging information recorded for every boot, and the normal
> printf() output is not detailed enough. For example for verified boot
> I want to see details about boot failures and what went wrong (key
> verification, etc.).

This should be warn level, (or notice at least)
not info.


> So I expect that at least INFO (and probably
> DETAIL) logging would be useful to record for such a system, even if
> it does not appear on the console (in fact the console would normally
> be disabled in such a system).

OK.  Logging is useful, but your example will be used
with info level.

I still do not understand the necessity of
category / file filtering.


>>
>>
>>
>>> +int log_init(void)
>>> +{
>>> +       struct log_driver *drv = ll_entry_start(struct log_driver, log_driver);
>>> +       const int count = ll_entry_count(struct log_driver, log_driver);
>>> +       struct log_driver *end = drv + count;
>>> +
>>> +       /*
>>> +        * We cannot add runtime data to the driver since it is likely stored
>>> +        * in rodata. Instead, set up a 'device' corresponding to each driver.
>>> +        * We only support having a single device.
>>> +        */
>>> +       INIT_LIST_HEAD((struct list_head *)&gd->log_head);
>>> +       while (drv < end) {
>>> +               struct log_device *ldev;
>>> +
>>> +               ldev = calloc(1, sizeof(*ldev));
>>> +               if (!ldev) {
>>> +                       debug("%s: Cannot allocate memory\n", __func__);
>>> +                       return -ENOMEM;
>>> +               }
>>> +               INIT_LIST_HEAD(&ldev->sibling_node);
>>
>> This INIT_LIST_HEAD() is unneeded.
>
> How come? If I don't do that how will the list be set up?

Because ldev->sibling_node is not a list_head.
It is used as a list node.


See include/linux/list.h
for the implementation of list_add_tail().

The argument "head" must be initialized in advance,
but "new" does not need initialization.



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

Here, gd->log_head is a head, so
INIT_LIST_HEAD((struct list_head *)&gd->log_head);
is correct.

INIT_LIST_HEAD(&ldev->sibling_node);
is non-sense.





>> I know that this (struct list_head *) cast is needed,
>> but it is very unfortunate.
>> I believe gd_t is design mistake in the first place,
>> but U-Boot has gone to unfixable already...
>
> With driver model I added DM_ROOT_NON_CONST. I suppose we could use
> something like that.
>
> But perhaps we should start dropping the 'volatile' in gd? I'm not
> sure why it is needed.

Me neither.


>>
>>
>>
>>
>>
>>> +#if CONFIG_VAL(LOG_MAX_LEVEL)
>>> +#define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL)
>>> +#else
>>> +#define _LOG_MAX_LEVEL LOGL_INFO
>>> +#endif
>>
>>
>> I cannot understand your intention of #if CONFIG_VAL(LOG_MAX_LEVEL).
>> From your Kconfig entry,
>>
>>    0 - panic
>>    1 - critical
>>    2 - error
>>    3 - warning
>>    4 - note
>>    5 - info
>>    6 - detail
>>    7 - debug
>>
>> I expect CONFIG_VAL(LOG_MAX_LEVEL) is an integer value
>> range 0 to 7.
>>
>> If the log level is 0 (= critial), the conditional is false, so
>> _LOG_MAX_LEVEL is set to "info" level.
>>
>> Why is this #if necessary?
>
> If we don't have CONFIG_LOG enabled then this value will not exist.
>

This implementation is wrong.

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


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



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

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

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




-- 
Best Regards
Masahiro Yamada


More information about the U-Boot mailing list