[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