`phosphor-logging` APIs (RFC)

`phosphor-logging` APIs (RFC)

[Patrick Williams]

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

Greetings,

There have been discussions before on this mailing list about the APIs present
in phosphor-logging and some of the shortcomings they have.  I've implemented a
new API, inside phosphor-logging, that I think resolves the issues discussed
here and in some offline forums.

If you have an interest in the logging APIs, I would appreciate any feedback you
may have.  If there are additional issues with the APIs that I might have
missed, please feel free to let me know and I'll see what can be done about
resolving them.

lg2: introduce motivation and API
    https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-logging/+/45310
lg2: initial implementation of C++20 structured logging
    https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-logging/+/45311

The main highlights of what I attempted to fix are:
    - Verbose and clumsy API for previous `logging::log`.
    - Poor compile-time identification of certain (common) issues.
    - Source location data is invalid (issue openbmc/openbmc#2207).
    - Useful data is missing from `journalctl` resulting in people working
      around it by generating strings with `fmt` et.al.
    - No logging present when running on a TTY.

-- 
Patrick Williams

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

Re: `phosphor-logging` APIs (RFC)

[Andrew Jeffery]

On Wed, 28 Jul 2021, at 05:54, Patrick Williams wrote:
> Greetings,
> 
> There have been discussions before on this mailing list about the APIs present
> in phosphor-logging and some of the shortcomings they have.  I've implemented a
> new API, inside phosphor-logging, that I think resolves the issues discussed
> here and in some offline forums.
> 
> If you have an interest in the logging APIs, I would appreciate any feedback you
> may have.  If there are additional issues with the APIs that I might have
> missed, please feel free to let me know and I'll see what can be done about
> resolving them.
> 
> lg2: introduce motivation and API
>     https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-logging/+/45310
> lg2: initial implementation of C++20 structured logging
>     https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-logging/+/45311
> 
> The main highlights of what I attempted to fix are:
>     - Verbose and clumsy API for previous `logging::log`.
>     - Poor compile-time identification of certain (common) issues.
>     - Source location data is invalid (issue openbmc/openbmc#2207).

I think you wanted openbmc/openbmc#2297 there, but yes!

>     - Useful data is missing from `journalctl` resulting in people working
>       around it by generating strings with `fmt` et.al.

Sounds promising! Reading the proposal it seems like you're appending 
certain bits of structured data to the message. I think it would be 
nice if the data could be interpolated into arbitrary positions and not 
just appended (note, I'm not asking for interpolation of arbitrary 
variables here unlike what can be achieved with raw use of fmt, only 
those captured via the structured logging).

>     - No logging present when running on a TTY.

Great, this has caused quite a bit of confusion in the past.

Andrew

Re: `phosphor-logging` APIs (RFC)

[Patrick Williams]

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

On Wed, Jul 28, 2021 at 03:22:43PM +0930, Andrew Jeffery wrote:
> On Wed, 28 Jul 2021, at 05:54, Patrick Williams wrote:
 >     - Source location data is invalid (issue openbmc/openbmc#2207).
> 
> I think you wanted openbmc/openbmc#2297 there, but yes!

Indeed, that's the issue I meant to refer to.  Seems I mentioned it correctly in
the commit.

> >     - Useful data is missing from `journalctl` resulting in people working
> >       around it by generating strings with `fmt` et.al.
> 
> Sounds promising! Reading the proposal it seems like you're appending 
> certain bits of structured data to the message. I think it would be 
> nice if the data could be interpolated into arbitrary positions and not 
> just appended (note, I'm not asking for interpolation of arbitrary 
> variables here unlike what can be achieved with raw use of fmt, only 
> those captured via the structured logging).

Can you give me a concrete example of what you mean by this?  I'm not
understanding.

> Andrew

-- 
Patrick Williams

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

Re: `phosphor-logging` APIs (RFC)

[Andrew Jeffery]

On Wed, 28 Jul 2021, at 15:55, Patrick Williams wrote:
> On Wed, Jul 28, 2021 at 03:22:43PM +0930, Andrew Jeffery wrote:
> > On Wed, 28 Jul 2021, at 05:54, Patrick Williams wrote:
> 
> > >     - Useful data is missing from `journalctl` resulting in people working
> > >       around it by generating strings with `fmt` et.al.
> > 
> > Sounds promising! Reading the proposal it seems like you're appending 
> > certain bits of structured data to the message. I think it would be 
> > nice if the data could be interpolated into arbitrary positions and not 
> > just appended (note, I'm not asking for interpolation of arbitrary 
> > variables here unlike what can be achieved with raw use of fmt, only 
> > those captured via the structured logging).
> 
> Can you give me a concrete example of what you mean by this?  I'm not
> understanding.

I've left a comment on the patch:

https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-logging/+/45310/1/docs/structured-logging.md#60

But duplicating that here, how I'd like to use the API and what I'd 
like to see in the resulting journal message is:

```
value = "xyz.openbmc_project.EntityManager";
lg2::error("Error talking to {ENTITY} error code is {ERRNO}", "ENTITY", value, "ERRNO", 2);
```

The lg2 implementation renders the values into the format string and 
forwards the result as MESSAGE to the journal, along with the 
structured values (ENTITY and ERRNO in the example).

```
$ journalctl -b
...
Nov 25 13:13:09 bmc fansensor[3006]: Error talking to xyz.openbmc_project.EntityManager error code is 2
...
```

Better yet would be if we could just forward the format string and 
journalctl renders this at invocation time, but we'd need to work with 
upstream on that.

Andrew

Re: `phosphor-logging` APIs (RFC)

[Patrick Williams]

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

On Thu, Jul 29, 2021 at 09:04:14AM +0930, Andrew Jeffery wrote:
> I've left a comment on the patch:
> 
> https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-logging/+/45310/1/docs/structured-logging.md#60
> 
> But duplicating that here, how I'd like to use the API and what I'd 
> like to see in the resulting journal message is:
> 
> ```
> value = "xyz.openbmc_project.EntityManager";
> lg2::error("Error talking to {ENTITY} error code is {ERRNO}", "ENTITY", value, "ERRNO", 2);
> ```

Thanks for the description.  What you've proposed is at least able to be
compiled and wouldn't increase the call-site code footprint at all.  It would
have more work in the [common] code that translates from the lg2 API format to
systemd, but it isn't outrageous and is fairly straight-forward to implement
at this point.

So far there are 3 approaches on the table:

```

a. Yours.

  error("Hit {ERROR} during {STAGE}.", "ERROR", "bad foobar", "STAGE",
        "baz-grae", "EXTRA", 123);

->

  MESSAGE="Hit bad foobar during baz-grae."
  ERROR="bad foobar"
  STAGE="baz-grae"
  EXTRA=123

b. opt-in processing

  error("Hit error during processing.", "ERROR", primary, "bad foobar",
        "STAGE", primary, "baz-grae", "EXTRA", 123);

->

  MESSAGE="Hit error during processing. ERROR=bad foobar STAGE=baz-grae"
  ERROR="bad foobar"
  STAGE="baz-grae"
  EXTRA=123

c. opt-out processing

  error("Hit error during processing.", "ERROR", "bad foobar", "STAGE",
        "baz-grae", "EXTRA", quiet, 123);

->

  MESSAGE="Hit error during processing. ERROR=bad foobar STAGE=baz-grae"            
  ERROR="bad foobar"                                                                 
  STAGE="baz-grae"                                                              
  EXTRA=123 

```

Based on my experience trying to apply lg2 to a reasonable sample[1], (b)
seems rather verbose.  We're going to end up with most developers just
adding a `primary` on each data entry anyhow, so it is kind of pointless.

Both (a) and (c) are relatively succinct.  (a) has the advantage of being
slightly more human-friendly, but at a disadvantage of worse performance and
redundant tag identification (which cannot be checked at compile time either).
(c) is faster, has no redundancy, and is consistently structured, but is
slightly less human readable.

My question would be is if (a) is really that much better from a human
perspective to warrant the extra processing and redundancy (and thus potential
programming errors introduced by tag mismatches)?  To me, (c) provides all the
same information with only minimal readability impact and certainly better
performing.

> Better yet would be if we could just forward the format string and 
> journalctl renders this at invocation time, but we'd need to work with 
> upstream on that.

I kind of doubt they'd be interesting in absorbing this kind of string
formatting into the library, but maybe I'm wrong.

1. https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-virtual-sensor/+/45353/1/virtualSensor.cpp 

-- 
Patrick Williams

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

Re: `phosphor-logging` APIs (RFC)

[Patrick Williams]

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

On Wed, Jul 28, 2021 at 09:53:07PM -0500, Patrick Williams wrote:
> 
>   error("Hit {ERROR} during {STAGE}.", "ERROR", "bad foobar", "STAGE",
>         "baz-grae", "EXTRA", 123);
> 

I have implemented this formatting handling, since more people seemed to want
it, and also added compile-time confirmation that the keys match
systemd-journald requirements.  Patch sequence is all updated to resolve any
outstanding review comments.

-- 
Patrick Williams

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

Re: `phosphor-logging` APIs (RFC)

[Andrew Jeffery]

On Tue, 3 Aug 2021, at 09:57, Patrick Williams wrote:
> On Wed, Jul 28, 2021 at 09:53:07PM -0500, Patrick Williams wrote:
> > 
> >   error("Hit {ERROR} during {STAGE}.", "ERROR", "bad foobar", "STAGE",
> >         "baz-grae", "EXTRA", 123);
> > 
> 
> I have implemented this formatting handling, since more people seemed to want
> it, and also added compile-time confirmation that the keys match
> systemd-journald requirements.  Patch sequence is all updated to resolve any
> outstanding review comments.
> 

Thanks! The updated documentation gets a +1 from me.

Andrew