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

20 Sep 2017

      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

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

Dr. Philipp Tomsich