Date: Fri, 6 May 2022 19:58:43 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Cc: nathandbossart@gmail.com, pgsql-hackers@lists.postgresql.org,
	masao.fujii@oss.nttdata.com
Subject: Re: Possible corruption by CreateRestartPoint at promotion
Message-ID: <YnT/Y2sEYj7pyOdc@paquier.xyz>
References: <YmjRkYo2Ce+mO5WO@paquier.xyz>
 <20220427180945.GA3222843@nathanxps13>
 <Ymnb3XlT4YwJ5yOH@paquier.xyz>
 <20220428.114357.476887320744154615.horikyota.ntt@gmail.com>
 <Ymo5BlhEzvXhHObF@paquier.xyz>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="QIk4uINxgyqgT+gr"
Content-Disposition: inline
In-Reply-To: <Ymo5BlhEzvXhHObF@paquier.xyz>
Archived-At: 
 <https://www.postgresql.org/message-id/YnT/Y2sEYj7pyOdc%40paquier.xyz>
Precedence: bulk


--QIk4uINxgyqgT+gr
Content-Type: multipart/mixed; boundary="w6nUYho1oALJSScp"
Content-Disposition: inline


--w6nUYho1oALJSScp
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Thu, Apr 28, 2022 at 03:49:42PM +0900, Michael Paquier wrote:
> I am not sure what you mean here.  FWIW, I am translating the
> suggestion of Nathan to split the existing check in
> CreateRestartPoint() that we are discussing here into two if blocks,
> instead of just one:
> - Move the update of checkPoint and checkPointCopy into its own if
> block, controlled only by the check on
> (ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
> - Keep the code updating minRecoveryPoint and minRecoveryPointTLI
> mostly as-is, but just do the update when the control file state is
> DB_IN_ARCHIVE_RECOVERY.  Of course we need to keep the check on
> (minRecoveryPoint < lastCheckPointEndPtr).

And I have spent a bit of this stuff to finish with the attached.  It
will be a plus to get that done on HEAD for beta1, so I'll try to deal
with it on Monday.  I am still a bit stressed about the back branches
as concurrent checkpoints are possible via CreateCheckPoint() from the
startup process (not the case of HEAD), but the stable branches will
have a new point release very soon so let's revisit this choice there
later.  v6 attached includes a TAP test, but I don't intend to include
it as it is expensive.
--
Michael

--w6nUYho1oALJSScp
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="v6-0001-Correctly-update-control-file-at-promotion.patch"
Content-Transfer-Encoding: quoted-printable

=46rom ffc1469819b28ff76e3290cd695e60511d94305a Mon Sep 17 00:00:00 2001
=46rom: Michael Paquier <michael@paquier.xyz>
Date: Fri, 6 May 2022 19:57:54 +0900
Subject: [PATCH v6] Correctly update control file at promotion

If the cluster ends recovery on a promotion (aka the control file shows
a state different than DB_IN_ARCHIVE_RECOVERY) while
CreateRestartPoint() is still processing, this function could miss the
update the control file but still do the recycling/removal of the past
WAL segments, causing a follow-up restart doing recovery to fail on a
missing checkpoint record (aka PANIC) because the redo LSN referred in
the control file was located in a segment already gone.

This commit fixes the control file update so the redo LSN is updated to
reflect what gets recycled, with the minimum recovery point changed only
if the cluster is still doing archive recovery.
---
 src/backend/access/transam/xlog.c             |  48 ++++----
 .../t/027_invalid_checkpoint_after_promote.pl | 113 ++++++++++++++++++
 2 files changed, 141 insertions(+), 20 deletions(-)
 create mode 100644 src/test/recovery/t/027_invalid_checkpoint_after_promot=
e.pl

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam=
/xlog.c
index 61cda56c6f..c9c0b3f90a 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6921,6 +6921,9 @@ CreateRestartPoint(int flags)
 	XLogSegNo	_logSegNo;
 	TimestampTz xtime;
=20
+	/* Concurrent checkpoint/restartpoint cannot happen */
+	Assert (!IsUnderPostmaster || MyBackendType =3D=3D B_CHECKPOINTER);
+
 	/* Get a local copy of the last safe checkpoint record. */
 	SpinLockAcquire(&XLogCtl->info_lck);
 	lastCheckPointRecPtr =3D XLogCtl->lastCheckPointRecPtr;
@@ -7013,30 +7016,33 @@ CreateRestartPoint(int flags)
 	 */
 	PriorRedoPtr =3D ControlFile->checkPointCopy.redo;
=20
-	/*
-	 * Update pg_control, using current time.  Check that it still shows
-	 * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
-	 * this is a quick hack to make sure nothing really bad happens if somehow
-	 * we get here after the end-of-recovery checkpoint.
-	 */
+	/* Update pg_control, using current time */
 	LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
-	if (ControlFile->state =3D=3D DB_IN_ARCHIVE_RECOVERY &&
-		ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+
+	/*
+	 * Check if the control file still shows an older checkpoint, and update
+	 * its information.
+	 */
+	if (ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
 	{
 		ControlFile->checkPoint =3D lastCheckPointRecPtr;
 		ControlFile->checkPointCopy =3D lastCheckPoint;
+	}
=20
-		/*
-		 * Ensure minRecoveryPoint is past the checkpoint record.  Normally,
-		 * this will have happened already while writing out dirty buffers,
-		 * but not necessarily - e.g. because no buffers were dirtied.  We do
-		 * this because a backup performed in recovery uses minRecoveryPoint to
-		 * determine which WAL files must be included in the backup, and the
-		 * file (or files) containing the checkpoint record must be included,
-		 * at a minimum. Note that for an ordinary restart of recovery there's
-		 * no value in having the minimum recovery point any earlier than this
-		 * anyway, because redo will begin just after the checkpoint record.
-		 */
+	/*
+	 * Ensure minRecoveryPoint is past the checkpoint record while archive
+	 * recovery is still ongoing.  Normally, this will have happened already
+	 * while writing out dirty buffers, but not necessarily - e.g. because no
+	 * buffers were dirtied.  We do this because a base backup uses
+	 * minRecoveryPoint to determine which WAL files must be included in the
+	 * backup, and the file (or files) containing the checkpoint record must
+	 * be included, at a minimum.  Note that for an ordinary restart of
+	 * recovery there's no value in having the minimum recovery point any
+	 * earlier than this anyway, because redo will begin just after the
+	 * checkpoint record.
+	 */
+	if (ControlFile->state =3D=3D DB_IN_ARCHIVE_RECOVERY)
+	{
 		if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
 		{
 			ControlFile->minRecoveryPoint =3D lastCheckPointEndPtr;
@@ -7046,10 +7052,12 @@ CreateRestartPoint(int flags)
 			LocalMinRecoveryPoint =3D ControlFile->minRecoveryPoint;
 			LocalMinRecoveryPointTLI =3D ControlFile->minRecoveryPointTLI;
 		}
+
 		if (flags & CHECKPOINT_IS_SHUTDOWN)
 			ControlFile->state =3D DB_SHUTDOWNED_IN_RECOVERY;
-		UpdateControlFile();
 	}
+
+	UpdateControlFile();
 	LWLockRelease(ControlFileLock);
=20
 	/*
diff --git a/src/test/recovery/t/027_invalid_checkpoint_after_promote.pl b/=
src/test/recovery/t/027_invalid_checkpoint_after_promote.pl
new file mode 100644
index 0000000000..15c8d0a01a
--- /dev/null
+++ b/src/test/recovery/t/027_invalid_checkpoint_after_promote.pl
@@ -0,0 +1,113 @@
+use strict;
+use warnings;
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Time::HiRes qw(usleep nanosleep);
+use Test::More tests =3D> 5;
+
+# initialize primary node
+my $node_primary =3D PostgreSQL::Test::Cluster->new('master');
+$node_primary->init(allows_streaming =3D> 1);
+$node_primary->append_conf(
+	'postgresql.conf', q[
+checkpoint_timeout =3D 30s
+max_wal_size =3D 16GB
+log_checkpoints =3D on
+restart_after_crash =3D on
+]);
+$node_primary->start;
+my $backup_name =3D 'my_backup';
+$node_primary->backup($backup_name);
+
+# setup a standby
+my $node_standby =3D PostgreSQL::Test::Cluster->new('standby1');
+$node_standby->init_from_backup($node_primary, $backup_name, has_streaming=
 =3D> 1);
+$node_standby->start;
+
+# dummy table for the upcoming tests.
+$node_primary->safe_psql('postgres', 'checkpoint');
+$node_primary->safe_psql('postgres', 'create table test (a int, b varchar(=
255))');
+
+# use background psql to insert batch, just to make checkpoint a little sl=
ow.
+my $psql_timeout =3D IPC::Run::timer(3600);
+my ($stdin, $stdout, $stderr) =3D ('', '', '');
+my $psql_primary =3D IPC::Run::start(
+	[ 'psql', '-XAtq', '-v', 'ON_ERROR_STOP=3D1', '-f', '-', '-d', $node_prim=
ary->connstr('postgres') ],
+	'<',
+	\$stdin,
+	'>',
+	\$stdout,
+	'2>',
+	\$stderr,
+	$psql_timeout);
+$stdin .=3D q[
+INSERT INTO test SELECT i, 'aaaaaaaaaaaaaaaaaaaaaaa' from generate_series(=
1, 100000000) as i;
+];
+$psql_primary->pump_nb();
+
+# wait until restartpoint on standy
+my $logstart =3D -s $node_standby->logfile;
+my $checkpoint_start =3D 0;
+for (my $i =3D 0; $i < 3000; $i++)
+{
+    my $log =3D slurp_file($node_standby->logfile, $logstart);
+	if ($log =3D~ m/restartpoint starting: time/)
+	{
+        $checkpoint_start =3D 1;
+		last;
+	}
+	usleep(100_000);
+}
+is($checkpoint_start, 1, 'restartpoint has started');
+
+# promote during restartpoint
+$node_primary->stop;
+$node_standby->promote;
+
+# wait until checkpoint on new primary
+$logstart =3D -s $node_standby->logfile;
+$checkpoint_start =3D 0;
+for (my $i =3D 0; $i < 3000; $i++)
+{
+    my $log =3D slurp_file($node_standby->logfile, $logstart);
+	if ($log =3D~ m/restartpoint complete/)
+	{
+        $checkpoint_start =3D 1;
+		last;
+	}
+	usleep(100_000);
+}
+is($checkpoint_start, 1, 'checkpoint has started');
+
+# kill SIGKILL a backend, and all backend will restart. Note that previous=
 checkpoint has not completed.
+my ($killme_stdin, $killme_stdout, $killme_stderr) =3D ('', '', '');
+my $killme =3D IPC::Run::start(
+	[ 'psql', '-XAtq', '-v', 'ON_ERROR_STOP=3D1', '-f', '-', '-d', $node_stan=
dby->connstr('postgres') ],
+	'<',
+	\$killme_stdin,
+	'>',
+	\$killme_stdout,
+	'2>',
+	\$killme_stderr,
+	$psql_timeout);
+$killme_stdin .=3D q[
+SELECT pg_backend_pid();
+];
+$killme->pump until $killme_stdout =3D~ /[[:digit:]]+[\r\n]$/;
+my $pid =3D $killme_stdout;
+chomp($pid);
+my $ret =3D PostgreSQL::Test::Utils::system_log('pg_ctl', 'kill', 'KILL', =
$pid);
+is($ret, 0, 'killed process with KILL');
+
+# after recovery, the server will not start, and log PANIC: could not loca=
te a valid checkpoint record
+for (my $i =3D 0; $i < 30; $i++)
+{
+    ($ret, $stdout, $stderr) =3D $node_standby->psql('postgres', 'select 1=
');
+    last if $ret =3D=3D 0;
+	sleep(1);
+}
+is($ret, 0, "psql connect success");
+is($stdout, 1, "psql select 1");
+
+$psql_primary->finish;
+$killme->finish;
--=20
2.36.0


--w6nUYho1oALJSScp--

--QIk4uINxgyqgT+gr
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmJ0/2MACgkQnvQgOdby
QH0pfw/+LBPrGxDzjm/4q+S/vBvINvZF8PT4pkbqbW+VsBBbuYQnICprsuIqB9tM
MHjmXUvoFpeTVPcIqEfgq48PYeLmnhYwChkpACMcc1vHEZIACiqK0obOZYsYucS+
bYTj6ceoaqfuyfjaXRMZFzDRu55fmUrv0qv8WXsyxoNH0KxVWQD6hA8Dsyazpprn
nQnn9IyI7sZCJEp/o4ehRy072CHAxt/8f47uZzHPoC2megsJFIOdLnXAXD5JZdkB
ckknqwmtFJKzqhgEqLkqQZLCZ/H7Kv+F1EOYVQYAgTbi5So1+6YekXcsYEY/b9SG
+KvP6FG3KxtJNzaczlDENmUNqNu/C6S4RHnu2kwqJE46gFy4m0UCzGccCiMm1YLc
yD/WN6Wp5Ahmq8g7nUueZHocSoVqD3wdNbJmn03oJW1XvFM6qjSXbStu1ljzO0hK
/GVm+XMXA9t6szhlsuL68hjXEAx4aupGVIkcqJ6gpWVHj1TVUCqHFJC0i1biM4Kr
3IbOp2YZGs4XtKVoSNTLAln00f5d23tfP4g/FCiz84zLM7TH1dHBeDTXTCTqSclg
+34v+VO2IvtWXqBQa5LMy3yE6fDxXO0Ek4MyXbUvP0IkfOMSDrKzMOnfjQM05DX/
v8eOBcWv55thD8BBsNbA5cQcmYJWn2MQ+1skWiHSjmrcncIPDHg=
=Z8xJ
-----END PGP SIGNATURE-----

--QIk4uINxgyqgT+gr--