Frontend error logging style

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.

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

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?

regards, tom lane

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

On Tue, Nov 9, 2021 at 5:20 PM Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> 1. The distinction between "error" and "fatal" levels seems squishy
> to the point of uselessness.
>
> 2. What is the preferred style for adding extra lines to log messages?

I agree with this list of problems. I think that the end game here is
getting to be able to use ereport() and friends in the frontend, which
would require confronting both of these issues at a deep level. We
don't necessarily have to do that now, though, but I think it's an
argument against just nuking "fatal" from orbit. What I think we ought
to be driving towards is having pg_log_fatal() forcibly exit, and
pg_log_error() do the same unless the error is somehow caught. That
might require more changes than you or whoever wants to do right now,
so perhaps what we ought to do is just enforce the policy you
suggested before: if we're going to exit immediately afterward, it's
fatal; if not, it's an error.

I have been wondering for some time about trying to make the frontend
and backend facilities symmetric and using case to distinguish. That
is, if you see:

ERROR: this stinks
DETAIL: It smells very bad.
CONTEXT: garbage dump

...well then that's a backend message. And if you see:

error: this stinks
detail: It smells very bad.
context: garbage dump

...well then that's a frontend message. I don't completely love that
way of making a distinction, but I think we need something, and that's
pretty nearly the present practice at least for the primary message.
We don't really have a solid convention for detail/context/hint on the
FE side; this is one idea.

--
Robert Haas
EDB: http://www.enterprisedb.com

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> I agree with this list of problems. I think that the end game here is
> getting to be able to use ereport() and friends in the frontend, which
> would require confronting both of these issues at a deep level. We
> don't necessarily have to do that now, though, but I think it's an
> argument against just nuking "fatal" from orbit. What I think we ought
> to be driving towards is having pg_log_fatal() forcibly exit, and
> pg_log_error() do the same unless the error is somehow caught.

Perhaps. The usage that I'm concerned about is exemplified by this
common pattern:

pg_log_error("%s", PQerrorMessage(conn));
PQfinish(conn);
exit(1);

ie there's some cleanup you want to do between emitting the error and
actually exiting. (I grant that maybe someday the PQfinish could be
done in an atexit handler or the like, but that's way more redesign
than I want to do right now.) In the case where you *don't* have
any cleanup to do, though, it'd be nice to just write one line not
two.

That leads me to think that we should redefine pg_log_fatal as

#define pg_log_fatal(...) (pg_log_error(__VA_ARGS__), exit(1))

We still want to get rid of the distinct PG_LOG_FATAL log level,
because whether you are using this form of pg_log_fatal or writing
exit() separately is a coding detail that should not manifest
as visibly distinct user output.

This proposal doesn't move us very far towards your endgame,
but I think it's a reasonable incremental step, and it makes
the difference between pg_log_error() and pg_log_fatal()
clear and useful.

> I have been wondering for some time about trying to make the frontend
> and backend facilities symmetric and using case to distinguish. That
> is, if you see:

> ERROR: this stinks
> DETAIL: It smells very bad.
> CONTEXT: garbage dump

> ...well then that's a backend message. And if you see:

> error: this stinks
> detail: It smells very bad.
> context: garbage dump

> ...well then that's a frontend message. I don't completely love that
> way of making a distinction, but I think we need something, and that's
> pretty nearly the present practice at least for the primary message.
> We don't really have a solid convention for detail/context/hint on the
> FE side; this is one idea.

Hmm, interesting. Taking up my point #2, I'd been thinking about
proposing that we convert

pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_error("query was: %s", todo);

to

pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_error_detail("Query was: %s", todo);

and similarly add a pg_log_info_detail() companion for pg_log_info(), etc.
With your point above, the prefix these'd print would be "detail:" not
"DETAIL:", but otherwise it seems to match up pretty well.

Also, if we are modeling this on backend conventions, we should say that
style rules for pg_log_error_detail match those for errdetail(), with
complete sentences and so forth. I wonder whether "detail:" followed
by a capitalized sentence would look weird ... but you did it above,
so maybe that's what people would expect.

Again, there's more that could be done later, but this seems to be
enough to address the cases that people have been inventing ad-hoc
solutions for.

regards, tom lane

I wrote:
> Hmm, interesting. Taking up my point #2, I'd been thinking about
> proposing that we convert
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error("query was: %s", todo);
> to
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error_detail("Query was: %s", todo);

After looking around a bit, I see that a lot of these add-on messages
are more nearly hints than details, so we'd probably better support
both those cases right off the bat.

To move things along a bit, here's a draft patch to logging.h/.c only
to implement what I'm envisioning. I don't think there's much point
in doing the per-call-site gruntwork until we have agreement on what
the API is, so this seems like enough for discussion.

(As a fervent hater of colorization, I don't have an opinion about
whether or how to colorize the "detail:" and "hint:" fragments.
But I'll happily take somebody else's adjustment to add that.)

regards, tom lane

At Wed, 10 Nov 2021 14:25:08 -0500, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote in
> I wrote:
> > Hmm, interesting. Taking up my point #2, I'd been thinking about
> > proposing that we convert
> > pg_log_error("query failed: %s", PQerrorMessage(conn));
> > pg_log_error("query was: %s", todo);
> > to
> > pg_log_error("query failed: %s", PQerrorMessage(conn));
> > pg_log_error_detail("Query was: %s", todo);
>
> After looking around a bit, I see that a lot of these add-on messages
> are more nearly hints than details, so we'd probably better support
> both those cases right off the bat.

Sounds reasonable.

> To move things along a bit, here's a draft patch to logging.h/.c only
> to implement what I'm envisioning. I don't think there's much point
> in doing the per-call-site gruntwork until we have agreement on what
> the API is, so this seems like enough for discussion.
>
> (As a fervent hater of colorization, I don't have an opinion about
> whether or how to colorize the "detail:" and "hint:" fragments.
> But I'll happily take somebody else's adjustment to add that.)

(:) I don't hate colorization so much, but I'm frequently annoyed by
needing to turn off colorization and I disgust when there's no easy
way to disable that in a simple steps..)

Aren't DETAIL and HINT expected to be hidden at the targetted cutoff
level? In other words, I suspect that people want to hide non-primary
messages for a lower verbosity level. On the other hand I'm not sure
it is a proper behavior that log_level = WARNING causes ERROR messages
are accompanied by DETAIL/HINT submessages...

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

Kyotaro Horiguchi <horikyota(dot)ntt(at)gmail(dot)com> writes:
> Aren't DETAIL and HINT expected to be hidden at the targetted cutoff
> level? In other words, I suspect that people want to hide non-primary
> messages for a lower verbosity level. On the other hand I'm not sure
> it is a proper behavior that log_level = WARNING causes ERROR messages
> are accompanied by DETAIL/HINT submessages...

I abandoned that idea in the draft patch. We could maybe do something
about it further down the line, but I'm not sure there's really any
demand.

As the patch is set up, you could theoretically do something like

pg_log_error("blah blah");
pg_log_info_detail("Very boring detail goes here.");

(note the intentionally different log priorities). But that feels wrong
to me --- it doesn't seem like individual call sites should be setting
such policy. If we do arrange for a way to hide the optional message
parts, I'd rather that the control were centralized in logging.c.

It certainly wouldn't be hard for logging.c to make different decisions
about what to print; the thing that's not clear to me is what the
user-level knob for it should look like. We already used up the
option of more or fewer -v switches.

regards, tom lane

On 09.11.21 23:20, Tom Lane wrote:
> 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.

This logging system has been designed more generally, drawing some
inspiration from Python and Java libraries, for example. It's up to the
program using this to make sensible use of it. I think there are
programs such as pg_receivewal where there is a meaningful distinction
between errors flowing by and a fatal exit. But with something like
pg_basebackup, there is no real difference, so that code sort of uses
pg_log_error by default, since any error is implicitly fatal. I see the
apparent inconsistency, but I don't think it's a real problem. Each
program by itself has arguably sensible behavior.

On 09.11.21 23:20, Tom Lane wrote:
> 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);

This is mainly used for those few messages that are sort of a "global
standard".

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

I can't decide between those two. It depends on how each program
handles the log level internally.

Some kind of "detail" system could be useful. But it would need to be
tied into the log level, layout, etc. I have not seen much inspiration
for this kind of thing in other logging libraries, so I didn't do
anything about it yet.

On 10.11.21 16:28, Robert Haas wrote:
> What I think we ought
> to be driving towards is having pg_log_fatal() forcibly exit, and
> pg_log_error() do the same unless the error is somehow caught.

This is specifically designed not to do any flow control. In the
backend, we have many instances, where log messages are issued with the
wrong log level because the stronger log level would have flow control
impact that is not appropriate at the call site. I don't think we want
more of that, especially since the flow control requirements in the
varied suite of frontend programs is quite diverse. Moreover, we also
require control over the exit codes in some cases, which this kind of
API wouldn't allow.

Several programs wrap, say, pg_log_fatal() into a pg_fatal(), that does
logging, cleanup, and exit, as the case may be. I think that's a good
solution. If someone wanted to write a more widely reusable pg_fatal(),
why not, but in my previous attempts, this was quite complicated and
didn't turn out to be useful.

On Mon, Nov 15, 2021 at 2:15 PM Peter Eisentraut
<peter(dot)eisentraut(at)enterprisedb(dot)com> wrote:
> This is specifically designed not to do any flow control. In the
> backend, we have many instances, where log messages are issued with the
> wrong log level because the stronger log level would have flow control
> impact that is not appropriate at the call site. I don't think we want
> more of that, especially since the flow control requirements in the
> varied suite of frontend programs is quite diverse. Moreover, we also
> require control over the exit codes in some cases, which this kind of
> API wouldn't allow.

I agree that the system we use in the backend isn't problem free, but
making the frontend do something randomly different isn't an
improvement. I think that most people who are writing PostgreSQL
frontend code have also written a lot of backend code, and they are
used to the way things work in the backend. More importantly, there's
an increasing amount of code that wants to run in either environment.
And there have been suggestions that we want to make more things, like
memory contexts, work that way. The design decision that you've made
here makes that harder, and results in stuff like this:

[rhaas pgsql]$ git grep pg_log_fatal.*VA_ARGS
src/bin/pg_rewind/pg_rewind.h:#define pg_fatal(...) do {
pg_log_fatal(__VA_ARGS__); exit(1); } while(0)
src/bin/pg_waldump/pg_waldump.c:#define fatal_error(...) do {
pg_log_fatal(__VA_ARGS__); exit(EXIT_FAILURE); } while(0)
src/include/lib/simplehash.h: do { pg_log_fatal(__VA_ARGS__);
exit(1); } while(0)

Having different frontend utilities each invent their own
slightly-different way of doing this makes it hard to reuse code, and
hard to understand code. We need to find ways to make it more uniform,
not just observe that it isn't uniform today and give up.

IOW, I think the fact that it's not designed to do any flow control is
a bad thing.

--
Robert Haas
EDB: http://www.enterprisedb.com

Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> writes:
> Several programs wrap, say, pg_log_fatal() into a pg_fatal(), that does
> logging, cleanup, and exit, as the case may be. I think that's a good
> solution.

I agree, and my draft patch formalized that by turning pg_log_fatal into
exactly that.

The question that I think is relevant here is what is the point of
labeling errors as "error:" or "fatal:" if we're not going to make any
serious attempt to make that distinction meaningful. I'm not really
buying your argument that it's fine as-is. Anybody who thinks that
there's a difference is going to be very confused by the behavior they
observe. But, if we all know there's no difference, why have the
difference?

regards, tom lane

On Mon, Nov 15, 2021 at 02:40:10PM -0500, Robert Haas wrote:
> Having different frontend utilities each invent their own
> slightly-different way of doing this makes it hard to reuse code, and
> hard to understand code. We need to find ways to make it more uniform,
> not just observe that it isn't uniform today and give up.

I agree with this sentiment, but this is a bit more complex than just
calling exit() with pg_log_fatal(), no? pg_dump likes playing a lot
with its exit_nicely(), meaning that we may want to allow frontends to
plug in callbacks.
--
Michael

On Mon, Nov 15, 2021 at 10:02 PM Michael Paquier <michael(at)paquier(dot)xyz> wrote:
> On Mon, Nov 15, 2021 at 02:40:10PM -0500, Robert Haas wrote:
> > Having different frontend utilities each invent their own
> > slightly-different way of doing this makes it hard to reuse code, and
> > hard to understand code. We need to find ways to make it more uniform,
> > not just observe that it isn't uniform today and give up.
>
> I agree with this sentiment, but this is a bit more complex than just
> calling exit() with pg_log_fatal(), no? pg_dump likes playing a lot
> with its exit_nicely(), meaning that we may want to allow frontends to
> plug in callbacks.

Yep.

I think we need frontend facilities that look like the backend
facilities, so try/catch blocks, on-exit callbacks, and whatever else
there is. Otherwise code reuse is going to continue to be annoying.

--
Robert Haas
EDB: http://www.enterprisedb.com

On 16.11.21 16:18, Robert Haas wrote:
> I think we need frontend facilities that look like the backend
> facilities, so try/catch blocks, on-exit callbacks, and whatever else
> there is. Otherwise code reuse is going to continue to be annoying.

If people want to do that kind of thing (I'm undecided whether the
complexity is worth it), then make it a different API. The pg_log_*
calls are for writing formatted output. They normalized existing
hand-coded patterns at the time. We can wrap another API on top of them
that does flow control and output. The pg_log_* stuff is more on the
level of syslog(), which also just outputs stuff. Nobody is suggesting
that syslog(LOG_EMERG) should exit the program automatically. But you
can wrap higher-level APIs such as ereport() on top of that that might
do that.

On Fri, Nov 19, 2021 at 5:17 AM Peter Eisentraut
<peter(dot)eisentraut(at)enterprisedb(dot)com> wrote:
> If people want to do that kind of thing (I'm undecided whether the
> complexity is worth it), then make it a different API. The pg_log_*
> calls are for writing formatted output. They normalized existing
> hand-coded patterns at the time. We can wrap another API on top of them
> that does flow control and output. The pg_log_* stuff is more on the
> level of syslog(), which also just outputs stuff. Nobody is suggesting
> that syslog(LOG_EMERG) should exit the program automatically. But you
> can wrap higher-level APIs such as ereport() on top of that that might
> do that.

Yeah, that might be a way forward.

--
Robert Haas
EDB: http://www.enterprisedb.com

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Fri, Nov 19, 2021 at 5:17 AM Peter Eisentraut
> <peter(dot)eisentraut(at)enterprisedb(dot)com> wrote:
>> If people want to do that kind of thing (I'm undecided whether the
>> complexity is worth it), then make it a different API. The pg_log_*
>> calls are for writing formatted output. They normalized existing
>> hand-coded patterns at the time. We can wrap another API on top of them
>> that does flow control and output. The pg_log_* stuff is more on the
>> level of syslog(), which also just outputs stuff. Nobody is suggesting
>> that syslog(LOG_EMERG) should exit the program automatically. But you
>> can wrap higher-level APIs such as ereport() on top of that that might
>> do that.

> Yeah, that might be a way forward.

This conversation seems to have tailed off without full resolution,
but I observe that pretty much everyone except Peter is on board
with defining pg_log_fatal as pg_log_error + exit(1). So I think
we should just do that, unless Peter wants to produce a finished
alternative proposal.

I've now gone through and fleshed out the patch I sketched upthread.
This exercise convinced me that we absolutely should do something
very like this, because

(1) As it stands, this patch removes a net of just about 1000 lines
of code. So we clearly need *something*.

(2) The savings would be even more, except that people have invented
macros for pg_log_error + exit(1) in at least four places already.
(None of them quite the same of course.) Here I've just fixed those
macro definitions to use pg_log_fatal. In the name of consistency, we
should probably get rid of those macros in favor of using pg_log_fatal
directly; but I've not done so here, since this patch is eyewateringly
long and boring already.

(3) The amount of inconsistency in how we add on details/hints right
now is even worse than I thought. For example, we've got places
burying the lede like this:

- pg_log_error("server version: %s; %s version: %s",
- remoteversion_str, progname, PG_VERSION);
- fatal("aborting because of server version mismatch");
+ pg_log_error("aborting because of server version mismatch");
+ pg_log_error_detail("server version: %s; %s version: %s",
+ remoteversion_str, progname, PG_VERSION);
+ exit(1);

or misidentifying the primary message altogether, like this:

pg_log_error("query failed: %s",
PQerrorMessage(AH->connection));
- fatal("query was: %s", query);
+ pg_log_error_detail("Query was: %s", query);
+ exit(1);

Thoughts?

regards, tom lane

Hi,

On 2022-02-22 18:23:19 -0500, Tom Lane wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> > On Fri, Nov 19, 2021 at 5:17 AM Peter Eisentraut
> > <peter(dot)eisentraut(at)enterprisedb(dot)com> wrote:
> >> If people want to do that kind of thing (I'm undecided whether the
> >> complexity is worth it), then make it a different API. The pg_log_*
> >> calls are for writing formatted output. They normalized existing
> >> hand-coded patterns at the time. We can wrap another API on top of them
> >> that does flow control and output. The pg_log_* stuff is more on the
> >> level of syslog(), which also just outputs stuff. Nobody is suggesting
> >> that syslog(LOG_EMERG) should exit the program automatically. But you
> >> can wrap higher-level APIs such as ereport() on top of that that might
> >> do that.

That'd maybe be a convincing argument in a project that didn't have
elog(FATAL).

> > Yeah, that might be a way forward.
>
> This conversation seems to have tailed off without full resolution,
> but I observe that pretty much everyone except Peter is on board
> with defining pg_log_fatal as pg_log_error + exit(1). So I think
> we should just do that, unless Peter wants to produce a finished
> alternative proposal.

What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps
pg_log_* stuff "log only", but adds something adjacent enough to hopefully
reduce future misunderstandings?

To further decrease the chance of such mistakes, we could rename
pg_log_fatal() to something else. Or add a a pg_log_fatal() function that's
marked pg_nodiscard(), so that each callsite explicitly has to be (void)
pg_log_fatal().

> I've now gone through and fleshed out the patch I sketched upthread.
> This exercise convinced me that we absolutely should do something
> very like this, because
>
> (1) As it stands, this patch removes a net of just about 1000 lines
> of code. So we clearly need *something*.

> (2) The savings would be even more, except that people have invented
> macros for pg_log_error + exit(1) in at least four places already.
> (None of them quite the same of course.) Here I've just fixed those
> macro definitions to use pg_log_fatal. In the name of consistency, we
> should probably get rid of those macros in favor of using pg_log_fatal
> directly; but I've not done so here, since this patch is eyewateringly
> long and boring already.

Agreed.

I don't care that much about the naming here.

For a moment I was wondering whether there'd be a benefit for having the "pure
logging" stuff be in a different static library than the erroring variant. So
that e.g. libpq's check for exit() doesn't run into trouble. But then I
remembered that libpq doesn't link against common...

Greetings,

Andres Freund

Andres Freund <andres(at)anarazel(dot)de> writes:
> What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps
> pg_log_* stuff "log only", but adds something adjacent enough to hopefully
> reduce future misunderstandings?

I'd be okay with that, except that pg_upgrade already has a pg_fatal
(because it has its *own* logging system, just in case you thought
this wasn't enough of a mess yet). I'm in favor of aligning
pg_upgrade's logging with the rest, but I'd hoped to leave that for
later. Making the names collide would be bad even as a short-term
thing, I fear.

Looks like libpq_pipeline.c has its own pg_fatal, too.

I'm not against choosing some name other than pg_log_fatal, but that
particular suggestion has got conflicts. Got any other ideas?

regards, tom lane

On 2022-02-22 22:44:25 -0500, Tom Lane wrote:
> Andres Freund <andres(at)anarazel(dot)de> writes:
> > What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps
> > pg_log_* stuff "log only", but adds something adjacent enough to hopefully
> > reduce future misunderstandings?
>
> I'd be okay with that, except that pg_upgrade already has a pg_fatal
> (because it has its *own* logging system, just in case you thought
> this wasn't enough of a mess yet). I'm in favor of aligning
> pg_upgrade's logging with the rest, but I'd hoped to leave that for
> later. Making the names collide would be bad even as a short-term
> thing, I fear.

I guess we could name pg_upgrade's out of the way...

> I'm not against choosing some name other than pg_log_fatal, but that
> particular suggestion has got conflicts. Got any other ideas?

Maybe pg_fatal_exit(), pg_exit_fatal() or pg_fatal_error()?

I wrote:
> Andres Freund <andres(at)anarazel(dot)de> writes:
>> What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps
>> pg_log_* stuff "log only", but adds something adjacent enough to hopefully
>> reduce future misunderstandings?

> I'd be okay with that, except that pg_upgrade already has a pg_fatal
> (because it has its *own* logging system, just in case you thought
> this wasn't enough of a mess yet).

Wait a moment. After looking closer, I realize that pg_upgrade's
pg_fatal could trivially be turned into a macro; and the other two
existing definitions already are macros. That would remove the risk
of link-time symbol collisions that I was worried about. As a bonus,
it'd substantially reduce the number of changes needed to make
pg_upgrade use logging.c, whenever somebody wants to make that happen.

So I now propose modifying yesterday's patch thus:

* Reinstantiate the PG_LOG_FATAL enum value, add support macros
pg_log_fatal, pg_log_fatal_hint, pg_log_fatal_detail.

* Define pg_fatal as pg_log_fatal + exit(1). (This would essentially
move pg_rewind's definition into logging.h. pg_upgrade will
define it slightly differently, but the semantics end up the same.)

* Adjust call sites to match.

I do like this idea because it would not break any existing code
that expects pg_log_fatal to return. There is likely to be some
of that in outstanding patches, and this approach would merely
render it less-than-idiomatic rather than outright broken.

Updating the patch is going to be a bit tedious, so I'm not
going to do it without buy-in that this solution would be
okay to commit. Any objections?

regards, tom lane

Hi,

On 2022-02-23 10:30:02 -0500, Tom Lane wrote:
> So I now propose modifying yesterday's patch thus:
>
> * Reinstantiate the PG_LOG_FATAL enum value, add support macros
> pg_log_fatal, pg_log_fatal_hint, pg_log_fatal_detail.
>
> * Define pg_fatal as pg_log_fatal + exit(1). (This would essentially
> move pg_rewind's definition into logging.h. pg_upgrade will
> define it slightly differently, but the semantics end up the same.)
>
> * Adjust call sites to match.

+1

> I do like this idea because it would not break any existing code
> that expects pg_log_fatal to return. There is likely to be some
> of that in outstanding patches, and this approach would merely
> render it less-than-idiomatic rather than outright broken.
>
> Updating the patch is going to be a bit tedious, so I'm not
> going to do it without buy-in that this solution would be
> okay to commit. Any objections?

+1

Greetings,

Andres Freund

On Wed, Feb 23, 2022, at 12:30 PM, Tom Lane wrote:
> Updating the patch is going to be a bit tedious, so I'm not
> going to do it without buy-in that this solution would be
> okay to commit. Any objections?
No. I was confused by the multiple log functions spread in the client programs
while I was working on pg_subscriber [1]. Your proposal looks good to me.

[1] https://postgr.es/m/5ac50071-f2ed-4ace-a8fd-b892cffd33eb%40www.fastmail.com

--
Euler Taveira
EDB https://www.enterprisedb.com/

On 23.02.22 00:23, Tom Lane wrote:
> This conversation seems to have tailed off without full resolution,
> but I observe that pretty much everyone except Peter is on board
> with defining pg_log_fatal as pg_log_error + exit(1). So I think
> we should just do that, unless Peter wants to produce a finished
> alternative proposal.
>
> I've now gone through and fleshed out the patch I sketched upthread.

This patch already illustrates a couple of things that are wrong with
this approach:

- It doesn't allow any other way of exiting. For example, in pg_dump,
you have removed a few exit_nicely() calls. It's not clear why that is
valid or whether it would always be valid for all call sites.

- It doesn't allow other exit codes. For example, in psql, you have
changed a pg_log_fatal() call to pg_log_error() because it needed
another exit code. This slides us right back into that annoying
situation where in the backend we have to log error messages using
elog(LOG) because the flow control is tangled up with the log level.

My suggestion is to just get rid of pg_log_fatal() and replace them all
with pg_log_error().

Hi,

On 2022-02-24 14:06:18 +0100, Peter Eisentraut wrote:
> My suggestion is to just get rid of pg_log_fatal() and replace them all with
> pg_log_error().

-1. This ignores that already several places came up with their slightly
different versions of fatal exit handlers. We don't gain anything by not
standardizing on one notion of a fatal error wrapper.

Greetings,

Andres Freund

Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> writes:
> This patch already illustrates a couple of things that are wrong with
> this approach:

All of these objections are a bit moot with my followup proposal, no?

> - It doesn't allow any other way of exiting. For example, in pg_dump,
> you have removed a few exit_nicely() calls. It's not clear why that is
> valid or whether it would always be valid for all call sites.

As the patch stood, I'd hacked it so that pg_log_fatal called
exit_nicely() not exit() within pg_dump. I agree that's not a great
solution, but I think that the correct fix is to get rid of exit_nicely
in favor of doing the requisite cleanup in an atexit hook. pg_dump
is already at great hazard of somebody calling exit() not exit_nicely(),
either through failure to pay attention to that undocumented convention,
or because some code it imports from someplace like src/common calls
exit() directly. You need not look any further than pg_malloc()
to see that there are live problems there.

I figured this could be addressed in a separate patch, though,
because to the extent that missing the exit-nicely callbacks is
a real bug, it's already a bug.

> My suggestion is to just get rid of pg_log_fatal() and replace them all
> with pg_log_error().

I'm on board with dropping the separate FATAL log level if there's
consensus to do so; I think it adds more confusion than anything else.
I still want to have something like pg_fatal(), though, because it's
impossible to deny the usefulness of such an abbreviation. It's already
been reinvented three or four times independently.

Independently of either of those points, I still want to make the changes
I proposed w.r.t. making explicit concepts of "detail" and "hint"
addendums. What we have right now in the frontend code is an impossible
mishmash of three or four ways of filling that lack, all inconsistent.

regards, tom lane

I wrote:
> I'm on board with dropping the separate FATAL log level if there's
> consensus to do so; I think it adds more confusion than anything else.

I feel that the reasonable alternatives are either to drop the FATAL
log level, or try to make it actually mean something by consistently
using it for errors that are indeed fatal. I had a go at doing the
latter, but eventually concluded that that way madness lies. It's
not too hard to use "pg_log_fatal" when there's an exit(1) right
after it, but there are quite a lot of cases where a subroutine
reports an error and returns a failure code to its caller, whereupon
the caller exits. Either the subroutine has to make an unwarranted
assumption about what its callers will do, or we need to make an API
change to allow the subroutine itself to exit(), or we are going to
present a user experience that is inconsistently different depending
on internal implementation details.

Just to add insult to injury, once I'd gotten done with the easy
part (use pg_log_fatal where there's an adjacent exit()), a whole
lot of TAP tests fell over, because they were expecting "error:"
not "fatal:". The reverse direction of s/fatal/error/g only breaks
one TAP test, which says a lot about how many places are troubling
to make this distinction now.

I conclude that we ought to drop the separate FATAL level and just
use ERROR instead.

The attached revision does that, standardizes on pg_fatal() as the
abbreviation for pg_log_error() + exit(1), and invents detail/hint
features as per previous discussion.

regards, tom lane

On Fri, Feb 25, 2022 at 12:15:25PM -0500, Tom Lane wrote:
> I feel that the reasonable alternatives are either to drop the FATAL
> log level, or try to make it actually mean something by consistently
> using it for errors that are indeed fatal. I had a go at doing the
> latter, but eventually concluded that that way madness lies. It's
> not too hard to use "pg_log_fatal" when there's an exit(1) right
> after it, but there are quite a lot of cases where a subroutine
> reports an error and returns a failure code to its caller, whereupon
> the caller exits. Either the subroutine has to make an unwarranted
> assumption about what its callers will do, or we need to make an API
> change to allow the subroutine itself to exit(), or we are going to
> present a user experience that is inconsistently different depending
> on internal implementation details.

Nice code cut.

> I conclude that we ought to drop the separate FATAL level and just
> use ERROR instead.

FWIW, I have found the uses of pg_log_error() and pg_log_fatal()
rather confusing in some of the src/bin/ tools, so I am in favor of
removing completely one or the other, and getting rid of FATAL is the
best choice.

> The attached revision does that, standardizes on pg_fatal() as the
> abbreviation for pg_log_error() + exit(1), and invents detail/hint
> features as per previous discussion.

+#define pg_log_warning_hint(...) do { \
+ if (likely(__pg_log_level <= PG_LOG_WARNING)) \
+ pg_log_generic(PG_LOG_WARNING, PG_LOG_HINT, __VA_ARGS__);
\
} while(0)

Hm. I am not sure to like much this abstraction by having so many
macros that understand the log level through their name. Wouldn't it
be cleaner to have only one pg_log_hint() and one pg_log_detail() with
the log level passed as argument of the macro?
--
Michael

Michael Paquier <michael(at)paquier(dot)xyz> writes:
> Hm. I am not sure to like much this abstraction by having so many
> macros that understand the log level through their name. Wouldn't it
> be cleaner to have only one pg_log_hint() and one pg_log_detail() with
> the log level passed as argument of the macro?

Mmm ... that doesn't sound better to me. I think it wouldn't be
obvious that pg_log_warning and pg_log_hint are fundamentally
different sorts of things: in the first, "warning" refers to
an error severity level, while in the second, "hint" refers to
a message component. I'm not wedded to the way I did it in this
patch, but I think we ought to maintain a notational distinction
between those two sorts of concepts.

regards, tom lane

Hi,

On 2022-02-25 12:15:25 -0500, Tom Lane wrote:
> The attached revision does that, standardizes on pg_fatal() as the
> abbreviation for pg_log_error() + exit(1), and invents detail/hint
> features as per previous discussion.

This unfortunately has had some bitrot: http://cfbot.cputube.org/patch_37_3574.log

Marked as waiting-on-author.

Greetings,

Andres

Andres Freund <andres(at)anarazel(dot)de> writes:
> On 2022-02-25 12:15:25 -0500, Tom Lane wrote:
>> The attached revision does that, standardizes on pg_fatal() as the
>> abbreviation for pg_log_error() + exit(1), and invents detail/hint
>> features as per previous discussion.

> This unfortunately has had some bitrot: http://cfbot.cputube.org/patch_37_3574.log

Yeah, I know. That patch touches enough places that it's sure to
break every few days during a commitfest. I'm not real excited about
maintaining it reactively. The flip side of the coin is that pushing
it will doubtless break a lot of other uncommitted patches. So I'm
not sure how to proceed.

Maybe the plan could be to push it at the end of the commitfest? But
what I'd really like at the moment is buy-in or rejection of the whole
concept, so I know whether it's worth spending more time on.

regards, tom lane

Hi,

On 2022-03-21 22:00:37 -0400, Tom Lane wrote:
> Andres Freund <andres(at)anarazel(dot)de> writes:
> > This unfortunately has had some bitrot: http://cfbot.cputube.org/patch_37_3574.log
>
> Yeah, I know. That patch touches enough places that it's sure to
> break every few days during a commitfest. I'm not real excited about
> maintaining it reactively.

Makes sense. I'd leave it on waiting-on-author then, so that reviewers looking
through the CF don't need to look at it?

> Maybe the plan could be to push it at the end of the commitfest?

Would make sense to me.

Arguably parts of it could be committed sooner than that, e.g. exit(-1). But
that'd not make it meaningfully easier to maintain, so ...

> But what I'd really like at the moment is buy-in or rejection of the whole
> concept, so I know whether it's worth spending more time on.

I'm +1. I've not carefully looked through every single changed callsite, but
IMO it looks like a clear improvement.

Greetings,

Andres Freund

Here's a rebase up to today's HEAD. I've fixed the merge problems,
but there may be some stray new error calls that could be converted
to use pg_fatal() and haven't been. I don't want to do a full
fresh scan of the code until we're about ready to commit this.

regards, tom lane

> On 27 Mar 2022, at 22:19, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>
> Here's a rebase up to today's HEAD. I've fixed the merge problems,
> but there may be some stray new error calls that could be converted
> to use pg_fatal() and haven't been. I don't want to do a full
> fresh scan of the code until we're about ready to commit this.

I focused on finding any changes in logic (exiting where it previously kept
going after error, or vice versa) and was unable to find any which inspires
confidence. This was a large patch to read through, so I'm fairly sure I've
missed something.

Below are comments (nitpicks to a large extent) which either relates to this
patch or to the messages in general. For the latter, feel free to deem them
out of scope and we can take those comments separately from this work on
-hackers.

As a side-note realization from reading this, there is a tremendous amount of
code paths in pg_dump which leads to a fatal error.. thats not necessarily a
bad thing, it's just striking when reading them all at once.

> @@ -508,24 +502,15 @@ writefile(char *path, char **lines)

> if (fclose(out_file))
> - {
> - pg_log_error("could not write file \"%s\": %m", path);
> - exit(1);
> - }
> + pg_fatal("could not write file \"%s\": %m", path);
> }

Should we update this message to differentiate it from the fwrite error case?
Something like "an error occurred during writing.."

> @@ -2057,10 +2004,7 @@ check_locale_name(int category, const char *locale, char **canonname)
>
> save = setlocale(category, NULL);
> if (!save)
> - {
> - pg_log_error("setlocale() failed");
> - exit(1);
> - }
> + pg_fatal("setlocale() failed");

Should this gain a hint message for those users who have no idea what this
really means?

> @@ -2127,15 +2067,14 @@ check_locale_encoding(const char *locale, int user_enc)
> user_enc == PG_SQL_ASCII))
> {
> pg_log_error("encoding mismatch");
> - fprintf(stderr,
> - _("The encoding you selected (%s) and the encoding that the\n"
> - "selected locale uses (%s) do not match. This would lead to\n"
> - "misbehavior in various character string processing functions.\n"
> - "Rerun %s and either do not specify an encoding explicitly,\n"
> - "or choose a matching combination.\n"),
> - pg_encoding_to_char(user_enc),
> - pg_encoding_to_char(locale_enc),
> - progname);
> + pg_log_error_detail("The encoding you selected (%s) and the encoding that the "
> + "selected locale uses (%s) do not match. This would lead to "

I will be sad to see double space after period go, but I think I'm rare in
preferring that.

> @@ -2344,10 +2276,7 @@ setup_pgdata(void)
> * have embedded spaces.
> */
> if (setenv("PGDATA", pg_data, 1) != 0)
> - {
> - pg_log_error("could not set environment");
> - exit(1);
> - }
> + pg_fatal("could not set environment");

Should we be explicit about which env var?

> @@ -3089,18 +2979,14 @@ main(int argc, char *argv[])
> else if (strcmp(optarg, "libc") == 0)
> locale_provider = COLLPROVIDER_LIBC;
> else
> - {
> - pg_log_error("unrecognized locale provider: %s", optarg);
> - exit(1);
> - }
> + pg_fatal("unrecognized locale provider: %s", optarg);

Should this %s be within quotes to match how we usually emit user-input?

> @@ -1123,9 +1097,9 @@ verify_btree_slot_handler(PGresult *res, PGconn *conn, void *context)
> pg_log_warning("btree index \"%s.%s.%s\": btree checking function returned unexpected number of rows: %d",
> rel->datinfo->datname, rel->nspname, rel->relname, ntups);
> if (opts.verbose)
> - pg_log_info("query was: %s", rel->sql);
> - pg_log_warning("Are %s's and amcheck's versions compatible?",
> - progname);
> + pg_log_warning_detail("Query was: %s", rel->sql);
> + pg_log_warning_hint("Are %s's and amcheck's versions compatible?",
> + progname);

Should "amcheck's" be a %s parameter to make translation reusable (which it
miht never be) and possibly avoid translation mistake?

> --- a/src/bin/pg_basebackup/receivelog.c
> +++ b/src/bin/pg_basebackup/receivelog.c
> @@ -140,7 +140,7 @@ open_walfile(StreamCtl *stream, XLogRecPtr startpoint)
> /* fsync file in case of a previous crash */
> if (stream->walmethod->sync(f) != 0)
> {
> - pg_log_fatal("could not fsync existing write-ahead log file \"%s\": %s",
> + pg_log_error("could not fsync existing write-ahead log file \"%s\": %s",
> fn, stream->walmethod->getlasterror());
> stream->walmethod->close(f, CLOSE_UNLINK);
> exit(1);

In the case where we already have IO related errors, couldn't the close() call
cause an additional error message which potentially could be helpful for
debugging?

> @@ -597,31 +570,19 @@ main(int argc, char *argv[])

> if (ControlFile->data_checksum_version == 0 &&
> mode == PG_MODE_CHECK)
> - {
> - pg_log_error("data checksums are not enabled in cluster");
> - exit(1);
> - }
> + pg_fatal("data checksums are not enabled in cluster");
>
> if (ControlFile->data_checksum_version == 0 &&
> mode == PG_MODE_DISABLE)
> - {
> - pg_log_error("data checksums are already disabled in cluster");
> - exit(1);
> - }
> + pg_fatal("data checksums are already disabled in cluster");
>
> if (ControlFile->data_checksum_version > 0 &&
> mode == PG_MODE_ENABLE)
> - {
> - pg_log_error("data checksums are already enabled in cluster");
> - exit(1);
> - }
> + pg_fatal("data checksums are already enabled in cluster");

Fatal seems sort of out place here, it's not really a case of "something
terrible happened" but rather "the preconditions weren't met". Couldn't these
be a single pg_log_error erroring out with the reason in a pg_log_detail?

> @@ -1323,10 +1320,10 @@ lockTableForWorker(ArchiveHandle *AH, TocEntry *te)
> res = PQexec(AH->connection, query->data);
>
> if (!res || PQresultStatus(res) != PGRES_COMMAND_OK)
> - fatal("could not obtain lock on relation \"%s\"\n"
> - "This usually means that someone requested an ACCESS EXCLUSIVE lock "
> - "on the table after the pg_dump parent process had gotten the "
> - "initial ACCESS SHARE lock on the table.", qualId);
> + pg_fatal("could not obtain lock on relation \"%s\"\n"
> + "This usually means that someone requested an ACCESS EXCLUSIVE lock "
> + "on the table after the pg_dump parent process had gotten the "
> + "initial ACCESS SHARE lock on the table.", qualId);

Punctuation and formatting in a pg_fatal feels a bit wrong, and smells of need
for _detail/_hint. I guess there isn't a way to do that here though, but still
a shame.

> @@ -50,9 +50,10 @@ _check_database_version(ArchiveHandle *AH)
> && (remoteversion < AH->public.minRemoteVersion ||
> remoteversion > AH->public.maxRemoteVersion))
> {
> - pg_log_error("server version: %s; %s version: %s",
> - remoteversion_str, progname, PG_VERSION);
> - fatal("aborting because of server version mismatch");
> + pg_log_error("aborting because of server version mismatch");
> + pg_log_error_detail("server version: %s; %s version: %s",
> + remoteversion_str, progname, PG_VERSION);
> + exit(1);

Capitalization of the _detail message?

> @@ -166,7 +167,7 @@ ConnectDatabase(Archive *AHX,
> AH->connection = PQconnectdbParams(keywords, values, true);
>
> if (!AH->connection)
> - fatal("could not connect to database");
> + pg_fatal("could not connect to database");

Shouldn't this print which database it failed to connect to?

> @@ -721,7 +721,7 @@ setFilePath(ArchiveHandle *AH, char *buf, const char *relativeFilename)
> dname = ctx->directory;
>
> if (strlen(dname) + 1 + strlen(relativeFilename) + 1 > MAXPGPATH)

Unrelated, but shouldn't that be >= MAXPGPATH?

> @@ -2033,8 +2027,8 @@ dumpTableData_copy(Archive *fout, const void *dcontext)
> {
> /* copy data transfer failed */
> pg_log_error("Dumping the contents of table \"%s\" failed: PQgetCopyData() failed.", classname);
> - pg_log_error("Error message from server: %s", PQerrorMessage(conn));
> - pg_log_error("The command was: %s", q->data);
> + pg_log_error_detail("Error message from server: %s", PQerrorMessage(conn));
> + pg_log_error_detail("Command was: %s", q->data);

Shouldn't the pg_log_error() call be with leading lowercase and no punctuation?
(same in the following hunk)

> @@ -11756,8 +11747,8 @@ dumpFunc(Archive *fout, const FuncInfo *finfo)
> else if (provolatile[0] == PROVOLATILE_STABLE)
> appendPQExpBufferStr(q, " STABLE");
> else if (provolatile[0] != PROVOLATILE_VOLATILE)
> - fatal("unrecognized provolatile value for function \"%s\"",
> - finfo->dobj.name);
> + pg_fatal("unrecognized provolatile value for function \"%s\"",
> + finfo->dobj.name);
> }
>
> if (proisstrict[0] == 't')
> @@ -11806,8 +11797,8 @@ dumpFunc(Archive *fout, const FuncInfo *finfo)
> else if (proparallel[0] == PROPARALLEL_RESTRICTED)
> appendPQExpBufferStr(q, " PARALLEL RESTRICTED");
> else if (proparallel[0] != PROPARALLEL_UNSAFE)
> - fatal("unrecognized proparallel value for function \"%s\"",
> - finfo->dobj.name);
> + pg_fatal("unrecognized proparallel value for function \"%s\"",
> + finfo->dobj.name);

We should probably move the provolatile and propallel keywords to a %s param so
we can reuse the translation.

> @@ -14951,18 +14942,18 @@ createViewAsClause(Archive *fout, const TableInfo *tbinfo)

> - fatal("definition of view \"%s\" appears to be empty (length zero)",
> - tbinfo->dobj.name);
> + pg_fatal("definition of view \"%s\" appears to be empty (length zero)",
> + tbinfo->dobj.name);

I'm not sure we need to provide a definition of empty here, most readers will
probably understand that already =)

> @@ -16602,13 +16593,10 @@ dumpSequence(Archive *fout, const TableInfo *tbinfo)
> res = ExecuteSqlQuery(fout, query->data, PGRES_TUPLES_OK);
>
> if (PQntuples(res) != 1)
> - {
> - pg_log_error(ngettext("query to get data of sequence \"%s\" returned %d row (expected 1)",
> - "query to get data of sequence \"%s\" returned %d rows (expected 1)",
> - PQntuples(res)),
> - tbinfo->dobj.name, PQntuples(res));
> - exit_nicely(1);
> - }
> + pg_fatal(ngettext("query to get data of sequence \"%s\" returned %d row (expected 1)",
> + "query to get data of sequence \"%s\" returned %d rows (expected 1)",
> + PQntuples(res)),
> + tbinfo->dobj.name, PQntuples(res));

The ngettext() call seems a bit out of place here since we already know that
second form will be taken given the check on PQntuples(res).

> @@ -16824,13 +16812,10 @@ dumpSequenceData(Archive *fout, const TableDataInfo *tdinfo)
> res = ExecuteSqlQuery(fout, query->data, PGRES_TUPLES_OK);
>
> if (PQntuples(res) != 1)
> - {
> - pg_log_error(ngettext("query to get data of sequence \"%s\" returned %d row (expected 1)",
> - "query to get data of sequence \"%s\" returned %d rows (expected 1)",
> - PQntuples(res)),
> - tbinfo->dobj.name, PQntuples(res));
> - exit_nicely(1);
> - }
> + pg_fatal(ngettext("query to get data of sequence \"%s\" returned %d row (expected 1)",
> + "query to get data of sequence \"%s\" returned %d rows (expected 1)",
> + PQntuples(res)),
> + tbinfo->dobj.name, PQntuples(res));

Same as above, PQntuples(res) cannot be 1 so there os just one form used no?

> --- a/src/bin/pg_dump/pg_dumpall.c
> +++ b/src/bin/pg_dump/pg_dumpall.c
> @@ -200,16 +200,15 @@ main(int argc, char *argv[])
> strlcpy(full_path, progname, sizeof(full_path));
>
> if (ret == -1)
> - pg_log_error("The program \"%s\" is needed by %s but was not found in the\n"
> - "same directory as \"%s\".\n"
> - "Check your installation.",
> - "pg_dump", progname, full_path);
> + pg_fatal("The program \"%s\" is needed by %s but was not found in the\n"
> + "same directory as \"%s\".\n"
> + "Check your installation.",
> + "pg_dump", progname, full_path);
> else
> - pg_log_error("The program \"%s\" was found by \"%s\"\n"
> - "but was not the same version as %s.\n"
> - "Check your installation.",
> - "pg_dump", full_path, progname);
> - exit_nicely(1);
> + pg_fatal("The program \"%s\" was found by \"%s\"\n"
> + "but was not the same version as %s.\n"
> + "Check your installation.",

"Check your installation" seems superfluous here given the error. (we do this
in a number of places)

> @@ -1611,9 +1572,9 @@ connectDatabase(const char *dbname, const char *connection_string,
> && (server_version < 90200 ||
> (server_version / 100) > (my_version / 100)))
> {
> - pg_log_error("server version: %s; %s version: %s",
> - remoteversion_str, progname, PG_VERSION);
> pg_log_error("aborting because of server version mismatch");
> + pg_log_error_detail("server version: %s; %s version: %s",
> + remoteversion_str, progname, PG_VERSION);

Capitalization?

> @@ -388,13 +387,13 @@ WALDumpReadPage(XLogReaderState *state, XLogRecPtr targetPagePtr, int reqLen,
> if (errinfo.wre_errno != 0)
> {
> errno = errinfo.wre_errno;
> - fatal_error("could not read from file %s, offset %d: %m",
> - fname, errinfo.wre_off);
> + pg_fatal("could not read from file %s, offset %d: %m",
> + fname, errinfo.wre_off);
> }
> else
> - fatal_error("could not read from file %s, offset %d: read %d of %d",
> - fname, errinfo.wre_off, errinfo.wre_read,
> - errinfo.wre_req);
> + pg_fatal("could not read from file %s, offset %d: read %d of %d",
> + fname, errinfo.wre_off, errinfo.wre_read,
> + errinfo.wre_req);

Filename %s should be quoted like \"%s\".

> @@ -7379,7 +7254,7 @@ main(int argc, char **argv)
> THREAD_BARRIER_DESTROY(&barrier);
>
> if (exit_code != 0)
> - pg_log_fatal("Run was aborted; the above results are incomplete.");
> + pg_log_error("Run was aborted; the above results are incomplete.");

Capitalization and punctuation?

> @@ -781,10 +772,7 @@ process_psqlrc(char *argv0)
> char *envrc = getenv("PSQLRC");
>
> if (find_my_exec(argv0, my_exec_path) < 0)
> - {
> - pg_log_fatal("could not find own program executable");
> - exit(EXIT_FAILURE);
> - }
> + pg_fatal("could not find own program executable");

I have a feeling this will be confusing to a fair few users. Not sure how to
improve it, but there seems to be some room for it.

> @@ -144,16 +145,10 @@ main(int argc, char *argv[])
> if (alldb)
> {
> if (dbname)
> - {
> - pg_log_error("cannot cluster all databases and a specific one at the same time");
> - exit(1);
> - }
> + pg_fatal("cannot cluster all databases and a specific one at the same time");
>
> if (tables.head != NULL)
> - {
> - pg_log_error("cannot cluster specific table(s) in all databases");
> - exit(1);
> - }
> + pg_fatal("cannot cluster specific table(s) in all databases");

An ngettext() candidate perhaps? There are more like this in main() hunks further down omitted for brevity here.

> diff --git a/src/fe_utils/connect_utils.c b/src/fe_utils/connect_utils.c
> index a30c66f13a..f2e583f9fa 100644
> --- a/src/fe_utils/connect_utils.c
> +++ b/src/fe_utils/connect_utils.c
> @@ -88,11 +88,8 @@ connectDatabase(const ConnParams *cparams, const char *progname,
> conn = PQconnectdbParams(keywords, values, true);
>
> if (!conn)
> - {
> - pg_log_error("could not connect to database %s: out of memory",
> - cparams->dbname);
> - exit(1);
> - }
> + pg_fatal("could not connect to database %s: out of memory",
> + cparams->dbname);

Database name quoted like \"%s\" to match other messages?

--
Daniel Gustafsson https://vmware.com/

On 27.03.22 22:19, Tom Lane wrote:
> Here's a rebase up to today's HEAD. I've fixed the merge problems,
> but there may be some stray new error calls that could be converted
> to use pg_fatal() and haven't been. I don't want to do a full
> fresh scan of the code until we're about ready to commit this.

This looks like a good improvement to me.

I think I would want the program name/location also in front of the
detail and hint lines. I need to think about this a bit more. This
shouldn't hold up this patch; it would be a quick localized change.
(I'm also thinking about providing a separate color code for the
secondary messages. Again, this could be a quick follow-up patch.)

The one change I didn't like was

- pg_log_error("The program \"%s\" is needed by %s
but was not found in the\n"
- "same directory as
\"%s\".\n"
- "Check your installation.",
+ pg_log_error("the program \"%s\" is needed by %s
but was not found in the same directory as \"%s\"",
"postgres", progname,
full_path);

This appears to prioritize the guideline "don't punctuate error message
as full sentence" over what should be the actual guideline "don't make
the error message a full sentence".

There are other occurrences of a similar message that were not changed
in the same way by the patch. Maybe we should leave this one alone in
this patch and consider rewriting the message instead.

On 29.03.22 12:13, Daniel Gustafsson wrote:

Most of these should probably be addressed separately from Tom's patch.

>> @@ -508,24 +502,15 @@ writefile(char *path, char **lines)
>
>> if (fclose(out_file))
>> - {
>> - pg_log_error("could not write file \"%s\": %m", path);
>> - exit(1);
>> - }
>> + pg_fatal("could not write file \"%s\": %m", path);
>> }
>
> Should we update this message to differentiate it from the fwrite error case?
> Something like "an error occurred during writing.."

Should be "could not close ...", no?

>> @@ -2057,10 +2004,7 @@ check_locale_name(int category, const char *locale, char **canonname)
>>
>> save = setlocale(category, NULL);
>> if (!save)
>> - {
>> - pg_log_error("setlocale() failed");
>> - exit(1);
>> - }
>> + pg_fatal("setlocale() failed");
>
> Should this gain a hint message for those users who have no idea what this
> really means?

My setlocale() man page says:

ERRORS
No errors are defined.

So uh ... ;-)

>> @@ -3089,18 +2979,14 @@ main(int argc, char *argv[])
>> else if (strcmp(optarg, "libc") == 0)
>> locale_provider = COLLPROVIDER_LIBC;
>> else
>> - {
>> - pg_log_error("unrecognized locale provider: %s", optarg);
>> - exit(1);
>> - }
>> + pg_fatal("unrecognized locale provider: %s", optarg);
>
> Should this %s be within quotes to match how we usually emit user-input?

Usually not done after colon, but could be.

>> @@ -1123,9 +1097,9 @@ verify_btree_slot_handler(PGresult *res, PGconn *conn, void *context)
>> pg_log_warning("btree index \"%s.%s.%s\": btree checking function returned unexpected number of rows: %d",
>> rel->datinfo->datname, rel->nspname, rel->relname, ntups);
>> if (opts.verbose)
>> - pg_log_info("query was: %s", rel->sql);
>> - pg_log_warning("Are %s's and amcheck's versions compatible?",
>> - progname);
>> + pg_log_warning_detail("Query was: %s", rel->sql);
>> + pg_log_warning_hint("Are %s's and amcheck's versions compatible?",
>> + progname);
>
> Should "amcheck's" be a %s parameter to make translation reusable (which it
> miht never be) and possibly avoid translation mistake?

We don't have translations set up for contrib modules. Otherwise, this
kind of thing would probably be something to look into.

>> --- a/src/bin/pg_basebackup/receivelog.c
>> +++ b/src/bin/pg_basebackup/receivelog.c
>> @@ -140,7 +140,7 @@ open_walfile(StreamCtl *stream, XLogRecPtr startpoint)
>> /* fsync file in case of a previous crash */
>> if (stream->walmethod->sync(f) != 0)
>> {
>> - pg_log_fatal("could not fsync existing write-ahead log file \"%s\": %s",
>> + pg_log_error("could not fsync existing write-ahead log file \"%s\": %s",
>> fn, stream->walmethod->getlasterror());
>> stream->walmethod->close(f, CLOSE_UNLINK);
>> exit(1);
>
> In the case where we already have IO related errors, couldn't the close() call
> cause an additional error message which potentially could be helpful for
> debugging?

Yeah, I think in general we have been sloppy with reporting file-closing
errors properly. Those presumably happen very rarely, but when they do,
things are probably very bad.

>> @@ -597,31 +570,19 @@ main(int argc, char *argv[])
>
>> if (ControlFile->data_checksum_version == 0 &&
>> mode == PG_MODE_CHECK)
>> - {
>> - pg_log_error("data checksums are not enabled in cluster");
>> - exit(1);
>> - }
>> + pg_fatal("data checksums are not enabled in cluster");

> Fatal seems sort of out place here, it's not really a case of "something
> terrible happened" but rather "the preconditions weren't met". Couldn't these
> be a single pg_log_error erroring out with the reason in a pg_log_detail?

"fatal" means error plus exit, so this seems ok. There is no separate
log level for really-bad-error.

>> @@ -721,7 +721,7 @@ setFilePath(ArchiveHandle *AH, char *buf, const char *relativeFilename)
>> dname = ctx->directory;
>>
>> if (strlen(dname) + 1 + strlen(relativeFilename) + 1 > MAXPGPATH)
>
> Unrelated, but shouldn't that be >= MAXPGPATH?

Seems correct to me as is.

>> @@ -14951,18 +14942,18 @@ createViewAsClause(Archive *fout, const TableInfo *tbinfo)
>
>> - fatal("definition of view \"%s\" appears to be empty (length zero)",
>> - tbinfo->dobj.name);
>> + pg_fatal("definition of view \"%s\" appears to be empty (length zero)",
>> + tbinfo->dobj.name);
>
> I'm not sure we need to provide a definition of empty here, most readers will
> probably understand that already =)

It could mean, contains no columns, or something similar. If I had to
change it, I would remove the "empty" and keep the "length zero".

>> @@ -16602,13 +16593,10 @@ dumpSequence(Archive *fout, const TableInfo *tbinfo)
>> res = ExecuteSqlQuery(fout, query->data, PGRES_TUPLES_OK);
>>
>> if (PQntuples(res) != 1)
>> - {
>> - pg_log_error(ngettext("query to get data of sequence \"%s\" returned %d row (expected 1)",
>> - "query to get data of sequence \"%s\" returned %d rows (expected 1)",
>> - PQntuples(res)),
>> - tbinfo->dobj.name, PQntuples(res));
>> - exit_nicely(1);
>> - }
>> + pg_fatal(ngettext("query to get data of sequence \"%s\" returned %d row (expected 1)",
>> + "query to get data of sequence \"%s\" returned %d rows (expected 1)",
>> + PQntuples(res)),
>> + tbinfo->dobj.name, PQntuples(res));
>
> The ngettext() call seems a bit out of place here since we already know that
> second form will be taken given the check on PQntuples(res).

See
<https://www.postgresql.org/message-id/flat/CALj2ACUfJKTmK5v%3DvF%2BH2iLkqM9Yvjsp6iXaCqAks6gDpzZh6g%40mail.gmail.com>
for a similar case that explains why this is still correct and necessary.

>> @@ -144,16 +145,10 @@ main(int argc, char *argv[])
>> if (alldb)
>> {
>> if (dbname)
>> - {
>> - pg_log_error("cannot cluster all databases and a specific one at the same time");
>> - exit(1);
>> - }
>> + pg_fatal("cannot cluster all databases and a specific one at the same time");
>>
>> if (tables.head != NULL)
>> - {
>> - pg_log_error("cannot cluster specific table(s) in all databases");
>> - exit(1);
>> - }
>> + pg_fatal("cannot cluster specific table(s) in all databases");
>
> An ngettext() candidate perhaps? There are more like this in main() hunks further down omitted for brevity here.

I would just rephrase this as

"cannot cluster specific tables in all databases"

This is still correct and sensible if the user specified just one table.

> On 29 Mar 2022, at 16:38, Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> wrote:
>
> On 29.03.22 12:13, Daniel Gustafsson wrote:
>
> Most of these should probably be addressed separately from Tom's patch.

Yeah, I think so too. I'll await input from Tom on how he wants to do, but I'm
happy to take these to a new thread. The main point of the review was to find
logic errors in the logging changes, these came as a bonus from reading them
all in one place.

>>> @@ -508,24 +502,15 @@ writefile(char *path, char **lines)
>>> if (fclose(out_file))
>>> - {
>>> - pg_log_error("could not write file \"%s\": %m", path);
>>> - exit(1);
>>> - }
>>> + pg_fatal("could not write file \"%s\": %m", path);
>>> }
>> Should we update this message to differentiate it from the fwrite error case?
>> Something like "an error occurred during writing.."
>
> Should be "could not close ...", no?

Yes, it should, not sure what I was thinking.

>>> @@ -2057,10 +2004,7 @@ check_locale_name(int category, const char *locale, char **canonname)
>>>
>>> save = setlocale(category, NULL);
>>> if (!save)
>>> - {
>>> - pg_log_error("setlocale() failed");
>>> - exit(1);
>>> - }
>>> + pg_fatal("setlocale() failed");
>> Should this gain a hint message for those users who have no idea what this
>> really means?
>
> My setlocale() man page says:
>
> ERRORS
> No errors are defined.
>
> So uh ... ;-)

Even more reason to be confused then =) We have a mixed bag in the tree on how
we handle errors from setlocale, in this case we could reword it to say
something like "failed to retrieve locale for %s, category" which IMO would be
slightly more informative. Might be academic though since I guess it rarely, if
ever, happens.

>>> --- a/src/bin/pg_basebackup/receivelog.c
>>> +++ b/src/bin/pg_basebackup/receivelog.c
>>> @@ -140,7 +140,7 @@ open_walfile(StreamCtl *stream, XLogRecPtr startpoint)
>>> /* fsync file in case of a previous crash */
>>> if (stream->walmethod->sync(f) != 0)
>>> {
>>> - pg_log_fatal("could not fsync existing write-ahead log file \"%s\": %s",
>>> + pg_log_error("could not fsync existing write-ahead log file \"%s\": %s",
>>> fn, stream->walmethod->getlasterror());
>>> stream->walmethod->close(f, CLOSE_UNLINK);
>>> exit(1);
>> In the case where we already have IO related errors, couldn't the close() call
>> cause an additional error message which potentially could be helpful for
>> debugging?
>
> Yeah, I think in general we have been sloppy with reporting file-closing errors properly. Those presumably happen very rarely, but when they do, things are probably very bad.

Agreed. I'm not sure if Tom wants to add net new loggings in this patchset,
else we could do this separately.

>> The ngettext() call seems a bit out of place here since we already know that
>> second form will be taken given the check on PQntuples(res).
>
> See <https://www.postgresql.org/message-id/flat/CALj2ACUfJKTmK5v%3DvF%2BH2iLkqM9Yvjsp6iXaCqAks6gDpzZh6g%40mail.gmail.com> for a similar case that explains why this is still correct and necessary.

Doh, I knew that, sorry.

>>> }
>>> + pg_fatal("cannot cluster specific table(s) in all databases");
>> An ngettext() candidate perhaps? There are more like this in main() hunks further down omitted for brevity here.
>
> I would just rephrase this as
>
> "cannot cluster specific tables in all databases"
>
> This is still correct and sensible if the user specified just one table.

That's one way yes. Mostly I'm just a bit allergic to the "foo(s)" which my
unscientifically based gut feeling am concerned about not necessarily always
working well for translations.

--
Daniel Gustafsson https://vmware.com/

Daniel Gustafsson <daniel(at)yesql(dot)se> writes:
> On 29 Mar 2022, at 16:38, Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> wrote:
>> Most of these should probably be addressed separately from Tom's patch.

> Yeah, I think so too.

Agreed. I tried to confine my patch to mechanical changes, except
for changing places where the detail/hint features could be used.
(I don't say that I yielded to temptation nowhere, because I don't
recall that for certain; but editing the message texts was not the
point of my patch.)

Feel free to work on a followup editing patch though.

Another thing that occurred to me as I looked at your list is that
I think a lot of these are nearly-can't-happen cases that we didn't
put a lot of effort into devising great error messages for. Maybe
we should continue that approach, and in particular not put effort
into translating such messages. That would suggest inventing
"pg_fatal_internal" and so forth, with the same functionality
except for not being gettext triggers, comparable to
errmsg_internal. However, then somebody would have to make
judgment calls about which messages not to bother translating.
Do we want to go down that path?

regards, tom lane

FYI this patch no longer applies.

Given it's a Tom patch and due to its nature it'll bitrot rapidly
anyways I'm don't see a point in updating the status though.

Greg Stark <stark(at)mit(dot)edu> writes:
> FYI this patch no longer applies.

No surprise :-(

> Given it's a Tom patch and due to its nature it'll bitrot rapidly
> anyways I'm don't see a point in updating the status though.

We now seem to have buy-in on the concept, so my plan is to let
this sit till the end of the commitfest, then rebase and push.
That should avoid unnecessary churn for other pending patches.

regards, tom lane

> On 30 Mar 2022, at 00:38, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>
> Daniel Gustafsson <daniel(at)yesql(dot)se> writes:
>> On 29 Mar 2022, at 16:38, Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> wrote:
>>> Most of these should probably be addressed separately from Tom's patch.
>
>> Yeah, I think so too.
>
> Agreed. I tried to confine my patch to mechanical changes, except
> for changing places where the detail/hint features could be used.
> (I don't say that I yielded to temptation nowhere, because I don't
> recall that for certain; but editing the message texts was not the
> point of my patch.)
>
> Feel free to work on a followup editing patch though.

Thats my plan, once this lands I'll rebase the comments on top of your work and
we can have a separate discussion around them then.

> Another thing that occurred to me as I looked at your list is that
> I think a lot of these are nearly-can't-happen cases that we didn't
> put a lot of effort into devising great error messages for. Maybe
> we should continue that approach, and in particular not put effort
> into translating such messages. That would suggest inventing
> "pg_fatal_internal" and so forth, with the same functionality
> except for not being gettext triggers, comparable to
> errmsg_internal. However, then somebody would have to make
> judgment calls about which messages not to bother translating.
> Do we want to go down that path?

I'm not sure. If, against the odds, these cases do happen then a user of a
localized build probably really want to see the error in language they can
easily understand and take in.

--
Daniel Gustafsson https://vmware.com/

Daniel Gustafsson <daniel(at)yesql(dot)se> writes:
> On 30 Mar 2022, at 00:38, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Feel free to work on a followup editing patch though.

> Thats my plan, once this lands I'll rebase the comments on top of your work and
> we can have a separate discussion around them then.

The main patch is pushed now. I addressed the complaint Peter had
about the messages with "Check your installation" pseudo-hints
by getting rid of them; I concur with your observation that those
hints were basically useless. I also fixed the one place where the
message should clearly be "could not close" not "could not write".
Mostly didn't yield to temptation anywhere else.

One other loose end is bothering me: I stuck with logging.h's
original choice to put "if (likely())" or "if (unlikely())"
conditionals into the macros, but I rather suspect that that's
just a waste. I think we should put a centralized level check
into logging.c, and get rid of at least the "if (likely())"
checks, because those are going to succeed approximately 100.0%
of the time. Maybe there's an argument for keeping the unlikely()
ones.

regards, tom lane

I wrote:
> One other loose end is bothering me: I stuck with logging.h's
> original choice to put "if (likely())" or "if (unlikely())"
> conditionals into the macros, but I rather suspect that that's
> just a waste. I think we should put a centralized level check
> into logging.c, and get rid of at least the "if (likely())"
> checks, because those are going to succeed approximately 100.0%
> of the time. Maybe there's an argument for keeping the unlikely()
> ones.

Concretely, something like the attached. As a simple check,
I looked at the compiled size of pg_dump. It went from

text data bss dec hex filename
380298 4008 1384 385690 5e29a /home/postgres/testversion/bin/pg_dump

to

text data bss dec hex filename
374954 4008 1384 380346 5cdba src/bin/pg_dump/pg_dump

for a savings of about 5K or 1.5%. Not a huge amount, but
not nothing either, especially considering that the existing
coding isn't buying us anything.

regards, tom lane

On 08.04.22 22:26, Tom Lane wrote:
> I wrote:
>> One other loose end is bothering me: I stuck with logging.h's
>> original choice to put "if (likely())" or "if (unlikely())"
>> conditionals into the macros, but I rather suspect that that's
>> just a waste. I think we should put a centralized level check
>> into logging.c, and get rid of at least the "if (likely())"
>> checks, because those are going to succeed approximately 100.0%
>> of the time. Maybe there's an argument for keeping the unlikely()
>> ones.
>
> Concretely, something like the attached. As a simple check,
> I looked at the compiled size of pg_dump. It went from
>
> text data bss dec hex filename
> 380298 4008 1384 385690 5e29a /home/postgres/testversion/bin/pg_dump
>
> to
>
> text data bss dec hex filename
> 374954 4008 1384 380346 5cdba src/bin/pg_dump/pg_dump
>
> for a savings of about 5K or 1.5%. Not a huge amount, but
> not nothing either, especially considering that the existing
> coding isn't buying us anything.

Yeah, that seems ok to change. The previous coding style is more useful
if you have a lot of debug messages in a hot code path, but that usually
doesn't apply to where this is used.

Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> writes:
> On 08.04.22 22:26, Tom Lane wrote:
>>> I think we should put a centralized level check
>>> into logging.c, and get rid of at least the "if (likely())"
>>> checks, because those are going to succeed approximately 100.0%
>>> of the time. Maybe there's an argument for keeping the unlikely()
>>> ones.

> Yeah, that seems ok to change. The previous coding style is more useful
> if you have a lot of debug messages in a hot code path, but that usually
> doesn't apply to where this is used.

The patch I presented keeps the unlikely() checks in the debug-level
macros. Do you think we should drop those too? I figured that avoiding
evaluating the arguments would be worth something.

regards, tom lane

On 11.04.22 17:22, Tom Lane wrote:
> Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> writes:
>> On 08.04.22 22:26, Tom Lane wrote:
>>>> I think we should put a centralized level check
>>>> into logging.c, and get rid of at least the "if (likely())"
>>>> checks, because those are going to succeed approximately 100.0%
>>>> of the time. Maybe there's an argument for keeping the unlikely()
>>>> ones.
>
>> Yeah, that seems ok to change. The previous coding style is more useful
>> if you have a lot of debug messages in a hot code path, but that usually
>> doesn't apply to where this is used.
>
> The patch I presented keeps the unlikely() checks in the debug-level
> macros. Do you think we should drop those too? I figured that avoiding
> evaluating the arguments would be worth something.

Oh, that's right, the whole thing is to not evaluate the arguments if
the log level isn't adequate. We should probably keep that.

Is the code size a big problem? ereport() has a bunch of extra code
around each call as well. Does it have similar problems?

Peter Eisentraut <peter(dot)eisentraut(at)enterprisedb(dot)com> writes:
> On 11.04.22 17:22, Tom Lane wrote:
>> The patch I presented keeps the unlikely() checks in the debug-level
>> macros. Do you think we should drop those too? I figured that avoiding
>> evaluating the arguments would be worth something.

> Oh, that's right, the whole thing is to not evaluate the arguments if
> the log level isn't adequate. We should probably keep that.

I don't think that's nearly as interesting in the frontend as in
the backend. Error messages in the backend frequently include
catalog lookups and the like in the arguments, but I think nearly
all frontend messages are writing nothing more complicated than
variables and maybe some indirections or array fetches. So I'm
not all that worried about runtime, and would rather save some
code space.

regards, tom lane

On 29.03.22 16:24, Peter Eisentraut wrote:
> I think I would want the program name/location also in front of the
> detail and hint lines.  I need to think about this a bit more.  This
> shouldn't hold up this patch; it would be a quick localized change.

After experiencing this for a bit now, I propose to make this change.
It lines up better and allows easier filtering of messages by program.

Example:

Before:

initdb: error: locale "zh_HK.Big5HKSCS" requires unsupported encoding "BIG5"
detail: Encoding "BIG5" is not allowed as a server-side encoding.
hint: Rerun initdb with a different locale selection.

After:

initdb: error: locale "zh_HK.Big5HKSCS" requires unsupported encoding "BIG5"
initdb: detail: Encoding "BIG5" is not allowed as a server-side encoding.
initdb: hint: Rerun initdb with a different locale selection.

On 23.05.22 11:53, Peter Eisentraut wrote:
> On 29.03.22 16:24, Peter Eisentraut wrote:
>> I think I would want the program name/location also in front of the
>> detail and hint lines.  I need to think about this a bit more.  This
>> shouldn't hold up this patch; it would be a quick localized change.
>
> After experiencing this for a bit now, I propose to make this change.
> It lines up better and allows easier filtering of messages by program.

This has been committed.

Hi!

Commit 9a374b77fb53 (Improve frontend error logging style.) replaced a
line of file src/include/common/logging.h
```
extern PGDLLIMPORT enum pg_log_level __pg_log_level;
```
to
```
extern enum pg_log_level __pg_log_level;
```
i.e. it is rollback of commit 8ec569479fc28 (Apply PGDLLIMPORT markings
broadly.)

Is it correct?

--
With best regards,
Dmitry Koval

Postgres Professional: http://postgrespro.com

Dmitry Koval <d(dot)koval(at)postgrespro(dot)ru> writes:
> Hi!
> Commit 9a374b77fb53 (Improve frontend error logging style.) replaced a
> line of file src/include/common/logging.h
> ```
> extern PGDLLIMPORT enum pg_log_level __pg_log_level;
> ```
> to
> ```
> extern enum pg_log_level __pg_log_level;
> ```
> i.e. it is rollback of commit 8ec569479fc28 (Apply PGDLLIMPORT markings
> broadly.)

> Is it correct?

Yes, since that file is frontend-only.

regards, tom lane