Horton

Thread

Commits

  1. Fix race condition in t/028_pitr_timelines.pl.

  2. Fix race condition in 028_pitr_timelines.pl test, add note to docs.

  3. Add more logging to new 028_pitr_timelines.pl test.

  4. Add test case for an archive recovery corner case.

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

    Heikki Linnakangas <heikki.linnakangas@iki.fi> — 2022-02-14T09:34:10Z

    Add test case for an archive recovery corner case.

While I was working on a patch to refactor things around xlog.c, I mixed
up EndOfLogTLI and replayTLI at the end of recovery. As a result, if you
recovered to a point with a lower-numbered timeline in a WAL segment
that has a higher TLI in the filename, the end-of-recovery WAL record
was created with invalid PrevTimeLineId. I noticed that while
self-reviewing, but no tests failed. So add a test to cover that corner
case.

Thanks to Amul Sul who also submitted a test case for the same corner
case, although this patch is different from that.

Reviewed-by: Amul Sul, Michael Paquier
Discussion: https://www.postgresql.org/message-id/52bc9ccd-8591-431b-0086-15d9acf25a3f@iki.fi
Discussion: https://www.postgresql.org/message-id/CAAJ_b94Vjt5cXGza_1MkjLQWciNdEemsmiWuQj0d%3DM7JfjAa1g%40mail.gmail.com

Branch
------
master

Details
-------
https://git.postgresql.org/pg/commitdiff/50e5bc582a4371a88218078a2c651d901bf87d96

Modified Files
--------------
src/test/recovery/t/028_pitr_timelines.pl | 176 ++++++++++++++++++++++++++++++
1 file changed, 176 insertions(+)

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

    Tom Lane <tgl@sss.pgh.pa.us> — 2022-02-14T14:41:40Z

    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&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

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

    Heikki Linnakangas <hlinnaka@iki.fi> — 2022-02-14T20:43:43Z

    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&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

  4. last_archived_wal is not necessary the latest WAL file (was Re: pgsql: Add test case for an archive recovery corner case.)

    Heikki Linnakangas <hlinnaka@iki.fi> — 2022-02-15T21:20:50Z

    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&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

  5. Re: last_archived_wal is not necessary the latest WAL file (was Re: pgsql: Add test case for an archive recovery corner case.)

    Tom Lane <tgl@sss.pgh.pa.us> — 2022-02-15T21:28:27Z

    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

  6. Re: last_archived_wal is not necessary the latest WAL file (was Re: pgsql: Add test case for an archive recovery corner case.)

    Heikki Linnakangas <hlinnaka@iki.fi> — 2022-02-15T23:42:27Z

    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

  7. Re: last_archived_wal is not necessary the latest WAL file (was Re: pgsql: Add test case for an archive recovery corner case.)

    Noah Misch <noah@leadboat.com> — 2022-06-27T07:04:57Z

    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&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&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

  8. Re: last_archived_wal is not necessary the latest WAL file (was Re: pgsql: Add test case for an archive recovery corner case.)

    Michael Paquier <michael@paquier.xyz> — 2022-06-27T10:32:08Z

    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

  9. Re: last_archived_wal is not necessary the latest WAL file (was Re: pgsql: Add test case for an archive recovery corner case.)

    Noah Misch <noah@leadboat.com> — 2022-06-30T05:03:10Z

    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.