Обсуждение: Adjusting elog behavior in bootstrap/standalone mode
In <3688.1355509732@sss.pgh.pa.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 sortLOG 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 diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 7210ca5fddba177fb1c6949761e938165892bb28..654c9c18d8ba0168c44c81e428b5c26731921a8d 100644 *** a/src/backend/access/transam/xlog.c --- b/src/backend/access/transam/xlog.c *************** StartupXLOG(void) *** 4883,4891 **** (errmsg("control file contains invalid data"))); if (ControlFile->state == DB_SHUTDOWNED) ! ereport(LOG, (errmsg("database system was shut down at %s", str_time(ControlFile->time)))); else if (ControlFile->state == DB_SHUTDOWNED_IN_RECOVERY) ereport(LOG, (errmsg("database system was shut down in recovery at %s", --- 4883,4894 ---- (errmsg("control file contains invalid data"))); if (ControlFile->state == DB_SHUTDOWNED) ! { ! /* This is the expected case, so don't be chatty in standalone mode */ ! ereport(IsPostmasterEnvironment ? LOG : NOTICE, (errmsg("database system was shut down at %s", str_time(ControlFile->time)))); + } else if (ControlFile->state == DB_SHUTDOWNED_IN_RECOVERY) ereport(LOG, (errmsg("database system was shut down in recovery at %s", *************** GetNextXidAndEpoch(TransactionId *xid, u *** 6590,6596 **** void ShutdownXLOG(int code, Datum arg) { ! ereport(LOG, (errmsg("shutting down"))); if (RecoveryInProgress()) --- 6593,6600 ---- void ShutdownXLOG(int code, Datum arg) { ! /* Don't be chatty in standalone mode */ ! ereport(IsPostmasterEnvironment ? LOG : NOTICE, (errmsg("shutting down"))); if (RecoveryInProgress()) *************** ShutdownXLOG(int code, Datum arg) *** 6612,6618 **** ShutdownSUBTRANS(); ShutdownMultiXact(); ! ereport(LOG, (errmsg("database system is shut down"))); } --- 6616,6623 ---- ShutdownSUBTRANS(); ShutdownMultiXact(); ! /* Don't be chatty in standalone mode */ ! ereport(IsPostmasterEnvironment ? LOG : NOTICE, (errmsg("database system is shut down"))); } diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index e9eb3d5be8cc8fbb4fc3ba4dc58f1b27e1057e45..7f03f419dead8f7f325a8e24a345d23fb1667192 100644 *** a/src/backend/utils/error/elog.c --- b/src/backend/utils/error/elog.c *************** errstart(int elevel, const char *filenam *** 285,295 **** */ /* 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); /* Determine whether message is enabled for client output */ if (whereToSendOutput == DestRemote && elevel != COMMERROR) --- 285,291 ---- */ /* Determine whether message is enabled for server log output */ ! output_to_server = is_log_level_output(elevel, log_min_messages); /* Determine whether message is enabled for client output */ if (whereToSendOutput == DestRemote && elevel != COMMERROR)
* Tom Lane (tgl@sss.pgh.pa.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