Found issues related with logical replication and 2PC

On Wed, Jul 24, 2024 at 12:25 PM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:

Hi hackers,

While creating a patch which allows ALTER SUBSCRIPTION SET (two_phase) [1],
we found some issues related with logical replication and two_phase. I think this
can happen not only HEAD but PG14+, but for now I shared patches for HEAD.

Issue #1

When handling a PREPARE message, the subscriber mistook the wrong lsn position
(the end position of the last commit) as the end position of the current prepare.
This can be fixed by adding a new global variable to record the end position of
the last prepare. 0001 patch fixes the issue.

Thanks for the patches. I have started reviewing this. I reviewed and
tested patch001 alone.

I have a query, shouldn't the local-lsn stored in
apply_handle_commit_prepared() be the end position of
'COMMIT_PREPARED' instead of 'PREPARE'? I put additional logging on
sub and got this:

LOG: apply_handle_prepare - prepare_data.end_lsn: 0/15892E0 ,
XactLastPrepareEnd: 0/1537FD8.
LOG: apply_handle_commit_prepared - prepare_data.end_lsn: 0/1589318
, XactLastPrepareEnd: 0/1537FD8.

In apply_handle_prepare(), remote-lsn ('0/15892E0') is end position of
'PREPARE' and in apply_handle_commit_prepared(), remote-lsn
('0/1589318') is end position of 'COMMIT_PREPARED', while local-lsn in
both cases is end-lsn of 'PREPARE'. Details at [1]Pub: ------ SELECT * FROM pg_get_wal_record_info('0/15892E0'); start_lsn | end_lsn | prev_lsn | record_type ---------+-----------+-----------+----------------- 0/15892E0 | 0/1589318 | 0/15891E8 | COMMIT_PREPARED.

Shouldn't we use 'XactLastCommitEnd' in apply_handle_commit_prepared()
which is the end position of last COMMIT_PREPARED? It is assigned in
the below flow:
apply_handle_commit_prepared-->CommitTransactionCommand...->RecordTransactionCommit?

Please let me know if I have misunderstood.

[1]: Pub: ------ SELECT * FROM pg_get_wal_record_info('0/15892E0'); start_lsn | end_lsn | prev_lsn | record_type ---------+-----------+-----------+----------------- 0/15892E0 | 0/1589318 | 0/15891E8 | COMMIT_PREPARED

Pub:
------
SELECT * FROM pg_get_wal_record_info('0/15892E0');
start_lsn | end_lsn | prev_lsn | record_type
---------+-----------+-----------+-----------------
0/15892E0 | 0/1589318 | 0/15891E8 | COMMIT_PREPARED

--see prev_lsn
SELECT * FROM pg_get_wal_record_info('0/15891E8');
start_lsn | end_lsn | prev_lsn | record_type
---------+-----------+-----------+-------------
0/15891E8 | 0/15892E0 | 0/15891A8 | PREPARE

SELECT * FROM pg_get_wal_record_info('0/1589318');
start_lsn | end_lsn | prev_lsn | record_type
---------+-----------+-----------+---------------
0/1589318 | 0/1589350 | 0/15892E0 | RUNNING_XACTS

--see prev_lsn
SELECT * FROM pg_get_wal_record_info('0/15892E0');
start_lsn | end_lsn | prev_lsn | record_type
---------+-----------+-----------+-----------------
0/15892E0 | 0/1589318 | 0/15891E8 | COMMIT_PREPARED

Sub:
------
SELECT * FROM pg_get_wal_record_info('0/1537FD8');
start_lsn | end_lsn | prev_lsn | record_type
---------+-----------+-----------+------------------
0/1537FD8 | 0/1538030 | 0/1537ED0 | COMMIT_PREPARED

--see prev_lsn:
SELECT * FROM pg_get_wal_record_info('0/1537ED0');
start_lsn | end_lsn | prev_lsn |record_type
---------+-----------+-----------+------------
0/1537ED0 | 0/1537FD8 | 0/1537E90 |PREPARE

thanks
Shveta

On Wed, Aug 7, 2024 at 12:38 PM shveta malik <shveta.malik@gmail.com> wrote:

On Wed, Jul 24, 2024 at 12:25 PM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:

Issue #1

When handling a PREPARE message, the subscriber mistook the wrong lsn position
(the end position of the last commit) as the end position of the current prepare.
This can be fixed by adding a new global variable to record the end position of
the last prepare. 0001 patch fixes the issue.

Thanks for the patches. I have started reviewing this. I reviewed and
tested patch001 alone.

It makes sense. As both are different bugs we should discuss them separately.

I have a query, shouldn't the local-lsn stored in
apply_handle_commit_prepared() be the end position of
'COMMIT_PREPARED' instead of 'PREPARE'? I put additional logging on
sub and got this:

LOG: apply_handle_prepare - prepare_data.end_lsn: 0/15892E0 ,
XactLastPrepareEnd: 0/1537FD8.
LOG: apply_handle_commit_prepared - prepare_data.end_lsn: 0/1589318
, XactLastPrepareEnd: 0/1537FD8.

In apply_handle_prepare(), remote-lsn ('0/15892E0') is end position of
'PREPARE' and in apply_handle_commit_prepared(), remote-lsn
('0/1589318') is end position of 'COMMIT_PREPARED', while local-lsn in
both cases is end-lsn of 'PREPARE'. Details at [1].

Shouldn't we use 'XactLastCommitEnd' in apply_handle_commit_prepared()
which is the end position of last COMMIT_PREPARED? It is assigned in
the below flow:
apply_handle_commit_prepared-->CommitTransactionCommand...->RecordTransactionCommit?

I also think so. Additionally, I feel a test case (or some description
of the bug that can arise) should be provided for issue-1.

--
With Regards,
Amit Kapila.

On Wed, Aug 7, 2024 at 3:32 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

I also think so. Additionally, I feel a test case (or some description
of the bug that can arise) should be provided for issue-1.

IIUC, the problem could be that we would end up updating the wrong
local_end LSN in lsn_mappings via store_flush_position(). Then
get_flush_position() could end up computing the wrong flush position
and send the confirmation of flush to the publisher even when it is
not flushed. This ideally could lead to a situation where the prepared
transaction is not flushed to disk on the subscriber and because
publisher would have gotten the confirmation earlier than required, it
won't send the prepared transaction again. I think this theory is not
true for prepare transactions because we always flush WAL of prepare
even for asynchronous commit mode. See EndPrepare(). So, if my
analysis is correct, this shouldn't be a bug and ideally, we should
update local_end LSN as InvalidXLogRecPtr and add appropriate
comments.

--
With Regards,
Amit Kapila.

On Wed, Aug 7, 2024 at 5:43 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Wed, Aug 7, 2024 at 3:32 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

I also think so. Additionally, I feel a test case (or some description
of the bug that can arise) should be provided for issue-1.

IIUC, the problem could be that we would end up updating the wrong
local_end LSN in lsn_mappings via store_flush_position(). Then
get_flush_position() could end up computing the wrong flush position
and send the confirmation of flush to the publisher even when it is
not flushed. This ideally could lead to a situation where the prepared
transaction is not flushed to disk on the subscriber and because
publisher would have gotten the confirmation earlier than required, it
won't send the prepared transaction again.

Yes, that is what my understanding was.

I think this theory is not
true for prepare transactions because we always flush WAL of prepare
even for asynchronous commit mode. See EndPrepare().

Okay, I was not aware of this. Thanks for explaining.

So, if my
analysis is correct, this shouldn't be a bug and ideally, we should
update local_end LSN as InvalidXLogRecPtr and add appropriate
comments.

Okay, we can do that. Then get_flush_position() can also be changed to
*explicitly* deal with the case where local_end is InvalidXLogRecPtr.
Having said that, even though it is not a bug, shouldn't we still have
the correct mapping updated in lsn_mapping? When remote_end is PREPARE
Or COMMIT_PREPARED, local_end should also point to the same?

thanks
Shveta

On Thu, Aug 8, 2024 at 8:54 AM shveta malik <shveta.malik@gmail.com> wrote:

On Wed, Aug 7, 2024 at 5:43 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

So, if my
analysis is correct, this shouldn't be a bug and ideally, we should
update local_end LSN as InvalidXLogRecPtr and add appropriate
comments.

Okay, we can do that. Then get_flush_position() can also be changed to
*explicitly* deal with the case where local_end is InvalidXLogRecPtr.

AFAICS, it should be handled without any change as the value of
InvalidXLogRecPtr is 0. So, it should be less than equal to the
local_flush position.

Having said that, even though it is not a bug, shouldn't we still have
the correct mapping updated in lsn_mapping? When remote_end is PREPARE
Or COMMIT_PREPARED, local_end should also point to the same?

Ideally yes, but introducing a new global variable just for this
purpose doesn't sound advisable. We can add in comments that in the
future, if adding such a variable serves some purpose then we can
surely extend the functionality.

--
With Regards,
Amit Kapila.

On Wed, Jul 24, 2024 at 12:25 PM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:

While creating a patch which allows ALTER SUBSCRIPTION SET (two_phase) [1],
we found some issues related with logical replication and two_phase. I think this
can happen not only HEAD but PG14+, but for now I shared patches for HEAD.

Issue #1

When handling a PREPARE message, the subscriber mistook the wrong lsn position
(the end position of the last commit) as the end position of the current prepare.
This can be fixed by adding a new global variable to record the end position of
the last prepare. 0001 patch fixes the issue.

Issue #2

When the subscriber enables two-phase commit but doesn't set max_prepared_transaction >0
and a transaction is prepared on the publisher, the apply worker reports an ERROR
on the subscriber. After that, the prepared transaction is not replayed, which
means it's lost forever. Attached script can emulate the situation.

--
ERROR: prepared transactions are disabled
HINT: Set "max_prepared_transactions" to a nonzero value.
--

The reason is that we advanced the origin progress when aborting the
transaction as well (RecordTransactionAbort->replorigin_session_advance). So,
after setting replorigin_session_origin_lsn, if any ERROR happens when preparing
the transaction, the transaction aborts which incorrectly advances the origin lsn.

An easiest fix is to reset session replication origin before calling the
RecordTransactionAbort(). I think this can happen when 1) LogicalRepApplyLoop()
raises an ERROR or 2) apply worker exits. 0002 patch fixes the issue.

Can we start a separate thread to issue 2? I understand that this one
is also related to two_phase but since both are different issues it is
better to discuss in separate threads. This will also help us refer to
the discussion in future if required.

BTW, why did the 0002 patch change the below code:
--- a/src/include/replication/worker_internal.h
+++ b/src/include/replication/worker_internal.h
@@ -164,7 +164,8 @@ typedef struct ParallelApplyWorkerShared

  /*
  * XactLastCommitEnd or XactLastPrepareEnd from the parallel apply worker.
- * This is required by the leader worker so it can update the lsn_mappings.
+ * This is required by the leader worker so it can update the
+ * lsn_mappings.
  */
  XLogRecPtr last_commit_end;

--
With Regards,
Amit Kapila.

Dear Amit,

Can we start a separate thread to issue 2? I understand that this one
is also related to two_phase but since both are different issues it is
better to discuss in separate threads. This will also help us refer to
the discussion in future if required.

You are right, we should discuss one topic per thread. Forked: [1]/messages/by-id/TYAPR01MB5692FAC23BE40C69DA8ED4AFF5B92@TYAPR01MB5692.jpnprd01.prod.outlook.com.

BTW, why did the 0002 patch change the below code:
--- a/src/include/replication/worker_internal.h
+++ b/src/include/replication/worker_internal.h
@@ -164,7 +164,8 @@ typedef struct ParallelApplyWorkerShared

/*
* XactLastCommitEnd or XactLastPrepareEnd from the parallel apply worker.
- * This is required by the leader worker so it can update the lsn_mappings.
+ * This is required by the leader worker so it can update the
+ * lsn_mappings.
*/
XLogRecPtr last_commit_end;

Opps. Fixed version is posted in [1]/messages/by-id/TYAPR01MB5692FAC23BE40C69DA8ED4AFF5B92@TYAPR01MB5692.jpnprd01.prod.outlook.com.

[1]: /messages/by-id/TYAPR01MB5692FAC23BE40C69DA8ED4AFF5B92@TYAPR01MB5692.jpnprd01.prod.outlook.com

Best regards,
Hayato Kuroda
FUJITSU LIMITED

On Thu, Aug 8, 2024 at 9:53 AM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Thu, Aug 8, 2024 at 8:54 AM shveta malik <shveta.malik@gmail.com> wrote:

On Wed, Aug 7, 2024 at 5:43 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

So, if my
analysis is correct, this shouldn't be a bug and ideally, we should
update local_end LSN as InvalidXLogRecPtr and add appropriate
comments.

Okay, we can do that. Then get_flush_position() can also be changed to
*explicitly* deal with the case where local_end is InvalidXLogRecPtr.

AFAICS, it should be handled without any change as the value of
InvalidXLogRecPtr is 0. So, it should be less than equal to the
local_flush position.

Yes, existing code will work, no doubt about that. But generally we
explictly use XLogRecPtrIsInvalid if we need to include or exclude
lsn=0 in some logic. We do not consider 0 lsn for comparisons like
this which we currently have in get_flush_position. Thus stated for an
explicit check. But, yes, the current code will work.

Having said that, even though it is not a bug, shouldn't we still have
the correct mapping updated in lsn_mapping? When remote_end is PREPARE
Or COMMIT_PREPARED, local_end should also point to the same?

Ideally yes, but introducing a new global variable just for this
purpose doesn't sound advisable. We can add in comments that in the
future, if adding such a variable serves some purpose then we can
surely extend the functionality.

Okay. Sounds reasonable.

thanks
Shveta

Dear Amit, Shveta,

Thanks for discussing!

I reported the issue because 1) I feared the risk of data loss and 2) simply
because the coding looked incorrect. However, per discussion, I understood that
it wouldn't lead to loss, and adding a global variable was unacceptable in this
case. I modified the patch completely.

The attached patch avoids using the LastCommitLSN as the local_lsn while applying
PREPARE. get_flush_position() was not changed. Also, it contains changes that
have not been discussed yet:

- Set last_commit_end to InvaldXLogPtr in the PREPARE case.
This causes the same result as when the stream option is not "parallel."
- XactLastCommitEnd was replaced even ROLLBACK PREPARED case.
Since the COMMIT PREPARED record is flushed in RecordTransactionAbortPrepared(),
there is no need to ensure the WAL must be sent.

Best regards,
Hayato Kuroda
FUJITSU LIMITED

On Thu, Aug 8, 2024 at 2:37 PM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:

Thanks for discussing!

I reported the issue because 1) I feared the risk of data loss and 2) simply
because the coding looked incorrect. However, per discussion, I understood that
it wouldn't lead to loss, and adding a global variable was unacceptable in this
case. I modified the patch completely.

The attached patch avoids using the LastCommitLSN as the local_lsn while applying
PREPARE. get_flush_position() was not changed. Also, it contains changes that
have not been discussed yet:

- Set last_commit_end to InvaldXLogPtr in the PREPARE case.
This causes the same result as when the stream option is not "parallel."
- XactLastCommitEnd was replaced even ROLLBACK PREPARED case.
Since the COMMIT PREPARED record is flushed in RecordTransactionAbortPrepared(),
there is no need to ensure the WAL must be sent.

The code changes look mostly good to me. I have changed/added a few
comments in the attached modified version.

--
With Regards,
Amit Kapila.

On Thu, Aug 8, 2024 at 5:53 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Thu, Aug 8, 2024 at 2:37 PM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:

Thanks for discussing!

I reported the issue because 1) I feared the risk of data loss and 2) simply
because the coding looked incorrect. However, per discussion, I understood that
it wouldn't lead to loss, and adding a global variable was unacceptable in this
case. I modified the patch completely.

The attached patch avoids using the LastCommitLSN as the local_lsn while applying
PREPARE. get_flush_position() was not changed. Also, it contains changes that
have not been discussed yet:

- Set last_commit_end to InvaldXLogPtr in the PREPARE case.
This causes the same result as when the stream option is not "parallel."
- XactLastCommitEnd was replaced even ROLLBACK PREPARED case.
Since the COMMIT PREPARED record is flushed in RecordTransactionAbortPrepared(),
there is no need to ensure the WAL must be sent.

The code changes look mostly good to me. I have changed/added a few
comments in the attached modified version.

Code changes with Amit's correction patch look good to me.

thanks
Shveta

Dear Amit,

The code changes look mostly good to me. I have changed/added a few
comments in the attached modified version.

Thanks for updating the patch! It LGTM. I've tested your patch and confirmed
it did not cause the data loss. I used the source which was applied v3 and additional
fix to visualize the replication command [1]``` @@ -3297,6 +3297,8 @@ apply_dispatch(StringInfo s) saved_command = apply_error_callback_arg.command; apply_error_callback_arg.command = action;.

Method
======

1. Construct a logical replication system with two_phase = true and
synchronous_commit = false
2. attach a walwriter of the subscriber to stop the process
3. Start a transaction and prepare it for the publisher.
4. Wait until the worker replies to the publisher.
5. Stop the subscriber
6. Restart subscriber.
7. Do COMMIT PREPARED

Attached script can construct the same situation.

Result
======

After the step 5, I ran pg_waldump and confirmed PREPARE record existed on
the subscriber.

```
$ pg_waldump data_sub/pg_wal/000000010000000000000001
...
rmgr: Transaction len..., desc: PREPARE gid pg_gid_16389_741: ...
rmgr: XLOG len..., desc: CHECKPOINT_SHUTDOWN ...
```

Also, after the step 7, I confirmed that only the COMMIT PREPARED record
was sent because log output the below line. "75" means the ASCII character 'K';
this indicated that the replication message corresponded to COMMIT PREPARED.
```
LOG: XXX got message 75
```

Additionally, I did another test, which is basically same as above but 1) XLogFlush()
in EndPrepare() was commented out and 2) kill -9 was used at step 5 to emulate a
crash. Since the PREPAREd transaction cannot survive on the subscriber in this case,
so COMMIT PREPARED command on publisher causes an ERROR on the subscriber.
```
ERROR: prepared transaction with identifier "pg_gid_16389_741" does not exist
CONTEXT: processing remote data for replication origin "pg_16389" during message
type "COMMIT PREPARED" in transaction 741, finished at 0/15463C0
```
I think this shows that the backend process can ensure the WAL is persisted so data loss
won't occur.

[1]: ``` @@ -3297,6 +3297,8 @@ apply_dispatch(StringInfo s) saved_command = apply_error_callback_arg.command; apply_error_callback_arg.command = action;
```
@@ -3297,6 +3297,8 @@ apply_dispatch(StringInfo s)
saved_command = apply_error_callback_arg.command;
apply_error_callback_arg.command = action;

+ elog(LOG, "XXX got message %d", action);
```

Best regards,
Hayato Kuroda
FUJITSU LIMITED

On Fri, Aug 9, 2024 at 10:34 AM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:

The code changes look mostly good to me. I have changed/added a few
comments in the attached modified version.

Thanks for updating the patch! It LGTM. I've tested your patch and confirmed
it did not cause the data loss.

Thanks for the additional testing. I have pushed this patch.

--
With Regards,
Amit Kapila.