Date: Mon, 27 Apr 2020 16:49:45 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Jehan-Guillaume de Rorthais <jgdr@dalibo.com>
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: <20200427074945.GG11369@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>
 <20200424150300.1b3b0c20@firost>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="bFsKbPszpzYNtEU6"
Content-Disposition: inline
In-Reply-To: <20200424150300.1b3b0c20@firost>
Precedence: bulk


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

On Fri, Apr 24, 2020 at 03:03:00PM +0200, Jehan-Guillaume de Rorthais wrote:
> 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.

FWIW, I would prefer keeping all three tests as well.

So..  I have spent more time on this problem and mereswin here is a
very good sample because it failed all three tests:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=mereswine&dt=2020-04-24%2006%3A03%3A53

For standby2, we get this failure:
ok 11 - .ready file for WAL segment 000000010000000000000001 existing
  in backup is kept with archive_mode=always on standby
not ok 12 - .ready file for WAL segment 000000010000000000000002
  created with archive_mode=always on standby

Then, looking at 020_archive_status_standby2.log, we have the
following logs:
2020-04-24 02:08:32.032 PDT [9841:3] 020_archive_status.pl LOG:
statement: CHECKPOINT
[...]
2020-04-24 02:08:32.303 PDT [9821:7] LOG:  restored log file
"000000010000000000000002" from archive

In this case, the test forced a checkpoint to test the segment
recycling *before* the extra restored segment we'd like to work on was
actually restored.  So it looks like my initial feeling about the
timing issue was right, and I am also able to reproduce the original
set of failures by adding a manual sleep to delay restores of
segments, like that for example:
--- a/src/backend/access/transam/xlogarchive.c
+++ b/src/backend/access/transam/xlogarchive.c
@@ -74,6 +74,8 @@ RestoreArchivedFile(char *path, const char *xlogfname,
    if (recoveryRestoreCommand == NULL ||
    strcmp(recoveryRestoreCommand, "") == 0)
            goto not_available;

+   pg_usleep(10 * 1000000); /* 10s */
+
    /*

With your patch the problem does not show up anymore even with the
delay added, so I would like to apply what you have sent and add back
those tests.  For now, I would just patch HEAD though as that's not
worth the risk of destabilizing stable branches in the buildfarm.

>  $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";

Some noise in the patch.  This may have come from some unfinished
business with pgindent.
--
Michael

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

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAl6mjpkACgkQnvQgOdby
QH3j8g//Se7McciQAtYMAFPBxNfsX62LFfeMkLxo/UyddPoTB1U9vhQsMNyeyrLL
+zJF8ff9qujkVxbjioFwkb+n0DwhyHOtCw5mNsuh+Crixlr6AVkscC0fU8fUECW6
w5x/RbvsDUsMrsz16fRqRKWRqf3g2cJThUHqpjW/L60aqzdrshhxF0om8sJAFKRK
cWeqGE6uyxszmvaEuZFyihcsuwt1g4adHIn/HSqgrmXkLrw5nbVA0GQ3o81Hd8Nl
lW0exii4wA5LGb2SWGPsyeJkjHuPbCvHXlL8hktks0UqGlHwQUwp7EHFTXku3oJM
pbAd1xSYg0EUmCJZGnQyI6mZ8WhysbemSpBE3mab8FUfado6uDibERJlafIY+HtZ
1SJr1qVkbdHDXltQHr4lJJ9GOBF9Ls+ot2aivcWknqcYG2L0FZ2ohO8y2tmCoCDg
g6T26EVqHboGKLGOP99ZTS1VrUE0O40NBJqm6cNu5NvgUSeEjtNUirG2nxXZTzjo
6j6KbBUNVi1x7/2iLMRu6ODneW2GiFS4qUpmWQ8H/OM+O4NM8OhbVkXsrU79GHjV
MqE5yvRg9bIBomht6KpnSlub4VazVNrobQVVjG36n01XjyE/vrBJhTauYAtirnJB
ytsp0QSqqLw0JVgij2SwXeJjFCWN7zdbLJ+5wxUH7H5ptP0y1s8=
=zh72
-----END PGP SIGNATURE-----

--bFsKbPszpzYNtEU6--