pg.ddx.io pgsql-bugs@postgresql.org mailing list archive
help / color / mirror / Atom feedBUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
10+ messages / 4 participants
[nested] [flat]
Commits from this thread:
2024-10-07 efe706e273 8175a7d11f 0f0e253dbf 9181077590 022564f60c Fix fetching default toast value during decoding of in-progress transactions.
* BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-09-28 11:00 PG Bug reporting form <noreply@postgresql.org>
0 siblings, 1 reply; 10+ messages in thread
From: PG Bug reporting form @ 2024-09-28 11:00 UTC (permalink / raw)
To: pgsql-bugs@lists.postgresql.org; +Cc: exclusion@gmail.com
The following bug has been logged on the website:
Bug reference: 18641
Logged by: Alexander Lakhin
Email address: exclusion@gmail.com
PostgreSQL version: 17.0
Operating system: Ubuntu 22.04
Description:
Logical decoding of a transaction like:
BEGIN;
INSERT INTO test_tab VALUES(1);
PREPARE TRANSACTION 'pt';
where test_tab defined as:
CREATE TABLE test_tab(a int primary key,
t text DEFAULT 'Some TOASTable value';
for a subscription created with two_phase = on, fails as below:
2024-09-28 06:44:50.708 UTC [3741774:6][client backend][6/2:740] LOG:
statement: PREPARE TRANSACTION 'pt';
2024-09-28 06:44:50.709 UTC [3741774:7][client backend][:0] LOG:
disconnection: session time: 0:00:00.006 user=law database=postgres
host=[local]
2024-09-28 06:44:50.713 UTC [3741741:17][walsender][25/0:0] ERROR:
unexpected table_index_fetch_tuple call during logical decoding
2024-09-28 06:44:50.713 UTC [3741741:18][walsender][25/0:0] BACKTRACE:
table_index_fetch_tuple at tableam.h:1253:3
index_fetch_heap at indexam.c:637:10
index_getnext_slot at indexam.c:697:6
systable_getnext_ordered at genam.c:717:5
heap_fetch_toast_slice at heaptoast.c:698:17
table_relation_fetch_toast_slice at tableam.h:1924:1
toast_fetch_datum at detoast.c:379:2
detoast_attr at detoast.c:123:10
pg_detoast_datum_packed at fmgr.c:1867:10
text_to_cstring at varlena.c:220:23
AttrDefaultFetch at relcache.c:4537:17
RelationBuildTupleDesc at relcache.c:697:4
RelationBuildDesc at relcache.c:1188:24
RelationIdGetRelation at relcache.c:2116:7
ReorderBufferProcessTXN at reorderbuffer.c:2246:17
ReorderBufferReplay at reorderbuffer.c:2725:2
ReorderBufferPrepare at reorderbuffer.c:2822:2
DecodePrepare at decode.c:826:2
xact_decode at decode.c:347:5
LogicalDecodingProcessRecord at decode.c:123:1
XLogSendLogical at walsender.c:3413:33
WalSndLoop at walsender.c:2814:4
StartLogicalReplication at walsender.c:1523:2
exec_replication_command at walsender.c:2148:5
PostgresMain at postgres.c:4763:11
BackendInitialize at backend_startup.c:123:1
postmaster_child_launch at launch_backend.c:281:9
BackendStartup at postmaster.c:3593:8
ServerLoop at postmaster.c:1677:10
PostmasterMain at postmaster.c:1372:11
startup_hacks at main.c:217:1
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)
[0x7f30a90d7e40]
postgres: node_publisher: walsender law postgres [local]
START_REPLICATION(_start+0x25) [0x5647b6023565]
2024-09-28 06:44:50.713 UTC [3741741:19][walsender][25/0:0] LOG: released
logical replication slot "test_sub"
2024-09-28 06:44:50.713 UTC [3741741:20][walsender][25/0:0] LOG: could not
send data to client: Broken pipe
2024-09-28 06:44:50.713 UTC [3741741:21][walsender][25/0:0] FATAL:
connection to client lost
The issue can be easily reproduced with 022_twophase_cascade.pl modified
like this:
@@ -67,0 +68 @@ $node_A->safe_psql('postgres',
+my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
@@ -69 +70 @@ $node_B->safe_psql('postgres',
- "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
DEFAULT now(), d bigint DEFAULT 999)"
+ "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
DEFAULT now(), d bigint DEFAULT 999, t text DEFAULT '$default')"
@@ -72 +73 @@ $node_C->safe_psql('postgres',
- "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
DEFAULT now(), d bigint DEFAULT 999)"
+ "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
DEFAULT now(), d bigint DEFAULT 999, t text DEFAULT '$default')"
Reproduced on REL_15_STABLE (starting from a8fd13cab) .. master.
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-09-30 01:16 Takeshi Ideriha <iderihatakeshi@gmail.com>
parent: PG Bug reporting form <noreply@postgresql.org>
0 siblings, 2 replies; 10+ messages in thread
From: Takeshi Ideriha @ 2024-09-30 01:16 UTC (permalink / raw)
To: exclusion@gmail.com; pgsql-bugs@lists.postgresql.org
Hi, Alexander and hackers
>
> The following bug has been logged on the website:
>
> Bug reference: 18641
> Logged by: Alexander Lakhin
> Email address: exclusion@gmail.com
> PostgreSQL version: 17.0
> Operating system: Ubuntu 22.04
> Description:
>
> Logical decoding of a transaction like:
> BEGIN;
> INSERT INTO test_tab VALUES(1);
> PREPARE TRANSACTION 'pt';
>
> where test_tab defined as:
> CREATE TABLE test_tab(a int primary key,
> t text DEFAULT 'Some TOASTable value';
>
> for a subscription created with two_phase = on, fails as below:
> 2024-09-28 06:44:50.708 UTC [3741774:6][client backend][6/2:740] LOG:
> statement: PREPARE TRANSACTION 'pt';
> 2024-09-28 06:44:50.709 UTC [3741774:7][client backend][:0] LOG:
> disconnection: session time: 0:00:00.006 user=law database=postgres
> host=[local]
> 2024-09-28 06:44:50.713 UTC [3741741:17][walsender][25/0:0] ERROR:
> unexpected table_index_fetch_tuple call during logical decoding
> 2024-09-28 06:44:50.713 UTC [3741741:18][walsender][25/0:0] BACKTRACE:
> table_index_fetch_tuple at tableam.h:1253:3
> index_fetch_heap at indexam.c:637:10
> index_getnext_slot at indexam.c:697:6
> systable_getnext_ordered at genam.c:717:5
> heap_fetch_toast_slice at heaptoast.c:698:17
> table_relation_fetch_toast_slice at tableam.h:1924:1
> toast_fetch_datum at detoast.c:379:2
> detoast_attr at detoast.c:123:10
> pg_detoast_datum_packed at fmgr.c:1867:10
> text_to_cstring at varlena.c:220:23
> AttrDefaultFetch at relcache.c:4537:17
> RelationBuildTupleDesc at relcache.c:697:4
> RelationBuildDesc at relcache.c:1188:24
> RelationIdGetRelation at relcache.c:2116:7
> ReorderBufferProcessTXN at reorderbuffer.c:2246:17
> ReorderBufferReplay at reorderbuffer.c:2725:2
> ReorderBufferPrepare at reorderbuffer.c:2822:2
> DecodePrepare at decode.c:826:2
> xact_decode at decode.c:347:5
> LogicalDecodingProcessRecord at decode.c:123:1
> XLogSendLogical at walsender.c:3413:33
> WalSndLoop at walsender.c:2814:4
> StartLogicalReplication at walsender.c:1523:2
> exec_replication_command at walsender.c:2148:5
> PostgresMain at postgres.c:4763:11
> BackendInitialize at backend_startup.c:123:1
> postmaster_child_launch at launch_backend.c:281:9
> BackendStartup at postmaster.c:3593:8
> ServerLoop at postmaster.c:1677:10
> PostmasterMain at postmaster.c:1372:11
> startup_hacks at main.c:217:1
> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)
> [0x7f30a90d7e40]
> postgres: node_publisher: walsender law postgres [local]
> START_REPLICATION(_start+0x25) [0x5647b6023565]
> 2024-09-28 06:44:50.713 UTC [3741741:19][walsender][25/0:0] LOG: released
> logical replication slot "test_sub"
> 2024-09-28 06:44:50.713 UTC [3741741:20][walsender][25/0:0] LOG: could not
> send data to client: Broken pipe
> 2024-09-28 06:44:50.713 UTC [3741741:21][walsender][25/0:0] FATAL:
> connection to client lost
>
> The issue can be easily reproduced with 022_twophase_cascade.pl modified
> like this:
> @@ -67,0 +68 @@ $node_A->safe_psql('postgres',
> +my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
> @@ -69 +70 @@ $node_B->safe_psql('postgres',
> - "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
> DEFAULT now(), d bigint DEFAULT 999)"
> + "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
> DEFAULT now(), d bigint DEFAULT 999, t text DEFAULT '$default')"
> @@ -72 +73 @@ $node_C->safe_psql('postgres',
> - "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
> DEFAULT now(), d bigint DEFAULT 999)"
> + "CREATE TABLE test_tab (a int primary key, b bytea, c timestamptz
> DEFAULT now(), d bigint DEFAULT 999, t text DEFAULT '$default')"
>
> Reproduced on REL_15_STABLE (starting from a8fd13cab) .. master.
Thank you for reporting the issue.
I was able to reproduce the issue by modifying 022_twophase_cascade.pl
accordingly.
The scan for toast index is actually done under systable_getnext_ordered,
where HandleConcurrentAbort() is called. So it seems to me that this
scan is actually safe for concurrent abort in logical decoding.
Logic around HandleConcurrentAbort is intorduced
https://github.com/postgres/postgres/commit/7259736a6e5b7c7588fff9578370736a6648acbb.
Though I may not understand the logic around HandleConcurrentAbort
fully and I am not sure not-setting bsysscan at
systable_beginscan_ordered is intentional,
it seems to me setting and unsetting a bsysscan flag in
systable_beginscan_ordered and systable_endscan_ordered would resolve
the issue.
Patch is attached.
Regards,
Takeshi Ideriha
Attachments:
0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered.patch (application/octet-stream, 1.5K) download
From 181ff3783ea73ef909aec23b7fdd2378d08f166a Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 17 +++++++++++++++++
1 file changed, 17 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 52fde5cc4d..94a00ec00b 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -713,6 +713,15 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, idxkey, nkeys, NULL, 0);
sysscan->scan = NULL;
+
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -757,6 +766,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.40.1
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-09-30 12:44 Amit Kapila <amit.kapila16@gmail.com>
parent: Takeshi Ideriha <iderihatakeshi@gmail.com>
1 sibling, 0 replies; 10+ messages in thread
From: Amit Kapila @ 2024-09-30 12:44 UTC (permalink / raw)
To: Takeshi Ideriha <iderihatakeshi@gmail.com>; +Cc: exclusion@gmail.com; pgsql-bugs@lists.postgresql.org
On Mon, Sep 30, 2024 at 6:46 AM Takeshi Ideriha
<iderihatakeshi@gmail.com> wrote:
>
> Patch is attached.
>
Thanks for the patch. I'll look into it.
--
With Regards,
Amit Kapila.
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-09-30 16:20 Amit Kapila <amit.kapila16@gmail.com>
parent: Takeshi Ideriha <iderihatakeshi@gmail.com>
1 sibling, 1 reply; 10+ messages in thread
From: Amit Kapila @ 2024-09-30 16:20 UTC (permalink / raw)
To: Takeshi Ideriha <iderihatakeshi@gmail.com>; +Cc: exclusion@gmail.com; pgsql-bugs@lists.postgresql.org
On Mon, Sep 30, 2024 at 6:46 AM Takeshi Ideriha
<iderihatakeshi@gmail.com> wrote:
>
> Thank you for reporting the issue.
> I was able to reproduce the issue by modifying 022_twophase_cascade.pl
> accordingly.
>
> The scan for toast index is actually done under systable_getnext_ordered,
> where HandleConcurrentAbort() is called. So it seems to me that this
> scan is actually safe for concurrent abort in logical decoding.
> Logic around HandleConcurrentAbort is intorduced
> https://github.com/postgres/postgres/commit/7259736a6e5b7c7588fff9578370736a6648acbb.
>
> Though I may not understand the logic around HandleConcurrentAbort
> fully and I am not sure not-setting bsysscan at
> systable_beginscan_ordered is intentional,
> it seems to me setting and unsetting a bsysscan flag in
> systable_beginscan_ordered and systable_endscan_ordered would resolve
> the issue.
>
We forgot to set/unset the flag in functions
systable_beginscan_ordered and systable_endscan_ordered. BTW,
shouldn't this occur even without prepare transaction? If so, we need
to backpatch this till 14.
Also, it is better to have a test for this, and let's ensure that the
new test doesn't increase the regression time too much if possible.
One minor point:
+
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
The indentation in the first comment line seems off.
--
With Regards,
Amit Kapila.
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-10-01 13:37 Takeshi Ideriha <iderihatakeshi@gmail.com>
parent: Amit Kapila <amit.kapila16@gmail.com>
0 siblings, 3 replies; 10+ messages in thread
From: Takeshi Ideriha @ 2024-10-01 13:37 UTC (permalink / raw)
To: Amit Kapila <amit.kapila16@gmail.com>; pgsql-hackers@postgresql.org; +Cc: exclusion@gmail.com; pgsql-bugs@lists.postgresql.org
Hi, Amit
(adding hackers for discussion)
>We forgot to set/unset the flag in functions
>systable_beginscan_ordered and systable_endscan_ordered. BTW,
Thank you for the clarification.
>shouldn't this occur even without prepare transaction? If so, we need
>to backpatch this till 14.
Yes, it occurred also at PG14.
I did some tests using 015_stream.pl with some modification like
below, which tests the subscription about stream is on but two-phase
is off.
The same issue occurred at both current head source code and PG14.
```
inline patch 1: src/test/subscription/t/015_stream.pl (+0/-0 lines) download inline-1.patch
--- a/src/test/subscription/t/015_stream.pl
+++ b/src/test/subscription/t/015_stream.pl
@@ -134,9 +134,11 @@ my $node_subscriber =
PostgreSQL::Test::Cluster->new('subscriber');
$node_subscriber->init;
$node_subscriber->start;
+my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
+
# Create some preexisting content on publisher
$node_publisher->safe_psql('postgres',
- "CREATE TABLE test_tab (a int primary key, b bytea)");
+ "CREATE TABLE test_tab (a int primary key, b bytea, t text
DEFAULT '$default')");
$node_publisher->safe_psql('postgres',
"INSERT INTO test_tab VALUES (1, 'foo'), (2, 'bar')");
@@ -144,7 +146,7 @@ $node_publisher->safe_psql('postgres', "CREATE
TABLE test_tab_2 (a int)");
# Setup structure on subscriber
$node_subscriber->safe_psql('postgres',
- "CREATE TABLE test_tab (a int primary key, b bytea, c
timestamptz DEFAULT now(), d bigint DEFAULT 999)"
+ "CREATE TABLE test_tab (a int primary key, b bytea, t text
DEFAULT '$default', c timestamptz DEFAULT now(), d bigint DEFAULT
999)"
);
```
Logs from head source:
```
2024-10-01 12:34:56.694 UTC [575202] LOG: starting PostgreSQL 18devel
on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
11.4.1-2), 64-bit
...
2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement: BEGIN;
2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement:
INSERT INTO test_tab SELECT i, sha256(i::text::bytea) FROM
generate_series(3, 5000) s(i);
2024-10-01 12:34:57.524 UTC [575242] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 12:34:57.524 UTC [575242] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: released logical
replication slot "tap_sub"
2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 12:34:57.525 UTC [575242] tap_sub FATAL: connection to client lost
...
2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: starting logical
decoding for slot "tap_sub"
2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: Streaming
transactions committing after 0/1583A68, reading WAL from 0/1583A30.
2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: logical decoding
found consistent point at 0/1583A30
2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: There are no
running transactions.
2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.831 UTC [575260] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 12:34:57.831 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: released logical
replication slot "tap_sub"
2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 12:34:57.832 UTC [575260] tap_sub FATAL: connection to client lost
```
Logs from PG14 source:
```
2024-10-01 13:20:29.409 UTC [593696] LOG: starting PostgreSQL 14.9 on
x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
11.4.1-2), 64-bit
...
2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement: BEGIN;
2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement:
INSERT INTO test_tab SELECT i, md5(i::text) FROM generate_series(3,
5000) s(i);
2024-10-01 13:20:31.301 UTC [593740] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 13:20:31.301 UTC [593740] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.302 UTC [593740] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 13:20:31.302 UTC [593740] tap_sub FATAL: connection to client lost
...
2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.830 UTC [593756] tap_sub LOG: logical decoding
found consistent point at 0/172C758
2024-10-01 13:20:31.830 UTC [593756] tap_sub DETAIL: There are no
running transactions.
2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.834 UTC [593756] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 13:20:31.834 UTC [593756] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.835 UTC [593756] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 13:20:31.835 UTC [593756] tap_sub FATAL: connection to client lost
```
>Also, it is better to have a test for this, and let's ensure that the
>new test doesn't increase the regression time too much if possible.
Sure. I'm going to add some test codes in a few days.
> The indentation in the first comment line seems off.
Opps, thank you. Fixed.
regards,
Takeshi Ideriha
Patches and attachments: download all (2 files, .tar.gz)
0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered-v2.patch (application/x-patch, 1.5K) download
From 2a4116ebf5f6b838dd3df64c78322c4e70375b6f Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 52fde5cc4d..2ecc3e8b31 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -713,6 +713,14 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, idxkey, nkeys, NULL, 0);
sysscan->scan = NULL;
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -757,6 +765,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.40.1
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-10-02 00:36 Takeshi Ideriha <iderihatakeshi@gmail.com>
parent: Takeshi Ideriha <iderihatakeshi@gmail.com>
2 siblings, 0 replies; 10+ messages in thread
From: Takeshi Ideriha @ 2024-10-02 00:36 UTC (permalink / raw)
To: Amit Kapila <amit.kapila16@gmail.com>; +Cc: exclusion@gmail.com; pgsql-bugs@lists.postgresql.org
Hi, Amit
(Sending this again due to previous email got moderated because I
tried to multi post to hackers and bugs.)
>We forgot to set/unset the flag in functions
>systable_beginscan_ordered and systable_endscan_ordered. BTW,
Thank you for the clarification.
>shouldn't this occur even without prepare transaction? If so, we need
>to backpatch this till 14.
Yes, it occurred also at PG14.
I did some tests using 015_stream.pl with some modification like
below, which tests the subscription about stream is on but two-phase
is off.
The same issue occurred at both current head source code and PG14.
```
inline patch 1: src/test/subscription/t/015_stream.pl (+0/-0 lines) download inline-1.patch
--- a/src/test/subscription/t/015_stream.pl
+++ b/src/test/subscription/t/015_stream.pl
@@ -134,9 +134,11 @@ my $node_subscriber =
PostgreSQL::Test::Cluster->new
('subscriber');
$node_subscriber->init;
$node_subscriber->start;
+my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
+
# Create some preexisting content on publisher
$node_publisher->safe_psql('postgres',
- "CREATE TABLE test_tab (a int primary key, b bytea)");
+ "CREATE TABLE test_tab (a int primary key, b bytea, t text
DEFAULT '$default')");
$node_publisher->safe_psql('postgres',
"INSERT INTO test_tab VALUES (1, 'foo'), (2, 'bar')");
@@ -144,7 +146,7 @@ $node_publisher->safe_psql('postgres', "CREATE
TABLE test_tab_2 (a int)");
# Setup structure on subscriber
$node_subscriber->safe_psql('postgres',
- "CREATE TABLE test_tab (a int primary key, b bytea, c
timestamptz DEFAULT now(), d bigint DEFAULT 999)"
+ "CREATE TABLE test_tab (a int primary key, b bytea, t text
DEFAULT '$default', c timestamptz DEFAULT now(), d bigint DEFAULT
999)"
);
```
Logs from head source:
```
2024-10-01 12:34:56.694 UTC [575202] LOG: starting PostgreSQL 18devel
on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
11.4.1-2), 64-bit
...
2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement: BEGIN;
2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement:
INSERT INTO test_tab SELECT i, sha256(i::text::bytea) FROM
generate_series(3, 5000) s(i);
2024-10-01 12:34:57.524 UTC [575242] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 12:34:57.524 UTC [575242] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: released logical
replication slot "tap_sub"
2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 12:34:57.525 UTC [575242] tap_sub FATAL: connection to client lost
...
2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: starting logical
decoding for slot "tap_sub"
2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: Streaming
transactions committing after 0/1583A68, reading WAL from 0/1583A30.
2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: logical decoding
found consistent point at 0/1583A30
2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: There are no
running transactions.
2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.831 UTC [575260] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 12:34:57.831 UTC [575260] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
streaming 'on', origin 'any', publication_names '"tap_pub"')
2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: released logical
replication slot "tap_sub"
2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 12:34:57.832 UTC [575260] tap_sub FATAL: connection to client lost
```
Logs from PG14 source:
```
2024-10-01 13:20:29.409 UTC [593696] LOG: starting PostgreSQL 14.9 on
x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
11.4.1-2), 64-bit
...
2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement: BEGIN;
2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement:
INSERT INTO test_tab SELECT i, md5(i::text) FROM generate_series(3,
5000) s(i);
2024-10-01 13:20:31.301 UTC [593740] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 13:20:31.301 UTC [593740] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.302 UTC [593740] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 13:20:31.302 UTC [593740] tap_sub FATAL: connection to client lost
...
2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.830 UTC [593756] tap_sub LOG: logical decoding
found consistent point at 0/172C758
2024-10-01 13:20:31.830 UTC [593756] tap_sub DETAIL: There are no
running transactions.
2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.834 UTC [593756] tap_sub ERROR: unexpected
table_index_fetch_tuple call during logical decoding
2024-10-01 13:20:31.834 UTC [593756] tap_sub STATEMENT:
START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
streaming 'on', publication_names '"tap_pub"')
2024-10-01 13:20:31.835 UTC [593756] tap_sub LOG: could not send data
to client: Broken pipe
2024-10-01 13:20:31.835 UTC [593756] tap_sub FATAL: connection to client lost
```
>Also, it is better to have a test for this, and let's ensure that the
>new test doesn't increase the regression time too much if possible.
Sure. I'm going to add some test codes in a few days.
> The indentation in the first comment line seems off.
Opps, thank you. Fixed.
regards,
Takeshi Ideriha
Patches and attachments: download all (2 files, .tar.gz)
0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered-v2.patch (application/octet-stream, 1.5K) download
From 2a4116ebf5f6b838dd3df64c78322c4e70375b6f Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 52fde5cc4d..2ecc3e8b31 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -713,6 +713,14 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, idxkey, nkeys, NULL, 0);
sysscan->scan = NULL;
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -757,6 +765,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.40.1
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-10-05 10:12 Amit Kapila <amit.kapila16@gmail.com>
parent: Takeshi Ideriha <iderihatakeshi@gmail.com>
2 siblings, 0 replies; 10+ messages in thread
From: Amit Kapila @ 2024-10-05 10:12 UTC (permalink / raw)
To: Takeshi Ideriha <iderihatakeshi@gmail.com>; +Cc: pgsql-hackers@postgresql.org; exclusion@gmail.com; pgsql-bugs@lists.postgresql.org
On Tue, Oct 1, 2024 at 7:07 PM Takeshi Ideriha <iderihatakeshi@gmail.com> wrote:
>
> >We forgot to set/unset the flag in functions
> >systable_beginscan_ordered and systable_endscan_ordered. BTW,
>
> Thank you for the clarification.
>
> >shouldn't this occur even without prepare transaction? If so, we need
> >to backpatch this till 14.
>
> Yes, it occurred also at PG14.
> I did some tests using 015_stream.pl with some modification like
> below, which tests the subscription about stream is on but two-phase
> is off.
> The same issue occurred at both current head source code and PG14.
>
> ```
> --- a/src/test/subscription/t/015_stream.pl
> +++ b/src/test/subscription/t/015_stream.pl
> @@ -134,9 +134,11 @@ my $node_subscriber =
> PostgreSQL::Test::Cluster->new('subscriber');
> $node_subscriber->init;
> $node_subscriber->start;
>
> +my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
> +
> # Create some preexisting content on publisher
> $node_publisher->safe_psql('postgres',
> - "CREATE TABLE test_tab (a int primary key, b bytea)");
> + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> DEFAULT '$default')");
> $node_publisher->safe_psql('postgres',
> "INSERT INTO test_tab VALUES (1, 'foo'), (2, 'bar')");
>
> @@ -144,7 +146,7 @@ $node_publisher->safe_psql('postgres', "CREATE
> TABLE test_tab_2 (a int)");
>
> # Setup structure on subscriber
> $node_subscriber->safe_psql('postgres',
> - "CREATE TABLE test_tab (a int primary key, b bytea, c
> timestamptz DEFAULT now(), d bigint DEFAULT 999)"
> + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> DEFAULT '$default', c timestamptz DEFAULT now(), d bigint DEFAULT
> 999)"
> );
> ```
>
> Logs from head source:
> ```
> 2024-10-01 12:34:56.694 UTC [575202] LOG: starting PostgreSQL 18devel
> on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
> 11.4.1-2), 64-bit
> ...
> 2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement: BEGIN;
> 2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement:
> INSERT INTO test_tab SELECT i, sha256(i::text::bytea) FROM
> generate_series(3, 5000) s(i);
> 2024-10-01 12:34:57.524 UTC [575242] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 12:34:57.524 UTC [575242] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: released logical
> replication slot "tap_sub"
> 2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 12:34:57.525 UTC [575242] tap_sub FATAL: connection to client lost
> ...
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: starting logical
> decoding for slot "tap_sub"
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: Streaming
> transactions committing after 0/1583A68, reading WAL from 0/1583A30.
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: logical decoding
> found consistent point at 0/1583A30
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: There are no
> running transactions.
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.831 UTC [575260] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 12:34:57.831 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: released logical
> replication slot "tap_sub"
> 2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 12:34:57.832 UTC [575260] tap_sub FATAL: connection to client lost
> ```
>
> Logs from PG14 source:
>
> ```
> 2024-10-01 13:20:29.409 UTC [593696] LOG: starting PostgreSQL 14.9 on
> x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
> 11.4.1-2), 64-bit
> ...
> 2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement: BEGIN;
> 2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement:
> INSERT INTO test_tab SELECT i, md5(i::text) FROM generate_series(3,
> 5000) s(i);
> 2024-10-01 13:20:31.301 UTC [593740] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 13:20:31.301 UTC [593740] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.302 UTC [593740] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 13:20:31.302 UTC [593740] tap_sub FATAL: connection to client lost
> ...
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub LOG: logical decoding
> found consistent point at 0/172C758
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub DETAIL: There are no
> running transactions.
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.834 UTC [593756] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 13:20:31.834 UTC [593756] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.835 UTC [593756] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 13:20:31.835 UTC [593756] tap_sub FATAL: connection to client lost
> ```
>
> >Also, it is better to have a test for this, and let's ensure that the
> >new test doesn't increase the regression time too much if possible.
>
> Sure. I'm going to add some test codes in a few days.
>
The above test shown in the email will work to test this issue.
However, we should use 'debug_logical_replication_streaming' as that
will help to reproduce the issue with just one write operation. Is it
possible to add the test in 018_stream_subxact_abort where we already
use it?
--
With Regards,
Amit Kapila.
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-10-05 10:20 Amit Kapila <amit.kapila16@gmail.com>
parent: Takeshi Ideriha <iderihatakeshi@gmail.com>
2 siblings, 1 reply; 10+ messages in thread
From: Amit Kapila @ 2024-10-05 10:20 UTC (permalink / raw)
To: Takeshi Ideriha <iderihatakeshi@gmail.com>; +Cc: exclusion@gmail.com; pgsql-bugs@lists.postgresql.org
On Tue, Oct 1, 2024 at 7:07 PM Takeshi Ideriha <iderihatakeshi@gmail.com> wrote:
>
Sending it again to avoid getting it stuck because the original was
replied to both -hackers and -bugs.
>
> >We forgot to set/unset the flag in functions
> >systable_beginscan_ordered and systable_endscan_ordered. BTW,
>
> Thank you for the clarification.
>
> >shouldn't this occur even without prepare transaction? If so, we need
> >to backpatch this till 14.
>
> Yes, it occurred also at PG14.
> I did some tests using 015_stream.pl with some modification like
> below, which tests the subscription about stream is on but two-phase
> is off.
> The same issue occurred at both current head source code and PG14.
>
> ```
> --- a/src/test/subscription/t/015_stream.pl
> +++ b/src/test/subscription/t/015_stream.pl
> @@ -134,9 +134,11 @@ my $node_subscriber =
> PostgreSQL::Test::Cluster->new('subscriber');
> $node_subscriber->init;
> $node_subscriber->start;
>
> +my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
> +
> # Create some preexisting content on publisher
> $node_publisher->safe_psql('postgres',
> - "CREATE TABLE test_tab (a int primary key, b bytea)");
> + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> DEFAULT '$default')");
> $node_publisher->safe_psql('postgres',
> "INSERT INTO test_tab VALUES (1, 'foo'), (2, 'bar')");
>
> @@ -144,7 +146,7 @@ $node_publisher->safe_psql('postgres', "CREATE
> TABLE test_tab_2 (a int)");
>
> # Setup structure on subscriber
> $node_subscriber->safe_psql('postgres',
> - "CREATE TABLE test_tab (a int primary key, b bytea, c
> timestamptz DEFAULT now(), d bigint DEFAULT 999)"
> + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> DEFAULT '$default', c timestamptz DEFAULT now(), d bigint DEFAULT
> 999)"
> );
> ```
>
> Logs from head source:
> ```
> 2024-10-01 12:34:56.694 UTC [575202] LOG: starting PostgreSQL 18devel
> on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
> 11.4.1-2), 64-bit
> ...
> 2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement: BEGIN;
> 2024-10-01 12:34:57.506 UTC [575258] 015_stream.pl LOG: statement:
> INSERT INTO test_tab SELECT i, sha256(i::text::bytea) FROM
> generate_series(3, 5000) s(i);
> 2024-10-01 12:34:57.524 UTC [575242] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 12:34:57.524 UTC [575242] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: released logical
> replication slot "tap_sub"
> 2024-10-01 12:34:57.525 UTC [575242] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 12:34:57.525 UTC [575242] tap_sub FATAL: connection to client lost
> ...
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: starting logical
> decoding for slot "tap_sub"
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: Streaming
> transactions committing after 0/1583A68, reading WAL from 0/1583A30.
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub LOG: logical decoding
> found consistent point at 0/1583A30
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub DETAIL: There are no
> running transactions.
> 2024-10-01 12:34:57.829 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.831 UTC [575260] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 12:34:57.831 UTC [575260] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '4',
> streaming 'on', origin 'any', publication_names '"tap_pub"')
> 2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: released logical
> replication slot "tap_sub"
> 2024-10-01 12:34:57.832 UTC [575260] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 12:34:57.832 UTC [575260] tap_sub FATAL: connection to client lost
> ```
>
> Logs from PG14 source:
>
> ```
> 2024-10-01 13:20:29.409 UTC [593696] LOG: starting PostgreSQL 14.9 on
> x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat
> 11.4.1-2), 64-bit
> ...
> 2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement: BEGIN;
> 2024-10-01 13:20:31.285 UTC [593750] 015_stream.pl LOG: statement:
> INSERT INTO test_tab SELECT i, md5(i::text) FROM generate_series(3,
> 5000) s(i);
> 2024-10-01 13:20:31.301 UTC [593740] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 13:20:31.301 UTC [593740] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.302 UTC [593740] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 13:20:31.302 UTC [593740] tap_sub FATAL: connection to client lost
> ...
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub LOG: logical decoding
> found consistent point at 0/172C758
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub DETAIL: There are no
> running transactions.
> 2024-10-01 13:20:31.830 UTC [593756] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.834 UTC [593756] tap_sub ERROR: unexpected
> table_index_fetch_tuple call during logical decoding
> 2024-10-01 13:20:31.834 UTC [593756] tap_sub STATEMENT:
> START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2',
> streaming 'on', publication_names '"tap_pub"')
> 2024-10-01 13:20:31.835 UTC [593756] tap_sub LOG: could not send data
> to client: Broken pipe
> 2024-10-01 13:20:31.835 UTC [593756] tap_sub FATAL: connection to client lost
> ```
>
> >Also, it is better to have a test for this, and let's ensure that the
> >new test doesn't increase the regression time too much if possible.
>
> Sure. I'm going to add some test codes in a few days.
>
The above test shown in the email will work to test this issue.
However, we should use 'debug_logical_replication_streaming' as that
will help to reproduce the issue with just one write operation. Is it
possible to add the test in 018_stream_subxact_abort where we already
use it?
--
With Regards,
Amit Kapila.
^ permalink raw reply [nested|flat] 10+ messages in thread
* RE: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-10-07 05:57 Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
parent: Amit Kapila <amit.kapila16@gmail.com>
0 siblings, 1 reply; 10+ messages in thread
From: Zhijie Hou (Fujitsu) @ 2024-10-07 05:57 UTC (permalink / raw)
To: Amit Kapila <amit.kapila16@gmail.com>; Takeshi Ideriha <iderihatakeshi@gmail.com>; +Cc: exclusion@gmail.com <exclusion@gmail.com>; pgsql-bugs@lists.postgresql.org <pgsql-bugs@lists.postgresql.org>
On Saturday, October 5, 2024 6:12 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
Sending it again to avoid getting it stuck because the original was replied to both -hackers and -bugs.
>
> On Tue, Oct 1, 2024 at 7:07 PM Takeshi Ideriha
> <iderihatakeshi@gmail.com>
> wrote:
> >
> > >We forgot to set/unset the flag in functions
> > >systable_beginscan_ordered and systable_endscan_ordered. BTW,
> >
> > Thank you for the clarification.
> >
> > >shouldn't this occur even without prepare transaction? If so, we
> > >need to backpatch this till 14.
> >
> > Yes, it occurred also at PG14.
> > I did some tests using 015_stream.pl with some modification like
> > below, which tests the subscription about stream is on but two-phase
> > is off.
> > The same issue occurred at both current head source code and PG14.
> >
> > ```
> > --- a/src/test/subscription/t/015_stream.pl
> > +++ b/src/test/subscription/t/015_stream.pl
> > @@ -134,9 +134,11 @@ my $node_subscriber =
> > PostgreSQL::Test::Cluster->new('subscriber');
> > $node_subscriber->init;
> > $node_subscriber->start;
> >
> > +my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
> > +
> > # Create some preexisting content on publisher
> > $node_publisher->safe_psql('postgres',
> > - "CREATE TABLE test_tab (a int primary key, b bytea)");
> > + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> > DEFAULT '$default')");
> > $node_publisher->safe_psql('postgres',
> > "INSERT INTO test_tab VALUES (1, 'foo'), (2, 'bar')");
> >
> > @@ -144,7 +146,7 @@ $node_publisher->safe_psql('postgres', "CREATE
> > TABLE test_tab_2 (a int)");
> >
> > # Setup structure on subscriber
> > $node_subscriber->safe_psql('postgres',
> > - "CREATE TABLE test_tab (a int primary key, b bytea, c
> > timestamptz DEFAULT now(), d bigint DEFAULT 999)"
> > + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> > DEFAULT '$default', c timestamptz DEFAULT now(), d bigint DEFAULT
> > 999)"
> >
> > >Also, it is better to have a test for this, and let's ensure that
> > >the new test doesn't increase the regression time too much if possible.
> >
> > Sure. I'm going to add some test codes in a few days.
> >
>
> The above test shown in the email will work to test this issue.
> However, we should use 'debug_logical_replication_streaming' as that
> will help to reproduce the issue with just one write operation. Is it
> possible to add the test in 018_stream_subxact_abort where we already use it?
I think it might be better to put the test in test_decoding/sql/stream.sql as
the bug is only related to the decoding part. Writing it in sql test also seems cheaper.
Just share a top-up patch 0002 which includes the tests I suggested for
reference. The test would fail without the fix.
Node that I didn't change any logic in 0001 as the fix looks good to
me. I just ran the pgindent for the 0001.
Best Regards,
Hou zj
Attachments: download all (2 files, .tar.gz)
v3-0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered.patch (application/octet-stream, 1.5K) download
From 83804c82c289d2fc3fea00058fff0ab934b590ac Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH v3] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 52fde5cc4d..69c3608432 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -713,6 +713,14 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, idxkey, nkeys, NULL, 0);
sysscan->scan = NULL;
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -757,6 +765,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.31.1
v3-0002-add-a-testcase-in-stream.sql.patch (application/octet-stream, 2.8K) download
From f36657c9cfe1620a3f698a5932a97c019d7322e9 Mon Sep 17 00:00:00 2001
From: Hou Zhijie <houzj.fnst@cn.fujitsu.com>
Date: Mon, 7 Oct 2024 11:48:57 +0800
Subject: [PATCH v3 2/2] add a testcase in stream.sql
---
contrib/test_decoding/expected/stream.out | 22 ++++++++++++++++++++++
contrib/test_decoding/sql/stream.sql | 22 ++++++++++++++++++++++
2 files changed, 44 insertions(+)
diff --git a/contrib/test_decoding/expected/stream.out b/contrib/test_decoding/expected/stream.out
index a76f77601e..6a8a00a65b 100644
--- a/contrib/test_decoding/expected/stream.out
+++ b/contrib/test_decoding/expected/stream.out
@@ -128,6 +128,28 @@ SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL,
5
(1 row)
+-- Test that accessing a TOAST table in streaming mode is allowed.
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SET debug_logical_replication_streaming = immediate;
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+ ?column?
+-------------
+ force flush
+(1 row)
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+ count
+-------
+ 3
+(1 row)
+
+COMMIT;
+RESET debug_logical_replication_streaming;
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
pg_drop_replication_slot
diff --git a/contrib/test_decoding/sql/stream.sql b/contrib/test_decoding/sql/stream.sql
index 7f43f0c2ab..d7a696586e 100644
--- a/contrib/test_decoding/sql/stream.sql
+++ b/contrib/test_decoding/sql/stream.sql
@@ -59,5 +59,27 @@ ROLLBACK TO s1;
COMMIT;
SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+-- Test that accessing a TOAST table in streaming mode is allowed.
+
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SELECT 'CREATE TABLE test_tab (a text DEFAULT ''' || string_agg('toast value', '') || ''');' FROM generate_series(1, 4000)
+\gexec
+\set ECHO all
+
+SET debug_logical_replication_streaming = immediate;
+
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+COMMIT;
+
+RESET debug_logical_replication_streaming;
+
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
--
2.30.0.windows.2
^ permalink raw reply [nested|flat] 10+ messages in thread
* RE: BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values
@ 2024-10-07 08:36 Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
parent: Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
0 siblings, 0 replies; 10+ messages in thread
From: Zhijie Hou (Fujitsu) @ 2024-10-07 08:36 UTC (permalink / raw)
To: Amit Kapila <amit.kapila16@gmail.com>; Takeshi Ideriha <iderihatakeshi@gmail.com>; +Cc: exclusion@gmail.com <exclusion@gmail.com>; pgsql-bugs@lists.postgresql.org <pgsql-bugs@lists.postgresql.org>
On Monday, October 7, 2024 1:57 PM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com> wrote:
>
> On Saturday, October 5, 2024 6:12 PM Amit Kapila <amit.kapila16@gmail.com>
> wrote:
>
> Sending it again to avoid getting it stuck because the original was replied to
> both -hackers and -bugs.
>
> >
> > On Tue, Oct 1, 2024 at 7:07 PM Takeshi Ideriha
> > <iderihatakeshi@gmail.com>
> > wrote:
> > >
> > > >We forgot to set/unset the flag in functions
> > > >systable_beginscan_ordered and systable_endscan_ordered. BTW,
> > >
> > > Thank you for the clarification.
> > >
> > > >shouldn't this occur even without prepare transaction? If so, we
> > > >need to backpatch this till 14.
> > >
> > > Yes, it occurred also at PG14.
> > > I did some tests using 015_stream.pl with some modification like
> > > below, which tests the subscription about stream is on but two-phase
> > > is off.
> > > The same issue occurred at both current head source code and PG14.
> > >
> > > ```
> > > --- a/src/test/subscription/t/015_stream.pl
> > > +++ b/src/test/subscription/t/015_stream.pl
> > > @@ -134,9 +134,11 @@ my $node_subscriber =
> > > PostgreSQL::Test::Cluster->new('subscriber');
> > > $node_subscriber->init;
> > > $node_subscriber->start;
> > >
> > > +my $default = join('', map {chr(65 + rand 26)} (1 .. 10000));
> > > +
> > > # Create some preexisting content on publisher
> > > $node_publisher->safe_psql('postgres',
> > > - "CREATE TABLE test_tab (a int primary key, b bytea)");
> > > + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> > > DEFAULT '$default')");
> > > $node_publisher->safe_psql('postgres',
> > > "INSERT INTO test_tab VALUES (1, 'foo'), (2, 'bar')");
> > >
> > > @@ -144,7 +146,7 @@ $node_publisher->safe_psql('postgres', "CREATE
> > > TABLE test_tab_2 (a int)");
> > >
> > > # Setup structure on subscriber
> > > $node_subscriber->safe_psql('postgres',
> > > - "CREATE TABLE test_tab (a int primary key, b bytea, c
> > > timestamptz DEFAULT now(), d bigint DEFAULT 999)"
> > > + "CREATE TABLE test_tab (a int primary key, b bytea, t text
> > > DEFAULT '$default', c timestamptz DEFAULT now(), d bigint DEFAULT
> > > 999)"
> > >
> > > >Also, it is better to have a test for this, and let's ensure that
> > > >the new test doesn't increase the regression time too much if possible.
> > >
> > > Sure. I'm going to add some test codes in a few days.
> > >
> >
> > The above test shown in the email will work to test this issue.
> > However, we should use 'debug_logical_replication_streaming' as that
> > will help to reproduce the issue with just one write operation. Is it
> > possible to add the test in 018_stream_subxact_abort where we already use
> it?
>
> I think it might be better to put the test in test_decoding/sql/stream.sql as the
> bug is only related to the decoding part. Writing it in sql test also seems
> cheaper.
>
> Just share a top-up patch 0002 which includes the tests I suggested for
> reference. The test would fail without the fix.
>
> Node that I didn't change any logic in 0001 as the fix looks good to me. I just ran
> the pgindent for the 0001.
While testing the fix on back-branches, I realized that we don't have the
debug_logical_replication_streaming GUC on PG14 and 15. So I tried to generate
enough data to exceed the logical_decoding_work_mem in the test instead. Please
see the attachment for reference. I also rebased 0001 on back-branches, so just
share them here as well.
Best Regards,
Hou zj
Attachments: download all (8 files, .tar.gz)
v3-0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered-HEAD.patch (application/octet-stream, 1.5K) download
From 83804c82c289d2fc3fea00058fff0ab934b590ac Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH v3] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 52fde5cc4d..69c3608432 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -713,6 +713,14 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, idxkey, nkeys, NULL, 0);
sysscan->scan = NULL;
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -757,6 +765,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.31.1
v3-0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered-PG16.patch (application/octet-stream, 1.5K) download
From 9b90537c94f3f2128fc58acd905e1ad5a1d5748f Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH v4 1/2] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 16c7aa9fbf..e3b626b303 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -703,6 +703,14 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, key, nkeys, NULL, 0);
sysscan->scan = NULL;
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -747,6 +755,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.31.1
v3-0002-add-a-testcase-in-stream.sql-PG16.patch (application/octet-stream, 2.9K) download
From 066ef2eb5de3f7403cb4d779190a2275a06dc277 Mon Sep 17 00:00:00 2001
From: Hou Zhijie <houzj.fnst@cn.fujitsu.com>
Date: Mon, 7 Oct 2024 14:29:55 +0800
Subject: [PATCH v4 2/2] add a testcase in stream.sql PG16
---
contrib/test_decoding/expected/stream.out | 22 ++++++++++++++++++++++
contrib/test_decoding/sql/stream.sql | 22 ++++++++++++++++++++++
2 files changed, 44 insertions(+)
diff --git a/contrib/test_decoding/expected/stream.out b/contrib/test_decoding/expected/stream.out
index 0f21dcb8e0..d4bfbf975d 100644
--- a/contrib/test_decoding/expected/stream.out
+++ b/contrib/test_decoding/expected/stream.out
@@ -106,6 +106,28 @@ SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL,NULL, 'incl
committing streamed transaction
(17 rows)
+-- Test that accessing a TOAST table in streaming mode is allowed.
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SET debug_logical_replication_streaming = immediate;
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+ ?column?
+-------------
+ force flush
+(1 row)
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+ count
+-------
+ 3
+(1 row)
+
+COMMIT;
+RESET debug_logical_replication_streaming;
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
pg_drop_replication_slot
diff --git a/contrib/test_decoding/sql/stream.sql b/contrib/test_decoding/sql/stream.sql
index 4feec62972..0549d3204a 100644
--- a/contrib/test_decoding/sql/stream.sql
+++ b/contrib/test_decoding/sql/stream.sql
@@ -44,5 +44,27 @@ toasted-123456789012345678901234567890123456789012345678901234567890123456789012
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL,NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+-- Test that accessing a TOAST table in streaming mode is allowed.
+
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SELECT 'CREATE TABLE test_tab (a text DEFAULT ''' || string_agg('toast value', '') || ''');' FROM generate_series(1, 4000)
+\gexec
+\set ECHO all
+
+SET debug_logical_replication_streaming = immediate;
+
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+COMMIT;
+
+RESET debug_logical_replication_streaming;
+
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
--
2.31.1
v3-0002-add-a-testcase-in-stream.sql-PG14-PG15.patch (application/octet-stream, 2.8K) download
From 8a4d3d81a182ba774606047f72e91b76ced613c2 Mon Sep 17 00:00:00 2001
From: Hou Zhijie <houzj.fnst@cn.fujitsu.com>
Date: Mon, 7 Oct 2024 15:16:25 +0800
Subject: [PATCH v3] add a testcase in stream.sql PG14
---
contrib/test_decoding/expected/stream.out | 20 ++++++++++++++++++++
contrib/test_decoding/sql/stream.sql | 18 ++++++++++++++++++
2 files changed, 38 insertions(+)
diff --git a/contrib/test_decoding/expected/stream.out b/contrib/test_decoding/expected/stream.out
index 0f21dcb8e0..502cd2af17 100644
--- a/contrib/test_decoding/expected/stream.out
+++ b/contrib/test_decoding/expected/stream.out
@@ -106,6 +106,26 @@ SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL,NULL, 'incl
committing streamed transaction
(17 rows)
+-- Test that accessing a TOAST table in streaming mode is allowed.
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+BEGIN;
+INSERT INTO test_tab SELECT repeat('a', 6000) || g.i FROM generate_series(1, 350) g(i);
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+ ?column?
+-------------
+ force flush
+(1 row)
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+ count
+-------
+ 315
+(1 row)
+
+COMMIT;
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
pg_drop_replication_slot
diff --git a/contrib/test_decoding/sql/stream.sql b/contrib/test_decoding/sql/stream.sql
index 4feec62972..d6915958d4 100644
--- a/contrib/test_decoding/sql/stream.sql
+++ b/contrib/test_decoding/sql/stream.sql
@@ -44,5 +44,23 @@ toasted-123456789012345678901234567890123456789012345678901234567890123456789012
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL,NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+-- Test that accessing a TOAST table in streaming mode is allowed.
+
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SELECT 'CREATE TABLE test_tab (a text DEFAULT ''' || string_agg('toast value', '') || ''');' FROM generate_series(1, 4000)
+\gexec
+\set ECHO all
+
+BEGIN;
+INSERT INTO test_tab SELECT repeat('a', 6000) || g.i FROM generate_series(1, 350) g(i);
+
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+COMMIT;
+
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
--
2.30.0.windows.2
v3-0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered-PG14-PG15.patch (application/octet-stream, 1.5K) download
From 83804c82c289d2fc3fea00058fff0ab934b590ac Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH v3] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 52fde5cc4d..69c3608432 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -713,6 +713,14 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, key, nkeys, NULL, 0);
sysscan->scan = NULL;
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -757,6 +765,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.31.1
v3-0001-Set-and-unset-bsysscan-flag-in-systable_-_ordered-PG17.patch (application/octet-stream, 1.5K) download
From 83804c82c289d2fc3fea00058fff0ab934b590ac Mon Sep 17 00:00:00 2001
From: Ideriha Takeshi <iderihatakeshi@gmail.com>
Date: Mon, 30 Sep 2024 00:24:13 +0000
Subject: [PATCH v3] Set and unset bsysscan flag in systable_*_ordered.
We call HandleConcurrentAbort in systable_getnext_ordered so that
we can handle concurrent abort case in logical decoding same as
systable_getnext. Set and unset bsysscan flag is forgotten.
---
src/backend/access/index/genam.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/src/backend/access/index/genam.c b/src/backend/access/index/genam.c
index 52fde5cc4d..69c3608432 100644
--- a/src/backend/access/index/genam.c
+++ b/src/backend/access/index/genam.c
@@ -713,6 +713,14 @@ systable_beginscan_ordered(Relation heapRelation,
index_rescan(sysscan->iscan, key, nkeys, NULL, 0);
sysscan->scan = NULL;
+ /*
+ * If CheckXidAlive is set then set a flag to indicate that system table
+ * scan is in-progress. See detailed comments in xact.c where these
+ * variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = true;
+
return sysscan;
}
@@ -757,6 +765,14 @@ systable_endscan_ordered(SysScanDesc sysscan)
index_endscan(sysscan->iscan);
if (sysscan->snapshot)
UnregisterSnapshot(sysscan->snapshot);
+
+ /*
+ * Reset the bsysscan flag at the end of the systable scan. See detailed
+ * comments in xact.c where these variables are declared.
+ */
+ if (TransactionIdIsValid(CheckXidAlive))
+ bsysscan = false;
+
pfree(sysscan);
}
--
2.31.1
v3-0002-add-a-testcase-in-stream.sql-HEAD.patch (application/octet-stream, 2.8K) download
From f36657c9cfe1620a3f698a5932a97c019d7322e9 Mon Sep 17 00:00:00 2001
From: Hou Zhijie <houzj.fnst@cn.fujitsu.com>
Date: Mon, 7 Oct 2024 11:48:57 +0800
Subject: [PATCH v3 2/2] add a testcase in stream.sql
---
contrib/test_decoding/expected/stream.out | 22 ++++++++++++++++++++++
contrib/test_decoding/sql/stream.sql | 22 ++++++++++++++++++++++
2 files changed, 44 insertions(+)
diff --git a/contrib/test_decoding/expected/stream.out b/contrib/test_decoding/expected/stream.out
index a76f77601e..6a8a00a65b 100644
--- a/contrib/test_decoding/expected/stream.out
+++ b/contrib/test_decoding/expected/stream.out
@@ -128,6 +128,28 @@ SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL,
5
(1 row)
+-- Test that accessing a TOAST table in streaming mode is allowed.
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SET debug_logical_replication_streaming = immediate;
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+ ?column?
+-------------
+ force flush
+(1 row)
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+ count
+-------
+ 3
+(1 row)
+
+COMMIT;
+RESET debug_logical_replication_streaming;
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
pg_drop_replication_slot
diff --git a/contrib/test_decoding/sql/stream.sql b/contrib/test_decoding/sql/stream.sql
index 7f43f0c2ab..d7a696586e 100644
--- a/contrib/test_decoding/sql/stream.sql
+++ b/contrib/test_decoding/sql/stream.sql
@@ -59,5 +59,27 @@ ROLLBACK TO s1;
COMMIT;
SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+-- Test that accessing a TOAST table in streaming mode is allowed.
+
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SELECT 'CREATE TABLE test_tab (a text DEFAULT ''' || string_agg('toast value', '') || ''');' FROM generate_series(1, 4000)
+\gexec
+\set ECHO all
+
+SET debug_logical_replication_streaming = immediate;
+
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+COMMIT;
+
+RESET debug_logical_replication_streaming;
+
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
--
2.30.0.windows.2
v3-0002-add-a-testcase-in-stream.sql-PG17.patch (application/octet-stream, 2.8K) download
From f36657c9cfe1620a3f698a5932a97c019d7322e9 Mon Sep 17 00:00:00 2001
From: Hou Zhijie <houzj.fnst@cn.fujitsu.com>
Date: Mon, 7 Oct 2024 11:48:57 +0800
Subject: [PATCH v3 2/2] add a testcase in stream.sql
---
contrib/test_decoding/expected/stream.out | 22 ++++++++++++++++++++++
contrib/test_decoding/sql/stream.sql | 22 ++++++++++++++++++++++
2 files changed, 44 insertions(+)
diff --git a/contrib/test_decoding/expected/stream.out b/contrib/test_decoding/expected/stream.out
index a76f77601e..6a8a00a65b 100644
--- a/contrib/test_decoding/expected/stream.out
+++ b/contrib/test_decoding/expected/stream.out
@@ -128,6 +128,28 @@ SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL,
5
(1 row)
+-- Test that accessing a TOAST table in streaming mode is allowed.
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SET debug_logical_replication_streaming = immediate;
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+ ?column?
+-------------
+ force flush
+(1 row)
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+ count
+-------
+ 3
+(1 row)
+
+COMMIT;
+RESET debug_logical_replication_streaming;
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
pg_drop_replication_slot
diff --git a/contrib/test_decoding/sql/stream.sql b/contrib/test_decoding/sql/stream.sql
index 7f43f0c2ab..d7a696586e 100644
--- a/contrib/test_decoding/sql/stream.sql
+++ b/contrib/test_decoding/sql/stream.sql
@@ -59,5 +59,27 @@ ROLLBACK TO s1;
COMMIT;
SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+-- Test that accessing a TOAST table in streaming mode is allowed.
+
+-- Create a table with a column that uses a TOASTed default value.
+-- (temporarily hide query, to avoid the long CREATE TABLE stmt)
+\set ECHO none
+SELECT 'CREATE TABLE test_tab (a text DEFAULT ''' || string_agg('toast value', '') || ''');' FROM generate_series(1, 4000)
+\gexec
+\set ECHO all
+
+SET debug_logical_replication_streaming = immediate;
+
+BEGIN;
+INSERT INTO test_tab VALUES(1);
+
+-- Force WAL flush, so that the above changes will be streamed.
+SELECT 'force flush' FROM pg_switch_wal();
+
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1', 'stream-changes', '1');
+COMMIT;
+
+RESET debug_logical_replication_streaming;
+
DROP TABLE stream_test;
SELECT pg_drop_replication_slot('regression_slot');
--
2.30.0.windows.2
^ permalink raw reply [nested|flat] 10+ messages in thread
end of thread, other threads:[~2024-10-07 08:36 UTC | newest]
Thread overview: 10+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2024-09-28 11:00 BUG #18641: Logical decoding of two-phase commit fails with TOASTed default values PG Bug reporting form <noreply@postgresql.org>
2024-09-30 01:16 ` Takeshi Ideriha <iderihatakeshi@gmail.com>
2024-09-30 12:44 ` Amit Kapila <amit.kapila16@gmail.com>
2024-09-30 16:20 ` Amit Kapila <amit.kapila16@gmail.com>
2024-10-01 13:37 ` Takeshi Ideriha <iderihatakeshi@gmail.com>
2024-10-02 00:36 ` Takeshi Ideriha <iderihatakeshi@gmail.com>
2024-10-05 10:12 ` Amit Kapila <amit.kapila16@gmail.com>
2024-10-05 10:20 ` Amit Kapila <amit.kapila16@gmail.com>
2024-10-07 05:57 ` Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
2024-10-07 08:36 ` Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox