OpenBMC Logging and Error Handling Dos and Don'ts

[Vernon Mauery]

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> 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 looks like C++20 has a shiny new helper for this: source_location
https://en.cppreference.com/w/cpp/experimental/source_location

--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