Assertion failure in SnapBuildInitialSnapshot()

Hi,

On 2022-11-10 16:04:40 +0530, Amit Kapila wrote:

I don't have any good ideas on how to proceed with this. Any thoughts
on this would be helpful?

One thing worth doing might be to convert the assertion path into an elog(),
mentioning both xids (or add a framework for things like AssertLT(), but that
seems hard). With the concrete values we could make a better guess at what's
going wrong.

It'd probably not hurt to just perform this check independent of
USE_ASSERT_CHECKING - compared to the cost of creating a slot it's neglegible.

That'll obviously only help us whenever we re-encounter the issue, which will
likely be a while...

Have you tried reproducing the issue by running the test in a loop?

One thing I noticed just now is that we don't assert
builder->building_full_snapshot==true. I think we should? That didn't use to
be an option, but now it is... It doesn't look to me like that's the issue,
but ...

Hm, also, shouldn't the patch adding CRS_USE_SNAPSHOT have copied more of
SnapBuildExportSnapshot()? Why aren't the error checks for
SnapBuildExportSnapshot() needed? Why don't we need to set XactReadOnly? Which
transactions are we even in when we import the snapshot (cf.
SnapBuildExportSnapshot() doing a StartTransactionCommand()).

I'm also somewhat suspicious of calling RestoreTransactionSnapshot() with
source=MyProc. Looks like it works, but it'd be pretty easy to screw up, and
there's no comments in SetTransactionSnapshot() or
ProcArrayInstallRestoredXmin() warning that that might be the case.

Greetings,

Andres Freund

Hi,

On 2022-11-14 17:25:31 -0800, Andres Freund wrote:

Hm, also, shouldn't the patch adding CRS_USE_SNAPSHOT have copied more of
SnapBuildExportSnapshot()? Why aren't the error checks for
SnapBuildExportSnapshot() needed? Why don't we need to set XactReadOnly? Which
transactions are we even in when we import the snapshot (cf.
SnapBuildExportSnapshot() doing a StartTransactionCommand()).

Most of the checks for that are in CreateReplicationSlot() - but not al,
e.g. XactReadOnly isn't set, nor do we enforce in an obvious place that we
don't already hold a snapshot.

I first thought this might directly explain the problem, due to the
MyProc->xmin assignment in SnapBuildInitialSnapshot() overwriting a value that
could influence the return value for GetOldestSafeDecodingTransactionId(). But
that happens later, and we check that MyProc->xmin is invalid at the start.

But it still seems supicious. This will e.g. influence whether
StartupDecodingContext() sets PROC_IN_LOGICAL_DECODING. Which probably is
fine, but...

Another theory: I dimly remember Thomas mentioning that there's some different
behaviour of xlogreader during shutdown as part of the v15 changes. I don't
quite remember what the scenario leading up to that was. Thomas?

It's certainly interesting that we see stuff like:

2022-11-08 00:20:23.255 GMT [2012][walsender] [pg_16400_sync_16395_7163433409941550636][8/0:0] ERROR: could not find record while sending logically-decoded data: missing contrecord at 0/1D3B710
2022-11-08 00:20:23.255 GMT [2012][walsender] [pg_16400_sync_16395_7163433409941550636][8/0:0] STATEMENT: START_REPLICATION SLOT "pg_16400_sync_16395_7163433409941550636" LOGICAL 0/1D2B650 (proto_version '3', origin 'any', publication_names '"testpub"')
ERROR: could not find record while sending logically-decoded data: missing contrecord at 0/1D3B710
2022-11-08 00:20:23.255 GMT [248][logical replication worker] ERROR: error while shutting down streaming COPY: ERROR: could not find record while sending logically-decoded data: missing contrecord at 0/1D3B710

It could entirely be caused by postmaster slowly killing processes after the
assertion failure and that that is corrupting shared memory state though. But
it might also be related.

Greetings,

Andres Freund

On Tue, Nov 15, 2022 at 3:38 PM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-14 17:25:31 -0800, Andres Freund wrote:
Another theory: I dimly remember Thomas mentioning that there's some different
behaviour of xlogreader during shutdown as part of the v15 changes. I don't
quite remember what the scenario leading up to that was. Thomas?

Yeah. So as mentioned in:

/messages/by-id/CA+hUKG+WKsZpdoryeqM8_rk5uQPCqS2HGY92WiMGFsK2wVkcig@mail.gmail.com

I still have on my list to remove a new "missing contrecord" error
that can show up in a couple of different scenarios that aren't
exactly error conditions depending on how you think about it, but I
haven't done that yet. I am not currently aware of anything bad
happening because of those messages, but I could be wrong.

It's certainly interesting that we see stuff like:

2022-11-08 00:20:23.255 GMT [2012][walsender] [pg_16400_sync_16395_7163433409941550636][8/0:0] ERROR: could not find record while sending logically-decoded data: missing contrecord at 0/1D3B710
2022-11-08 00:20:23.255 GMT [2012][walsender] [pg_16400_sync_16395_7163433409941550636][8/0:0] STATEMENT: START_REPLICATION SLOT "pg_16400_sync_16395_7163433409941550636" LOGICAL 0/1D2B650 (proto_version '3', origin 'any', publication_names '"testpub"')
ERROR: could not find record while sending logically-decoded data: missing contrecord at 0/1D3B710
2022-11-08 00:20:23.255 GMT [248][logical replication worker] ERROR: error while shutting down streaming COPY: ERROR: could not find record while sending logically-decoded data: missing contrecord at 0/1D3B710

Right, so that might fit the case described in my email above:
logical_read_xlog_page() notices that it has been asked to shut down
when it is between reads of pages with a spanning contrecord. Before,
it would fail silently, so XLogReadRecord() returns NULL without
setting *errmsg, but now it complains about a missing contrecord. In
the case where it was showing up on that other thread, just a few
machines often seemed to log that error when shutting down --
peripatus for example -- I don't know why, but I assume something to
do with shutdown timing and page alignment.

It could entirely be caused by postmaster slowly killing processes after the
assertion failure and that that is corrupting shared memory state though. But
it might also be related.

Hmm.

Hi,

On Tuesday, November 15, 2022 10:26 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-10 16:04:40 +0530, Amit Kapila wrote:

I don't have any good ideas on how to proceed with this. Any thoughts
on this would be helpful?

One thing worth doing might be to convert the assertion path into an elog(),
mentioning both xids (or add a framework for things like AssertLT(), but that
seems hard). With the concrete values we could make a better guess at
what's going wrong.

It'd probably not hurt to just perform this check independent of
USE_ASSERT_CHECKING - compared to the cost of creating a slot it's
neglegible.

That'll obviously only help us whenever we re-encounter the issue, which will
likely be a while...

Have you tried reproducing the issue by running the test in a loop?

Just FYI, I've tried to reproduce this failure in a loop,
but I couldn't hit the same assertion failure.

I extracted the #16643 of 100_bugs.pl only and
executed the tests more than 500 times.

My env and test was done in rhel7.9 and gcc 4.8 with configure option of
--enable-cassert --enable-debug --enable-tap-tests --with-icu CFLAGS=-O0 and prefix.

Best Regards,
Takamichi Osumi

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-14 17:25:31 -0800, Andres Freund wrote:

Hm, also, shouldn't the patch adding CRS_USE_SNAPSHOT have copied more of
SnapBuildExportSnapshot()? Why aren't the error checks for
SnapBuildExportSnapshot() needed? Why don't we need to set XactReadOnly? Which
transactions are we even in when we import the snapshot (cf.
SnapBuildExportSnapshot() doing a StartTransactionCommand()).

Most of the checks for that are in CreateReplicationSlot() - but not al,
e.g. XactReadOnly isn't set,

Yeah, I think we can add the check for XactReadOnly along with other
checks in CreateReplicationSlot().

nor do we enforce in an obvious place that we
don't already hold a snapshot.

We have a check for (FirstXactSnapshot == NULL) in
RestoreTransactionSnapshot->SetTransactionSnapshot. Won't that be
sufficient?

--
With Regards,
Amit Kapila.

On Tue, Nov 15, 2022 at 6:55 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-10 16:04:40 +0530, Amit Kapila wrote:

I don't have any good ideas on how to proceed with this. Any thoughts
on this would be helpful?

One thing worth doing might be to convert the assertion path into an elog(),
mentioning both xids (or add a framework for things like AssertLT(), but that
seems hard). With the concrete values we could make a better guess at what's
going wrong.

It'd probably not hurt to just perform this check independent of
USE_ASSERT_CHECKING - compared to the cost of creating a slot it's neglegible.

That'll obviously only help us whenever we re-encounter the issue, which will
likely be a while...

Agreed.

One thing I noticed just now is that we don't assert
builder->building_full_snapshot==true. I think we should? That didn't use to
be an option, but now it is... It doesn't look to me like that's the issue,
but ...

Agreed.

The attached patch contains both changes. It seems to me this issue
can happen, if somehow, either slot's effective_xmin increased after
we assign its initial value in CreateInitDecodingContext() or somehow
its value is InvalidTransactionId when we have invoked
SnapBuildInitialSnapshot(). The other possibility is that the
initial_xmin_horizon check in SnapBuildFindSnapshot() doesn't insulate
us from assigning builder->xmin value older than initial_xmin_horizon.
I am not able to see if any of this can be true.

--
With Regards,
Amit Kapila.

Hi,

On 2022-11-15 16:20:00 +0530, Amit Kapila wrote:

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

nor do we enforce in an obvious place that we
don't already hold a snapshot.

We have a check for (FirstXactSnapshot == NULL) in
RestoreTransactionSnapshot->SetTransactionSnapshot. Won't that be
sufficient?

I don't think that'd e.g. catch a catalog snapshot being held, yet that'd
still be bad. And I think checking in SetTransactionSnapshot() is too late,
we've already overwritten MyProc->xmin by that point.

On 2022-11-15 17:21:44 +0530, Amit Kapila wrote:

One thing I noticed just now is that we don't assert
builder->building_full_snapshot==true. I think we should? That didn't use to
be an option, but now it is... It doesn't look to me like that's the issue,
but ...

Agreed.

The attached patch contains both changes. It seems to me this issue
can happen, if somehow, either slot's effective_xmin increased after
we assign its initial value in CreateInitDecodingContext() or somehow
its value is InvalidTransactionId when we have invoked
SnapBuildInitialSnapshot(). The other possibility is that the
initial_xmin_horizon check in SnapBuildFindSnapshot() doesn't insulate
us from assigning builder->xmin value older than initial_xmin_horizon.
I am not able to see if any of this can be true.

Yea, I don't immediately see anything either. Given the discussion in
/messages/by-id/Yz2hivgyjS1RfMKs@depesz.com I am
starting to wonder if we've introduced a race in the slot machinery.

diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 5006a5c464..e85c75e0e6 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -566,11 +566,13 @@ SnapBuildInitialSnapshot(SnapBuild *builder)
{
Snapshot	snap;
TransactionId xid;
+	TransactionId safeXid;
TransactionId *newxip;
int			newxcnt = 0;

Assert(!FirstSnapshotSet);
Assert(XactIsoLevel == XACT_REPEATABLE_READ);
+ Assert(builder->building_full_snapshot);

if (builder->state != SNAPBUILD_CONSISTENT)
elog(ERROR, "cannot build an initial slot snapshot before reaching a consistent state");
@@ -589,17 +591,13 @@ SnapBuildInitialSnapshot(SnapBuild *builder)
* mechanism. Due to that we can do this without locks, we're only
* changing our own value.
*/

Perhaps add something like "Creating a snapshot is expensive and an unenforced
xmin horizon would have bad consequences, therefore always double-check that
the horizon is enforced"?

-#ifdef USE_ASSERT_CHECKING
-	{
-		TransactionId safeXid;
-
-		LWLockAcquire(ProcArrayLock, LW_SHARED);
-		safeXid = GetOldestSafeDecodingTransactionId(false);
-		LWLockRelease(ProcArrayLock);
+	LWLockAcquire(ProcArrayLock, LW_SHARED);
+	safeXid = GetOldestSafeDecodingTransactionId(false);
+	LWLockRelease(ProcArrayLock);

-		Assert(TransactionIdPrecedesOrEquals(safeXid, snap->xmin));
-	}
-#endif
+	if (TransactionIdFollows(safeXid, snap->xmin))
+		elog(ERROR, "cannot build an initial slot snapshot when oldest safe xid %u follows snapshot's xmin %u",
+			 safeXid, snap->xmin);

MyProc->xmin = snap->xmin;

s/when/as/

Greetings,

Andres Freund

On Wed, Nov 16, 2022 at 7:30 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-15 16:20:00 +0530, Amit Kapila wrote:

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

nor do we enforce in an obvious place that we
don't already hold a snapshot.

We have a check for (FirstXactSnapshot == NULL) in
RestoreTransactionSnapshot->SetTransactionSnapshot. Won't that be
sufficient?

I don't think that'd e.g. catch a catalog snapshot being held, yet that'd
still be bad. And I think checking in SetTransactionSnapshot() is too late,
we've already overwritten MyProc->xmin by that point.

So, shall we add the below Asserts in SnapBuildInitialSnapshot() after
we have the Assert for Assert(!FirstSnapshotSet)?
Assert(FirstXactSnapshot == NULL);
Assert(!HistoricSnapshotActive());

--
With Regards,
Amit Kapila.

Hi,

On 2022-11-16 14:22:01 +0530, Amit Kapila wrote:

On Wed, Nov 16, 2022 at 7:30 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-15 16:20:00 +0530, Amit Kapila wrote:

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

nor do we enforce in an obvious place that we
don't already hold a snapshot.

We have a check for (FirstXactSnapshot == NULL) in
RestoreTransactionSnapshot->SetTransactionSnapshot. Won't that be
sufficient?

I don't think that'd e.g. catch a catalog snapshot being held, yet that'd
still be bad. And I think checking in SetTransactionSnapshot() is too late,
we've already overwritten MyProc->xmin by that point.

So, shall we add the below Asserts in SnapBuildInitialSnapshot() after
we have the Assert for Assert(!FirstSnapshotSet)?
Assert(FirstXactSnapshot == NULL);
Assert(!HistoricSnapshotActive());

I don't think that'd catch a catalog snapshot. But perhaps the better answer
for the catalog snapshot is to just invalidate it explicitly. The user doesn't
have control over the catalog snapshot being taken, and it's not too hard to
imagine the walsender code triggering one somewhere.

So maybe we should add something like:

InvalidateCatalogSnapshot(); /* about to overwrite MyProc->xmin */
if (HaveRegisteredOrActiveSnapshot())
elog(ERROR, "cannot build an initial slot snapshot when snapshots exist")
Assert(!HistoricSnapshotActive());

I think we'd not need to assert FirstXactSnapshot == NULL or !FirstSnapshotSet
with that, because those would show up in HaveRegisteredOrActiveSnapshot().

Greetings,

Andres Freund

On Wed, Nov 16, 2022 at 11:56 PM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-16 14:22:01 +0530, Amit Kapila wrote:

On Wed, Nov 16, 2022 at 7:30 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-15 16:20:00 +0530, Amit Kapila wrote:

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

nor do we enforce in an obvious place that we
don't already hold a snapshot.

We have a check for (FirstXactSnapshot == NULL) in
RestoreTransactionSnapshot->SetTransactionSnapshot. Won't that be
sufficient?

I don't think that'd e.g. catch a catalog snapshot being held, yet that'd
still be bad. And I think checking in SetTransactionSnapshot() is too late,
we've already overwritten MyProc->xmin by that point.

So, shall we add the below Asserts in SnapBuildInitialSnapshot() after
we have the Assert for Assert(!FirstSnapshotSet)?
Assert(FirstXactSnapshot == NULL);
Assert(!HistoricSnapshotActive());

I don't think that'd catch a catalog snapshot. But perhaps the better answer
for the catalog snapshot is to just invalidate it explicitly. The user doesn't
have control over the catalog snapshot being taken, and it's not too hard to
imagine the walsender code triggering one somewhere.

So maybe we should add something like:

InvalidateCatalogSnapshot(); /* about to overwrite MyProc->xmin */

The comment "/* about to overwrite MyProc->xmin */" is unclear to me.
We already have a check (/* so we don't overwrite the existing value
*/
if (TransactionIdIsValid(MyProc->xmin))) in SnapBuildInitialSnapshot()
which ensures that we don't overwrite MyProc->xmin, so the above
comment seems contradictory to me.

--
With Regards,
Amit Kapila.

On Wed, Nov 16, 2022 at 11:56 PM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-16 14:22:01 +0530, Amit Kapila wrote:

On Wed, Nov 16, 2022 at 7:30 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-15 16:20:00 +0530, Amit Kapila wrote:

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

nor do we enforce in an obvious place that we
don't already hold a snapshot.

We have a check for (FirstXactSnapshot == NULL) in
RestoreTransactionSnapshot->SetTransactionSnapshot. Won't that be
sufficient?

I don't think that'd e.g. catch a catalog snapshot being held, yet that'd
still be bad. And I think checking in SetTransactionSnapshot() is too late,
we've already overwritten MyProc->xmin by that point.

So, shall we add the below Asserts in SnapBuildInitialSnapshot() after
we have the Assert for Assert(!FirstSnapshotSet)?
Assert(FirstXactSnapshot == NULL);
Assert(!HistoricSnapshotActive());

I don't think that'd catch a catalog snapshot. But perhaps the better answer
for the catalog snapshot is to just invalidate it explicitly. The user doesn't
have control over the catalog snapshot being taken, and it's not too hard to
imagine the walsender code triggering one somewhere.

So maybe we should add something like:

InvalidateCatalogSnapshot(); /* about to overwrite MyProc->xmin */
if (HaveRegisteredOrActiveSnapshot())
elog(ERROR, "cannot build an initial slot snapshot when snapshots exist")
Assert(!HistoricSnapshotActive());

I think we'd not need to assert FirstXactSnapshot == NULL or !FirstSnapshotSet
with that, because those would show up in HaveRegisteredOrActiveSnapshot().

In the attached patch, I have incorporated this change and other
feedback. I think this should probably help us find the reason for
this problem when we see it in the future.

--
With Regards,
Amit Kapila.

Hi,

On 2022-11-17 10:44:18 +0530, Amit Kapila wrote:

On Wed, Nov 16, 2022 at 11:56 PM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-16 14:22:01 +0530, Amit Kapila wrote:

On Wed, Nov 16, 2022 at 7:30 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-15 16:20:00 +0530, Amit Kapila wrote:

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

I don't think that'd catch a catalog snapshot. But perhaps the better answer
for the catalog snapshot is to just invalidate it explicitly. The user doesn't
have control over the catalog snapshot being taken, and it's not too hard to
imagine the walsender code triggering one somewhere.

So maybe we should add something like:

InvalidateCatalogSnapshot(); /* about to overwrite MyProc->xmin */

The comment "/* about to overwrite MyProc->xmin */" is unclear to me.
We already have a check (/* so we don't overwrite the existing value
*/
if (TransactionIdIsValid(MyProc->xmin))) in SnapBuildInitialSnapshot()
which ensures that we don't overwrite MyProc->xmin, so the above
comment seems contradictory to me.

The point is that catalog snapshots could easily end up setting MyProc->xmin,
even though the caller hasn't done anything wrong. So the
InvalidateCatalogSnapshot() would avoid erroring out in a number of scenarios.

Greetings,

Andres Freund

On Thu, Nov 17, 2022 at 11:15 PM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-17 10:44:18 +0530, Amit Kapila wrote:

On Wed, Nov 16, 2022 at 11:56 PM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-16 14:22:01 +0530, Amit Kapila wrote:

On Wed, Nov 16, 2022 at 7:30 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-15 16:20:00 +0530, Amit Kapila wrote:

On Tue, Nov 15, 2022 at 8:08 AM Andres Freund <andres@anarazel.de> wrote:

I don't think that'd catch a catalog snapshot. But perhaps the better answer
for the catalog snapshot is to just invalidate it explicitly. The user doesn't
have control over the catalog snapshot being taken, and it's not too hard to
imagine the walsender code triggering one somewhere.

So maybe we should add something like:

InvalidateCatalogSnapshot(); /* about to overwrite MyProc->xmin */

The comment "/* about to overwrite MyProc->xmin */" is unclear to me.
We already have a check (/* so we don't overwrite the existing value
*/
if (TransactionIdIsValid(MyProc->xmin))) in SnapBuildInitialSnapshot()
which ensures that we don't overwrite MyProc->xmin, so the above
comment seems contradictory to me.

The point is that catalog snapshots could easily end up setting MyProc->xmin,
even though the caller hasn't done anything wrong. So the
InvalidateCatalogSnapshot() would avoid erroring out in a number of scenarios.

Okay, updated the patch accordingly.

--
With Regards,
Amit Kapila.

Hi,

On 2022-11-18 11:20:36 +0530, Amit Kapila wrote:

Okay, updated the patch accordingly.

Assuming it passes tests etc, this'd work for me.

- Andres

On Sat, Nov 19, 2022 at 6:35 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-18 11:20:36 +0530, Amit Kapila wrote:

Okay, updated the patch accordingly.

Assuming it passes tests etc, this'd work for me.

Thanks, Pushed.

--
With Regards,
Amit Kapila.

On Mon, Nov 21, 2022 at 4:31 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Sat, Nov 19, 2022 at 6:35 AM Andres Freund <andres@anarazel.de> wrote:

On 2022-11-18 11:20:36 +0530, Amit Kapila wrote:

Okay, updated the patch accordingly.

Assuming it passes tests etc, this'd work for me.

Thanks, Pushed.

The same assertion failure has been reported on another thread[1]/messages/by-id/tencent_7EB71DA5D7BA00EB0B429DCE45D0452B6406@qq.com.
Since I could reproduce this issue several times in my environment
I've investigated the root cause.

I think there is a race condition of updating
procArray->replication_slot_xmin by CreateInitDecodingContext() and
LogicalConfirmReceivedLocation().

What I observed in the test was that a walsender process called:
SnapBuildProcessRunningXacts()
LogicalIncreaseXminForSlot()
LogicalConfirmReceivedLocation()
ReplicationSlotsComputeRequiredXmin(false).

In ReplicationSlotsComputeRequiredXmin() it acquired the
ReplicationSlotControlLock and got 0 as the minimum xmin since there
was no wal sender having effective_xmin. Before calling
ProcArraySetReplicationSlotXmin() (i.e. before acquiring
ProcArrayLock), another walsender process called
CreateInitDecodingContext(), acquired ProcArrayLock, computed
slot->effective_catalog_xmin, called
ReplicationSlotsComputeRequiredXmin(true). Since its
effective_catalog_xmin had been set, it got 39968 as the minimum xmin,
and updated replication_slot_xmin. However, as soon as the second
walsender released ProcArrayLock, the first walsender updated the
replication_slot_xmin to 0. After that, the second walsender called
SnapBuildInitialSnapshot(), and GetOldestSafeDecodingTransactionId()
returned an XID newer than snap->xmin.

One idea to fix this issue is that in
ReplicationSlotsComputeRequiredXmin(), we compute the minimum xmin
while holding both ProcArrayLock and ReplicationSlotControlLock, and
release only ReplicationSlotsControlLock before updating the
replication_slot_xmin. I'm concerned it will increase the contention
on ProcArrayLock but I've attached the patch for discussion.

Regards,

[1]: /messages/by-id/tencent_7EB71DA5D7BA00EB0B429DCE45D0452B6406@qq.com

--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

On Thu, Dec 8, 2022 at 8:17 AM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

The same assertion failure has been reported on another thread[1].
Since I could reproduce this issue several times in my environment
I've investigated the root cause.

I think there is a race condition of updating
procArray->replication_slot_xmin by CreateInitDecodingContext() and
LogicalConfirmReceivedLocation().

What I observed in the test was that a walsender process called:
SnapBuildProcessRunningXacts()
LogicalIncreaseXminForSlot()
LogicalConfirmReceivedLocation()
ReplicationSlotsComputeRequiredXmin(false).

In ReplicationSlotsComputeRequiredXmin() it acquired the
ReplicationSlotControlLock and got 0 as the minimum xmin since there
was no wal sender having effective_xmin.

What about the current walsender process which is processing
running_xacts via SnapBuildProcessRunningXacts()? Isn't that walsender
slot's effective_xmin have a non-zero value? If not, then why?

--
With Regards,
Amit Kapila.

Dear Sawada-san,

Thank you for making the patch! I'm still considering whether this approach is
correct, but I can put a comment to your patch anyway.

```
-	Assert(!already_locked || LWLockHeldByMe(ProcArrayLock));
-
-	if (!already_locked)
-		LWLockAcquire(ProcArrayLock, LW_EXCLUSIVE);
+	Assert(LWLockHeldByMe(ProcArrayLock));
```

In this function, we regard that the ProcArrayLock has been already acquired as
exclusive mode and modify data. I think LWLockHeldByMeInMode() should be used
instead of LWLockHeldByMe().
I confirmed that there is only one caller that uses ReplicationSlotsComputeRequiredXmin(true)
and it acquires exclusive lock correctly, but it can avoid future bug.

Best Regards,
Hayato Kuroda
FUJITSU LIMITED

Dear Amit, Sawada-san,

I have also reproduced the failure on PG15 with some debug log, and I agreed that
somebody changed procArray->replication_slot_xmin to InvalidTransactionId.

The same assertion failure has been reported on another thread[1].
Since I could reproduce this issue several times in my environment
I've investigated the root cause.

I think there is a race condition of updating
procArray->replication_slot_xmin by CreateInitDecodingContext() and
LogicalConfirmReceivedLocation().

What I observed in the test was that a walsender process called:
SnapBuildProcessRunningXacts()
LogicalIncreaseXminForSlot()
LogicalConfirmReceivedLocation()
ReplicationSlotsComputeRequiredXmin(false).

In ReplicationSlotsComputeRequiredXmin() it acquired the
ReplicationSlotControlLock and got 0 as the minimum xmin since there
was no wal sender having effective_xmin.

What about the current walsender process which is processing
running_xacts via SnapBuildProcessRunningXacts()? Isn't that walsender
slot's effective_xmin have a non-zero value? If not, then why?

Normal walsenders which are not for tablesync create a replication slot with
NOEXPORT_SNAPSHOT option. I think in this case, CreateInitDecodingContext() is
called with need_full_snapshot = false, and slot->effective_xmin is not updated.
It is set as InvalidTransactionId at ReplicationSlotCreate() and no functions update
that. Hence the slot acquired by the walsender may have Invalid effective_min.

Best Regards,
Hayato Kuroda
FUJITSU LIMITED