pgsql: Add test case for an archive recovery corner case.

Heikki Linnakangas <heikki.linnakangas@iki.fi> writes:

Add test case for an archive recovery corner case.

hoverfly seems not to like this:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hoverfly&amp;dt=2022-02-14%2012%3A36%3A12

# poll_query_until timed out executing this query:
# SELECT '000000020000000000000003' <= last_archived_wal FROM pg_stat_archiver;
# expecting this output:
# t
# last actual query output:
# f
# with stderr:
# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 29 just after 1.
[13:22:56] t/028_pitr_timelines.pl ..............
Dubious, test returned 29 (wstat 7424, 0x1d00)
All 1 subtests passed

regards, tom lane

On 14/02/2022 16:41, Tom Lane wrote:

Heikki Linnakangas <heikki.linnakangas@iki.fi> writes:

Add test case for an archive recovery corner case.

hoverfly seems not to like this:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hoverfly&amp;dt=2022-02-14%2012%3A36%3A12

Hmm, only hoverfly - and even that succeeded on next run. Some kind of a
flakyness I guess. I'll try to run the test in a loop and see if I can
reproduce it.

- Heikki

On 14/02/2022 22:43, Heikki Linnakangas wrote:

On 14/02/2022 16:41, Tom Lane wrote:

Heikki Linnakangas <heikki.linnakangas@iki.fi> writes:

Add test case for an archive recovery corner case.

hoverfly seems not to like this:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hoverfly&amp;dt=2022-02-14%2012%3A36%3A12

Hmm, only hoverfly - and even that succeeded on next run. Some kind of a
flakyness I guess. I'll try to run the test in a loop and see if I can
reproduce it.

That was interesting: the order that WAL segments are archived when a
standby is promoted is not fully deterministic. The test polled
pg_stat_archiver.last_archived_wal to wait until a particular WAL
segment was archived, but it could happen that a lower-numbered WAL
segment was archived *after* the waited-for segment, and
pg_stat_archiver.last_archived_wal therefore displayed the
lower-numbered WAL segment. So the test incorrectly thought that the
higher-numbered segment that it waits for hadn't been archived yet.

I realized that this test doesn't really need to wait for the segment to
be archived, because it will stop the standby server immediately after
that, and stopping a server implicitly waits for all the WAL to be
archived before the archiver process exits. So I just removed it.

During normal operations the WAL segments are archived in order. But I'm
not sure if there are some other corner cases, aside from promoting a
standby server, when this could happen. After crash restart, maybe, if
some .ready/done files are lost.

I find it a bit surprising that pg_stat_archiver.last_archived_wal is
not necessarily the highest-numbered segment that was archived. I
propose that we mention that in the docs, as in the attached patch.

I'll commit this soon, to silence the occasional failures on the
buildfarm, but let me know if you have any better suggestions or thoughts.

- Heikki

Heikki Linnakangas <hlinnaka@iki.fi> writes:

That was interesting: the order that WAL segments are archived when a
standby is promoted is not fully deterministic.

Oh, of course.

I find it a bit surprising that pg_stat_archiver.last_archived_wal is
not necessarily the highest-numbered segment that was archived. I
propose that we mention that in the docs, as in the attached patch.

+1, but I think the description of that field in the pg-stat-archiver-view
table is also pretty misleading. Maybe like

-      Name of the last WAL file successfully archived
+      Name of the WAL file most recently successfully archived

and similarly s/last/most recent/ for the other fields claiming
to be "last" something.

regards, tom lane

On 15/02/2022 23:28, Tom Lane wrote:

Heikki Linnakangas <hlinnaka@iki.fi> writes:

That was interesting: the order that WAL segments are archived when a
standby is promoted is not fully deterministic.

Oh, of course.

I find it a bit surprising that pg_stat_archiver.last_archived_wal is
not necessarily the highest-numbered segment that was archived. I
propose that we mention that in the docs, as in the attached patch.

+1, but I think the description of that field in the pg-stat-archiver-view
table is also pretty misleading. Maybe like

-      Name of the last WAL file successfully archived
+      Name of the WAL file most recently successfully archived

and similarly s/last/most recent/ for the other fields claiming
to be "last" something.

Makes sense, committed it that way.

- Heikki

On Wed, Feb 16, 2022 at 01:42:27AM +0200, Heikki Linnakangas wrote:

On 15/02/2022 23:28, Tom Lane wrote:

Heikki Linnakangas <hlinnaka@iki.fi> writes:

That was interesting: the order that WAL segments are archived when a
standby is promoted is not fully deterministic.

Oh, of course.

I find it a bit surprising that pg_stat_archiver.last_archived_wal is
not necessarily the highest-numbered segment that was archived. I
propose that we mention that in the docs, as in the attached patch.

+1, but I think the description of that field in the pg-stat-archiver-view
table is also pretty misleading. Maybe like

-      Name of the last WAL file successfully archived
+      Name of the WAL file most recently successfully archived

and similarly s/last/most recent/ for the other fields claiming
to be "last" something.

Makes sense, committed it that way.

This has seen two failures like the following:
# Failed test 'check table contents after point-in-time recovery'
# at t/028_pitr_timelines.pl line 167.
# got: '2'
# expected: '3'
# Looks like you failed 1 test of 3.

sysname │ snapshot │ branch │ bfurl
──────────┼─────────────────────┼────────┼──────────────────────────────────────────────────────────────────────────────────────────────
sungazer │ 2022-03-08 16:24:46 │ HEAD │ http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sungazer&amp;dt=2022-03-08%2016%3A24%3A46
mylodon │ 2022-05-18 00:14:19 │ HEAD │ http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=mylodon&amp;dt=2022-05-18%2000%3A14%3A19

For me, it reproduces consistently with a sleep just before the startup
process exits:

--- a/src/backend/postmaster/startup.c
+++ b/src/backend/postmaster/startup.c
@@ -266,6 +266,8 @@ StartupProcessMain(void)
 	 */
 	StartupXLOG();

+ pg_usleep(3 * 1000 * 1000);
+
/*
* Exit normally. Exit code 0 tells postmaster that we completed recovery
* successfully.

A normal/passing run gets this sequence of events:

checkpointer: end-of-recovery checkpoint
startup process: exits
postmaster reaper(): "Startup succeeded, commence normal operations" = StartArchiver()
test issues its INSERT
shutdown checkpoint
checkpointer: exits
postmaster reaper(): signal_child(PgArchPID, SIGUSR2)
archiver: completes archiving, exits

However, if the startup process exit is slow enough, you get:

checkpointer: end-of-recovery checkpoint
test issues its INSERT
shutdown checkpoint
checkpointer: exits
postmaster reaper(): no PgArchPID, skip that part
[no archiving]

One can adapt the test to the server behavior by having the test wait for the
archiver to start, as attached. This is sufficient to make check-world pass
with the above sleep in place. I think we should also modify the PostgresNode
archive_command to log a message. That lack of logging was a obstacle
upthread (as seen in commit 3279cef) and again here.

An alternative would be to declare that the test is right and the server is
wrong. The postmaster knows how to start the checkpointer if the checkpointer
is not running when the postmaster needs a shutdown checkpoint. It could
start the archiver around that same area:

/* Start the checkpointer if not running */
if (CheckpointerPID == 0)
CheckpointerPID = StartCheckpointer();
/* And tell it to shut down */
if (CheckpointerPID != 0)
{
signal_child(CheckpointerPID, SIGUSR2);
pmState = PM_SHUTDOWN;
}

Any opinions between the change-test and change-server approaches?

The test is new in HEAD, but I get the same behavior in v14 and v13. In v12,
node_pitr2 never exits pg_is_in_recovery(). v11 would need test code changes,
which I did not attempt.

Thanks,
nm

On Mon, Jun 27, 2022 at 12:04:57AM -0700, Noah Misch wrote:

For me, it reproduces consistently with a sleep just before the startup
process exits:

Nice catch.

One can adapt the test to the server behavior by having the test wait for the
archiver to start, as attached. This is sufficient to make check-world pass
with the above sleep in place. I think we should also modify the PostgresNode
archive_command to log a message. That lack of logging was a obstacle
upthread (as seen in commit 3279cef) and again here.

          ? qq{copy "%p" "$path\\\\%f"}
-         : qq{cp "%p" "$path/%f"};
+         : qq{echo >&2 "ARCHIVE_COMMAND %p"; cp "%p" "$path/%f"};

This is a bit inelegant. Perhaps it would be better through a perl
wrapper like cp_history_files?

An alternative would be to declare that the test is right and the server is
wrong. The postmaster knows how to start the checkpointer if the checkpointer
is not running when the postmaster needs a shutdown checkpoint. It could
start the archiver around that same area:

/* Start the checkpointer if not running */
if (CheckpointerPID == 0)
CheckpointerPID = StartCheckpointer();
/* And tell it to shut down */
if (CheckpointerPID != 0)
{
signal_child(CheckpointerPID, SIGUSR2);
pmState = PM_SHUTDOWN;
}

Any opinions between the change-test and change-server approaches?

The startup sequence can be sometimes tricky. Though I don't have a
specific argument coming into mind, I would stick to a fix in the
test.
--
Michael

On Mon, Jun 27, 2022 at 07:32:08PM +0900, Michael Paquier wrote:

On Mon, Jun 27, 2022 at 12:04:57AM -0700, Noah Misch wrote:

One can adapt the test to the server behavior by having the test wait for the
archiver to start, as attached. This is sufficient to make check-world pass
with the above sleep in place. I think we should also modify the PostgresNode
archive_command to log a message. That lack of logging was a obstacle
upthread (as seen in commit 3279cef) and again here.

? qq{copy "%p" "$path\\\\%f"}
-         : qq{cp "%p" "$path/%f"};
+         : qq{echo >&2 "ARCHIVE_COMMAND %p"; cp "%p" "$path/%f"};

This is a bit inelegant. Perhaps it would be better through a perl
wrapper like cp_history_files?

I see it the other way. Replacing a 49-character compound command with a
wrapper script would gain no particular advantage, and it would give readers
of the test code one more file to open and understand.