Date: Fri, 17 Apr 2020 15:50:43 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Jehan-Guillaume de Rorthais <jgdr@dalibo.com>
Cc: Kyotaro Horiguchi <horikyota.ntt@gmail.com>,
	masao.fujii@oss.nttdata.com, pgsql-bugs@lists.postgresql.org
Subject: Re: [BUG] non archived WAL removed during production crash recovery
Message-ID: <20200417065043.GC350229@paquier.xyz>
References: <20200408022345.GC1606@paquier.xyz>
 <20200408135830.25a8e2ef@firost>
 <20200409184622.390f9b7f@firost>
 <20200410.111454.269125561493324950.horikyota.ntt@gmail.com>
 <20200413071414.GF2169@paquier.xyz>
 <20200414180319.731f9593@firost>
 <20200416081100.GD81957@paquier.xyz>
 <20200416234308.3e5f64bf@firost>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="pY3vCvL1qV+PayAL"
Content-Disposition: inline
In-Reply-To: <20200416234308.3e5f64bf@firost>
Precedence: bulk


--pY3vCvL1qV+PayAL
Content-Type: multipart/mixed; boundary="at6+YcpfzWZg/htY"
Content-Disposition: inline


--at6+YcpfzWZg/htY
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Fri, Apr 17, 2020 at 12:07:39AM +0200, Jehan-Guillaume de Rorthais wrote:
> On Thu, 16 Apr 2020 17:11:00 +0900 Michael Paquier <michael@paquier.xyz> =
wrote:
>> Removing .done files does not matter as the segments related to them are
>> already gone.
>=20
> Not necessarily. There's a time windows between the moment the archiver s=
et
> the .done file and when the checkpointer removes the associated WAL file.
> So, after a PANIC because of lack of space, WAL associated with .done fil=
es but
> not removed yet will be removed during the crash recovery.

Not sure that it is something that matters for this thread though, so
if necessary I think that it could be be discussed separately.

>> Even with that, why should we need to make the backend smarter about
>> the removal of .ready files during crash recovery.  It seems to me
>> that we should keep them, and an operator could always come by himself
>> and do some manual cleanup to free some space in the pg_wal partition.
>=20
> We are agree on this.

Okay.

> Unless I'm wrong, the empty string does not raise an error in pg_stat_arc=
hiver,
> and I wanted to add a test on this as well.

Exactly, it won't raise an error.  Instead I switched to use a poll
query with pg_stat_file() and .ready files, but this has proved to
delay the test considerably if we did not create more segments.  And
your approach has the merit to be more simple with only two segments
manipulated for the whole test.  So I have tried first my idea,
noticed the mess it introduced, and just kept your approach.

> Thanks for your review! Let me know if you want me to add/change/fix some=
 tests.

Thanks, I have worked more on the test, refactoring pieces related to
the segment names, adjusting some comments and fixing some of the
logic.  Note that you introduced something incorrect at the creation
of $standby2 as you have been updating postgresql.conf.auto for
$standby1.

I have noticed an extra issue while looking at the backend pieces
today: at the beginning of the REDO loop we forgot one place where
SharedRecoveryState *has* to be updated to a correct state (around
the comment "Update pg_control to show that we are..." in xlog.c) as
the startup process may decide to switch the control file state to
DB_IN_ARCHIVE_RECOVERY or DB_IN_CRASH_RECOVERY, but we forgot to
update the new shared flag at this early stage.  It did not matter
before because SharedRecoveryInProgress would be only "true" for both,
but that's not the case anymore as we need to make the difference
between crash recovery and archive recovery in the new flag.  There is
no actual need to update SharedRecoveryState to RECOVERY_STATE_CRASH
as the initial shared memory state is RECOVERY_STATE_CRASH, but
updating the flag makes the code more consistent IMO so I updated it
anyway in the attached.

I have the feeling that I need to work a bit more on this patch, but
my impression is that we are getting to something committable here.

Thoughts?
--
Michael

--at6+YcpfzWZg/htY
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="recovery-archives-v7.patch"
Content-Transfer-Encoding: quoted-printable

diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index f60ed2d36c..2cce871dc9 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -166,6 +166,14 @@ typedef enum WalLevel
 	WAL_LEVEL_LOGICAL
 } WalLevel;
=20
+/* Recovery states */
+typedef enum RecoveryState
+{
+	RECOVERY_STATE_CRASH =3D 0,	/* crash recovery */
+	RECOVERY_STATE_ARCHIVE,		/* archive recovery */
+	RECOVERY_STATE_NONE			/* currently in production */
+} RecoveryState;
+
 extern PGDLLIMPORT int wal_level;
=20
 /* Is WAL archiving enabled (always or only while server is running normal=
ly)? */
@@ -291,6 +299,7 @@ extern const char *xlog_identify(uint8 info);
 extern void issue_xlog_fsync(int fd, XLogSegNo segno);
=20
 extern bool RecoveryInProgress(void);
+extern RecoveryState GetRecoveryState(void);
 extern bool HotStandbyActive(void);
 extern bool HotStandbyActiveInReplay(void);
 extern bool XLogInsertAllowed(void);
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam=
/xlog.c
index 11e32733c4..b8f696ffdc 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -221,8 +221,9 @@ static TimeLineID receiveTLI =3D 0;
 static bool lastFullPageWrites;
=20
 /*
- * Local copy of SharedRecoveryInProgress variable. True actually means "n=
ot
- * known, need to check the shared state".
+ * Local copy of the state tracked by SharedRecoveryState in shared memory,
+ * It is false if SharedRecoveryState is RECOVERY_STATE_NONE.  True actual=
ly
+ * means "not known, need to check the shared state".
  */
 static bool LocalRecoveryInProgress =3D true;
=20
@@ -653,10 +654,10 @@ typedef struct XLogCtlData
 	TimeLineID	PrevTimeLineID;
=20
 	/*
-	 * SharedRecoveryInProgress indicates if we're still in crash or archive
+	 * SharedRecoveryState indicates if we're either in crash or archive
 	 * recovery.  Protected by info_lck.
 	 */
-	bool		SharedRecoveryInProgress;
+	RecoveryState SharedRecoveryState;
=20
 	/*
 	 * SharedHotStandbyActive indicates if we allow hot standby queries to be
@@ -4434,6 +4435,16 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
 				updateMinRecoveryPoint =3D true;
=20
 				UpdateControlFile();
+
+				/*
+				 * We update SharedRecoveryState while holding the lock on
+				 * ControlFileLock so both states are consistent in shared
+				 * memory.
+				 */
+				SpinLockAcquire(&XLogCtl->info_lck);
+				XLogCtl->SharedRecoveryState =3D RECOVERY_STATE_ARCHIVE;
+				SpinLockRelease(&XLogCtl->info_lck);
+
 				LWLockRelease(ControlFileLock);
=20
 				CheckRecoveryConsistency();
@@ -5166,7 +5177,7 @@ XLOGShmemInit(void)
 	 * in additional info.)
 	 */
 	XLogCtl->XLogCacheBlck =3D XLOGbuffers - 1;
-	XLogCtl->SharedRecoveryInProgress =3D true;
+	XLogCtl->SharedRecoveryState =3D RECOVERY_STATE_CRASH;
 	XLogCtl->SharedHotStandbyActive =3D false;
 	XLogCtl->SharedPromoteIsTriggered =3D false;
 	XLogCtl->WalWriterSleeping =3D false;
@@ -6871,7 +6882,13 @@ StartupXLOG(void)
 		 */
 		dbstate_at_startup =3D ControlFile->state;
 		if (InArchiveRecovery)
+		{
 			ControlFile->state =3D DB_IN_ARCHIVE_RECOVERY;
+
+			SpinLockAcquire(&XLogCtl->info_lck);
+			XLogCtl->SharedRecoveryState =3D RECOVERY_STATE_ARCHIVE;
+			SpinLockRelease(&XLogCtl->info_lck);
+		}
 		else
 		{
 			ereport(LOG,
@@ -6884,6 +6901,10 @@ StartupXLOG(void)
 								ControlFile->checkPointCopy.ThisTimeLineID,
 								recoveryTargetTLI)));
 			ControlFile->state =3D DB_IN_CRASH_RECOVERY;
+
+			SpinLockAcquire(&XLogCtl->info_lck);
+			XLogCtl->SharedRecoveryState =3D RECOVERY_STATE_CRASH;
+			SpinLockRelease(&XLogCtl->info_lck);
 		}
 		ControlFile->checkPoint =3D checkPointLoc;
 		ControlFile->checkPointCopy =3D checkPoint;
@@ -7911,7 +7932,7 @@ StartupXLOG(void)
 	ControlFile->time =3D (pg_time_t) time(NULL);
=20
 	SpinLockAcquire(&XLogCtl->info_lck);
-	XLogCtl->SharedRecoveryInProgress =3D false;
+	XLogCtl->SharedRecoveryState =3D RECOVERY_STATE_NONE;
 	SpinLockRelease(&XLogCtl->info_lck);
=20
 	UpdateControlFile();
@@ -8057,7 +8078,7 @@ RecoveryInProgress(void)
 		 */
 		volatile XLogCtlData *xlogctl =3D XLogCtl;
=20
-		LocalRecoveryInProgress =3D xlogctl->SharedRecoveryInProgress;
+		LocalRecoveryInProgress =3D (xlogctl->SharedRecoveryState !=3D RECOVERY_=
STATE_NONE);
=20
 		/*
 		 * Initialize TimeLineID and RedoRecPtr when we discover that recovery
@@ -8069,8 +8090,8 @@ RecoveryInProgress(void)
 		{
 			/*
 			 * If we just exited recovery, make sure we read TimeLineID and
-			 * RedoRecPtr after SharedRecoveryInProgress (for machines with
-			 * weak memory ordering).
+			 * RedoRecPtr after SharedRecoveryState (for machines with weak
+			 * memory ordering).
 			 */
 			pg_memory_barrier();
 			InitXLOGAccess();
@@ -8086,6 +8107,24 @@ RecoveryInProgress(void)
 	}
 }
=20
+/*
+ * Returns current recovery state from shared memory.
+ *
+ * This returned state is accurate after StartupXLOG() finished.  See
+ * details about the possible values of RecoveryState in xlog.h.
+ */
+RecoveryState
+GetRecoveryState(void)
+{
+	RecoveryState retval;
+
+	SpinLockAcquire(&XLogCtl->info_lck);
+	retval =3D XLogCtl->SharedRecoveryState;
+	SpinLockRelease(&XLogCtl->info_lck);
+
+	return retval;
+}
+
 /*
  * Is HotStandby active yet? This is only important in special backends
  * since normal backends won't ever be able to connect until this returns
diff --git a/src/backend/access/transam/xlogarchive.c b/src/backend/access/=
transam/xlogarchive.c
index d62c12310a..d71453f2e8 100644
--- a/src/backend/access/transam/xlogarchive.c
+++ b/src/backend/access/transam/xlogarchive.c
@@ -572,17 +572,21 @@ XLogArchiveCheckDone(const char *xlog)
 {
 	char		archiveStatusPath[MAXPGPATH];
 	struct stat stat_buf;
-	bool		inRecovery =3D RecoveryInProgress();
+
+	/* The file is always deletable if archive_mode is "off". */
+	if (!XLogArchivingActive())
+		return true;
+
+	/* On standbys, the file is deletable if archive_mode is not "always". */
+	if (!XLogArchivingAlways() &&
+		GetRecoveryState() =3D=3D RECOVERY_STATE_ARCHIVE)
+		return true;
=20
 	/*
-	 * The file is always deletable if archive_mode is "off".  On standbys
-	 * archiving is disabled if archive_mode is "on", and enabled with
-	 * "always".  On a primary, archiving is enabled if archive_mode is "on"
-	 * or "always".
+	 * At this point of the logic, note that we are either a primary with
+	 * archive_mode set to "on" or "always", or a standby with archive_mode
+	 * set to "always".
 	 */
-	if (!((XLogArchivingActive() && !inRecovery) ||
-		  (XLogArchivingAlways() && inRecovery)))
-		return true;
=20
 	/* First check for .done --- this means archiver is done with it */
 	StatusFilePath(archiveStatusPath, xlog, ".done");
diff --git a/src/test/recovery/t/020_archive_status.pl b/src/test/recovery/=
t/020_archive_status.pl
new file mode 100644
index 0000000000..1ba237ee1d
--- /dev/null
+++ b/src/test/recovery/t/020_archive_status.pl
@@ -0,0 +1,218 @@
+#
+# Tests related to WAL archiving and recovery.
+#
+use strict;
+use warnings;
+use PostgresNode;
+use TestLib;
+use Test::More;
+use Config;
+
+if ($Config{osname} eq 'MSWin32')
+{
+
+	# some Windows Perls at least don't like IPC::Run's start/kill_kill regim=
e.
+	plan skip_all =3D> "Test fails on Windows perl";
+}
+else
+{
+	plan tests =3D> 16;
+}
+
+my $primary =3D get_new_node('master');
+$primary->init(
+	has_archiving    =3D> 1,
+	allows_streaming =3D> 1);
+$primary->append_conf('postgresql.conf', 'autovacuum =3D off');
+$primary->start;
+my $primary_data =3D $primary->data_dir;
+
+# Temporarily use an archive_command value to make the archiver fail,
+# knowing that archiving is enabled.  This allows keeping around
+# .ready files for the follow-up tests.
+$primary->safe_psql(
+	'postgres', q{
+	ALTER SYSTEM SET archive_command TO 'false';
+	SELECT pg_reload_conf();
+});
+
+# Save the WAL segment currently in use and switch to a new segment.
+# This will be used to track the activity of the archiver.
+my $segment_name_1 =3D $primary->safe_psql('postgres',
+	q{SELECT pg_walfile_name(pg_current_wal_lsn())});
+my $segment_path_1       =3D "pg_wal/archive_status/$segment_name_1";
+my $segment_path_1_ready =3D "$segment_path_1.ready";
+my $segment_path_1_done  =3D "$segment_path_1.done";
+$primary->safe_psql(
+	'postgres', q{
+	CREATE TABLE mine AS SELECT generate_series(1,10) AS x;
+	SELECT pg_switch_wal();
+	CHECKPOINT;
+});
+
+# Wait for an archive failure.
+$primary->poll_query_until('postgres',
+	q{SELECT failed_count > 0 FROM pg_stat_archiver}, 't')
+  or die "Timed out while waiting for archiving to fail";
+ok( -f "$primary_data/$segment_path_1_ready",
+	".ready file exists for WAL segment $segment_name_1 waiting to be archive=
d"
+);
+ok( !-f "$primary_data/$segment_path_1_done",
+	".done file does not exist for WAL segment $segment_name_1 waiting to be =
archived"
+);
+
+is( $primary->safe_psql(
+		'postgres', q{
+		SELECT archived_count, last_failed_wal
+		FROM pg_stat_archiver
+	}),
+	"0|$segment_name_1",
+	'pg_stat_archiver failed to archive $segment_name_1');
+
+# We need to crash the cluster because next test checks the crash
+# recovery step do not removes non-archived WAL.
+$primary->stop('immediate');
+
+# Recovery tests for the achiving with a standby partially check
+# the recovery behavior when restoring a backup taken using eg.
+# a snapshot with no pg_start/stop_backup.  In this situation,
+# the recovered standby should enter first crash recovery then
+# switch to regular archive recovery.  Note that the base backup
+# is taken here so as archive_command is not set.  This is
+# necessary for the assumptions of the tests done with the
+# standbys below.
+$primary->backup_fs_cold('backup');
+
+$primary->start;
+ok( -f "$primary_data/$segment_path_1_ready",
+	".ready file for WAL segment $segment_name_1 still exists after crash rec=
overy on primary"
+);
+
+# Allow WAL archiving again and wait for a success.
+$primary->safe_psql(
+	'postgres', q{
+	ALTER SYSTEM RESET archive_command;
+	SELECT pg_reload_conf();
+});
+
+$primary->poll_query_until('postgres',
+	q{SELECT archived_count FROM pg_stat_archiver}, '1')
+  or die "Timed out while waiting for archiving to finish";
+
+ok(!-f "$primary_data/$segment_path_1_ready",
+	".ready file for archived WAL segment $segment_name_1 removed");
+
+ok(-f "$primary_data/$segment_path_1_done",
+	".done file for archived WAL segment $segment_name_1 exists");
+
+is( $primary->safe_psql(
+		'postgres', q{ SELECT last_archived_wal FROM pg_stat_archiver }),
+	$segment_name_1,
+	'archive success reported in pg_stat_archiver for WAL segment $segment_na=
me_1'
+);
+
+# Create some WAL activity and a new checkpoint so as the next standby can
+# create a restartpoint.  As this standby starts in crash recovery because
+# of the cold backup taken previously, it needs a clean restartpoint to de=
al
+# with existing status files.
+my $segment_name_2 =3D $primary->safe_psql('postgres',
+	q{SELECT pg_walfile_name(pg_current_wal_lsn())});
+my $segment_path_2       =3D "pg_wal/archive_status/$segment_name_2";
+my $segment_path_2_ready =3D "$segment_path_2.ready";
+my $segment_path_2_done  =3D "$segment_path_2.done";
+$primary->safe_psql(
+	'postgres', q{
+	INSERT INTO mine SELECT generate_series(10,20) AS x;
+	SELECT pg_switch_wal();
+	CHECKPOINT;
+});
+
+$primary->poll_query_until('postgres',
+	q{ SELECT last_archived_wal FROM pg_stat_archiver },
+	$segment_name_2)
+  or die "Timed out while waiting for archiving to finish";
+
+# Test standby with archive_mode =3D on.
+my $standby1 =3D get_new_node('standby');
+$standby1->init_from_backup($primary, 'backup', has_restoring =3D> 1);
+$standby1->append_conf('postgresql.conf', "archive_mode =3D on");
+my $standby1_data =3D $standby1->data_dir;
+$standby1->start;
+$standby1->safe_psql('postgres', q{CHECKPOINT});
+
+# Recovery with archive_mode=3Don does not keep .ready signal files inheri=
ted
+# from backup.  Note that this WAL segment existed in the backup.
+ok( !-f "$standby1_data/$segment_path_1_ready",
+	".ready file for WAL segment $segment_name_1 present in backup got remove=
d with archive_mode=3Don on standby"
+);
+
+# Recovery with archive_mode=3Don should not create .ready files.
+# Note that this segment did not exist in the backup.
+ok( !-f "$standby1_data/$segment_path_2_ready",
+	".ready file for WAL segment $segment_name_2 not created on standby when =
archive_mode=3Don on standby"
+);
+
+# Recovery with archive_mode =3D on creates .done files.
+ok( -f "$standby1_data/$segment_path_2_done",
+	".done file for WAL segment $segment_name_2 created when archive_mode=3Do=
n on standby"
+);
+
+# Test recovery with archive_mode =3D always, which should always keep
+# .ready files if archiving is enabled, though here we want the archive
+# command to fail to persist the .ready files.  Note that this node
+# has inherited the archive command of the previous cold backup, that
+# will cause archiving failures.
+my $standby2 =3D get_new_node('standby2');
+$standby2->init_from_backup($primary, 'backup', has_restoring =3D> 1);
+$standby2->append_conf('postgresql.conf', 'archive_mode =3D always');
+my $standby2_data =3D $standby2->data_dir;
+$standby2->start;
+
+$standby2->safe_psql('postgres', q{CHECKPOINT});
+
+ok( -f "$standby2_data/$segment_path_1_ready",
+	".ready file for WAL segment $segment_name_1 existing in backup is kept w=
ith archive_mode=3Dalways on standby"
+);
+
+ok( -f "$standby2_data/$segment_path_2_ready",
+	".ready file for WAL segment $segment_name_2 created with archive_mode=3D=
always on standby"
+);
+
+# Reset statistics of the archiver for the next checks.
+$standby2->safe_psql('postgres', q{SELECT pg_stat_reset_shared('archiver')=
});
+
+# Now crash the cluster to check that recovery step does not
+# remove non-archived WAL segments on a standby where archiving
+# is enabled.
+$standby2->stop('immediate');
+$standby2->start;
+
+ok( -f "$standby2_data/$segment_path_1_ready",
+	"WAL segment still ready to archive after crash recovery on standby with =
archive_mode=3Dalways"
+);
+
+# Allow WAL archiving again, and wait for the segments to be archived.
+$standby2->safe_psql(
+	'postgres', q{
+	ALTER SYSTEM RESET archive_command;
+	SELECT pg_reload_conf();
+});
+$standby2->poll_query_until('postgres',
+	q{SELECT last_archived_wal FROM pg_stat_archiver},
+	$segment_name_2)
+  or die "Timed out while waiting for archiving to finish";
+
+is( $standby2->safe_psql(
+		'postgres', q{SELECT archived_count FROM pg_stat_archiver}),
+	'2',
+	'correct number of WAL segments archived from standby');
+
+ok( !-f "$standby2_data/$segment_path_1_ready"
+	  && !-f "$standby2_data/$segment_path_2_ready",
+	".ready files removed after archive success with archive_mode=3Dalways on=
 standby"
+);
+
+ok( -f "$standby2_data/$segment_path_1_done"
+	  && -f "$standby2_data/$segment_path_2_done",
+	".done files created after archive success with archive_mode=3Dalways on =
standby"
+);
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs=
=2Elist
index 525d58e7f0..b319266bb3 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1983,6 +1983,7 @@ RecordCacheEntry
 RecordCompareData
 RecordIOData
 RecoveryLockListsEntry
+RecoveryState
 RecoveryTargetTimeLineGoal
 RecoveryTargetType
 RectBox

--at6+YcpfzWZg/htY--

--pY3vCvL1qV+PayAL
Content-Type: application/pgp-signature; name="signature.asc"

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAl6ZUcMACgkQnvQgOdby
QH1L4A//Rys4nIJ6s+gYZLcccHu4z5Lvqo5bCwMsVQbZIuDDSh5Zf70+pykjh1g/
QEAGXO2BvjBkrEAuQiPQ/RnfXMJELpnOJCMnx83fdXM6spQoHJL35r5AjPnsaXD8
oU13XO9Gf01RG1gbJ29PqSplEm0CkE7UIQL1GcUhGO0cmrMxLozmOeblpjg/NAtH
DeatOT3mPZzvxVcta85dOBbJc3NOSp/cyWMsrRe1LH8cIv1z449qgK2I60c99ez6
H8j5bYDxOphfBQAqn/OnWfpTSbCOzakKQCPDq0qVERUK+DcAPfzfHakVW6LE17Kb
jZULSgGn6mxj7qY+cTGRRxAXZU4468G1xp0CKpWh+9OqfLwx6/z/zlY63aTSJ/+q
pvU9e/gzzPK/6F8UlfZ/eJQGKjq/9mxuYNGJw8QfiJGMxt/IuV6kzxe3lRkPdF2M
vAbmCUwtDsntTWdJMDw0O/a/TOZiRIb2D4/ZHlvtRdiQYDAYMufJaTPlR661+m3m
fGWWYIPEYjZ6jKStHkMFeIkNkVK8aZ6Cabl7vB0fFbP02eiTQtSwJb/w9RTCFTxo
rA4DLLokUHE7zBMkD6tQy2iTOPYVvZ0MTJxy/RF4+R+IBYMQmNa9x5ZmMw28SF6C
4ROpKiWIhcwpBkPMIIreY+Qf9lO9FUEvxbJCY/1oKqsmruBShCw=
=Y4TN
-----END PGP SIGNATURE-----

--pY3vCvL1qV+PayAL--