OpenBMC Logging and Error Handling Dos and Don'ts

[Vijay Khemka]

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