MIME-Version: 1.0
References: <1d12d2-67235980-35-19a406a0@63439497>
 <CAPpHfdtp61pSt72KxxOnnV_Oj4OTAiKYCSTek0Pm87hVDod4Bg@mail.gmail.com>
 <CAA4eK1Lmd-stXWrNqX9iXugjY=ahhe7zRfyq+-vN512xvF4G2w@mail.gmail.com>
 <CAPpHfdsTiYQPywr4yeqVhUtA+eFdqisqcAOiTb+kiYhi9EVEvw@mail.gmail.com>
 <CAPpHfdvk-nfu5xzJyPArxWctofWPR+1L9uJ+yyWFA34n6b5rGQ@mail.gmail.com>
 <CAA4eK1Ladnm40UO-YC+c7eBYqjyFQSwg0dn1w_CiaMoBTsJUDA@mail.gmail.com>
 <CAPpHfduX--KKX853UwaJ8Cjo5bxbh19V_+McKQ3p9aS6b8T1Wg@mail.gmail.com>
 <CAA4eK1+VbBxYY-rG4B7Jq6TsYvdjt3d2nbUrs7p9-1sP5mH+sw@mail.gmail.com>
 <CAPpHfdvxqjE+RZdoOODQZAmQip6NpvSH40DuvVFWuf_00ek-yQ@mail.gmail.com>
 <1d97ec-6841b600-3-b7b4780@40747246>
 <CAA4eK1LvssAcp61qg957xRF0=K4xF0hfJQjQ6c9V7EGHSqraPg@mail.gmail.com>
 <28c8bf-68470780-3-51b29480@89454035>
 <CAPpHfdt77k3BqD=anh4b7UiRevfPOu2Hcf3rvSZXntxH+4G=Ug@mail.gmail.com>
 <fbc5d94e-6fbd-4a64-85d4-c9e284a58eb2@gmail.com>
 <CAPpHfdvPpg5VUTNOqfKSNx66ij3ZJNZbf4kn6SDcPkdq9FTvng@mail.gmail.com>
 <0a617d34-abc3-4090-92a5-ea15d45e36f6@gmail.com>
 <228607.1750003556@sss.pgh.pa.us>
 <CAPpHfdvJMe4i0_wp1tq2ZGSDKqUHKPwkfD_Y6KyJ3XQRFvc0cQ@mail.gmail.com>
 <OSCPR01MB1496667BEA93302F8903EE512F570A@OSCPR01MB14966.jpnprd01.prod.outlook.com>
 <CAPpHfdsdJ4YPTzH=cnany5_LjCNb_Z9e+Oucv53qYQHaHzJhag@mail.gmail.com>
 <CALDaNm3s-jpQTe1MshsvQ8GO=TLj233JCdkQ7uZ6pwqRVpxAdw@mail.gmail.com>
 <3f242e-68518380-11-78125f00@134027639>
 <CAPpHfds0ScFbExsT+pnY7K0JGH6pFPHMOSfCOknC-1s7ahmRFA@mail.gmail.com>
 <214ba-6852df80-9-7e0df800@134698799> <21b44-6852e000-3-a556820@87831171>
 <CAPpHfdv3UEUBjsLhB_CwJT0xX9LmN6U+__myYopq4KcgvCSbTg@mail.gmail.com>
 <CAA4eK1+qL9QFOD2Q5kcq0Ff=7OcBLE34QuDBdPcdznUzQwv+eg@mail.gmail.com>
 <OSCPR01MB1496646E4CF72B9231DB711AFF57DA@OSCPR01MB14966.jpnprd01.prod.outlook.com>
 <CAPpHfdvjGWo--xqqjJbyb_amdkhqamnzrwCZWe_hBD-rSTFbBg@mail.gmail.com>
 <CALDaNm1prhebmnAY_0=5UJ-WodSSbj6C8X-igrGa1EamtLw5BA@mail.gmail.com>
 <CAPpHfdsyzHvG1OSEBVc9LWoRyLehXxL3QQRH3tO0Xvir9uKwmg@mail.gmail.com>
 <CALDaNm3cBTVX7fd+3bfQ5QZmt5=nQ5zE_kDcFEpDaWwhoxOH+w@mail.gmail.com>
In-Reply-To: 
 <CALDaNm3cBTVX7fd+3bfQ5QZmt5=nQ5zE_kDcFEpDaWwhoxOH+w@mail.gmail.com>
From: Alexander Korotkov <aekorotkov@gmail.com>
Date: Mon, 23 Jun 2025 21:50:50 +0300
Message-ID: 
 <CAPpHfdvvhV0WA0fkWFJobMQwS33s7GpB2rH5ZUSSsntPKNPEKg@mail.gmail.com>
Subject: Re: Slot's restart_lsn may point to removed WAL segment after hard
 restart unexpectedly
To: vignesh C <vignesh21@gmail.com>
Cc: "Hayato Kuroda (Fujitsu)" <kuroda.hayato@fujitsu.com>,
 Amit Kapila <amit.kapila16@gmail.com>,
	Vitaly Davydov <v.davydov@postgrespro.ru>, Tom Lane <tgl@sss.pgh.pa.us>,
	Alexander Lakhin <exclusion@gmail.com>,
 pgsql-hackers <pgsql-hackers@postgresql.org>,
	Masahiko Sawada <sawada.mshk@gmail.com>, "tomas@vondra.me" <tomas@vondra.me>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: 
 <https://www.postgresql.org/message-id/CAPpHfdvvhV0WA0fkWFJobMQwS33s7GpB2rH5ZUSSsntPKNPEKg%40mail.gmail.com>
Precedence: bulk

On Mon, Jun 23, 2025 at 8:04=E2=80=AFPM vignesh C <vignesh21@gmail.com> wro=
te:
>
> On Mon, 23 Jun 2025 at 04:36, Alexander Korotkov <aekorotkov@gmail.com> w=
rote:
> >
> > On Fri, Jun 20, 2025 at 2:24=E2=80=AFPM vignesh C <vignesh21@gmail.com>=
 wrote:
> > > On Fri, 20 Jun 2025 at 05:54, Alexander Korotkov <aekorotkov@gmail.co=
m> wrote:
> > > > Dear Kuroda-san,
> > > >
> > > > On Thu, Jun 19, 2025 at 2:05=E2=80=AFPM Hayato Kuroda (Fujitsu)
> > > > <kuroda.hayato@fujitsu.com> wrote:
> > > > > > > Regarding assertion failure, I've found that assert in
> > > > > > > PhysicalConfirmReceivedLocation() conflicts with restart_lsn
> > > > > > > previously set by ReplicationSlotReserveWal().  As I can see,
> > > > > > > ReplicationSlotReserveWal() just picks fresh XLogCtl->RedoRec=
Ptr lsn.
> > > > > > > So, it doesn't seems there is a guarantee that restart_lsn ne=
ver goes
> > > > > > > backward.  The commit in ReplicationSlotReserveWal() even sta=
tes there
> > > > > > > is a "chance that we have to retry".
> > > > > > >
> > > > > >
> > > > > > I don't see how this theory can lead to a restart_lsn of a slot=
 going
> > > > > > backwards. The retry mentioned there is just a retry to reserve=
 the
> > > > > > slot's position again if the required WAL is already removed. S=
uch a
> > > > > > retry can only get the position later than the previous restart=
_lsn.
> > > > >
> > > > > We analyzed the assertion failure happened at pg_basebackup/020_p=
g_receivewal,
> > > > > and confirmed that restart_lsn can go backward. This meant that A=
ssert() added
> > > > > by the ca307d5 can cause crash.
> > > > >
> > > > > Background
> > > > > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> > > > > When pg_receivewal starts the replication and it uses the replica=
tion slot, it
> > > > > sets as the beginning of the segment where restart_lsn exists, as=
 the startpoint.
> > > > > E.g., if the restart_lsn of the slot is 0/B000D0, pg_receivewal r=
equests WALs
> > > > > from 0/B00000.
> > > > > More detail of this behavior, see f61e1dd2 and d9bae531.
> > > > >
> > > > > What happened here
> > > > > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> > > > > Based on above theory, walsender sent from the beginning of segme=
nt (0/B00000).
> > > > > When walreceiver receives, it tried to send reply. At that time t=
he flushed
> > > > > location of WAL would be 0/B00000. walsender sets the received ls=
n as restart_lsn
> > > > > in PhysicalConfirmReceivedLocation(). Here the restart_lsn went b=
ackward (0/B000D0->0/B00000).
> > > > >
> > > > > The assertion failure could happen if CHECKPOINT happened at that=
 time.
> > > > > Attribute last_saved_restart_lsn of the slot was 0/B000D0, but th=
e data.restart_lsn
> > > > > was 0/B00000. It could not satisfy the assertion added in Invalid=
atePossiblyObsoleteSlot().
> > > >
> > > > Thank you for your detailed explanation!
> > > >
> > > > > Note
> > > > > =3D=3D=3D=3D
> > > > > 1.
> > > > > In this case, starting from the beginning of the segment is not a=
 problem, because
> > > > > the checkpoint process only removes WAL files from segments that =
precede the
> > > > > restart_lsn's wal segment. The current segment (0/B00000) will no=
t be removed,
> > > > > so there is no risk of data loss or inconsistency.
> > > > >
> > > > > 2.
> > > > > A similar pattern applies to pg_basebackup. Both use logic that a=
djusts the
> > > > > requested streaming position to the start of the segment, and it =
replies the
> > > > > received LSN as flushed.
> > > > >
> > > > > 3.
> > > > > I considered the theory above, but I could not reproduce 040_stan=
dby_failover_slots_sync
> > > > > because it is a timing issue. Have someone else reproduced?
> > > > >
> > > > > We are still investigating failure caused at 040_standby_failover=
_slots_sync.
> > > >
> > > > I didn't manage to reproduce this.  But as I see from the logs [1] =
on
> > > > mamba that START_REPLICATION command was issued just before assert
> > > > trap.  Could it be something similar to what I described in [2].
> > > > Namely:
> > > > 1. ReplicationSlotReserveWal() sets restart_lsn for the slot.
> > > > 2. Concurrent checkpoint flushes that restart_lsn to the disk.
> > > > 3. PhysicalConfirmReceivedLocation() sets restart_lsn of the slot t=
o
> > > > the beginning of the segment.
> > >
> > > Here is my analysis for the 040_standby_failover_slots_sync test
> > > failure where the physical replication slot can point to backward lsn=
:
> > > In certain rare cases the restart LSN can go backwards. This scenario
> > > can be reproduced by performing checkpoint continuously and slowing
> > > the WAL applying. I have a patch with changes to handle this.
> > > Here's a summary of the sequence of events:
> > > 1) Standby confirms a new LSN (0/40369C8) when primary sends some WAL=
 contents:
> > > After the standby writes the received WAL contents in XLogWalRcvWrite=
,
> > > the standby sends this lsn 0/40369C8 as the confirmed flush location.
> > > The primary acknowledges this and updates the replication slot's
> > > restart_lsn accordingly:
> > > 2025-06-20 14:33:21.777 IST [134998] standby1 LOG:
> > > PhysicalConfirmReceivedLocation replication slot "sb1_slot" set
> > > restart_lsn to 0/40369C8
> > > 2025-06-20 14:33:21.777 IST [134998] standby1 STATEMENT:
> > > START_REPLICATION SLOT "sb1_slot" 0/3000000 TIMELINE 1
> > >
> > > 2) Shortly after receiving the new LSN, a checkpoint occurs which
> > > saves this restart_lsn:
> > > 2025-06-20 14:33:21.780 IST [134913] LOG:  checkpoint complete: wrote
> > > 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL file(s) added, 0
> > > removed, 0 recycled; write=3D0.001 s, sync=3D0.001 s, total=3D0.002 s=
; sync
> > > files=3D0, longest=3D0.000 s, average=3D0.000 s; distance=3D0 kB, est=
imate=3D0
> > > kB; lsn=3D0/4036A20, redo lsn=3D0/40369C8
> > >
> > > 3) Streaming replication is restarted because of primary_conninfo guc
> > > change and reload
> > > The WAL receiver process is restarted:
> > > 25-06-20 14:33:21.779 IST [134997] FATAL: terminating walreceiver
> > > process due to administrator command
> > >
> > > 4) Standby sends an older flush pointer after restart:
> > > Upon restart, the WAL receiver sends a flush location (0/401D448)
> > > derived from XLogRecoveryCtl->lastReplayedEndRecPtr, which is older
> > > than the previously confirmed restart_lsn. It is important to note
> > > that we are sending the lastReplayedEndRecPtr which is the last
> > > successfully replayed lsn in this case:
> > > 5-06-20 14:33:21.796 IST [135135] LOG:  WalReceiverMain
> > > LogstreamResult.Flush initialized to 0/401D448
> > > 2025-06-20 14:33:21.796 IST [135135] LOG:  sending write 0/401D448
> > > flush 0/401D448 apply 0/401D448
> > >
> > > This is done from here:
> > > ....
> > > /* Initialize LogstreamResult and buffers for processing messages */
> > > LogstreamResult.Write =3D LogstreamResult.Flush =3D GetXLogReplayRecP=
tr(NULL);
> > >
> > > initStringInfo(&reply_message);
> > >
> > > /* Initialize nap wakeup times. */
> > > now =3D GetCurrentTimestamp();
> > > for (int i =3D 0; i < NUM_WALRCV_WAKEUPS; ++i)
> > > WalRcvComputeNextWakeup(i, now);
> > >
> > > /* Send initial reply/feedback messages. */
> > > XLogWalRcvSendReply(true, false);
> > > ...
> > >
> > > In case of step 1, we are sending the lsn of the WAL that is written,
> > > since we have slowed down the WAL applying the replay location is
> > > lesser.
> > >
> > > 5) I have added logs to detect this inconsistency:
> > > This leads to a scenario where the standby tries to confirm a
> > > restart_lsn older than the one currently held by the primary:
> > > 2025-06-20 14:33:21.797 IST [135136] standby1 LOG:  crash scenario -
> > > slot sb1_slot, cannot confirm a restart LSN (0/401D448) that is older
> > > than the current one (0/40369C8)
> > >
> > > If a checkpoint happens concurrently during this condition, it may
> > > trigger an assertion failure on the primary due to the restart_lsn
> > > being less than the last_saved_restart_lsn.
> > > Currently this does not break physical replication, but I'm not sure
> > > if the gap increases to many WAL files and if the WAL files get
> > > deleted, how it will behave.
> > >
> > > Attached the restart_lsn_backup_repro_v1 patch changes with which you
> > > can reproduce the 040_standby_failover_slots_sync failure. grep for
> > > "crash scenario - slot sb1_slot" in the logs. For me it occurs with
> > > every run. The reproduced logs
> > > 040_standby_failover_slots_sync_publisher and
> > > 040_standby_failover_slots_sync_standby1.log are attached.
> > >
> > > This proves that the restart_lsn can go backward in cases where the
> > > standby is slowly applying. But this has nothing to do with this
> > > thread, I felt you can commit the assert removal patch. I will
> > > continue the analysis further and see if there is any impact or not o=
n
> > > physical replication, and we can later add comments accordingly.
> >
> > I think this thread now have well-documented cases when restart_lsn
> > goes backward.  I suppose the first thing we should do is to remove
> > the assert to make buildfarm stop failing on this.  I've prepared a
> > patch with revised commit message.  Then we can focus on documenting
> > that correctly in the code comments.
>
> +1 to proceed this way, one minor suggestion we can include
> pg_basebackup also in the commit message as I noticed this can happen
> with pg_basebackup too.

Thank you!  Pushed including your suggestion to mention pg_basebackup.

------
Regards,
Alexander Korotkov
Supabase