Re: [HACKERS] Logical replication woes
On 05/15/2014 11:58 PM, Andres Freund wrote: On 2014-05-15 22:30:53 +0300, Heikki Linnakangas wrote: Attached patch fixes things, but I want to add some regression tests before commit. Looks good to me. Attached are two patches. One for the unitialized dbId/tsId issue; one for the decoding bug. The former should be backpatched. Thanks, committed. Should you wonder about the slight reordering of the assignments in RecordTransactionCommitPrepared() - I've made it more similar to RecordTransactionCommit() to make it easier to see they are equivalent. Makes sense. - Heikki -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
[HACKERS] Logical replication woes
Spotted while testing pg_recvlogical: 1. Set up pg_recvlogical to receive: ./pg_recvlogical -S fooslot -d postgres --create ./pg_recvlogical -S fooslot -d postgres --start -f - 2. In another terminal, with psql: create table foo (id int4); begin; insert into foo values (4); alter table foo alter column id type text; prepare transaction 'foo'; commit prepared 'foo'; insert into foo values (1); 3. With current HEAD, after commit bb38fb0d43c8d7ff54072bfd8bd63154e536b384, this produces an assertion failure: TRAP: FailedAssertion(!(((xid) != ((TransactionId) 0))), File: reorderbuffer.c, Line: 508) I believe that's we no longer assign another XID to the transaction that does the COMMIT PREPARED. Previously, an extra XID, in addition to the XID of the prepared transaction, was assigned for use in locking the global transaction entry in shared memory, but that's no longer required. However, even with that patch reverted, it doesn't work correctly: ERROR: could not map filenode base/12142/16390 to relation OID LOG: starting logical decoding for slot fooslot DETAIL: streaming transactions committing after 0/16D1670, reading WAL from 0/16BC470 - Heikki -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Logical replication woes
On 05/15/2014 07:57 PM, Heikki Linnakangas wrote: Spotted while testing pg_recvlogical: 1. Set up pg_recvlogical to receive: ./pg_recvlogical -S fooslot -d postgres --create ./pg_recvlogical -S fooslot -d postgres --start -f - 2. In another terminal, with psql: create table foo (id int4); begin; insert into foo values (4); alter table foo alter column id type text; prepare transaction 'foo'; commit prepared 'foo'; insert into foo values (1); 3. With current HEAD, after commit bb38fb0d43c8d7ff54072bfd8bd63154e536b384, this produces an assertion failure: TRAP: FailedAssertion(!(((xid) != ((TransactionId) 0))), File: reorderbuffer.c, Line: 508) I believe that's we no longer assign another XID to the transaction that does the COMMIT PREPARED. Previously, an extra XID, in addition to the XID of the prepared transaction, was assigned for use in locking the global transaction entry in shared memory, but that's no longer required. However, even with that patch reverted, it doesn't work correctly: ERROR: could not map filenode base/12142/16390 to relation OID LOG: starting logical decoding for slot fooslot DETAIL: streaming transactions committing after 0/16D1670, reading WAL from 0/16BC470 Ok, so the immediate cause was quick to find: when decoding a commit-prepared WAL record, we have to use the XID from the record content (patch attached). The XID in the record header is the XID of the transaction doing the COMMIT PREPARED, which is always 0 after patch bb38fb0d43c8d7ff54072bfd8bd63154e536b384 which causes the assertion. But it was always wrong. After fixing, it no longer asserts or gives the above could not map filenode error. However, it still doesn't seem right. When I do the above as a regular transaction, ie: begin; insert into foo values (6); alter table foo alter column id type text; commit; pg_recvlogical prints this: BEGIN 708 table public.foo: INSERT: id[text]:'6' COMMIT 708 But if I do it as a prepared transaction: begin; insert into foo values (7); alter table foo alter column id type text; prepare transaction 'foo'; commit prepared 'foo'; pg_recvlogical prints nothing. - Heikki diff --git a/src/backend/replication/logical/decode.c b/src/backend/replication/logical/decode.c index d6499d5..cc73652 100644 --- a/src/backend/replication/logical/decode.c +++ b/src/backend/replication/logical/decode.c @@ -225,7 +225,7 @@ DecodeXactOp(LogicalDecodingContext *ctx, XLogRecordBuffer *buf) subxacts = (TransactionId *) (xlrec-xnodes[xlrec-nrels]); invals = (SharedInvalidationMessage *) (subxacts[xlrec-nsubxacts]); -DecodeCommit(ctx, buf, prec-xl_xid, xlrec-dbId, +DecodeCommit(ctx, buf, prec-xid, xlrec-dbId, xlrec-xact_time, xlrec-nsubxacts, subxacts, xlrec-nmsgs, invals); -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Logical replication woes
Hi, On 2014-05-15 20:07:23 +0300, Heikki Linnakangas wrote: On 05/15/2014 07:57 PM, Heikki Linnakangas wrote: Spotted while testing pg_recvlogical: 1. Set up pg_recvlogical to receive: ./pg_recvlogical -S fooslot -d postgres --create ./pg_recvlogical -S fooslot -d postgres --start -f - 2. In another terminal, with psql: create table foo (id int4); begin; insert into foo values (4); alter table foo alter column id type text; prepare transaction 'foo'; commit prepared 'foo'; insert into foo values (1); 3. With current HEAD, after commit bb38fb0d43c8d7ff54072bfd8bd63154e536b384, this produces an assertion failure: TRAP: FailedAssertion(!(((xid) != ((TransactionId) 0))), File: reorderbuffer.c, Line: 508) I believe that's we no longer assign another XID to the transaction that does the COMMIT PREPARED. Previously, an extra XID, in addition to the XID of the prepared transaction, was assigned for use in locking the global transaction entry in shared memory, but that's no longer required. However, even with that patch reverted, it doesn't work correctly: ERROR: could not map filenode base/12142/16390 to relation OID LOG: starting logical decoding for slot fooslot DETAIL: streaming transactions committing after 0/16D1670, reading WAL from 0/16BC470 Ok, so the immediate cause was quick to find: when decoding a commit-prepared WAL record, we have to use the XID from the record content (patch attached). The XID in the record header is the XID of the transaction doing the COMMIT PREPARED, which is always 0 after patch bb38fb0d43c8d7ff54072bfd8bd63154e536b384 which causes the assertion. But it was always wrong. After fixing, it no longer asserts or gives the above could not map filenode error. However, it still doesn't seem right. When I do the above as a regular transaction, ie: begin; insert into foo values (6); alter table foo alter column id type text; commit; pg_recvlogical prints this: BEGIN 708 table public.foo: INSERT: id[text]:'6' COMMIT 708 But if I do it as a prepared transaction: begin; insert into foo values (7); alter table foo alter column id type text; prepare transaction 'foo'; commit prepared 'foo'; Looking into it. I at some point dropped the prepared xact tests and that was obviously a mistake. Will re-add them and fix. Andres Freund -- Andres Freund http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Logical replication woes
On 2014-05-15 20:07:23 +0300, Heikki Linnakangas wrote: Ok, so the immediate cause was quick to find: when decoding a commit-prepared WAL record, we have to use the XID from the record content (patch attached). The XID in the record header is the XID of the transaction doing the COMMIT PREPARED, which is always 0 after patch bb38fb0d43c8d7ff54072bfd8bd63154e536b384 which causes the assertion. But it was always wrong. After fixing, it no longer asserts or gives the above could not map filenode error. However, it still doesn't seem right. When I do the above as a regular transaction, ie: begin; insert into foo values (6); alter table foo alter column id type text; commit; pg_recvlogical prints this: BEGIN 708 table public.foo: INSERT: id[text]:'6' COMMIT 708 But if I do it as a prepared transaction: begin; insert into foo values (7); alter table foo alter column id type text; prepare transaction 'foo'; commit prepared 'foo'; How very wierd. The reason for this is that RecordTransactionCommitPrepared() forgets to fill a couple of fields in xl_xact_commit. Any reason dbId/tsId aren't filled? They aren't strictly needed because afaics they're only looked at for relcache invalidations which prepared xacts don't support, but still? That also explains why decoding for prepared xacts (besides the typo you found) didn't work anymore - the filtering at commit was added pretty late... Attached patch fixes things, but I want to add some regression tests before commit. Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Logical replication woes
On 2014-05-15 19:46:57 +0200, Andres Freund wrote: Attached patch fixes things, but I want to add some regression tests before commit. And now actually attached. Will send a patch with regression tests later tonight or tomorrow. Need to eat first... Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services diff --git a/src/backend/access/transam/twophase.c b/src/backend/access/transam/twophase.c index 2cefa08..5d8e195 100644 --- a/src/backend/access/transam/twophase.c +++ b/src/backend/access/transam/twophase.c @@ -2082,9 +2082,10 @@ RecordTransactionCommitPrepared(TransactionId xid, /* Emit the XLOG commit record */ xlrec.xid = xid; + xlrec.crec.dbId = MyDatabaseId; + xlrec.crec.tsId = MyDatabaseTableSpace; xlrec.crec.xact_time = GetCurrentTimestamp(); xlrec.crec.xinfo = initfileinval ? XACT_COMPLETION_UPDATE_RELCACHE_FILE : 0; - xlrec.crec.nmsgs = 0; xlrec.crec.nrels = nrels; xlrec.crec.nsubxacts = nchildren; xlrec.crec.nmsgs = ninvalmsgs; diff --git a/src/backend/replication/logical/decode.c b/src/backend/replication/logical/decode.c index 06b99e7..603d083 100644 --- a/src/backend/replication/logical/decode.c +++ b/src/backend/replication/logical/decode.c @@ -225,7 +225,7 @@ DecodeXactOp(LogicalDecodingContext *ctx, XLogRecordBuffer *buf) subxacts = (TransactionId *) (xlrec-xnodes[xlrec-nrels]); invals = (SharedInvalidationMessage *) (subxacts[xlrec-nsubxacts]); -DecodeCommit(ctx, buf, r-xl_xid, xlrec-dbId, +DecodeCommit(ctx, buf, prec-xid, xlrec-dbId, xlrec-xact_time, xlrec-nsubxacts, subxacts, xlrec-nmsgs, invals); -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Logical replication woes
On 05/15/2014 08:46 PM, Andres Freund wrote: On 2014-05-15 20:07:23 +0300, Heikki Linnakangas wrote: Ok, so the immediate cause was quick to find: when decoding a commit-prepared WAL record, we have to use the XID from the record content (patch attached). The XID in the record header is the XID of the transaction doing the COMMIT PREPARED, which is always 0 after patch bb38fb0d43c8d7ff54072bfd8bd63154e536b384 which causes the assertion. But it was always wrong. After fixing, it no longer asserts or gives the above could not map filenode error. However, it still doesn't seem right. When I do the above as a regular transaction, ie: begin; insert into foo values (6); alter table foo alter column id type text; commit; pg_recvlogical prints this: BEGIN 708 table public.foo: INSERT: id[text]:'6' COMMIT 708 But if I do it as a prepared transaction: begin; insert into foo values (7); alter table foo alter column id type text; prepare transaction 'foo'; commit prepared 'foo'; How very wierd. The reason for this is that RecordTransactionCommitPrepared() forgets to fill a couple of fields in xl_xact_commit. Any reason dbId/tsId aren't filled? They aren't strictly needed because afaics they're only looked at for relcache invalidations which prepared xacts don't support, but still? Seems like an oversight in commit dd428c79, which added the fields to xl_xact_commit. They are needed. A prepared xact can indeed cause relcache invalidations, and removal of the init file. For example: begin; cluster pg_opclass using pg_opclass_oid_index ; prepare transaction 'foo'; commit prepared 'foo'; Attached patch fixes things, but I want to add some regression tests before commit. Looks good to me. - Heikki -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Logical replication woes
On 2014-05-15 22:30:53 +0300, Heikki Linnakangas wrote: On 05/15/2014 08:46 PM, Andres Freund wrote: On 2014-05-15 20:07:23 +0300, Heikki Linnakangas wrote: How very wierd. The reason for this is that RecordTransactionCommitPrepared() forgets to fill a couple of fields in xl_xact_commit. Any reason dbId/tsId aren't filled? They aren't strictly needed because afaics they're only looked at for relcache invalidations which prepared xacts don't support, but still? Seems like an oversight in commit dd428c79, which added the fields to xl_xact_commit. They are needed. A prepared xact can indeed cause relcache invalidations, and removal of the init file. For example: Hm, so that part has to be backpatched to 9.0. Ick, I wonder if that's been hit in production. Seems like it could cause pretty random looking errors. It's easy enough to cause errors like: ERROR: could not open file base/12753/12613: No such file or directory I guess not many people will do relevant stuff in prepared xacts tho. Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Logical replication woes
On 2014-05-15 22:30:53 +0300, Heikki Linnakangas wrote:
Attached patch fixes things, but I want to add some regression tests
before commit.
Looks good to me.
Attached are two patches. One for the unitialized dbId/tsId issue; one
for the decoding bug. The former should be backpatched.
Should you wonder about the slight reordering of the assignments in
RecordTransactionCommitPrepared() - I've made it more similar to
RecordTransactionCommit()
to make it easier to see they are equivalent.
Thanks for the testing!
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
From 07d0f4330f7c25bcec9e356527b0dc86372d2886 Mon Sep 17 00:00:00 2001
From: Andres Freund and...@anarazel.de
Date: Thu, 15 May 2014 22:23:12 +0200
Subject: [PATCH 1/2] Initialize all members of xl_xact_commit during prepared
transaction commits.
Commit dd428c79 added dbId and tsId to the xl_xact_commit struct but
missed that prepared transaction commits reuse that struct. Fix that.
Because those fields were used WAL logged unitialized a hot standby
node could miss relcache init file invalidations leading to errors like
ERROR: could not open file ...: No such file or directory
on the standby. A restart of the database is sufficient to fix the
problem.
As problems can only be triggered when a system table/index has been
rewritten in a transaction using two phase commit the problem is
unlikely to have affected many installations.
Found while investigating a logical decoding bugreport from Heikki.
Backpatch to 9.0 where the bug was introduced.
---
src/backend/access/transam/twophase.c | 8 ++--
1 file changed, 6 insertions(+), 2 deletions(-)
diff --git a/src/backend/access/transam/twophase.c b/src/backend/access/transam/twophase.c
index 2cefa08..d5409a6 100644
--- a/src/backend/access/transam/twophase.c
+++ b/src/backend/access/transam/twophase.c
@@ -2082,9 +2082,13 @@ RecordTransactionCommitPrepared(TransactionId xid,
/* Emit the XLOG commit record */
xlrec.xid = xid;
- xlrec.crec.xact_time = GetCurrentTimestamp();
+
xlrec.crec.xinfo = initfileinval ? XACT_COMPLETION_UPDATE_RELCACHE_FILE : 0;
- xlrec.crec.nmsgs = 0;
+
+ xlrec.crec.dbId = MyDatabaseId;
+ xlrec.crec.tsId = MyDatabaseTableSpace;
+
+ xlrec.crec.xact_time = GetCurrentTimestamp();
xlrec.crec.nrels = nrels;
xlrec.crec.nsubxacts = nchildren;
xlrec.crec.nmsgs = ninvalmsgs;
--
2.0.0.rc2.4.g1dc51c6.dirty
From de22d8e5308b1c4c509d8566317d9aea0956c2bc Mon Sep 17 00:00:00 2001
From: Andres Freund and...@anarazel.de
Date: Thu, 15 May 2014 22:42:27 +0200
Subject: [PATCH 2/2] Fix typo-induced bug in decoding of prepared
transactions.
The decoding of prepared transaction commits accidentally used the xid
of the transaction performing the COMMIT PREPARED. Before
bb38fb0d43c8d that lead to those transactions not being decoded,
afterwards to a assertion failure.
Add tests for the decoding of prepared transactions.
Bug found and fixed by Heikki Linnakangas; new regression test by
Andres Freund.
---
contrib/test_decoding/Makefile | 2 +-
contrib/test_decoding/expected/ddl.out | 6 +--
contrib/test_decoding/expected/prepared.out | 82 +
contrib/test_decoding/sql/ddl.sql | 2 +-
contrib/test_decoding/sql/prepared.sql | 50 ++
src/backend/replication/logical/decode.c| 2 +-
6 files changed, 138 insertions(+), 6 deletions(-)
create mode 100644 contrib/test_decoding/expected/prepared.out
create mode 100644 contrib/test_decoding/sql/prepared.sql
diff --git a/contrib/test_decoding/Makefile b/contrib/test_decoding/Makefile
index 685986c..58e0f38 100644
--- a/contrib/test_decoding/Makefile
+++ b/contrib/test_decoding/Makefile
@@ -37,7 +37,7 @@ submake-isolation:
submake-test_decoding:
$(MAKE) -C $(top_builddir)/contrib/test_decoding
-REGRESSCHECKS=ddl rewrite toast permissions decoding_in_xact binary
+REGRESSCHECKS=ddl rewrite toast permissions decoding_in_xact binary prepared
regresscheck: all | submake-regress submake-test_decoding
$(MKDIR_P) regression_output
diff --git a/contrib/test_decoding/expected/ddl.out b/contrib/test_decoding/expected/ddl.out
index 05a4bd3..37ff8b7 100644
--- a/contrib/test_decoding/expected/ddl.out
+++ b/contrib/test_decoding/expected/ddl.out
@@ -640,8 +640,8 @@ SELECT pg_drop_replication_slot('regression_slot');
(1 row)
/* check that we aren't visible anymore now */
-SELECT * FROM pg_stat_replication;
- pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | backend_xmin | state | sent_location | write_location | flush_location | replay_location | sync_priority | sync_state
