Date: Thu, 16 Apr 2020 17:11:00 +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: <20200416081100.GD81957@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>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="iBwuxWUsK/REspAd"
Content-Disposition: inline
In-Reply-To: <20200414180319.731f9593@firost>
Precedence: bulk


--iBwuxWUsK/REspAd
Content-Type: multipart/mixed; boundary="+JUInw4efm7IfTNU"
Content-Disposition: inline


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

On Tue, Apr 14, 2020 at 06:03:19PM +0200, Jehan-Guillaume de Rorthais wrote:

Thanks for the new version.

> On Mon, 13 Apr 2020 16:14:14 +0900 Michael Paquier <michael@paquier.xyz> =
wrote:
>> It seems to me that the initial value of SharedRecoveryState should be
>> CRASH_RECOVERING all the time no?  StartupXLOG() is a code path taken
>> even if starting cleanly, and the flag would be reset correctly at the
>> end to NOT_IN_RECOVERY.
>=20
> Previous version of the patch was setting CRASH_RECOVERING. Fujii-san rep=
orted
> (the 4 Apr 2020 02:49:50 +0900) that it could be useful to expose a bette=
r value
> until relevant code is reached in StartupXLOG() so GetRecoveryState() ret=
urns
> a safer value for futur use.
>
> As I answered upthread, I'm not sure who would need this information befo=
re the
> WAL machinery is up though. Note that ARCHIVE_RECOVERING and CRASH_RECOVE=
RING
> are compatible with the previous behavior.

I am not sure either if we need this information until the startup
process is up, but even if we need it I'd rather keep the code
consistent with the past practice, which was that
SharedRecoveryInProgress got set to true, the equivalent of crash
recovery as that's more generic than the archive recovery switch.

> Maybe the solution would be to init with CRASH_RECOVERING and add some co=
mment
> in GetRecoveryState() to warn the state is "enforced" after the XLOG mach=
inery
> is started and is init'ed to RECOVERING in the meantime?
>=20
> I initialized it to CRASH_RECOVERING in the new v5 patch and added a comm=
ent
> to GetRecoveryState().

Not sure that the comment is worth it.  Your description of the state
looks enough, and the code is clear that we have just an initial
shared memory state in this case.

>> +   /* The file is always deletable if archive_mode is "off". */
>> +   if ( ! XLogArchivingActive() )
>> +       return true;
>> [...]
>> +   if ( recoveryState =3D=3D ARCHIVE_RECOVERING && !XLogArchivingAlways=
() )
>>         return true;
>> Incorrect indentation.
>=20
> Is it the spaces as reported by Horiguchi-san? I removed them in latest p=
atch.

Yes.

>> It would be good to mention that while in crash recovery, files are
>> not considered as deletable.
>=20
> Well, in fact, I am still wondering about this. I was hesitant to add a
> shortcut like:
>=20
>   /* no WAL segment cleanup during crash recovery */
>   if (recoveryState =3D=3D RECOVERT_STATE_CRASH)
>       return false;
>=20
> But, what if for example we crashed for lack of disk space during intensi=
ve
> writes?  During crash recovery, any WAL marked as .done could be removed =
and
> allow the system to start again and maybe make even further WAL cleanup by
> archiving some more WAL without competing with previous high write ratio.
>
> When we recover a primary, this behavior seems conform with any value of
> archive_mode, even if it has been changed after crash and before starting=
 it.
> On a standby, we might create .ready files, but they will be removed duri=
ng the
> first restartpoint if needed.

I guess that you mean .ready and not .done here?  Removing .done files
does not matter as the segments related to them are already gone.
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.

> I needed a failure so I can test pg_stat_archiver reports it as well. In =
my
> mind, using "false" would either trigger a failure because false returns =
1 or...
> a failure because the command is not found. In either way, the result is =
the
> same.
>=20
> Using poll_query_until+pg_stat_file, is a good idea, but not enough as
> archiver reports a failure some moment after the .ready signal file appea=
rs.

Using an empty string makes the test more portable, but while I looked
at it I have found out that it leads to delays in the archiver except
if you force the generation of more segments in the test, causing the
logic to get more complicated with the manipulation of the .ready and
=2Edone files.  And I was then finding myself to add an
archive_timeout..  Anyway, this reduced the readability of the test so
I am pretty much giving up on this idea.

>> The end of the tests actually relies on the
>> fact that archive_command is set to "false" when the cold backup is
>> taken, before resetting it.  I think that it would be cleaner to
>> enforce the configuration you want to test before starting each
>> standby.  It becomes easier to understand the flow of the test for the
>> reader.
>=20
> done as well.

I have put my hands on the code, and attached is a cleaned up
version for the backend part.  Below are some notes.

+ * RECOVERT_STATE_ARCHIVE is set for archive recovery or for a
standby.
Typo here that actually comes from my previous email, and that you
blindly copy-pasted, repeated five times in the tree actually.

+   RecoveryState   recoveryState =3D GetRecoveryState();
+
+   /* The file is always deletable if archive_mode is "off". */
+   if (!XLogArchivingActive())
+       return true;
There is no point to call GetRecoveryState() is archive_mode =3D off.

+ * There's two different reasons to recover WAL: when standby mode is
requested
+ * or after a crash to catchup with consistency.
Nit: s/There's/There are/.  Anyway, I don't see much point in keeping
this comment as the description of each state value should be enough,
so I have removed it.

I am currently in the middle of reviewing the test and there are a
couple of things that can be improved but I lack of time today, so
I'll continue tomorrow on it.  There is no need to send two separate
patches by the way as the code paths touched are different.
--
Michael

--+JUInw4efm7IfTNU
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="recovery-archives-v6.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..a1372b08f6 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,10 +5177,10 @@ XLOGShmemInit(void)
 	 * in additional info.)
 	 */
 	XLogCtl->XLogCacheBlck =3D XLOGbuffers - 1;
-	XLogCtl->SharedRecoveryInProgress =3D true;
 	XLogCtl->SharedHotStandbyActive =3D false;
 	XLogCtl->SharedPromoteIsTriggered =3D false;
 	XLogCtl->WalWriterSleeping =3D false;
+	XLogCtl->SharedRecoveryState =3D RECOVERY_STATE_CRASH;
=20
 	SpinLockInit(&XLogCtl->Insert.insertpos_lck);
 	SpinLockInit(&XLogCtl->info_lck);
@@ -7911,7 +7922,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 +8068,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 +8080,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 +8097,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..ce0127c3d0 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
+	 * 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..a5f4fd821a
--- /dev/null
+++ b/src/test/recovery/t/020_archive_status.pl
@@ -0,0 +1,193 @@
+#
+# Tests relating to WAL archiving and cleanup
+#
+use strict;
+use warnings;
+use PostgresNode;
+use TestLib;
+use Test::More;
+use Config;
+
+my ($node, $standby1, $standby2);
+my ($node_data, $standby1_data, $standby2_data);
+
+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;
+}
+
+$node =3D get_new_node('master');
+$node->init(
+	has_archiving =3D> 1,
+	allows_streaming =3D> 1
+);
+$node->start;
+$node_data =3D $node->data_dir;
+
+# temporary fail archive_command for futur tests
+$node->safe_psql('postgres', q{
+	ALTER SYSTEM SET archive_command TO 'false';
+	SELECT pg_reload_conf();
+});
+
+$node->safe_psql('postgres', q{
+	CREATE TABLE mine AS SELECT generate_series(1,10) AS x;
+	SELECT pg_switch_wal();
+	CHECKPOINT;
+});
+
+# wait for archive failure
+$node->poll_query_until('postgres',
+	q{SELECT failed_count > 0 FROM pg_stat_archiver},
+	't') or die "Timed out while waiting for archiver to fail";
+
+ok( -f "$node_data/pg_wal/archive_status/000000010000000000000001.ready",
+  "ready file exists for WAL waiting to be archived");
+
+is($node->safe_psql('postgres', q{
+		SELECT archived_count, last_failed_wal
+		FROM pg_stat_archiver
+	}),
+	'0|000000010000000000000001', 'pg_stat_archiver reports archive failure');
+
+# We need to crash the cluster because next test checks the crash
+# recovery step do not removes non-archived WAL.
+$node->stop('immediate');
+
+# Standby recovery tests checks 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.
+$node->backup_fs_cold('backup');
+
+$node->start;
+
+ok( -f "$node_data/pg_wal/archive_status/000000010000000000000001.ready",
+  "WAL segment still ready to archive after crash recovery on primary");
+
+# Allow WAL archiving again
+$node->safe_psql('postgres', q{
+	ALTER SYSTEM RESET archive_command;
+	SELECT pg_reload_conf();
+});
+
+# wait for archive success
+$node->poll_query_until('postgres',
+	q{SELECT archived_count FROM pg_stat_archiver},
+	'1')  or die "Timed out while waiting for archiver to success";
+
+ok( ! -f "$node_data/pg_wal/archive_status/000000010000000000000001.ready",
+  "ready file for archived WAL removed");
+
+ok( -f "$node_data/pg_wal/archive_status/000000010000000000000001.done",
+  "done file for archived WAL exists");
+
+is($node->safe_psql('postgres',
+		q{ SELECT last_archived_wal FROM pg_stat_archiver }),
+	'000000010000000000000001',
+	'Archive success reported in pg_stat_archiver');
+
+# create some wal activity and a new checkpoint so futur standby can create
+# a restartpoint.
+# As standby start in crash recovery because of the backup method, they ne=
ed
+# a clean restartpoint to deal with existing status files.
+$node->safe_psql('postgres', q{
+	INSERT INTO mine SELECT generate_series(10,20) AS x;
+	SELECT pg_switch_wal();
+	CHECKPOINT;
+});
+
+$node->poll_query_until('postgres',
+	q{ SELECT last_archived_wal FROM pg_stat_archiver },
+	'000000010000000000000002')  or die "Timed out while waiting for archiver=
 to succeed";
+
+# tests standby with archive_mode=3Don
+$standby1 =3D get_new_node('standby');
+$standby1->init_from_backup($node, 'backup', has_restoring =3D> 1);
+$standby1->append_conf('postgresql.conf', "archive_mode =3D on");
+$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.
+# 000000010000000000000001.ready existed in the backup.
+ok( ! -f "$standby1_data/pg_wal/archive_status/000000010000000000000001.re=
ady",
+  ".ready signal file existing in backup removed with archive_mode=3Don on=
 standby" );
+
+# recovery with archive_mode=3Don should not create .ready signal files
+# 000000010000000000000002.ready did not exist in the backup
+ok( ! -f "$standby1_data/pg_wal/archive_status/000000010000000000000002.re=
ady",
+  "standby doesn't create .ready signal file when archive_mode=3Don" );
+
+# recovery with archive_mode=3Don creates .done signal files
+ok( -f "$standby1_data/pg_wal/archive_status/000000010000000000000002.done=
",
+  "standby creates .done signal file when archive_mode=3Don" );
+
+# test recovery with archive_mode=3Dalways keeps .ready WALs
+$standby2 =3D get_new_node('standby2');
+$standby2->init_from_backup($node, 'backup', has_restoring =3D> 1);
+$standby2->append_conf('postgresql.conf', 'archive_mode =3D always');
+$standby1->append_conf('postgresql.auto.conf', "archive_command =3D false"=
);
+$standby2_data =3D $standby2->data_dir;
+$standby2->start;
+
+$standby2->safe_psql('postgres', q{CHECKPOINT});
+
+ok( -f "$standby2_data/pg_wal/archive_status/000000010000000000000001.read=
y",
+  ".ready signal file existing in backup are kept with archive_mode=3Dalwa=
ys on standby" );
+
+ok( -f "$standby2_data/pg_wal/archive_status/000000010000000000000002.read=
y",
+  ".ready signal file are created with archive_mode=3Dalways on standby" );
+
+# Allow WAL archiving again
+$standby2->safe_psql('postgres', q{SELECT pg_stat_reset_shared('archiver')=
});
+
+is($standby2->safe_psql('postgres',
+		q{ SELECT failed_count, archived_count FROM pg_stat_archiver }),
+	'0|0',
+	'statistics reset from pg_stat_archiver succeed');
+
+# We need to crash the cluster because next test checks the crash
+# recovery step do not removes non-archived WAL on a standby.
+$standby2->stop('immediate');
+$standby2->start;
+
+ok( -f "$standby2_data/pg_wal/archive_status/000000010000000000000001.read=
y",
+  "WAL segment still ready to archive after crash recovery on standby with=
 archive_mode=3Dalways");
+
+# Allow WAL archiving again
+$standby2->safe_psql('postgres', q{
+	ALTER SYSTEM RESET archive_command;
+	SELECT pg_reload_conf();
+});
+
+# wait for archive success
+$standby2->poll_query_until('postgres',
+	q{SELECT last_archived_wal FROM pg_stat_archiver},
+	'000000010000000000000002')  or die "Timed out while waiting for archiver=
 to success";
+
+is($standby2->safe_psql('postgres',
+		q{SELECT archived_count FROM pg_stat_archiver}),
+	'2', 'WAL segment archived from standby');
+
+ok( ! -f "$standby2_data/pg_wal/archive_status/000000010000000000000001.re=
ady"
+	&& ! -f "$standby2_data/pg_wal/archive_status/000000010000000000000002.re=
ady",
+  ".ready signal file removed after archiving with archive_mode=3Dalways o=
n standby" );
+
+ok( -f "$standby2_data/pg_wal/archive_status/000000010000000000000001.done"
+	and -f "$standby2_data/pg_wal/archive_status/000000010000000000000002.don=
e",
+  ".done signal file created after archiving with archive_mode=3Dalways on=
 standby" );
+
+#ok(0);
+#
+## wait for archive success
+#$standby2->poll_query_until('postgres',
+#	q{SELECT 1},
+#	'0')  or die "Timed out while waiting for archiver to success";
+

--+JUInw4efm7IfTNU--

--iBwuxWUsK/REspAd
Content-Type: application/pgp-signature; name="signature.asc"

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAl6YExQACgkQnvQgOdby
QH1qug/8CVhyCTIpdiu55wrVZVRE9bmQDyb/Wf2LHk1WR8YVB+z3eGtpqE5gHA6C
2pTDTbRGu7kjGm73A1116Dx6jtxS9aTDoMwHr1LPDxa13/UTtBHwm5R3uKKN2D+f
N81c0+paWSKHU+KgWv5LVdrP9V8L6pe3AhPSblOAQEFfjJzHEpLp+fgCTSEWBECu
U0hxxEE1RJpUqg0uKtO4lAJJbvzgem/hXE8jwySWMpPPKo3FR91M/jpPZQfmty4I
uwx5NsA2LiAydD1bWXlmBiiIBum9+zCQHwxo5Fgry4NtCvM82JLquFC1rThaEx6a
w5UD581a1055+64wTXb71UzTMqrtHANIg4iix+3mUbjzyqtXFPqJlAKrZcEEUqaw
862D11ZINiWchjwYtmtEQBC1TfSU+RbgyRgP+HN7V+bica6umrQSkah+uoWd3B+P
EmaE0+tDl9Xg01yeld4/Uf/jALPbQXb0jtMMoYvXSjBjcgT+pLon9fczy7l7/WcY
94JECiJ/fG1b75tyPpgCejwKHUdFSHECNdCKVDBZWQguF2R/pGKzdB1rksdhw0vf
LNQtVV/9DFLbes/kx8NdeFo+NxxpqTr7U+WzjVtRSaPPaMxws1eYjqEO2baUX7O0
tGpFC+Bl7zG2sn+SddW4iwESVbOmEjLETIhvpERWlW4I534xYlE=
=t9eA
-----END PGP SIGNATURE-----

--iBwuxWUsK/REspAd--