OpenBMC Logging and Error Handling Dos and Don'ts

[William Kennington]

The local process always emits all logs generated by phosphor-logging, it
is up to the journald configuration what levels are used for different
things.
https://www.freedesktop.org/software/systemd/man/journald.conf.html

You can change the priority level output by journalctl on the command line
too, to filter out lower priority messages.
`journal -p err` or some other level

On Wed, Jun 3, 2020 at 12:18 PM Johnathan Mantey <
johnathanx.mantey at intel.com> wrote:

> I would like it to be easier to determine how to change the error message
> level.
> I don't bother with the log code because I don't know where it's
> controlled.
>
> On 6/3/20 12:02 PM, Vijay Khemka wrote:
>
> On 6/2/20, 5:08 PM, "openbmc on behalf of Vernon Mauery" <openbmc-bounces+vijaykhemka=fb.com at lists.ozlabs.org on behalf of vernon.mauery at linux.intel.com> <openbmc-bounces+vijaykhemka=fb.com at lists.ozlabs.orgonbehalfofvernon.mauery@linux.intel.com> wrote:
>
>     On 02-Jun-2020 06:06 PM, Patrick Williams wrote:
>     >On Mon, Jun 01, 2020 at 11:07:46PM -0700, William Kennington wrote:
>     >> If you use the fmt library it would only require one extra temporary string
>     >> to be constructed and it works trivially with something like phosphor
>     >> logging.
>     >>
>     >> log<level::INFO>(fmt::format("My error: {}", filename));
>     >>
>     >> It also has the advantage of understanding basic c++ types like
>     >> std::strings and std::string_views.
>     >>
>     >> On Mon, Jun 1, 2020 at 8:33 PM 郁雷 <yulei.sh at bytedance.com> <yulei.sh at bytedance.com> wrote:
>     >>
>     >> > I have a bit concern about this. The existing phosphor-logging API
>     >> > does not support this well.
>     >> > Specifically, it does not support the "printf" way to generate a
>     >> > string with the variables to log.
>     >> > So previously we typically put the variables in entries.
>     >> > I do agree that logging the variables in the MESSAGE field is much better.
>     >> > But to encourage such logging, the logging API should be enhanced to
>     >> > support the "printf" way.
>     >> > E.g.
>     >> >     log<level::INFO>("Something is wrong: %s:%d", xx, xxx);
>     >> > is much better than:
>     >> >     std::string to_log = xxx; // generate the message manually
>     >> >     log<level::INFO>(to_log);
>     >> >
>     >> > Otherwise, it's really not convenient to write such logging code.
>     >> >
>     >
>     >Separate from this proposal from Brad, I'd like to work on a
>     >next-generation of phosphor-logging.  When we originally implemented
>     >phosphor-logging we were all pretty new to C++14.  I think there can be
>     >some great improvement in the syntax of phosphor-logging now that we
>     >have C++17 (and more experience).
>     >
>     >The biggest change I'd like to do is in the way the structured entries
>     >are defined, but I think we can improve the verbosity of syntax in
>     >making a log in general.
>
>     One more change I would like to see is a way to actually have the real
>     filename and line number show up in the systemd log. Right now the
>     filename and line number are always the logger code:
>         CODE_LINE=76
>         CODE_FUNC=helper_log
>         CODE_FILE=.../usr/include/phosphor-logging/log.hpp
>
> It will be good if we can have debug as a level and somehow we can see
> messages from debug by enabling or disabling.
>
>     It looks like C++20 has a shiny new helper for this: source_location
>     https://urldefense.proofpoint.com/v2/url?u=https-3A__en.cppreference.com_w_cpp_experimental_source-5Flocation&d=DwIFaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=v9MU0Ki9pWnTXCWwjHPVgpnCR80vXkkcrIaqU7USl5g&m=qFbu7FdFQSHVMy4ZvMtHDH5RzYQnqMUQ_T0h4qL0Xd0&s=QRsbQvb4LKAEoa8AITFyPFhcoCSVHtFLMOU66UodPnM&e=
>
>     --Vernon
>
>     >Some example syntax:
>     >
>     >// Current syntax (and I'm being especially verbose on the namespaces).
>     >phosphor::logging::log<phosphor::logging::level::ERR>("Some message",
>     >    phosphor::logging::entry("EXAMPLE=%s"), example_str);
>     >
>     >// Potential syntax
>     >lg::error("Some message", "EXAMPLE"_s, example_str);
>     >
>     >In a code-review I was on, we had some discussions about how difficult
>     >it is to create data that isn't in the "-o verbose" and I think William
>     >and Lei are both referring to that as well.  I am concerned that a
>     >generic format leads us more to unstructured logging, which personally I
>     >don't like.  My suggestion is that we have some easy syntax to indicate
>     >"also put this structured data into the raw message" so that my example
>     >above the message becomes "Some message. EXAMPLE='the string'".
>     >
>     >I'd be interested to hear what "next generation logging" others have in
>     >mind.
>     >
>     >--
>     >Patrick Williams
>
>
>
>
>
> --
> Johnathan Mantey
> Senior Software Engineer
> *azad te**chnology partners*
> Contributing to Technology Innovation since 1992
> Phone: (503) 712-6764
> Email: johnathanx.mantey at intel.com
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ozlabs.org/pipermail/openbmc/attachments/20200603/45cb1bcb/attachment-0001.htm>