All of lore.kernel.org
 help / color / mirror / Atom feed
* OpenBMC Logging and Error Handling Dos and Don'ts
@ 2020-06-01 20:35 Brad Bishop
  2020-06-02  3:32 ` 郁雷
  0 siblings, 1 reply; 10+ messages in thread
From: Brad Bishop @ 2020-06-01 20:35 UTC (permalink / raw)
  To: openbmc

I would like to start a document centered on logging best practices in
OpenBMC.  To get started I used a simple Do/Don't format and picked an
easy topic that I've repeatedly gotten feedback on.

Please let me know if you like the format or have any feedback.

Also please feel free to reply with suggestions for additional Do/Don't
items...I may write them up if time allows.

thanks!

-brad

----------

# OpenBMC Logging and Error Handling Dos and Don'ts
**Audience:** OpenBMC application developers

**Prerequisites:** None

---
## Don't require `-o verbose` for systemd journal MESSAGE field context
The MESSAGE field of a systemd journal entry should be self describing and not
rely on additional structured log data.  For example when the MESSAGE field
references a filesystem path, the path should appear in the MESSAGE field.
When the MESSAGE field references a failed system call, the system call and the
return value should appear in the MESSAGE field.  This keeps the journal
informative and useful for casual journal users.  Note that it is perfectly
acceptible to add (duplicate) structured log entry values for the data that
appears in MESSAGE.  This guideline only prescribes that the data _not_ be
omitted from the MESSAGE field value.


## Don't #2
TBD

## Do #1
TBD

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-01 20:35 OpenBMC Logging and Error Handling Dos and Don'ts Brad Bishop
@ 2020-06-02  3:32 ` 郁雷
  2020-06-02  6:07   ` William Kennington
  0 siblings, 1 reply; 10+ messages in thread
From: 郁雷 @ 2020-06-02  3:32 UTC (permalink / raw)
  To: Brad Bishop; +Cc: openbmc

> ---
> ## Don't require `-o verbose` for systemd journal MESSAGE field context
> The MESSAGE field of a systemd journal entry should be self describing and not
> rely on additional structured log data.  For example when the MESSAGE field
> references a filesystem path, the path should appear in the MESSAGE field.
> When the MESSAGE field references a failed system call, the system call and the
> return value should appear in the MESSAGE field.  This keeps the journal
> informative and useful for casual journal users.  Note that it is perfectly
> acceptible to add (duplicate) structured log entry values for the data that
> appears in MESSAGE.  This guideline only prescribes that the data _not_ be
> omitted from the MESSAGE field value.
>

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.

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-02  3:32 ` 郁雷
@ 2020-06-02  6:07   ` William Kennington
  2020-06-02 23:06     ` Patrick Williams
  0 siblings, 1 reply; 10+ messages in thread
From: William Kennington @ 2020-06-02  6:07 UTC (permalink / raw)
  To: 郁雷; +Cc: Brad Bishop, openbmc

[-- Attachment #1: Type: text/plain, Size: 1919 bytes --]

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@bytedance.com> wrote:

> > ---
> > ## Don't require `-o verbose` for systemd journal MESSAGE field context
> > The MESSAGE field of a systemd journal entry should be self describing
> and not
> > rely on additional structured log data.  For example when the MESSAGE
> field
> > references a filesystem path, the path should appear in the MESSAGE
> field.
> > When the MESSAGE field references a failed system call, the system call
> and the
> > return value should appear in the MESSAGE field.  This keeps the journal
> > informative and useful for casual journal users.  Note that it is
> perfectly
> > acceptible to add (duplicate) structured log entry values for the data
> that
> > appears in MESSAGE.  This guideline only prescribes that the data _not_
> be
> > omitted from the MESSAGE field value.
> >
>
> 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.
>

[-- Attachment #2: Type: text/html, Size: 2385 bytes --]

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-02  6:07   ` William Kennington
@ 2020-06-02 23:06     ` Patrick Williams
  2020-06-02 23:09       ` William Kennington
  2020-06-03  0:07       ` Vernon Mauery
  0 siblings, 2 replies; 10+ messages in thread
From: Patrick Williams @ 2020-06-02 23:06 UTC (permalink / raw)
  To: William Kennington; +Cc: 郁雷, openbmc, Brad Bishop

[-- Attachment #1: Type: text/plain, Size: 2627 bytes --]

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-02 23:06     ` Patrick Williams
@ 2020-06-02 23:09       ` William Kennington
  2020-06-03  0:07       ` Vernon Mauery
  1 sibling, 0 replies; 10+ messages in thread
From: William Kennington @ 2020-06-02 23:09 UTC (permalink / raw)
  To: Patrick Williams; +Cc: 郁雷, openbmc, Brad Bishop

[-- Attachment #1: Type: text/plain, Size: 3159 bytes --]

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

[-- Attachment #2: Type: text/html, Size: 3949 bytes --]

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-02 23:06     ` Patrick Williams
  2020-06-02 23:09       ` William Kennington
@ 2020-06-03  0:07       ` Vernon Mauery
  2020-06-03  2:51         ` 郁雷
  2020-06-03 19:02         ` Vijay Khemka
  1 sibling, 2 replies; 10+ messages in thread
From: Vernon Mauery @ 2020-06-03  0:07 UTC (permalink / raw)
  To: Patrick Williams
  Cc: William Kennington, Brad Bishop, openbmc, 郁雷

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

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-03  0:07       ` Vernon Mauery
@ 2020-06-03  2:51         ` 郁雷
  2020-06-03 19:02         ` Vijay Khemka
  1 sibling, 0 replies; 10+ messages in thread
From: 郁雷 @ 2020-06-03  2:51 UTC (permalink / raw)
  To: Vernon Mauery; +Cc: Patrick Williams, William Kennington, Brad Bishop, openbmc

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

Yup, this is what the logging needs to improve as well.
The new logging API is better to resolve the issue:
https://github.com/openbmc/openbmc/issues/2297

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-03  0:07       ` Vernon Mauery
  2020-06-03  2:51         ` 郁雷
@ 2020-06-03 19:02         ` Vijay Khemka
  2020-06-03 19:17           ` Johnathan Mantey
  1 sibling, 1 reply; 10+ messages in thread
From: Vijay Khemka @ 2020-06-03 19:02 UTC (permalink / raw)
  To: Vernon Mauery, Patrick Williams
  Cc: openbmc, Brad Bishop, 郁雷, William Kennington



On 6/2/20, 5:08 PM, "openbmc on behalf of Vernon Mauery" <openbmc-bounces+vijaykhemka=fb.com@lists.ozlabs.org on behalf of vernon.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@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




^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-03 19:02         ` Vijay Khemka
@ 2020-06-03 19:17           ` Johnathan Mantey
  2020-06-03 19:25             ` William Kennington
  0 siblings, 1 reply; 10+ messages in thread
From: Johnathan Mantey @ 2020-06-03 19:17 UTC (permalink / raw)
  To: Vijay Khemka, Vernon Mauery, Patrick Williams
  Cc: openbmc, Brad Bishop, 郁雷, William Kennington


[-- Attachment #1.1.1: Type: text/plain, Size: 4567 bytes --]

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@lists.ozlabs.org on behalf of vernon.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@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@intel.com <mailto:johnathanx.mantey@intel.com>


[-- Attachment #1.1.2: Type: text/html, Size: 6310 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: OpenBMC Logging and Error Handling Dos and Don'ts
  2020-06-03 19:17           ` Johnathan Mantey
@ 2020-06-03 19:25             ` William Kennington
  0 siblings, 0 replies; 10+ messages in thread
From: William Kennington @ 2020-06-03 19:25 UTC (permalink / raw)
  To: Johnathan Mantey
  Cc: Vijay Khemka, Vernon Mauery, Patrick Williams, openbmc,
	Brad Bishop, 郁雷

[-- Attachment #1: Type: text/plain, Size: 5156 bytes --]

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@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@lists.ozlabs.org on behalf of vernon.mauery@linux.intel.com> <openbmc-bounces+vijaykhemka=fb.com@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@bytedance.com> <yulei.sh@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@intel.com
>
>

[-- Attachment #2: Type: text/html, Size: 7098 bytes --]

^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2020-06-03 19:25 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-06-01 20:35 OpenBMC Logging and Error Handling Dos and Don'ts Brad Bishop
2020-06-02  3:32 ` 郁雷
2020-06-02  6:07   ` William Kennington
2020-06-02 23:06     ` Patrick Williams
2020-06-02 23:09       ` William Kennington
2020-06-03  0:07       ` Vernon Mauery
2020-06-03  2:51         ` 郁雷
2020-06-03 19:02         ` Vijay Khemka
2020-06-03 19:17           ` Johnathan Mantey
2020-06-03 19:25             ` William Kennington

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.