Horton
Menu

Thread

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →

  1. Fix timeline assignment in checkpoints with 2PC transactions

  1. PITR promote bug: Checkpointer writes to older timeline

    Soumyadeep Chakraborty <soumyadeep2007@gmail.com> — 2021-03-03T01:56:03Z

    Hello hackers,

We came across an issue where the checkpointer writes to the older
timeline while a promotion is ongoing after reaching the recovery point
in a PITR, when there are prepared transactions before the recovery
point. We came across this issue first in REL_12_STABLE and saw that it
also exists in devel.

Setup:
PFA a minimal reproduction script repro.txt.

After running the script, we notice that the checkpointer has written
the end-of-recovery shutdown checkpoint in the previous timeline (tli =
1), i.e. it wrote into the WAL segment 000000010000000000000003 instead
of writing to the WAL segment 000000020000000000000003, causing it to
overwrite WAL records past the recovery point (please see attached diff
output file waldiff.diff) in 000000010000000000000003.

Also, performing a subsequent shutdown on the recovered server may cause
the next shutdown checkpoint record to be written, again, to the
previous timeline, i.e. to 000000010000000000000003. A subsequent server
start will fail as the starup process will be unable to find the
checkpoint in the latest timeline (000000020000000000000003) and we will
get:

...
LOG:  invalid record length at 0/3016FB8: wante
d 24, got 0
LOG:  invalid primary checkpoint record
PANIC:  could not locate a valid checkpoint record
...

RCA:

When there are prepared transactions in an older timeline, in the
checkpointer, a call to CheckPointTwoPhase() and subsequently to
XlogReadTwoPhaseData() and subsequently to read_local_xlog_page() leads
to the following line:

read_upto = GetXLogReplayRecPtr(&ThisTimeLineID);

GetXLogReplayRecPtr() will change ThisTimeLineID to 1, in order to read
the two phase WAL records in the older timeline. This variable will
remain unchanged and the checkpointer ends up writing the checkpoint
record into the older WAL segment (when XLogBeginInsert() is called
within CreateCheckPoint(), the value is still 1). The value is not
synchronized as even if RecoveryInProgress() is called,
xlogctl->SharedRecoveryState is not RECOVERY_STATE_DONE
(SharedRecoveryInProgress = true in older versions) as the startup
process waits for the checkpointer inside RequestCheckpoint() (since
recovery_target_action='promote' involves a non-fast promotion). Thus,
InitXLOGAccess() is not called and the value of ThisTimeLineID is not
updated before the checkpoint record write.

Since 1148e22a82e, GetXLogReplayRecPtr() is called with ThisTimeLineID
instead of a local variable, within read_local_xlog_page().

PFA a small patch that fixes the problem by explicitly calling
InitXLOGAccess() in CheckPointTwoPhase(), after the two phase state data
is read, in order to update ThisTimeLineID to the latest timeline. It is
okay to call InitXLOGAccess() as it is lightweight and would mostly be
a no-op.

Regards,
Soumyadeep, Kevin and Jimmy
VMWare

  2. Re: PITR promote bug: Checkpointer writes to older timeline

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-03-03T06:47:42Z

    At Tue, 2 Mar 2021 17:56:03 -0800, Soumyadeep Chakraborty <soumyadeep2007@gmail.com> wrote in 
> Hello hackers,
> 
> We came across an issue where the checkpointer writes to the older
> timeline while a promotion is ongoing after reaching the recovery point
> in a PITR, when there are prepared transactions before the recovery
> point. We came across this issue first in REL_12_STABLE and saw that it
> also exists in devel.

Good Catch!  I can reproduce that.

> When there are prepared transactions in an older timeline, in the
> checkpointer, a call to CheckPointTwoPhase() and subsequently to
> XlogReadTwoPhaseData() and subsequently to read_local_xlog_page() leads
> to the following line:
> 
> read_upto = GetXLogReplayRecPtr(&ThisTimeLineID);
> 
> GetXLogReplayRecPtr() will change ThisTimeLineID to 1, in order to read
> the two phase WAL records in the older timeline. This variable will
> remain unchanged and the checkpointer ends up writing the checkpoint
> record into the older WAL segment (when XLogBeginInsert() is called
> within CreateCheckPoint(), the value is still 1). The value is not
> synchronized as even if RecoveryInProgress() is called,
> xlogctl->SharedRecoveryState is not RECOVERY_STATE_DONE
> (SharedRecoveryInProgress = true in older versions) as the startup
> process waits for the checkpointer inside RequestCheckpoint() (since
> recovery_target_action='promote' involves a non-fast promotion). Thus,
> InitXLOGAccess() is not called and the value of ThisTimeLineID is not
> updated before the checkpoint record write.
> 
> Since 1148e22a82e, GetXLogReplayRecPtr() is called with ThisTimeLineID
> instead of a local variable, within read_local_xlog_page().
> 
> PFA a small patch that fixes the problem by explicitly calling
> InitXLOGAccess() in CheckPointTwoPhase(), after the two phase state data
> is read, in order to update ThisTimeLineID to the latest timeline. It is
> okay to call InitXLOGAccess() as it is lightweight and would mostly be
> a no-op.

It is correct that read_local_xlog_page() changes ThisTimeLineID, but
InitXLOGAccess() is correctly called in CreateCheckPoint:

|	/*
|	 * An end-of-recovery checkpoint is created before anyone is allowed to
|	 * write WAL. To allow us to write the checkpoint record, temporarily
|	 * enable XLogInsertAllowed.  (This also ensures ThisTimeLineID is
|	 * initialized, which we need here and in AdvanceXLInsertBuffer.)
|	 */
|	if (flags & CHECKPOINT_END_OF_RECOVERY)
|		LocalSetXLogInsertAllowed();

It seems to e suficcient to recover ThisTimeLineID from the checkpoint
record to be written, as attached?

regareds.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  3. Re: PITR promote bug: Checkpointer writes to older timeline

    Heikki Linnakangas <hlinnaka@iki.fi> — 2021-03-03T08:46:42Z

    On 03/03/2021 08:47, Kyotaro Horiguchi wrote:
> At Tue, 2 Mar 2021 17:56:03 -0800, Soumyadeep Chakraborty <soumyadeep2007@gmail.com> wrote in
>> When there are prepared transactions in an older timeline, in the
>> checkpointer, a call to CheckPointTwoPhase() and subsequently to
>> XlogReadTwoPhaseData() and subsequently to read_local_xlog_page() leads
>> to the following line:
>>
>> read_upto = GetXLogReplayRecPtr(&ThisTimeLineID);
>>
>> GetXLogReplayRecPtr() will change ThisTimeLineID to 1, in order to read
>> the two phase WAL records in the older timeline. This variable will
>> remain unchanged and the checkpointer ends up writing the checkpoint
>> record into the older WAL segment (when XLogBeginInsert() is called
>> within CreateCheckPoint(), the value is still 1). The value is not
>> synchronized as even if RecoveryInProgress() is called,
>> xlogctl->SharedRecoveryState is not RECOVERY_STATE_DONE
>> (SharedRecoveryInProgress = true in older versions) as the startup
>> process waits for the checkpointer inside RequestCheckpoint() (since
>> recovery_target_action='promote' involves a non-fast promotion). Thus,
>> InitXLOGAccess() is not called and the value of ThisTimeLineID is not
>> updated before the checkpoint record write.
>>
>> Since 1148e22a82e, GetXLogReplayRecPtr() is called with ThisTimeLineID
>> instead of a local variable, within read_local_xlog_page().

Confusing...

>> PFA a small patch that fixes the problem by explicitly calling
>> InitXLOGAccess() in CheckPointTwoPhase(), after the two phase state data
>> is read, in order to update ThisTimeLineID to the latest timeline. It is
>> okay to call InitXLOGAccess() as it is lightweight and would mostly be
>> a no-op.
> 
> It is correct that read_local_xlog_page() changes ThisTimeLineID, but
> InitXLOGAccess() is correctly called in CreateCheckPoint:
> 
> |	/*
> |	 * An end-of-recovery checkpoint is created before anyone is allowed to
> |	 * write WAL. To allow us to write the checkpoint record, temporarily
> |	 * enable XLogInsertAllowed.  (This also ensures ThisTimeLineID is
> |	 * initialized, which we need here and in AdvanceXLInsertBuffer.)
> |	 */
> |	if (flags & CHECKPOINT_END_OF_RECOVERY)
> |		LocalSetXLogInsertAllowed();
> 
> It seems to e suficcient to recover ThisTimeLineID from the checkpoint
> record to be written, as attached?

I think it should be reset even earlier, inside XlogReadTwoPhaseData() 
probably. With your patch, doesn't the LogStandbySnapshot() call just 
above where you're ressetting ThisTimeLineID also write a WAL record 
with incorrect timeline?

Even better, can we avoid setting ThisTimeLineID in 
XlogReadTwoPhaseData() in the first place?

- Heikki

  4. Re: PITR promote bug: Checkpointer writes to older timeline

    Fujii Masao <masao.fujii@oss.nttdata.com> — 2021-03-03T09:04:05Z

    
On 2021/03/03 17:46, Heikki Linnakangas wrote:
> On 03/03/2021 08:47, Kyotaro Horiguchi wrote:
>> At Tue, 2 Mar 2021 17:56:03 -0800, Soumyadeep Chakraborty <soumyadeep2007@gmail.com> wrote in
>>> When there are prepared transactions in an older timeline, in the
>>> checkpointer, a call to CheckPointTwoPhase() and subsequently to
>>> XlogReadTwoPhaseData() and subsequently to read_local_xlog_page() leads
>>> to the following line:
>>>
>>> read_upto = GetXLogReplayRecPtr(&ThisTimeLineID);
>>>
>>> GetXLogReplayRecPtr() will change ThisTimeLineID to 1, in order to read
>>> the two phase WAL records in the older timeline. This variable will
>>> remain unchanged and the checkpointer ends up writing the checkpoint
>>> record into the older WAL segment (when XLogBeginInsert() is called
>>> within CreateCheckPoint(), the value is still 1). The value is not
>>> synchronized as even if RecoveryInProgress() is called,
>>> xlogctl->SharedRecoveryState is not RECOVERY_STATE_DONE
>>> (SharedRecoveryInProgress = true in older versions) as the startup
>>> process waits for the checkpointer inside RequestCheckpoint() (since
>>> recovery_target_action='promote' involves a non-fast promotion). Thus,
>>> InitXLOGAccess() is not called and the value of ThisTimeLineID is not
>>> updated before the checkpoint record write.
>>>
>>> Since 1148e22a82e, GetXLogReplayRecPtr() is called with ThisTimeLineID
>>> instead of a local variable, within read_local_xlog_page().
> 
> Confusing...
> 
>>> PFA a small patch that fixes the problem by explicitly calling
>>> InitXLOGAccess() in CheckPointTwoPhase(), after the two phase state data
>>> is read, in order to update ThisTimeLineID to the latest timeline. It is
>>> okay to call InitXLOGAccess() as it is lightweight and would mostly be
>>> a no-op.
>>
>> It is correct that read_local_xlog_page() changes ThisTimeLineID, but
>> InitXLOGAccess() is correctly called in CreateCheckPoint:
>>
>> |    /*
>> |     * An end-of-recovery checkpoint is created before anyone is allowed to
>> |     * write WAL. To allow us to write the checkpoint record, temporarily
>> |     * enable XLogInsertAllowed.  (This also ensures ThisTimeLineID is
>> |     * initialized, which we need here and in AdvanceXLInsertBuffer.)
>> |     */
>> |    if (flags & CHECKPOINT_END_OF_RECOVERY)
>> |        LocalSetXLogInsertAllowed();
>>
>> It seems to e suficcient to recover ThisTimeLineID from the checkpoint
>> record to be written, as attached?
> 
> I think it should be reset even earlier, inside XlogReadTwoPhaseData() probably. With your patch, doesn't the LogStandbySnapshot() call just above where you're ressetting ThisTimeLineID also write a WAL record with incorrect timeline?
> 
> Even better, can we avoid setting ThisTimeLineID in XlogReadTwoPhaseData() in the first place?

Or isn't it better to reset ThisTimeLineID in read_local_xlog_page(), i.e.,
prevent read_local_xlog_page() from changing ThisTimeLineID? I'm not
sure if that's possible, though.. In the future other functions that calls
read_local_xlog_page() during the promotion may appear. Fixing the issue
outside read_local_xlog_page() may cause those functions to get
the same issue.

Regards,


-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

  5. Re: PITR promote bug: Checkpointer writes to older timeline

    Soumyadeep Chakraborty <soumyadeep2007@gmail.com> — 2021-03-03T22:56:25Z

    On 2021/03/03 17:46, Heikki Linnakangas wrote:

> I think it should be reset even earlier, inside XlogReadTwoPhaseData()
> probably. With your patch, doesn't the LogStandbySnapshot() call just
> above where you're ressetting ThisTimeLineID also write a WAL record
> with incorrect timeline?

Agreed.

On Wed, Mar 3, 2021 at 1:04 AM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:

> > Even better, can we avoid setting ThisTimeLineID in XlogReadTwoPhaseData() in the first place?
>
>
>
> Or isn't it better to reset ThisTimeLineID in read_local_xlog_page(), i.e.,
> prevent read_local_xlog_page() from changing ThisTimeLineID? I'm not
> sure if that's possible, though.. In the future other functions that calls
> read_local_xlog_page() during the promotion may appear. Fixing the issue
> outside read_local_xlog_page() may cause those functions to get
> the same issue.

I agree. We should fix the issue in read_local_xlog_page(). I have
attached two different patches which do so:
saved_ThisTimeLineID.patch and pass_ThisTimeLineID.patch.

The former saves the value of the ThisTimeLineID before it gets changed
in read_local_xlog_page() and resets it after ThisTimeLineID has been
used later on in the code (by XLogReadDetermineTimeline()).

The latter removes occurrences of ThisTimeLineID from
XLogReadDetermineTimeline() and introduces an argument currTLI to
XLogReadDetermineTimeline() to be used in its stead.

Regards,
Soumyadeep

  6. Re: PITR promote bug: Checkpointer writes to older timeline

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-03-04T01:28:31Z

    At Wed, 3 Mar 2021 14:56:25 -0800, Soumyadeep Chakraborty <soumyadeep2007@gmail.com> wrote in 
> On 2021/03/03 17:46, Heikki Linnakangas wrote:
> 
> > I think it should be reset even earlier, inside XlogReadTwoPhaseData()
> > probably. With your patch, doesn't the LogStandbySnapshot() call just
> > above where you're ressetting ThisTimeLineID also write a WAL record
> > with incorrect timeline?
> 
> Agreed.

Right.

> On Wed, Mar 3, 2021 at 1:04 AM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
> 
> > > Even better, can we avoid setting ThisTimeLineID in XlogReadTwoPhaseData() in the first place?
> >
> >
> >
> > Or isn't it better to reset ThisTimeLineID in read_local_xlog_page(), i.e.,
> > prevent read_local_xlog_page() from changing ThisTimeLineID? I'm not
> > sure if that's possible, though.. In the future other functions that calls
> > read_local_xlog_page() during the promotion may appear. Fixing the issue
> > outside read_local_xlog_page() may cause those functions to get
> > the same issue.
> 
> I agree. We should fix the issue in read_local_xlog_page(). I have
> attached two different patches which do so:
> saved_ThisTimeLineID.patch and pass_ThisTimeLineID.patch.
> 
> The former saves the value of the ThisTimeLineID before it gets changed
> in read_local_xlog_page() and resets it after ThisTimeLineID has been
> used later on in the code (by XLogReadDetermineTimeline()).
> 
> The latter removes occurrences of ThisTimeLineID from
> XLogReadDetermineTimeline() and introduces an argument currTLI to
> XLogReadDetermineTimeline() to be used in its stead.

read_local_xlog_page() works as a part of logical decoding and has
responsibility to update ThisTimeLineID properly.  As the comment in
the function, it is the proper place to update ThisTimeLineID since we
miss a timeline change if we check it earlier and the function uses
the value just after. So we cannot change that behavior of the
function.  That is, neither of them doesn't seem to be the right fix.

The confusion here is that there's two ThisTimeLineID's here. The
previous TLI for read and the next TLI to write.  Most part of the
function is needed to read a 2pc recrod so the ways we can take here
is:

1. Somehow tell the function not to update ThisTimeLineID in specific
  cases. This can be done by xlogreader private data but this doesn't
  seem reasonable.

2. Restore ThisTimeLineID after calling XLogReadRecord() in the
  *caller* side.  This is what came up to me first but I don't like
  this, too, but I don't find better fix.  way.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  7. Re: PITR promote bug: Checkpointer writes to older timeline

    Michael Paquier <michael@paquier.xyz> — 2021-03-04T02:18:42Z

    On Thu, Mar 04, 2021 at 10:28:31AM +0900, Kyotaro Horiguchi wrote:
> read_local_xlog_page() works as a part of logical decoding and has
> responsibility to update ThisTimeLineID properly.  As the comment in
> the function, it is the proper place to update ThisTimeLineID since we
> miss a timeline change if we check it earlier and the function uses
> the value just after. So we cannot change that behavior of the
> function.  That is, neither of them doesn't seem to be the right fix.
> 
> The confusion here is that there's two ThisTimeLineID's here. The
> previous TLI for read and the next TLI to write.  Most part of the
> function is needed to read a 2pc recrod so the ways we can take here
> is:
> 
> 1. Somehow tell the function not to update ThisTimeLineID in specific
>   cases. This can be done by xlogreader private data but this doesn't
>   seem reasonable.
> 
> 2. Restore ThisTimeLineID after calling XLogReadRecord() in the
>   *caller* side.  This is what came up to me first but I don't like
>   this, too, but I don't find better fix.  way.

I have not looked in details at the solutions proposed here, but could
it be possible to have a TAP test at least please?  Seeing the script
from the top of the thread, it should not be difficult to do so.  I
would put that in a file different than 009_twophase.pl, within
src/test/recovery/.
--
Michael

  8. Re: PITR promote bug: Checkpointer writes to older timeline

    Fujii Masao <masao.fujii@oss.nttdata.com> — 2021-03-04T05:57:13Z

    
On 2021/03/04 10:28, Kyotaro Horiguchi wrote:
> At Wed, 3 Mar 2021 14:56:25 -0800, Soumyadeep Chakraborty <soumyadeep2007@gmail.com> wrote in
>> On 2021/03/03 17:46, Heikki Linnakangas wrote:
>>
>>> I think it should be reset even earlier, inside XlogReadTwoPhaseData()
>>> probably. With your patch, doesn't the LogStandbySnapshot() call just
>>> above where you're ressetting ThisTimeLineID also write a WAL record
>>> with incorrect timeline?
>>
>> Agreed.
> 
> Right.
> 
>> On Wed, Mar 3, 2021 at 1:04 AM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
>>
>>>> Even better, can we avoid setting ThisTimeLineID in XlogReadTwoPhaseData() in the first place?
>>>
>>>
>>>
>>> Or isn't it better to reset ThisTimeLineID in read_local_xlog_page(), i.e.,
>>> prevent read_local_xlog_page() from changing ThisTimeLineID? I'm not
>>> sure if that's possible, though.. In the future other functions that calls
>>> read_local_xlog_page() during the promotion may appear. Fixing the issue
>>> outside read_local_xlog_page() may cause those functions to get
>>> the same issue.
>>
>> I agree. We should fix the issue in read_local_xlog_page(). I have
>> attached two different patches which do so:
>> saved_ThisTimeLineID.patch and pass_ThisTimeLineID.patch.
>>
>> The former saves the value of the ThisTimeLineID before it gets changed
>> in read_local_xlog_page() and resets it after ThisTimeLineID has been
>> used later on in the code (by XLogReadDetermineTimeline()).
>>
>> The latter removes occurrences of ThisTimeLineID from
>> XLogReadDetermineTimeline() and introduces an argument currTLI to
>> XLogReadDetermineTimeline() to be used in its stead.
> 
> read_local_xlog_page() works as a part of logical decoding and has
> responsibility to update ThisTimeLineID properly.  As the comment in
> the function, it is the proper place to update ThisTimeLineID since we
> miss a timeline change if we check it earlier and the function uses
> the value just after. So we cannot change that behavior of the
> function.  That is, neither of them doesn't seem to be the right fix.

Could you tell me what actual issue happens if read_local_xlog_page() resets
ThisTimeLineID at the end? Some replication slot-related functions that use
read_local_xlog_page() can be executed even during recovery. For example,
you mean that, when timeline swithes during recovery, those functions
behave incorrectly if ThisTimeLineID is reset?

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

  9. Re: PITR promote bug: Checkpointer writes to older timeline

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-03-04T07:17:34Z

    At Thu, 4 Mar 2021 11:18:42 +0900, Michael Paquier <michael@paquier.xyz> wrote in 
> On Thu, Mar 04, 2021 at 10:28:31AM +0900, Kyotaro Horiguchi wrote:
> > read_local_xlog_page() works as a part of logical decoding and has
> > responsibility to update ThisTimeLineID properly.  As the comment in
> > the function, it is the proper place to update ThisTimeLineID since we
> > miss a timeline change if we check it earlier and the function uses
> > the value just after. So we cannot change that behavior of the
> > function.  That is, neither of them doesn't seem to be the right fix.
> > 
> > The confusion here is that there's two ThisTimeLineID's here. The
> > previous TLI for read and the next TLI to write.  Most part of the
> > function is needed to read a 2pc recrod so the ways we can take here
> > is:
> > 
> > 1. Somehow tell the function not to update ThisTimeLineID in specific
> >   cases. This can be done by xlogreader private data but this doesn't
> >   seem reasonable.
> > 
> > 2. Restore ThisTimeLineID after calling XLogReadRecord() in the
> >   *caller* side.  This is what came up to me first but I don't like
> >   this, too, but I don't find better fix.  way.
> 
> I have not looked in details at the solutions proposed here, but could
> it be possible to have a TAP test at least please?  Seeing the script
> from the top of the thread, it should not be difficult to do so.  I
> would put that in a file different than 009_twophase.pl, within
> src/test/recovery/.

Year, agreed. It is needed as the final patch. That situation is
easily caused. I'm not sure how to detect the corruption yet, though.
I'll consider that.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  10. Re: PITR promote bug: Checkpointer writes to older timeline

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-03-04T08:10:36Z

    At Thu, 4 Mar 2021 14:57:13 +0900, Fujii Masao <masao.fujii@oss.nttdata.com> wrote in 
> > read_local_xlog_page() works as a part of logical decoding and has
> > responsibility to update ThisTimeLineID properly.  As the comment in
> > the function, it is the proper place to update ThisTimeLineID since we
> > miss a timeline change if we check it earlier and the function uses
> > the value just after. So we cannot change that behavior of the
> > function.  That is, neither of them doesn't seem to be the right fix.
> 
> Could you tell me what actual issue happens if read_local_xlog_page()
> resets
> ThisTimeLineID at the end? Some replication slot-related functions
> that use
> read_local_xlog_page() can be executed even during recovery. For
> example,
> you mean that, when timeline swithes during recovery, those functions
> behave incorrectly if ThisTimeLineID is reset?

The most significant point for me was I'm not fully convinced that we
can safely (or validly) remove the fucntion to maintain the variable
from read_local_xlog_page.

> * RecoveryInProgress() will update ThisTimeLineID when it first
> * notices recovery finishes, so we only have to maintain it for the
> * local process until recovery ends.

read_local_xlog_page is *designed* to maintain ThisTimeLineID.
Currently it doesn't seem utilized but I think it's sufficiently
reasonable that the function maintains ThisTimeLineID.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  11. Re: PITR promote bug: Checkpointer writes to older timeline

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-03-04T08:17:15Z

    At Thu, 04 Mar 2021 16:17:34 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> At Thu, 4 Mar 2021 11:18:42 +0900, Michael Paquier <michael@paquier.xyz> wrote in 
> > I have not looked in details at the solutions proposed here, but could
> > it be possible to have a TAP test at least please?  Seeing the script
> > from the top of the thread, it should not be difficult to do so.  I
> > would put that in a file different than 009_twophase.pl, within
> > src/test/recovery/.

Isn't 004_timeline_switch.pl the place?

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  12. Re: PITR promote bug: Checkpointer writes to older timeline

    Soumyadeep Chakraborty <soumyadeep2007@gmail.com> — 2021-03-04T23:42:05Z

    Hey all,

I took a stab at a quick and dirty TAP test (my first ever). So it
can probably be improved a lot. Please take a look.

On Thu, Mar 04, 2021 at 10:28:31AM +0900, Kyotaro Horiguchi wrote:

> 2. Restore ThisTimeLineID after calling XLogReadRecord() in the
>   *caller* side.  This is what came up to me first but I don't like
>   this, too, but I don't find better fix.  way.

+1 to this patch [1].
The above TAP test passes with this patch applied.

[1] https://www.postgresql.org/message-id/attachment/119972/dont_change_thistimelineid.patch

Regards,
Soumyadeep

Regards,
Soumyadeep

  13. Re: PITR promote bug: Checkpointer writes to older timeline

    Soumyadeep Chakraborty <soumyadeep2007@gmail.com> — 2021-03-13T20:29:06Z

    Hello,

PFA version 2 of the TAP test. I removed the non-deterministic sleep
and introduced retries until the WAL segment is archived and promotion
is complete. Some additional tidying up too.

Regards,
Soumyadeep (VMware)

  14. Re: PITR promote bug: Checkpointer writes to older timeline

    Michael Paquier <michael@paquier.xyz> — 2021-03-14T08:59:59Z

    On Thu, Mar 04, 2021 at 05:10:36PM +0900, Kyotaro Horiguchi wrote:
> read_local_xlog_page is *designed* to maintain ThisTimeLineID.
> Currently it doesn't seem utilized but I think it's sufficiently
> reasonable that the function maintains ThisTimeLineID.

I don't quite follow this line of thoughts.  ThisTimeLineID is
designed to remain 0 while recovery is running in most processes
(at the close exception of a WAL sender with a cascading setup,
physical or logical, of course), so why is there any business for
read_local_xlog_page() to touch this field at all while in recovery to
begin with?

I equally find confusing that XLogReadDetermineTimeline() relies on a
specific value of ThisTimeLineID in its own logic, while it clearly
states that all its callers have to read the current active TLI
beforehand.  So I think that the existing logic is pretty weak, and
that resetting the field is an incorrect approach?  It seems to me
that we had better not change ThisTimeLineID actively while in
recovery in this code path and just let others do the job, like
RecoveryInProgress() once recovery finishes, or
GetStandbyFlushRecPtr() for a WAL sender.  And finally, we should
store the current TLI used for replay in a separate variable that gets
passed down to the XLogReadDetermineTimeline() as argument.

While going through it, I have simplified a bit the proposed TAP tests
(thanks for replacing the sleep() call, Soumyadeep.  This would have
made the test slower for nothing on fast machines, and it would cause
failures on very slow machines).

The attached fixes the original issue for me, keeping all the records
in their correct timeline.  And I have not been able to break
cascading setups.  If it happens that such cases actually break, we
have holes in our existing test coverage that should be improved.  I
cannot see anything fancy missing on this side, though.

Any thoughts?
--
Michael

  15. Re: PITR promote bug: Checkpointer writes to older timeline

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-03-15T06:01:09Z

    At Sun, 14 Mar 2021 17:59:59 +0900, Michael Paquier <michael@paquier.xyz> wrote in 
> On Thu, Mar 04, 2021 at 05:10:36PM +0900, Kyotaro Horiguchi wrote:
> > read_local_xlog_page is *designed* to maintain ThisTimeLineID.
> > Currently it doesn't seem utilized but I think it's sufficiently
> > reasonable that the function maintains ThisTimeLineID.
> 
> I don't quite follow this line of thoughts.  ThisTimeLineID is
> designed to remain 0 while recovery is running in most processes
> (at the close exception of a WAL sender with a cascading setup,

The reason for the "0" is they just aren't interested in the value.
Checkpointer temporarily uses it then restore to 0 soon.

> physical or logical, of course), so why is there any business for
> read_local_xlog_page() to touch this field at all while in recovery to
> begin with?

Logical decoding stuff is (I think) designed to turn any backend into
a walsender, which may need to maintain ThisTimeLineID.  It seems to
me that logical decoding stuff indents to maintain ThisTimeLineID of
such backends at reading a WAL record. logical_read_xlog_page also
updates ThisTimeLineID and pg_logical_slot_get_changes_guts(),
pg_replication_slot_advance() (and maybe other functions) updates
ThisTimeLineID. So it is natural that local_read_xlog_page() updates
it since it is intended to be used used in logical decoding plugins.

> I equally find confusing that XLogReadDetermineTimeline() relies on a
> specific value of ThisTimeLineID in its own logic, while it clearly
> states that all its callers have to read the current active TLI
> beforehand.  So I think that the existing logic is pretty weak, and
> that resetting the field is an incorrect approach?  It seems to me

It is initialized by IndentifySystem(). And the logical walsender
intends to maintain ThisTimeLineID by subsequent calls to
GetStandbyFlushRecPtr(), which happen in logical_read_xlog_page().

> that we had better not change ThisTimeLineID actively while in
> recovery in this code path and just let others do the job, like
> RecoveryInProgress() once recovery finishes, or
> GetStandbyFlushRecPtr() for a WAL sender.  And finally, we should
> store the current TLI used for replay in a separate variable that gets
> passed down to the XLogReadDetermineTimeline() as argument.

I agree that it's better that the replay TLI is stored in a separate
variable. It is what I was complained on in the previous mails. (It
might not have been so obvious, though..)

> While going through it, I have simplified a bit the proposed TAP tests
> (thanks for replacing the sleep() call, Soumyadeep.  This would have
> made the test slower for nothing on fast machines, and it would cause
> failures on very slow machines).
> 
> The attached fixes the original issue for me, keeping all the records
> in their correct timeline.  And I have not been able to break
> cascading setups.  If it happens that such cases actually break, we
> have holes in our existing test coverage that should be improved.  I
> cannot see anything fancy missing on this side, though.
> 
> Any thoughts?

I don't think there's any acutual user of the function for the
purpose, but..  Anyawy if we remove the update of ThisTimeLineID from
read_local_xlog_page, I think we should remove or rewrite the
following comment for the function.  It no longer works as written in
the catchphrase.

> * Public because it would likely be very helpful for someone writing another
> * output method outside walsender, e.g. in a bgworker.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  16. Re: PITR promote bug: Checkpointer writes to older timeline

    Michael Paquier <michael@paquier.xyz> — 2021-03-15T07:38:08Z

    On Mon, Mar 15, 2021 at 03:01:09PM +0900, Kyotaro Horiguchi wrote:
> Logical decoding stuff is (I think) designed to turn any backend into
> a walsender, which may need to maintain ThisTimeLineID.  It seems to
> me that logical decoding stuff indents to maintain ThisTimeLineID of
> such backends at reading a WAL record. logical_read_xlog_page also
> updates ThisTimeLineID and pg_logical_slot_get_changes_guts(),
> pg_replication_slot_advance() (and maybe other functions) updates
> ThisTimeLineID. So it is natural that local_read_xlog_page() updates
> it since it is intended to be used used in logical decoding plugins.

Logical decoding contexts cannot be created while in recovery as per
CheckLogicalDecodingRequirements(), and as mentioned not everything is
in place to allow that.  FWIW, I think that it is just confusing for
pg_replication_slot_advance() and pg_logical_slot_get_changes_guts()
to update it, and we just look for the latest value each time it is
necessary when reading a new WAL page.

> It is initialized by IndentifySystem(). And the logical walsender
> intends to maintain ThisTimeLineID by subsequent calls to
> GetStandbyFlushRecPtr(), which happen in logical_read_xlog_page().

I don't understand this part about logical_read_xlog_page(), though.
Do you mean a different routine or a different code path?

> I agree that it's better that the replay TLI is stored in a separate
> variable. It is what I was complained on in the previous mails. (It
> might not have been so obvious, though..)

Okay.  I understood that this was what you implied.

> I don't think there's any acutual user of the function for the
> purpose, but..  Anyawy if we remove the update of ThisTimeLineID from
> read_local_xlog_page, I think we should remove or rewrite the
> following comment for the function.  It no longer works as written in
> the catchphrase.

Who knows.  We cannot know all the users of this code, and the API is
public.

> > * Public because it would likely be very helpful for someone writing another
> > * output method outside walsender, e.g. in a bgworker.

I don't see a reason to remove this comment as this routine can still
be useful for many purposes.  What kind of rewording do you have in
mind?
--
Michael

  17. Re: PITR promote bug: Checkpointer writes to older timeline

    Michael Paquier <michael@paquier.xyz> — 2021-03-17T08:09:50Z

    On Mon, Mar 15, 2021 at 04:38:08PM +0900, Michael Paquier wrote:
> On Mon, Mar 15, 2021 at 03:01:09PM +0900, Kyotaro Horiguchi wrote:
>> Logical decoding stuff is (I think) designed to turn any backend into
>> a walsender, which may need to maintain ThisTimeLineID.  It seems to
>> me that logical decoding stuff indents to maintain ThisTimeLineID of
>> such backends at reading a WAL record. logical_read_xlog_page also
>> updates ThisTimeLineID and pg_logical_slot_get_changes_guts(),
>> pg_replication_slot_advance() (and maybe other functions) updates
>> ThisTimeLineID. So it is natural that local_read_xlog_page() updates
>> it since it is intended to be used used in logical decoding plugins.
>
> Logical decoding contexts cannot be created while in recovery as per
> CheckLogicalDecodingRequirements(), and as mentioned not everything
> is
> in place to allow that.  FWIW, I think that it is just confusing for
> pg_replication_slot_advance() and pg_logical_slot_get_changes_guts()
> to update it, and we just look for the latest value each time it is
> necessary when reading a new WAL page.

Studying some history today, having read_local_xlog_page() directly
update ThisTimeLineID has been extensively discussed here back in 2017
to attempt to introduce logical decoding on standbys (1148e22a):
https://www.postgresql.org/message-id/CAMsr%2BYEVmBJ%3DdyLw%3D%2BkTihmUnGy5_EW4Mig5T0maieg_Zu%3DXCg%40mail.gmail.com

Currently with HEAD and back branches, nothing would be broken as
logical contexts cannot exist in recovery.  Still it would be easy
to miss the new behavior for anybody attempting to work more on this
feature in the future if we change read_local_xlog_page to not update
ThisTimeLineID anymore.  Resetting the value of ThisTimeLineID in
read_local_xlog_page() does not seem completely right either with this
argument, as they could be some custom code relying on the existing
behavior of read_local_xlog_page() to maintain ThisTimeLineID.

Hmmm.  I am wondering whether the best answer for the moment would not
be to save and reset ThisTimeLineID just in XlogReadTwoPhaseData(), as
that's the local change that uses read_local_xlog_page().

The state of the code is really confusing on HEAD, and I'd like to
think that the best thing we could do in the long-term is to make the
logical decoding path not rely on ThisTimeLineID at all and decouple
all that, putting the code in a state sane enough so as we don't
finish with similar errors as what is discussed on this thread.  That
would be a work for a different patch though, not for stable
branches.  And seeing some slot and advancing functions update
directly ThisTimeLineID is no good either..

Any thoughts?
--
Michael

  18. Re: PITR promote bug: Checkpointer writes to older timeline

    Michael Paquier <michael@paquier.xyz> — 2021-03-18T03:56:12Z

    On Wed, Mar 17, 2021 at 05:09:50PM +0900, Michael Paquier wrote:
> Currently with HEAD and back branches, nothing would be broken as
> logical contexts cannot exist in recovery.  Still it would be easy
> to miss the new behavior for anybody attempting to work more on this
> feature in the future if we change read_local_xlog_page to not update
> ThisTimeLineID anymore.  Resetting the value of ThisTimeLineID in
> read_local_xlog_page() does not seem completely right either with this
> argument, as they could be some custom code relying on the existing
> behavior of read_local_xlog_page() to maintain ThisTimeLineID.

I was looking at uses of ThisTimeLineID in the wild, and could not
find it getting checked or used actually in backend-side code that
involved the WAL reader facility.  Even if it brings confidence, it
does not mean that it is not used somewhere :/

> Hmmm.  I am wondering whether the best answer for the moment would not
> be to save and reset ThisTimeLineID just in XlogReadTwoPhaseData(), as
> that's the local change that uses read_local_xlog_page().

And attached is the patch able to achieve that.  At least it is
simple, and does not break the actual assumptions this callback relies
on.  This is rather weak though if there are errors as this is out of
critical sections, still the disease is worse.  I have double-checked
all the existing backend code that uses XLogReadRecord(), and did not
notice any code paths with issues similar to this one.

> The state of the code is really confusing on HEAD, and I'd like to
> think that the best thing we could do in the long-term is to make the
> logical decoding path not rely on ThisTimeLineID at all and decouple
> all that, putting the code in a state sane enough so as we don't
> finish with similar errors as what is discussed on this thread.  That
> would be a work for a different patch though, not for stable
> branches.  And seeing some slot and advancing functions update
> directly ThisTimeLineID is no good either..

However, I'd like to think that we should completely untie the
dependency to ThisTimeLineID in any page read callbacks in core in the
long-term, and potentially clean up any assumptions behind timeline
jumps while in recovery for logical contexts as that cannot happen.
At this stage of the 14 dev cycle, that would be material for 15~, but
I also got to wonder if there is work going on to support logical
decoding on standbys, in particular if this would really rely on
ThisTimeLineID.

Thoughts are welcome.
--
Michael

  19. Re: PITR promote bug: Checkpointer writes to older timeline

    Michael Paquier <michael@paquier.xyz> — 2021-03-22T00:07:19Z

    On Thu, Mar 18, 2021 at 12:56:12PM +0900, Michael Paquier wrote:
> I was looking at uses of ThisTimeLineID in the wild, and could not
> find it getting checked or used actually in backend-side code that
> involved the WAL reader facility.  Even if it brings confidence, it
> does not mean that it is not used somewhere :/

I have been working on that over the last couple of days, and applied
a fix down to 10.  One thing that I did not like in the test was the
use of compare() to check if the contents of the WAL segment before
and after the timeline jump remained the same as this would have been
unstable with any concurrent activity.  Instead, I have added a phase
at the end of the test with an extra checkpoint and recovery triggered
once, which is enough to reproduce the PANIC reported at the top of
the thread.

I'll look into clarifying the use of ThisTimeLineID within the those
WAL reader callbacks, because this is really bug-prone in the long
term...  This requires some coordination with the recent work aimed at
adding some logical decoding support in standbys, though.
--
Michael

  20. Re: PITR promote bug: Checkpointer writes to older timeline

    Tom Lane <tgl@sss.pgh.pa.us> — 2021-06-27T18:35:24Z

    Michael Paquier <michael@paquier.xyz> writes:
> I have been working on that over the last couple of days, and applied
> a fix down to 10.  One thing that I did not like in the test was the
> use of compare() to check if the contents of the WAL segment before
> and after the timeline jump remained the same as this would have been
> unstable with any concurrent activity.  Instead, I have added a phase
> at the end of the test with an extra checkpoint and recovery triggered
> once, which is enough to reproduce the PANIC reported at the top of
> the thread.

Buildfarm member hornet just reported a failure in this test:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hornet&dt=2021-06-27%2013%3A40%3A57

the critical bit being

2021-06-27 17:35:46.504 UTC [11862234:1] [unknown] LOG:  connection received: host=[local]
2021-06-27 17:35:46.505 UTC [18350260:12] LOG:  recovering prepared transaction 734 from shared memory
TRAP: FailedAssertion("TransactionIdPrecedesOrEquals(TransactionXmin, RecentXmin)", File: "procarray.c", Line: 2492, PID: 11862234)
2021-06-27 17:35:46.511 UTC [14876838:4] LOG:  database system is ready to accept connections

It's not clear whether this is a problem with the test case or an
actual server bug, but I'm leaning to the latter theory.  My gut
feel is it's some problem in the "snapshot scalability" work.  It
doesn't look the same as the known open issue, but maybe related?

			regards, tom lane

  21. Re: PITR promote bug: Checkpointer writes to older timeline

    Tom Lane <tgl@sss.pgh.pa.us> — 2021-06-27T19:13:20Z

    I wrote:
> Buildfarm member hornet just reported a failure in this test:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hornet&dt=2021-06-27%2013%3A40%3A57
> It's not clear whether this is a problem with the test case or an
> actual server bug, but I'm leaning to the latter theory.  My gut
> feel is it's some problem in the "snapshot scalability" work.  It
> doesn't look the same as the known open issue, but maybe related?

Hmm, the plot thickens.  I scraped the buildfarm logs for similar-looking
assertion failures back to last August, when the snapshot scalability
patches went in.  The first such failure is not until 2021-03-24
(see attachment), and they all look to be triggered by
023_pitr_prepared_xact.pl.  It sure looks like recovering a prepared
transaction creates a transient state in which a new backend will
compute a broken snapshot.

			regards, tom lane

  22. Re: PITR promote bug: Checkpointer writes to older timeline

    Tom Lane <tgl@sss.pgh.pa.us> — 2021-06-27T19:20:50Z

    I wrote:
> It sure looks like recovering a prepared
> transaction creates a transient state in which a new backend will
> compute a broken snapshot.

Oh, after further digging this is the same issue discussed here:

https://www.postgresql.org/message-id/flat/20210422203603.fdnh3fu2mmfp2iov%40alap3.anarazel.de

			regards, tom lane