From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=google.com (client-ip=2a00:1450:4864:20::22a; helo=mail-lj1-x22a.google.com; envelope-from=wak@google.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=pass (p=reject dis=none) header.from=google.com Authentication-Results: lists.ozlabs.org; dkim=pass (2048-bit key; unprotected) header.d=google.com header.i=@google.com header.a=rsa-sha256 header.s=20161025 header.b=ZfJOlbVz; dkim-atps=neutral Received: from mail-lj1-x22a.google.com (mail-lj1-x22a.google.com [IPv6:2a00:1450:4864:20::22a]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 49c7695tsqzDqS3 for ; Wed, 3 Jun 2020 09:09:37 +1000 (AEST) Received: by mail-lj1-x22a.google.com with SMTP id c11so354490ljn.2 for ; Tue, 02 Jun 2020 16:09:37 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=o1oGzJ6nvz5iHlj4lmNa8C+h/SC8zPj+HciYm7Ilnj4=; b=ZfJOlbVzalgHg9HzFZXWvpuRNpJBR3TGJ2vV0PA6P/0DTGCPOO7SDKdBvD27hdk24z wJM8KUB9D0vHJTCkfjvmf1/+pp3I4S4QjJq4PFSNomA+bM0MPIiQjV7pMvHyWaiGh+Th PP7aq69r+Xs6l7lmYDbRYCsyqcUsW0iYpJ7oIgZ+5AQJYXzI0JyfonwSC6sNN5o4Iql8 8vc5rkFdkKOY3t/XBbMvRMOpMLz86REdZa1qObi/s4w8Bi+DVbq6ZUUcJup55YtBz48r YinYANxYWKGAsRlLQ7UgOU8dDX4XPT+x+QattfZ5wONvKLxgzo9hupqLN98BTVuu6G+t zAjw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=o1oGzJ6nvz5iHlj4lmNa8C+h/SC8zPj+HciYm7Ilnj4=; b=R2oOgHZJ5OtF70U4MZwyBJhA6dr5LHeuK9ZE2Wb3/aNy1WmgEcL6AiFB3oju0JTy3m 0HbDp95PIREFk4l/sJg+dgnVJ5C51ES1Ibx3fid7HBqSTxbGmAlvMljuWbQX2S8dJLdd bN7jSbwDy6MhyhiICoGe53ttxHOM48YXZlhztcPIa2zLIfu42nOnMV1fbx+DEZ7Uro10 iqj5EImSMrsJPp6C/vE9MHhHoM0zzpje3sJbGCpWGUnPLTJi0jH0Z0f8+EWWi0n3bSvu 2m6ZrtOoMtfJd5M/648tSJKNaUHLapNfRsaXdG+VbqNcXdTXNg5+SvtW911jyOHHavdn 8SKQ== X-Gm-Message-State: AOAM530epD55+VxivxI3BSAls4isd1+CXoKwV+caQa+GmZACxe8c77yb euwId8+y1mBPF8eZ3xSINK6g7ptfjr33JIZmcUl4TaF3lvQ= X-Google-Smtp-Source: ABdhPJynReZXz8NBy2dZBl0+iLV2f/2F82QHyu+9NscC7/foc8nexNH5GcH6JBpsNp6FHsQ9VHhXVM6mChHQeVKc57U= X-Received: by 2002:a05:651c:120d:: with SMTP id i13mr581942lja.381.1591139372747; Tue, 02 Jun 2020 16:09:32 -0700 (PDT) MIME-Version: 1.0 References: <4c4aa12b1ffde80ebbf49ad78b6046889f4226c0.camel@fuzziesquirrel.com> <20200602230639.GK17541@heinlein> In-Reply-To: <20200602230639.GK17541@heinlein> From: William Kennington Date: Tue, 2 Jun 2020 16:09:21 -0700 Message-ID: Subject: Re: OpenBMC Logging and Error Handling Dos and Don'ts To: Patrick Williams Cc: =?UTF-8?B?6YOB6Zu3?= , openbmc , Brad Bishop Content-Type: multipart/alternative; boundary="0000000000001a245f05a7220103" X-BeenThere: openbmc@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Development list for OpenBMC List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 02 Jun 2020 23:09:38 -0000 --0000000000001a245f05a7220103 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable 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 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(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 =E9=83=81=E9=9B=B7 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("Something is wrong: %s:%d", xx, xxx); > > > is much better than: > > > std::string to_log =3D xxx; // generate the message manually > > > log(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("Some message", > phosphor::logging::entry("EXAMPLE=3D%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=3D'the string'". > > I'd be interested to hear what "next generation logging" others have in > mind. > > -- > Patrick Williams > --0000000000001a245f05a7220103 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
The structured messaging is good to keep, but we should pu= t more useful information into the message. The message doesn't need to= have structure. Having duplicate information=C2=A0should be okay and desir= able to make messages nicely human parseable. Not sure I like just appendin= g in the key/values passed as systemd message entries.

On Tue, Jun 2, 2020 = at 4:06 PM Patrick Williams <patric= k@stwcx.xyz> wrote:
On Mon, Jun 01, 2020 at 11:07:46PM -0700, William Kennington wro= te:
> If you use the fmt library it would only require one extra temporary s= tring
> to be constructed and it works trivially with something like phosphor<= br> > 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 =E9=83=81=E9=9B=B7 <yulei.sh@bytedance.com> = wrote:
>
> > I have a bit concern about this. The existing phosphor-logging AP= I
> > does not support this well.
> > Specifically, it does not support the "printf" way to g= enerate 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 muc= h better.
> > But to encourage such logging, the logging API should be enhanced= to
> > support the "printf" way.
> > E.g.
> >=C2=A0 =C2=A0 =C2=A0log<level::INFO>("Something is wron= g: %s:%d", xx, xxx);
> > is much better than:
> >=C2=A0 =C2=A0 =C2=A0std::string to_log =3D xxx; // generate the me= ssage manually
> >=C2=A0 =C2=A0 =C2=A0log<level::INFO>(to_log);
> >
> > Otherwise, it's really not convenient to write such logging c= ode.
> >

Separate from this proposal from Brad, I'd like to work on a
next-generation of phosphor-logging.=C2=A0 When we originally implemented phosphor-logging we were all pretty new to C++14.=C2=A0 I think there can b= e
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<= br> 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 mess= age",
=C2=A0 =C2=A0 phosphor::logging::entry("EXAMPLE=3D%s"), example_s= tr);

// 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 thi= nk William
and Lei are both referring to that as well.=C2=A0 I am concerned that a
generic format leads us more to unstructured logging, which personally I don't like.=C2=A0 My suggestion is that we have some easy syntax to ind= icate
"also put this structured data into the raw message" so that my e= xample
above the message becomes "Some message. EXAMPLE=3D'the string'= ;".

I'd be interested to hear what "next generation logging" othe= rs have in
mind.

--
Patrick Williams
--0000000000001a245f05a7220103--