Обсуждение: 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