OpenBMC Logging and Error Handling Dos and Don'ts

[William Kennington]

The structured messaging is good to keep, but we should put more useful
information into the message. The message doesn't need to have structure.
Having duplicate information should be okay and desirable to make messages
nicely human parseable. Not sure I like just appending in the key/values
passed as systemd message entries.

On Tue, Jun 2, 2020 at 4:06 PM Patrick Williams <patrick at stwcx.xyz> 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> 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.
>
> 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ozlabs.org/pipermail/openbmc/attachments/20200602/9f015567/attachment.htm>