Обсуждение: confirmed flush lsn seems to be move backward in certain error cases

Hi,

The following assertion failure was seen while testing one scenario
for other patch:
TRAP: failed Assert("s->data.confirmed_flush >=
s->last_saved_confirmed_flush"), File: "slot.c", Line: 1760, PID:
545314
postgres: checkpointer performing shutdown
checkpoint(ExceptionalCondition+0xbb)[0x564ee6870c58]
postgres: checkpointer performing shutdown
checkpoint(CheckPointReplicationSlots+0x18e)[0x564ee65e9c71]
postgres: checkpointer performing shutdown checkpoint(+0x1e1403)[0x564ee61be403]
postgres: checkpointer performing shutdown
checkpoint(CreateCheckPoint+0x78a)[0x564ee61bdace]
postgres: checkpointer performing shutdown
checkpoint(ShutdownXLOG+0x150)[0x564ee61bc735]
postgres: checkpointer performing shutdown checkpoint(+0x5ae28c)[0x564ee658b28c]
postgres: checkpointer performing shutdown
checkpoint(CheckpointerMain+0x31e)[0x564ee658ad55]
postgres: checkpointer performing shutdown
checkpoint(AuxiliaryProcessMain+0x1d1)[0x564ee65888d9]
postgres: checkpointer performing shutdown checkpoint(+0x5b7200)[0x564ee6594200]
postgres: checkpointer performing shutdown
checkpoint(PostmasterMain+0x14da)[0x564ee658f12f]
postgres: checkpointer performing shutdown checkpoint(+0x464fc6)[0x564ee6441fc6]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7ff6afa29d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7ff6afa29e40]
postgres: checkpointer performing shutdown
checkpoint(_start+0x25)[0x564ee60b8e05]

I was able to reproduce this issue with the following steps:
-- Setup
-- Publisher node:
create table t1(c1 int);
create table t2(c1 int);
create publication pub1 for table t1;
create publication pub2 for table t2;

-- Subscriber node:
create table t1(c1 int);
create table t2(c1 int);
create subscription test1 connection 'dbname=postgres host=localhost
port=5432' publication pub1, pub2;
select * from pg_subscription;

-- Actual test
insert into t1 values(10);
insert into t2 values(20);
select pg_sleep(10);
drop publication pub2;
insert into t1 values(10);
insert into t2 values(20);

Stop the publisher to see the assertion.

For me the issue reproduces about twice in five times using the
assert_failure.sh script attached.

After the insert operation is replicated to the subscriber, the
subscriber will set the lsn value sent by the publisher in the
replication origin (in my case it was 0/1510978). publisher will then
send keepalive messages with the current WAL position in the publisher
(in my case it was 0/15109B0), but subscriber will simply send this
position as the flush_lsn to the publisher as there are no ongoing
transactions. Then since the publisher is started, it will identify
that publication does not exist and stop the walsender/apply worker
process. When the apply worker is restarted, we will get the
remote_lsn(in my case it was 0/1510978) of the origin and set it to
origin_startpos. We will start the apply worker with this
origin_startpos (origin's remote_lsn). This position will be sent as
feedback to the walsender process from the below stack:
run_apply_worker->start_apply->LogicalRepApplyLoop->send_feedback.
It will use the following send_feedback function call of
LogicalRepApplyLoop function as in below code here as nothing is
received from walsender:
LogicalRepApplyLoop function
.......
len = walrcv_receive(LogRepWorkerWalRcvConn, &buf, &fd);
if (len != 0)
{
               /* Loop to process all available data (without blocking). */
               for (;;)
               {
                              CHECK_FOR_INTERRUPTS();
                              ...
               }
}

/* confirm all writes so far */
send_feedback(last_received, false, false);
.......

In send_feedback, we will set flushpos to replication origin's
remote_lsn and send it to the walsender process. Walsender process
will receive this information and set confirmed_flush in:
ProcessStandbyReplyMessage->LogicalConfirmReceivedLocation

Then immediately we are trying to stop the publisher instance,
shutdown checkpoint process will be triggered. In this case:
confirmed_flush = 0/1510978 will be lesser than
last_saved_confirmed_flush = 0/15109B0 which will result in Assertion
failure.

This issue is happening because we allow setting the confirmed_flush
to a backward position.
There are a couple of ways to fix this:
a) One way it not to update the confirm_flush if the lsn sent is an
older value like in Confirm_flush_dont_allow_backward.patch
b) Another way is to remove the assertion in
CheckPointReplicationSlots and marking the slot as dirty only if
confirmed_flush is greater than last_saved_confirmed_flush like in
Assert_confirmed_flush_will_always_not_be_less_than_last_saved_confirmed_flush.patch

I preferred the first approach.

Thoughts?

Regards,
Vignesh

On Fri, Feb 16, 2024 at 5:53 PM vignesh C <vignesh21@gmail.com> wrote:
>
>
> After the insert operation is replicated to the subscriber, the
> subscriber will set the lsn value sent by the publisher in the
> replication origin (in my case it was 0/1510978). publisher will then
> send keepalive messages with the current WAL position in the publisher
> (in my case it was 0/15109B0), but subscriber will simply send this
> position as the flush_lsn to the publisher as there are no ongoing
> transactions. Then since the publisher is started, it will identify
> that publication does not exist and stop the walsender/apply worker
> process. When the apply worker is restarted, we will get the
> remote_lsn(in my case it was 0/1510978) of the origin and set it to
> origin_startpos. We will start the apply worker with this
> origin_startpos (origin's remote_lsn). This position will be sent as
> feedback to the walsender process from the below stack:
> run_apply_worker->start_apply->LogicalRepApplyLoop->send_feedback.
> It will use the following send_feedback function call of
> LogicalRepApplyLoop function as in below code here as nothing is
> received from walsender:
> LogicalRepApplyLoop function
> .......
> len = walrcv_receive(LogRepWorkerWalRcvConn, &buf, &fd);
> if (len != 0)
> {
>                /* Loop to process all available data (without blocking). */
>                for (;;)
>                {
>                               CHECK_FOR_INTERRUPTS();
>                               ...
>                }
> }
>
> /* confirm all writes so far */
> send_feedback(last_received, false, false);
> .......
>
> In send_feedback, we will set flushpos to replication origin's
> remote_lsn and send it to the walsender process. Walsender process
> will receive this information and set confirmed_flush in:
> ProcessStandbyReplyMessage->LogicalConfirmReceivedLocation
>
> Then immediately we are trying to stop the publisher instance,
> shutdown checkpoint process will be triggered. In this case:
> confirmed_flush = 0/1510978 will be lesser than
> last_saved_confirmed_flush = 0/15109B0 which will result in Assertion
> failure.
>
> This issue is happening because we allow setting the confirmed_flush
> to a backward position.
>

I see your point.

> There are a couple of ways to fix this:
> a) One way it not to update the confirm_flush if the lsn sent is an
> older value like in Confirm_flush_dont_allow_backward.patch
>

@@ -1839,7 +1839,8 @@ LogicalConfirmReceivedLocation(XLogRecPtr lsn)

  SpinLockAcquire(&MyReplicationSlot->mutex);

- MyReplicationSlot->data.confirmed_flush = lsn;
+ if (lsn > MyReplicationSlot->data.confirmed_flush)
+ MyReplicationSlot->data.confirmed_flush = lsn;

  /* if we're past the location required for bumping xmin, do so */
  if (MyReplicationSlot->candidate_xmin_lsn != InvalidXLogRecPtr &&
@@ -1904,7 +1905,8 @@ LogicalConfirmReceivedLocation(XLogRecPtr lsn)
  else
  {
  SpinLockAcquire(&MyReplicationSlot->mutex);
- MyReplicationSlot->data.confirmed_flush = lsn;
+ if (lsn > MyReplicationSlot->data.confirmed_flush)
+ MyReplicationSlot->data.confirmed_flush = lsn;

BTW, from which code path does it update the prior value of
confirmed_flush? If it is through the else check, then can we see if
it may change the confirm_flush to the prior position via the first
code path? I am asking because in the first code path, we can even
flush the re-treated value of confirm_flush LSN.

--
With Regards,
Amit Kapila.

On Sat, 17 Feb 2024 at 12:03, Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Fri, Feb 16, 2024 at 5:53 PM vignesh C <vignesh21@gmail.com> wrote:
> >
> >
> > After the insert operation is replicated to the subscriber, the
> > subscriber will set the lsn value sent by the publisher in the
> > replication origin (in my case it was 0/1510978). publisher will then
> > send keepalive messages with the current WAL position in the publisher
> > (in my case it was 0/15109B0), but subscriber will simply send this
> > position as the flush_lsn to the publisher as there are no ongoing
> > transactions. Then since the publisher is started, it will identify
> > that publication does not exist and stop the walsender/apply worker
> > process. When the apply worker is restarted, we will get the
> > remote_lsn(in my case it was 0/1510978) of the origin and set it to
> > origin_startpos. We will start the apply worker with this
> > origin_startpos (origin's remote_lsn). This position will be sent as
> > feedback to the walsender process from the below stack:
> > run_apply_worker->start_apply->LogicalRepApplyLoop->send_feedback.
> > It will use the following send_feedback function call of
> > LogicalRepApplyLoop function as in below code here as nothing is
> > received from walsender:
> > LogicalRepApplyLoop function
> > .......
> > len = walrcv_receive(LogRepWorkerWalRcvConn, &buf, &fd);
> > if (len != 0)
> > {
> >                /* Loop to process all available data (without blocking). */
> >                for (;;)
> >                {
> >                               CHECK_FOR_INTERRUPTS();
> >                               ...
> >                }
> > }
> >
> > /* confirm all writes so far */
> > send_feedback(last_received, false, false);
> > .......
> >
> > In send_feedback, we will set flushpos to replication origin's
> > remote_lsn and send it to the walsender process. Walsender process
> > will receive this information and set confirmed_flush in:
> > ProcessStandbyReplyMessage->LogicalConfirmReceivedLocation
> >
> > Then immediately we are trying to stop the publisher instance,
> > shutdown checkpoint process will be triggered. In this case:
> > confirmed_flush = 0/1510978 will be lesser than
> > last_saved_confirmed_flush = 0/15109B0 which will result in Assertion
> > failure.
> >
> > This issue is happening because we allow setting the confirmed_flush
> > to a backward position.
> >
>
> I see your point.
>
> > There are a couple of ways to fix this:
> > a) One way it not to update the confirm_flush if the lsn sent is an
> > older value like in Confirm_flush_dont_allow_backward.patch
> >
>
> @@ -1839,7 +1839,8 @@ LogicalConfirmReceivedLocation(XLogRecPtr lsn)
>
>   SpinLockAcquire(&MyReplicationSlot->mutex);
>
> - MyReplicationSlot->data.confirmed_flush = lsn;
> + if (lsn > MyReplicationSlot->data.confirmed_flush)
> + MyReplicationSlot->data.confirmed_flush = lsn;
>
>   /* if we're past the location required for bumping xmin, do so */
>   if (MyReplicationSlot->candidate_xmin_lsn != InvalidXLogRecPtr &&
> @@ -1904,7 +1905,8 @@ LogicalConfirmReceivedLocation(XLogRecPtr lsn)
>   else
>   {
>   SpinLockAcquire(&MyReplicationSlot->mutex);
> - MyReplicationSlot->data.confirmed_flush = lsn;
> + if (lsn > MyReplicationSlot->data.confirmed_flush)
> + MyReplicationSlot->data.confirmed_flush = lsn;
>
> BTW, from which code path does it update the prior value of
> confirmed_flush?

The confirmed_flush is getting set in the else condition for this scenario.

If it is through the else check, then can we see if
> it may change the confirm_flush to the prior position via the first
> code path? I am asking because in the first code path, we can even
> flush the re-treated value of confirm_flush LSN.

I was not able to find any scenario to set a prior position with the
first code path. I tried various scenarios like adding delay in
walsender, add delay in apply worker, restart the instances and with
various DML operations. It was always setting it to either to the same
value as previous or greater value.

Regards,
Vignesh

On Fri, 16 Feb 2024 at 17:39, vignesh C <vignesh21@gmail.com> wrote:
>
> Hi,
>
> The following assertion failure was seen while testing one scenario
> for other patch:
> TRAP: failed Assert("s->data.confirmed_flush >=
> s->last_saved_confirmed_flush"), File: "slot.c", Line: 1760, PID:
> 545314
> postgres: checkpointer performing shutdown
> checkpoint(ExceptionalCondition+0xbb)[0x564ee6870c58]
> postgres: checkpointer performing shutdown
> checkpoint(CheckPointReplicationSlots+0x18e)[0x564ee65e9c71]
> postgres: checkpointer performing shutdown checkpoint(+0x1e1403)[0x564ee61be403]
> postgres: checkpointer performing shutdown
> checkpoint(CreateCheckPoint+0x78a)[0x564ee61bdace]
> postgres: checkpointer performing shutdown
> checkpoint(ShutdownXLOG+0x150)[0x564ee61bc735]
> postgres: checkpointer performing shutdown checkpoint(+0x5ae28c)[0x564ee658b28c]
> postgres: checkpointer performing shutdown
> checkpoint(CheckpointerMain+0x31e)[0x564ee658ad55]
> postgres: checkpointer performing shutdown
> checkpoint(AuxiliaryProcessMain+0x1d1)[0x564ee65888d9]
> postgres: checkpointer performing shutdown checkpoint(+0x5b7200)[0x564ee6594200]
> postgres: checkpointer performing shutdown
> checkpoint(PostmasterMain+0x14da)[0x564ee658f12f]
> postgres: checkpointer performing shutdown checkpoint(+0x464fc6)[0x564ee6441fc6]
> /lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7ff6afa29d90]
> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7ff6afa29e40]
> postgres: checkpointer performing shutdown
> checkpoint(_start+0x25)[0x564ee60b8e05]
>
> I was able to reproduce this issue with the following steps:
> -- Setup
> -- Publisher node:
> create table t1(c1 int);
> create table t2(c1 int);
> create publication pub1 for table t1;
> create publication pub2 for table t2;
>
> -- Subscriber node:
> create table t1(c1 int);
> create table t2(c1 int);
> create subscription test1 connection 'dbname=postgres host=localhost
> port=5432' publication pub1, pub2;
> select * from pg_subscription;
>
> -- Actual test
> insert into t1 values(10);
> insert into t2 values(20);
> select pg_sleep(10);
> drop publication pub2;
> insert into t1 values(10);
> insert into t2 values(20);
>
> Stop the publisher to see the assertion.
>
> For me the issue reproduces about twice in five times using the
> assert_failure.sh script attached.
>
> After the insert operation is replicated to the subscriber, the
> subscriber will set the lsn value sent by the publisher in the
> replication origin (in my case it was 0/1510978). publisher will then
> send keepalive messages with the current WAL position in the publisher
> (in my case it was 0/15109B0), but subscriber will simply send this
> position as the flush_lsn to the publisher as there are no ongoing
> transactions. Then since the publisher is started, it will identify
> that publication does not exist and stop the walsender/apply worker
> process. When the apply worker is restarted, we will get the
> remote_lsn(in my case it was 0/1510978) of the origin and set it to
> origin_startpos. We will start the apply worker with this
> origin_startpos (origin's remote_lsn). This position will be sent as
> feedback to the walsender process from the below stack:
> run_apply_worker->start_apply->LogicalRepApplyLoop->send_feedback.
> It will use the following send_feedback function call of
> LogicalRepApplyLoop function as in below code here as nothing is
> received from walsender:
> LogicalRepApplyLoop function
> .......
> len = walrcv_receive(LogRepWorkerWalRcvConn, &buf, &fd);
> if (len != 0)
> {
>                /* Loop to process all available data (without blocking). */
>                for (;;)
>                {
>                               CHECK_FOR_INTERRUPTS();
>                               ...
>                }
> }
>
> /* confirm all writes so far */
> send_feedback(last_received, false, false);
> .......
>
> In send_feedback, we will set flushpos to replication origin's
> remote_lsn and send it to the walsender process. Walsender process
> will receive this information and set confirmed_flush in:
> ProcessStandbyReplyMessage->LogicalConfirmReceivedLocation
>
> Then immediately we are trying to stop the publisher instance,
> shutdown checkpoint process will be triggered. In this case:
> confirmed_flush = 0/1510978 will be lesser than
> last_saved_confirmed_flush = 0/15109B0 which will result in Assertion
> failure.
>
> This issue is happening because we allow setting the confirmed_flush
> to a backward position.
> There are a couple of ways to fix this:
> a) One way it not to update the confirm_flush if the lsn sent is an
> older value like in Confirm_flush_dont_allow_backward.patch
> b) Another way is to remove the assertion in
> CheckPointReplicationSlots and marking the slot as dirty only if
> confirmed_flush is greater than last_saved_confirmed_flush like in
> Assert_confirmed_flush_will_always_not_be_less_than_last_saved_confirmed_flush.patch
>
> I preferred the first approach.

I have created the following commitfest entry for this:
https://commitfest.postgresql.org/47/4845/

Regards,
Vignesh