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

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

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

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.