Re: pg_ctl -D PGDATA stop -m fast gets the following message 57P03FATAL: the database system is shutting down

Hello.

It might be a bug but rather seems to be a result of a wrong
operation in the first place.

At Tue, 15 May 2018 18:36:07 +0300, AYahorau@ibagroup.eu wrote in
<OFCA523F90.7499E22F-ON4325828E.005573C4-4325828E.0055B412@iba.by>
> The database on the master node was configured as follows:
> 
> initdb -D /var/PostgresDb 
> pg_ctl -D  /var/PostgresDb  start -w
> createdb -U dbuser -O dbuser dbname
> 
> and on the standby node as follows:
.(snip).
> In order to stop database server on master node I invoked the command at 
> 07:15:49:
> 
> pg_ctl -D /var/PostgresDb stop -m fast.
> 
> The most of the postgres processes were terminated but some of them 
> remained to be working.

The log shows that the state is broken in several aspects.
  
The first line of the standby's log is:

> 2018-05-14 07:14:55 EDT 00000 LOG:  database system was shut down at 2018-05-14 07:13:40 EDT

It means that the standby is not started from a base backup of
the master started at 7:14:02. There's no trace of pg_basebckup
in the master's log. So the standby must be taken at the earlier
trial. But its starting checkpoint LSN is 0/5034198, even later
than the latest master's starting checkpoint LSN 0/5033fc8. I
belive this is a result of a wrong operation. One possible cause
is only master is rolled back to an older state using something
like storage snapshot.

The following steps causes the same infite loop.

1. Create a master with the following setup.
   wal_keep_segments=10
   archive_mode=off
   log_min_messags=debug2

2. Start the master.

3. Take a basebackup using pg_basebackup then run it as a standby.

4. Do 'checkpoint;'. (Doing once is enough)

5. Take a 'storage snapshot'. (I used tar instead)

6. Do 'checkpoint;'.

7. Stop both servers.

8. Rollback the master. (I used tar instead)

9. Start the master and the standby and you will see feedback
  logs in which write LSN is smaller than flush LSN.

  > DEBUG:  sending write 0/3000488 flush 0/3000728 apply 0/3000728

10. Stop the master and you will see the infinite loop.
  (the latency is 100ms on the master branch)

  > DEBUG:  sending write 0/3000530 flush 0/3000728 apply 0/3000728
  > DEBUG:  sendtime 2018-05-17 16:01:53.630132+09 receipttime 2018-05-17 16:01:53.630171+09 replication apply delay
(N/A)transfer latency 0 ms
 

The immediate cause of the infinite loop is that the master was
waiting for all WAL records sent to standby have been flushed on
the standby before completing shutdown. Under normal operation
this finishes immediately.

I'm not sure this is worth fixing but anyway the attached patch
will reject such broken standbys. The standby will be rejected if
my diagnosis is correct. (It is for master branch but applies to
10.4.)

> ERROR:  Standby started from the future LSN for this server
> HINT:  This means that the standby is not created from this database.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index e47ddca6bc..ca25b1d862 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1809,6 +1809,20 @@ ProcessStandbyReplyMessage(void)
     if (replyRequested)
         WalSndKeepalive(false);
 
+    /*
+     * If we catch up or in-streaming mode but the standby reports that we
+     * haven't reached the standby's starting LSN, this database cannot be a
+     * proper master of the standby. The state causes infinite loop on
+     * shutdown.
+     */
+    if ((MyWalSnd->state == WALSNDSTATE_CATCHUP ||
+         MyWalSnd->state == WALSNDSTATE_STREAMING) &&
+        writePtr != InvalidXLogRecPtr && writePtr < flushPtr)
+        ereport(ERROR,
+                (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
+                 errmsg("Standby started from the future LSN for this server"),
+                 errhint("This means that the standby is not created from this database.")));
+
     /*
      * Update shared state for this WalSender process based on reply data from
      * standby.