Обсуждение: pg_ctl -D PGDATA stop -m fast gets the following message 57P03 FATAL: thedatabase system is shutting down
pg_ctl -D PGDATA stop -m fast gets the following message 57P03 FATAL: thedatabase system is shutting down
Sorry, I have cancelled the previous message, so I am sending it once again.
Master DB server hangs during stopping in two nodes Suse Linux Enterprise Sever 12 (SLES12) cluster.
The problem is reproducible on PostgreSQL 9.6.8 and PostgreSQL 10.4.
PosgreSQL 10.4 faces with such a problem more frequently than 9.6.8.
PostgreSQL 10.4 was downloaded from https://www.postgresql.org/ftp/source/, configured and installed on SLES 12 system as follows:
./configure –prefix=usr
Make
Make install
psql (PostgreSQL) 10.4
Our configuration:
I have configured 2-nodes database cluster( master (node01) and standby (node02)).
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:
1) the recovery.conf was created
2) the pg_basebackup comand was called:
pg_basebackup -h node01 -U dbuser -D /var/PostgresDb -p 5432 -w
pg_ctl -D /var/PostgresDb start -w
Configuration files postgresql.conf and pg_hba.conf from the master and standby nodes have been attached to the mail.
I was able to get some information about the replication by the following sql queries:
select * from pg_stat_replication # on master node
select * from pg_stat_wal_receiver # on standby node
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.
Here is the list of postgres processes on the master node:
ps -ef|grep postgres
postgres 8418 1 0 14:14 ? 00:00:00 postgres -D /var/PostgresDb
postgres 8428 8418 9 14:14 ? 00:02:30 postgres: logger process
postgres 8593 8418 28 14:14 ? 00:07:20 postgres: wal sender process dbuser 10.1.4.48(41137) streaming 0/50341D0
Here is the list of postgres processes on the standby node:
ps -ef|grep postgres
postgres 28578 1 0 14:14 ? 00:00:00 postgres -D /var/PostgresDb
postgres 28588 28578 9 14:14 ? 00:02:33 postgres: logger process
postgres 28593 28578 0 14:14 ? 00:00:00 postgres: startup process recovering 000000050000000000000005
postgres 28594 28578 0 14:14 ? 00:00:00 postgres: checkpointer process
postgres 28595 28578 0 14:14 ? 00:00:00 postgres: writer process
postgres 28596 28578 0 14:14 ? 00:00:00 postgres: stats collector process
postgres 28597 28578 25 14:14 ? 00:06:50 postgres: wal receiver process
postgres 28605 28578 0 14:14 ? 00:00:02 postgres: dbuser dbname 10.1.4.48(42893) idle
The logs from pg_log directory on master node are overfilled with the following messages:
57P03 FATAL: the database system is shutting down
DEBUG: write 0/50341D0 flush 0/5034208 apply 0/5034208
DEBUG: sending replication keepalive
The log level for log_min_messages and log_min_error_statement was deliberately set to debug5 in order to collect as more information as possible.
The contents of pg_log directory has been attached from the both nodes.
Could you please clarify this issue? Is it a bug or an incorrect configuration, usage or anything else?
Thank You in advance,
Andrei
Вложения
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.