Re: Adjusting elog behavior in bootstrap/standalone mode

In <3688(dot)1355509732(at)sss(dot)pgh(dot)pa(dot)us> I complained
> PS: one odd thing here is that the ereport(LOG) in
> InstallXLogFileSegment isn't doing anything; otherwise we'd have gotten
> a much more helpful error report about "could not link file". I don't
> think we run the bootstrap mode with log_min_messages set high enough to
> disable LOG messages, so why isn't it printing?

I looked into this and found that the reason the useful message didn't
appear is that elog.c has different rules for what to print in bootstrap
(and standalone-backend) mode:

/* Determine whether message is enabled for server log output */
if (IsPostmasterEnvironment)
output_to_server = is_log_level_output(elevel, log_min_messages);
else
/* In bootstrap/standalone case, do not sort LOG out-of-order */
output_to_server = (elevel >= log_min_messages);

In view of the confusion this caused just now, I wondered if we shouldn't
get rid of the special case and always follow the is_log_level_output
rule. I tried modifying the code that way, and soon found that it made
initdb rather noisy:

creating configuration files ... ok
creating template1 database in /home/postgres/data/base/1 ... LOG: bogus data in "postmaster.pid"
LOG: database system was shut down at 2012-12-14 15:55:35 EST
LOG: shutting down
LOG: database system is shut down
ok
initializing pg_authid ... LOG: bogus data in "postmaster.pid"
LOG: database system was shut down at 2012-12-14 15:55:54 EST
LOG: shutting down
LOG: database system is shut down
ok
initializing dependencies ... LOG: bogus data in "postmaster.pid"
LOG: database system was shut down at 2012-12-14 15:55:55 EST
LOG: shutting down
LOG: database system is shut down
ok

Unsurprisingly, the same four messages appear in a manual
standalone-backend run:

$ postgres --single
LOG: bogus data in "postmaster.pid"
LOG: database system was shut down at 2012-12-14 15:56:27 EST

PostgreSQL stand-alone backend 9.3devel
backend> LOG: shutting down
LOG: database system is shut down
$

Now, the "bogus data" message is actually indicative of a bug.
I've not tracked it down yet, but it evidently must mean that
AddToDataDirLockFile() is being called with out-of-sequence
target_line numbers in standalone mode. This is pretty bad because
it means that a standalone backend isn't setting up the lock file
the way it ought to. We hadn't realized that because elog.c's
behavior was hiding the message that a backend code author would
normally expect to appear.

So that reinforces my feeling that this special case in elog.c
is a bad idea that needs to die. However, to do that without
trashing initdb's normal display, we have to do something to
quiet the other three messages.

One possibility is to tweak the elog call sites for these specific
messages so that they are, say, NOTICE not LOG level when not
IsPostmasterEnvironment. That seems like a bit of a hack, but
I don't see another answer that doesn't involve behind-the-scenes
decisions in elog.c ... which is exactly what I want to get rid of.

Thoughts?

regards, tom lane

On Fri, Dec 14, 2012 at 04:20:30PM -0500, Tom Lane wrote:
> /* Determine whether message is enabled for server log output */
> if (IsPostmasterEnvironment)
> output_to_server = is_log_level_output(elevel, log_min_messages);
> else
> /* In bootstrap/standalone case, do not sort LOG out-of-order */
> output_to_server = (elevel >= log_min_messages);
>
> In view of the confusion this caused just now, I wondered if we shouldn't
> get rid of the special case and always follow the is_log_level_output
> rule. I tried modifying the code that way, and soon found that it made
> initdb rather noisy:

I can see why it was done that way, but agreed.

> creating configuration files ... ok
> creating template1 database in /home/postgres/data/base/1 ... LOG: bogus data in "postmaster.pid"
> LOG: database system was shut down at 2012-12-14 15:55:35 EST
> LOG: shutting down
> LOG: database system is shut down

> One possibility is to tweak the elog call sites for these specific
> messages so that they are, say, NOTICE not LOG level when not
> IsPostmasterEnvironment. That seems like a bit of a hack, but
> I don't see another answer that doesn't involve behind-the-scenes
> decisions in elog.c ... which is exactly what I want to get rid of.

Your proposed hack seems decent. The second and third lines, in particular,
are rather useless here despite their utility under normal logging.

Back before Christmas I complained that elog.c's behavior of
prioritizing LOG-level messages differently in standalone mode had
masked at least one significant bug, as well as causing confusion
in some other cases:
http://www.postgresql.org/message-id/6967.1355520030@sss.pgh.pa.us

I promptly forgot to do anything about it, but I'd still like to get
such a change into 9.3. I've now written and tested a patch that
makes that change without creating any new noise during initdb or in a
manually-started standalone backend. Does anyone have an objection to
applying the attached?

regards, tom lane

* Tom Lane (tgl(at)sss(dot)pgh(dot)pa(dot)us) wrote:
> I promptly forgot to do anything about it, but I'd still like to get
> such a change into 9.3. I've now written and tested a patch that
> makes that change without creating any new noise during initdb or in a
> manually-started standalone backend. Does anyone have an objection to
> applying the attached?

Looks like a good idea to me, +1.

Thanks,

Stephen