Subject: Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman

From: Andres Freund <[email-masked]>
Date: Thu, 7 Apr 2022 10:52:10 -0700

Hi,

On 2022-04-07 13:40:30 -0400, Tom Lane wrote:
> Michael Paquier <[email-masked]> writes:
> > Add TAP test for archive_cleanup_command and recovery_end_command
> 
> grassquit just showed a non-reproducible failure in this test [1]:

I was just staring at that as well.

> # Postmaster PID for node "standby" is 291160
> ok 1 - check content from archives
> not ok 2 - archive_cleanup_command executed on checkpoint
> 
> #   Failed test 'archive_cleanup_command executed on checkpoint'
> #   at t/002_archiving.pl line 74.
> 
> This test is sending a CHECKPOINT command to the standby and
> expecting it to run the archive_cleanup_command, but it looks
> like the standby did not actually run any checkpoint:
> 
> 2022-04-07 16:11:33.060 UTC [291806][not initialized][:0] LOG:  connection received: host=[local]
> 2022-04-07 16:11:33.078 UTC [291806][client backend][2/15:0] LOG:  connection authorized: user=bf database=postgres application_name=002_archiving.pl
> 2022-04-07 16:11:33.084 UTC [291806][client backend][2/16:0] LOG:  statement: CHECKPOINT
> 2022-04-07 16:11:33.092 UTC [291806][client backend][:0] LOG:  disconnection: session time: 0:00:00.032 user=bf database=postgres host=[local]
> 
> I am suspicious that the reason is that ProcessUtility does not
> ask for a forced checkpoint when in recovery:
> 
>             RequestCheckpoint(CHECKPOINT_IMMEDIATE | CHECKPOINT_WAIT |
>                               (RecoveryInProgress() ? 0 : CHECKPOINT_FORCE));
> 
> The trouble with this theory is that this test has been there for
> nearly six months and this is the first such failure (I scraped the
> buildfarm logs to be sure).  Seems like failures should be a lot
> more common than that.

> I wondered if the recent pg_stats changes could have affected this, but I
> don't really see how.

I don't really see either. It's a bit more conceivable that the recovery
prefetching changes could affect the timing sufficiently?

It's also possible that it requires an animal of a certain speed to happen -
we didn't have an -fsanitize=address animal until recently.

I guess we'll have to wait and see what the frequency of the problem is?

Greetings,

Andres Freund

---

From: Tom Lane <[email-masked]>
Date: Thu, 07 Apr 2022 13:57:45 -0400

Andres Freund <[email-masked]> writes:
>> ...

> prefetching changes could affect the timing sufficiently?

Oh, that's at least a little plausible.

> I guess we'll have to wait and see what the frequency of the problem is?

Yeah, with only one instance it could just be cosmic rays or something.
However, assuming it is real, I guess I wonder why we don't say
CHECKPOINT_FORCE in standby mode too.

			regards, tom lane

---

From: Andres Freund <[email-masked]>
Date: Thu, 7 Apr 2022 11:12:02 -0700

Hi,

> CHECKPOINT_FORCE in standby mode too.

I guess it might partially be that restartpoints require a checkpoint to have
happened on the primary. If we used FORCE, we'd have to wait till the next
checkpoint on the primary, which'd be a problem if it's e.g. a manually issued
CHECKPOINT; before shutting the standby down.

Greetings,

Andres Freund

---

From: Tom Lane <[email-masked]>
Date: Fri, 08 Apr 2022 12:36:08 -0400

>> Yeah, with only one instance it could just be cosmic rays or something.

Not cosmic rays: skink has shown the same symptom three times running.
Looks like maybe the archive_cleanup_command itself is doing something
it shouldn't?

			regards, tom lane

---

From: Tom Lane <[email-masked]>
Date: Fri, 08 Apr 2022 17:55:51 -0400

> CHECKPOINT; before shutting the standby down.

After seeing skink's results, I tried running that test under valgrind
here, and it fails just like that every time.  skink's history allows
us to bound the failure introduction between 79b716cfb7 and
d7ab2a9a3c, which I think makes it just about certain that it was
5dc0418fab (Prefetch data referenced by the WAL, take II), though I've
not bisected to be 100% sure.

Adding some debug printouts to ExecuteRecoveryCommand convinces me
that indeed the archive_cleanup_command is NOT getting called by the
problematic CHECKPOINT command.  I surmise based on Andres' comment
above that the standby isn't making a restartpoint for lack of
an available primary checkpoint, which looks to me like it could be
a pre-existing bug in the test case: it's sure not doing anything to
guarantee that the primary's checkpoint record has reached the standby.

I tried adjusting the patch so it does guarantee that (as attached),
and in two out of two tries it got past the archive_cleanup_command
failure but then hung up waiting for standby2 to promote.

On the whole, I'm not sure that the WAL prefetch logic is noticeably
more stable than when we booted it out last year :-(.  However, I also
wonder why it is that this test case wasn't occasionally failing already.

			regards, tom lane

diff --git a/src/test/recovery/t/002_archiving.pl b/src/test/recovery/t/002_archiving.pl
index c8f5ffbaf0..1032d8a388 100644
--- a/src/test/recovery/t/002_archiving.pl
+++ b/src/test/recovery/t/002_archiving.pl
@@ -44,13 +44,14 @@ $node_standby->start;
 # Create some content on primary
 $node_primary->safe_psql('postgres',
 	"CREATE TABLE tab_int AS SELECT generate_series(1,1000) AS a");
-my $current_lsn =
-  $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();");
 
 # Note the presence of this checkpoint for the archive_cleanup_command
 # check done below, before switching to a new segment.
 $node_primary->safe_psql('postgres', "CHECKPOINT");
 
+my $current_lsn =
+  $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();");
+
 # Force archiving of WAL file to make it present on primary
 $node_primary->safe_psql('postgres', "SELECT pg_switch_wal()");

---

From: Andres Freund <[email-masked]>
Date: Fri, 8 Apr 2022 16:56:08 -0700

Hi,

> not bisected to be 100% sure.

I've tested it, it's 5dc0418fab that makes the difference. I reduced the cycle
time by making initdb not go through valgrind, but have normal postgres
instances go through it.

> more stable than when we booted it out last year :-(.

IDK. Last year's issues seems to have largely been caused by a flaky
machine. And a bug, if it's that, in some archiving corner case that's not
normally reached during tests...

Greetings,

Andres Freund

---

From: Andres Freund <[email-masked]>
Date: Fri, 8 Apr 2022 17:59:10 -0700

Hi,

> failure but then hung up waiting for standby2 to promote.

Adding

$node_standby->safe_psql('postgres', "SELECT pg_switch_wal()");
just after
$node_standby2->start;

makes the tests pass here.

What is that second test really testing?

# Check the presence of temporary files specifically generated during
# archive recovery.  To ensure the presence of the temporary history
# file, switch to a timeline large enough to allow a standby to recover
# a history file from an archive.  As this requires at least two timeline
# switches, promote the existing standby first.  Then create a second
# standby based on the promoted one.  Finally, the second standby is
# promoted.

Note "Then create a second standby based on the promoted one." - but that's
not actually what's happening:

$node_standby2->init_from_backup($node_primary, $backup_name,
	has_restoring => 1);

It's created from the original primary, not the first standby, as the
description says...

Both nodes get promoted independently, in a run without valgrind:

standby:
2022-04-08 17:23:42.966 PDT [2463835][startup][1/0:0][] LOG:  INSERT @ 0/4000058:  - XLOG/END_OF_RECOVERY: tli 2; prev tli 1; time 2022-04-08 17:23:42.96686-07
2022-04-08 17:23:42.966 PDT [2463835][startup][1/0:0][] LOG:  xlog flush request 0/4000058; write 0/4000000; flush 0/4000000

standby2:
2022-04-08 17:23:43.307 PDT [2463999][startup][1/0:0][] LOG:  INSERT @ 0/4000058:  - XLOG/END_OF_RECOVERY: tli 3; prev tli 1; time 2022-04-08 17:23:43.307443->
2022-04-08 17:23:43.307 PDT [2463999][startup][1/0:0][] LOG:  xlog flush request 0/4000058; write 0/4000000; flush 0/4000000

except that standby2 can't choose tli 2 because it finds it used.

Sure looks like something is funky with that test.

But I think there's also something funky in the prefetching logic. I think it
may attempt restoring during prefetching somehow, even though there's code
that appears to try to prevent that?

on standby2 I can see replay progress like the following:
2022-04-08 17:02:12.310 PDT [2441453][startup][1/0:0][] LOG:  REDO @ 0/3024488; LSN 0/30244C8: prev 0/3024448; xid 725; len 3; blkref #0: rel 1663/5/16384, blk 4 - Heap/INSERT: off 60 flags 0x00
2022-04-08 17:02:12.311 PDT [2441453][startup][1/0:0][] DEBUG:  record known xact 725 latestObservedXid 725
2022-04-08 17:02:12.311 PDT [2441453][startup][1/0:0][] CONTEXT:  WAL redo at 0/3024488 for Heap/INSERT: off 60 flags 0x00; blkref #0: rel 1663/5/16384, blk 4
2022-04-08 17:02:12.312 PDT [2441453][startup][1/0:0][] DEBUG:  executing restore command "cp "/home/andres/build/postgres/dev-assert/vpath/src/test/recovery/tmp_check/t_002_archiving_primary_data/archives/000000010000000000000004" "pg_wal/RECOVERYXLOG""
2022-04-08 17:02:13.855 PDT [2441453][startup][1/0:0][] DEBUG:  could not restore file "000000010000000000000004" from archive: child process exited with exit code 1
2022-04-08 17:02:13.855 PDT [2441453][startup][1/0:0][] DEBUG:  could not open file "pg_wal/000000010000000000000004": No such file or directory
2022-04-08 17:02:13.856 PDT [2441453][startup][1/0:0][] LOG:  REDO @ 0/30244C8; LSN 0/3024508: prev 0/3024488; xid 725; len 3; blkref #0: rel 1663/5/16384, blk 4 - Heap/INSERT: off 61 flags 0x00
2022-04-08 17:02:13.856 PDT [2441453][startup][1/0:0][] DEBUG:  record known xact 725 latestObservedXid 725
2022-04-08 17:02:13.856 PDT [2441453][startup][1/0:0][] CONTEXT:  WAL redo at 0/30244C8 for Heap/INSERT: off 61 flags 0x00; blkref #0: rel 1663/5/16384, blk 4
2022-04-08 17:02:13.857 PDT [2441453][startup][1/0:0][] DEBUG:  executing restore command "cp "/home/andres/build/postgres/dev-assert/vpath/src/test/recovery/tmp_check/t_002_archiving_primary_data/archives/000000010000000000000004" "pg_wal/RECOVERYXLOG""
2022-04-08 17:02:15.413 PDT [2441453][startup][1/0:0][] DEBUG:  could not restore file "000000010000000000000004" from archive: child process exited with exit code 1
2022-04-08 17:02:15.413 PDT [2441453][startup][1/0:0][] DEBUG:  could not open file "pg_wal/000000010000000000000004": No such file or directory
2022-04-08 17:02:15.414 PDT [2441453][startup][1/0:0][] LOG:  REDO @ 0/3024508; LSN 0/3024548: prev 0/30244C8; xid 725; len 3; blkref #0: rel 1663/5/16384, blk 4 - Heap/INSERT: off 62 flags 0x00
2022-04-08 17:02:15.414 PDT [2441453][startup][1/0:0][] DEBUG:  record known xact 725 latestObservedXid 725
2022-04-08 17:02:15.414 PDT [2441453][startup][1/0:0][] CONTEXT:  WAL redo at 0/3024508 for Heap/INSERT: off 62 flags 0x00; blkref #0: rel 1663/5/16384, blk 4
2022-04-08 17:02:15.415 PDT [2441453][startup][1/0:0][] DEBUG:  executing restore command "cp "/home/andres/build/postgres/dev-assert/vpath/src/test/recovery/tmp_check/t_002_archiving_primary_data/archives/000000010000000000000004" "pg_wal/RECOVERYXLOG""

note that we appear to wait between replaying of records, even though we
apparently have WAL for the next record!

And interestingly I'm not seeing the
"switched WAL source from stream to archive after failure"
lines I'd expect.

Greetings,

Andres Freund