Re: `phosphor-logging` APIs (RFC)

[Patrick Williams <patrick@stwcx.xyz>]

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