Re: Race condition in recovery?

On Thu, May 27, 2021 at 6:19 AM Kyotaro Horiguchi
<horikyota(dot)ntt(at)gmail(dot)com> wrote:
>
> At Wed, 26 May 2021 22:08:32 +0530, Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote in
> > On Wed, 26 May 2021 at 10:06 PM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
> >
> > > On Wed, May 26, 2021 at 12:26 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com>
> > > wrote:
> > > > I will check if there is any timing dependency in the test case.
> > >
> > > There is. I explained it in the second part of my email, which you may
> > > have failed to notice.
> >
> >
> > Sorry, my bad. I got your point now. I will change the test.
>
> I didn't noticed that but that is actually possible to happen.
>
>
> By the way I'm having a hard time understanding what was happening on
> this thread.
>
> In the very early in this thread I posted a test script that exactly
> reproduces Dilip's case by starting from two standbys based on his
> explanation. But *we* didn't understand what the original commit
> ee994272ca intended and I understood that we wanted to know it.
>
> So in the mail [1] and [2] I tried to describe what's going on around
> the two issues. Although I haven't have a response to [2], can I
> think that we clarified the intention of ee994272ca? And may I think
> that we decided that we don't add a test for the commit?
>
> Then it seems to me that Robert refound how to reproduce Dilip's case
> using basebackup instead of using two standbys. It is using a broken
> archive_command with pg_basebackup -Xnone and I showed that the same
> resulting state is available by pg_basebackup -Xstream/fetch clearing
> pg_wal directory of the resulting backup including an explanation of
> why.

Maybe we can somehow achieve that without a broken archive command,
but I am not sure how it is enough to just delete WAL from pg_wal? I
mean my original case was that
1. Got the new history file from the archive but did not get the WAL
file yet which contains the checkpoint after TL switch
2. So the standby2 try to stream using new primary using old TL and
set the wrong TL in expectedTLEs

But if you are not doing anything to stop archiving WAL files or to
guarantee that WAL has come to archive and you deleted those then I am
not sure how we are reproducing the original problem.

BTW, I have also tested your script and I found below log, which shows
that standby2 is successfully able to select the timeline2 so it is
not reproducing the issue. Am I missing something?

--standby-1--
2021-05-27 10:45:35.866 IST [5096] LOG: last completed transaction
was at log time 2021-05-27 10:45:35.699316+05:30
2021-05-27 10:45:35.867 IST [5096] LOG: selected new timeline ID: 2
2021-05-27 10:45:35.882 IST [5096] LOG: archive recovery complete
2021-05-27 10:45:35.911 IST [5095] LOG: database system is ready to
accept connections
2021-05-27 10:45:36.096 IST [5134] standby_2 LOG: received
replication command: IDENTIFY_SYSTEM
2021-05-27 10:45:36.096 IST [5134] standby_2 STATEMENT: IDENTIFY_SYSTEM

--standby-2--
2021-05-27 10:45:36.089 IST [5129] LOG: entering standby mode
2021-05-27 10:45:36.090 IST [5129] LOG: redo starts at 0/2000028
2021-05-27 10:45:36.092 IST [5129] LOG: consistent recovery state
reached at 0/3030320
2021-05-27 10:45:36.092 IST [5129] LOG: invalid record length at
0/3030320: wanted 24, got 0
2021-05-27 10:45:36.092 IST [5128] LOG: database system is ready to
accept read only connections
2021-05-27 10:45:36.096 IST [5133] LOG: fetching timeline history
file for timeline 2 from primary server
2021-05-27 10:45:36.097 IST [5133] LOG: started streaming WAL from
primary at 0/3000000 on timeline 1
2021-05-27 10:45:36.098 IST [5133] LOG: replication terminated by
primary server
2021-05-27 10:45:36.098 IST [5133] DETAIL: End of WAL reached on
timeline 1 at 0/3030320.
2021-05-27 10:45:36.098 IST [5129] LOG: new target timeline is 2
2021-05-27 10:45:36.098 IST [5133] LOG: restarted WAL streaming at
0/3000000 on timeline 2

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com