Date: Fri, 24 Apr 2020 15:03:00 +0200
From: Jehan-Guillaume de Rorthais <jgdr@dalibo.com>
To: Michael Paquier <michael@paquier.xyz>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, 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: <20200424150300.1b3b0c20@firost>
In-Reply-To: <20200424034248.GL33034@paquier.xyz>
References: <20200422175824.637bda91@firost>
	<20200422181717.491fb499@firost>
	<20200422234618.GI33034@paquier.xyz>
	<20200423.140546.1055476118690602079.horikyota.ntt@gmail.com>
	<20200423185953.5f8e5b8f@firost>
	<20200423235402.GJ33034@paquier.xyz>
	<25921.1587694875@sss.pgh.pa.us>
	<20200424034248.GL33034@paquier.xyz>
Organization: Dalibo
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="MP_/kbqga+I=naXE+VsNP_fbnFv"
Precedence: bulk

--MP_/kbqga+I=naXE+VsNP_fbnFv
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
Content-Disposition: inline

On Fri, 24 Apr 2020 12:43:51 +0900
Michael Paquier <michael@paquier.xyz> wrote:

> On Thu, Apr 23, 2020 at 10:21:15PM -0400, Tom Lane wrote:
> > Looks like the news is not good :-(  
> 
> Yes, I was looking at that for the last couple of hours, and just
> pushed something to put back the buildfarm to a green state for now
> (based on the first results things seem stable now) by removing the
> defective subset of tests.
> 
> > I see that my own florican is one of the failing critters, though
> > it failed only on HEAD which seems odd.  Any suggestions what to
> > look for?  
> 
> The issue comes from the parts of the test where we expect some .ready
> files to exist (or not) after triggering a restartpoint to force some
> segments to be recycled.  And looking more at it, I suspect that the
> issue is actually that we don't make sure in the test that the
> standbys started have replayed up to the segment switch record
> triggered on the primary (the one within generate_series(10,20)), and
> then the follow-up restart point does not actually recycle the
> segments we expect to recycle.  That's more likely going to be a
> problem on slower machines as the window gets wider between the moment
> the standbys reach their consistency point and the moment the switch
> record is replayed.

Indeed.

In regard with your fix, as we don't know if the standby caught up with the
latest available record, there's really no point to keep this test either:

  # Recovery with archive_mode=on 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=on on standby" );

I agree the three tests could be removed as they were not covering the bug we
were chasing. However, they might still be useful to detect futur non expected
behavior changes. If you agree with this, please, find in attachment a patch
proposal against HEAD that recreate these three tests **after** a waiting loop
on both standby1 and standby2. This waiting loop is inspired from the tests in
9.5 -> 10.

Regards,

--MP_/kbqga+I=naXE+VsNP_fbnFv
Content-Type: text/x-patch
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment; filename=wait-for-wal-replay.patch

diff --git a/src/test/recovery/t/020_archive_status.pl b/src/test/recovery/t/020_archive_status.pl
index 401412e687..d197066567 100644
--- a/src/test/recovery/t/020_archive_status.pl
+++ b/src/test/recovery/t/020_archive_status.pl
@@ -5,7 +5,7 @@ use strict;
 use warnings;
 use PostgresNode;
 use TestLib;
-use Test::More tests => 13;
+use Test::More tests => 16;
 use Config;
 
 my $primary = get_new_node('master');
@@ -93,7 +93,7 @@ $primary->safe_psql(
 
 $primary->poll_query_until('postgres',
 	q{SELECT archived_count FROM pg_stat_archiver}, '1')
-  or die "Timed out while waiting for archiving to finish";
+	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");
@@ -119,14 +119,23 @@ my $segment_path_2_done  = "$segment_path_2.done";
 $primary->safe_psql(
 	'postgres', q{
 	INSERT INTO mine SELECT generate_series(10,20) AS x;
-	SELECT pg_switch_wal();
 	CHECKPOINT;
 });
 
+# Make sure that the standby has caught here.
+my $primary_lsn = $primary->safe_psql('postgres',
+	q{SELECT pg_current_wal_lsn()});
+
+# force archiving current wal
+$primary->safe_psql(
+	'postgres', q{
+	SELECT pg_switch_wal();
+});
+
 $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";
+	or die "Timed out while waiting for archiving to finish";
 
 # Test standby with archive_mode = on.
 my $standby1 = get_new_node('standby');
@@ -134,14 +143,30 @@ $standby1->init_from_backup($primary, 'backup', has_restoring => 1);
 $standby1->append_conf('postgresql.conf', "archive_mode = on");
 my $standby1_data = $standby1->data_dir;
 $standby1->start;
+
+$standby1->poll_query_until('postgres',
+	qq{ SELECT pg_wal_lsn_diff(pg_last_wal_replay_lsn(), '$primary_lsn') >= 0 })
+	or die "Timed out while waiting for xlog replay on standby2";
+
 $standby1->safe_psql('postgres', q{CHECKPOINT});
 
+# Recovery with archive_mode=on does not keep .ready signal files inherited
+# 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 removed with archive_mode=on on standby"
+);
+
 # Recovery with archive_mode=on 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=on on standby"
 );
 
+# Recovery with archive_mode = on creates .done files.
+ok( -f "$standby1_data/$segment_path_2_done",
+	".done file for WAL segment $segment_name_2 created when archive_mode=on on standby"
+);
+
 # Test recovery with archive_mode = 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
@@ -153,12 +178,20 @@ $standby2->append_conf('postgresql.conf', 'archive_mode = always');
 my $standby2_data = $standby2->data_dir;
 $standby2->start;
 
+$standby2->poll_query_until('postgres',
+	qq{ SELECT pg_wal_lsn_diff(pg_last_wal_replay_lsn(), '$primary_lsn') >= 0 })
+	or die "Timed out while waiting for xlog replay on standby2";
+
 $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 with archive_mode=always on standby"
 );
 
+ok( -f "$standby2_data/$segment_path_2_ready",
+	".ready file for WAL segment $segment_name_2 created with archive_mode=always on standby"
+);
+
 # Reset statistics of the archiver for the next checks.
 $standby2->safe_psql('postgres', q{SELECT pg_stat_reset_shared('archiver')});
 

--MP_/kbqga+I=naXE+VsNP_fbnFv--