Re: Frontend error logging style

At Tue, 09 Nov 2021 17:20:41 -0500, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote in
> ISTM that the recently-introduced new frontend logging support
> (common/logging.h et al) could use a second pass now that we have
> some experience with it. There are two points that are bugging me:
>
> 1. The distinction between "error" and "fatal" levels seems squishy
> to the point of uselessness. I think we should either get rid of it
> entirely, or make an effort to use "fatal" exactly for the cases that
> are going to give up and exit right away. Of the approximately 830
> pg_log_error calls in HEAD, I count at least 450 that are immediately
> followed by exit(1), and so should be pg_log_fatal if this distinction
> means anything at all. OTOH, if we decide it doesn't mean anything,
> there are only about 90 pg_log_fatal calls to convert. I lean
> slightly to the "get rid of the distinction" option, not only because
> it'd be a much smaller patch but also because I don't care to expend
> brain cells on the which-to-use question while reviewing future
> patches.

Agreed. On backends, FATAL is bound to a behavior defferent from
ERROR. I doubt of the necessity of the difference between the two on
a console application (or frontend in PG-term). I would prefer to get
rid of the FATAL level.

I once thought ERROR should cause outoright end of an application, but
things don't seem so simple..

> 2. What is the preferred style for adding extra lines to log messages?
> I see a lot of direct prints to stderr:
>
> pg_log_error("missing required argument: database name");
> fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
> exit(1);
>
> but a number of places have chosen to do this:
>
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error("query was: %s", todo);
>
> and some places got creative and did this:
>
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_info("query was: %s", sql.data);

In the first place the pg_log_info doesn't work at all since pgbench
doesn't make the log-level go below PG_LOG_INFO. (--quiet works the
different way..) In that case the pg_log_info can even be said to be
used just to avoid the message from being prepended by a severity tag.
I think we should fix that.

> I think this ought to be cleaned up so we have a more-or-less uniform
> approach. Aside from the randomly different source code, each of
> these choices has different implications for whether the extra line
> gets printed or not depending on verbosity level, and that seems bad.
>
> One plausible choice is to drop the first style (which surely has
> little to recommend it) and use either the second or third style
> depending on whether you think the addendum ought to appear at the
> same or higher verbosity level as the main message. But we'd
> still be at hazard of people making randomly different choices
> about that in identical cases, as indeed the second and third
> examples show.
>
> Another idea is to reduce such cases to one call:
>
> pg_log_error("query failed: %s\nquery was: %s",
> PQerrorMessage(conn), sql.data);
>
> but I don't much like that: it knows more than it should about
> the presentation format, and it can't support hiding the detail
> portion at lower verbosity levels.
>
> So I'm not totally satisfied with these ideas, but I don't
> immediately have a better one.
>
> Thoughts?

Honestly I don't like that:p

The cause of the confusion is we are using verbosity to hide *a part
of* a grouped messages. We make distinction beween the two concepts
in the backend code but not in frontend. At least in pgbench, it
seems to me as if the severity tag prepended by the pg_log_hoge
functions is mere a label just to be shown on console.

That being said it is a kind of impssible to expect users to specify
the two independent levels on command line.

Couldn't we have a function, say, named as "pg_log_error_detail",
which prints the message when __pg_log_level is *above* ERROR and
prepended by "detail:" tag? (or not showing the tag, keeping the
current behavior on surface.) We would have the same for
pg_log_warning. (pg_log_error_detail behaves a bit differetnly from
pg_log_info in this definition.)

> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error_detail("query was: %s", sql.data);

So pg_log_generic(_v) have an additional parameter, say, detailed bool.

pg_log_generic(enum pg_log_level level, bool detailed, const char *pg_restrict fmt,...)

Considering that the level is used only to identify severity tag
string, it is somewhat strange that the detailed flag conflicts with
it. But I'm not sure it is sane to add instead an extra-and-hidden log
level to pg_log_level..

Or as a simpler way, we could just have aliases for pg_log_info().

#define pg_log_error_detail(...) pg_log_info(__VA_ARGS__)
#define pg_log_warning_detail(...) pg_log_info(__VA_ARGS__)

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center