Thread: BUG #18509: Logical decoding behaves badly when processing a change record for a table with altered column
BUG #18509: Logical decoding behaves badly when processing a change record for a table with altered column
From
PG Bug reporting form
Date:
The following bug has been logged on the website:
Bug reference: 18509
Logged by: Alexander Lakhin
Email address: exclusion@gmail.com
PostgreSQL version: 17beta1
Operating system: Ubuntu 22.04
Description:
The following script:
numjobs=10
for ((j=1;j<=numjobs;j++)); do
psql -c "CREATE TABLE t$j(t1 text, i2 int);"
done
for i in `seq 50`; do
echo "iteration $i";
for ((j=1;j<=numjobs;j++)); do
cat << EOF | psql >/dev/null &
BEGIN;
SELECT txid_current();
SELECT pg_sleep(0.01);
EOF
cat << EOF | psql >/dev/null &
ALTER TABLE t$j RENAME COLUMN t1 TO i1;
SELECT pg_sleep(0.001);
ALTER TABLE t$j ALTER COLUMN i1 TYPE int4 USING (i1::int4);
SELECT pg_sleep(0.001);
INSERT INTO t$j(i1) VALUES (1);
SELECT pg_sleep(0.001);
INSERT INTO t$j(i1) VALUES (1);
SELECT pg_sleep(0.001);
INSERT INTO t$j(i1) VALUES (1);
EOF
cat << EOF | psql >/dev/null &
SELECT 'init' FROM pg_create_logical_replication_slot(
'regression_slot$j', 'test_decoding');
SELECT data FROM pg_logical_slot_get_changes(
'regression_slot$j', NULL,NULL);
EOF
done
wait
for ((j=1;j<=numjobs;j++)); do
cat << EOF | psql >/dev/null
SELECT pg_drop_replication_slot('regression_slot$j');
ALTER TABLE t$j ALTER COLUMN i1 TYPE text USING (i1::text);
ALTER TABLE t$j RENAME COLUMN i1 TO t1;
EOF
done
grep 'TRAP' server.log && { break; }
done
produces errors like:
2024-06-14 17:10:58.349 UTC|law|regression|666c79a2.3fe3a4|ERROR: could not
map filenumber "base/16384/16453" to relation OID
2024-06-14 17:10:58.349 UTC|law|regression|666c79a2.3fe3a4|BACKTRACE:
ReorderBufferProcessTXN at reorderbuffer.c:2218:7
ReorderBufferReplay at reorderbuffer.c:2701:2
ReorderBufferCommit at reorderbuffer.c:2725:2
DecodeCommit at decode.c:733:3
xact_decode at decode.c:243:5
LogicalDecodingProcessRecord at decode.c:123:1
pg_logical_slot_get_changes_guts at logicalfuncs.c:269:7
pg_logical_slot_get_changes at logicalfuncs.c:334:1
...
2024-06-14 17:10:58.349 UTC|law|regression|666c79a2.3fe3a4|STATEMENT:
SELECT data FROM pg_logical_slot_get_changes(
'regression_slot3', NULL,NULL);
and an assertion failure:
TRAP: failed Assert("TupleDescAttr(relation->rd_att, i)->attcacheoff ==
-1"), File: "relcache.c", Line: 673, PID: 4187156
...
#3 0x00007f03c690e476 in __GI_raise (sig=sig@entry=6) at
../sysdeps/posix/raise.c:26
#4 0x00007f03c68f47f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x000055c3c86d95f1 in ExceptionalCondition (
conditionName=0x55c3c8930198 "TupleDescAttr(relation->rd_att,
i)->attcacheoff == -1",
fileName=0x55c3c8930108 "relcache.c", lineNumber=673) at assert.c:66
#6 0x000055c3c86c2dd3 in RelationBuildTupleDesc (relation=0x7f03b75dd1a8)
at relcache.c:673
#7 0x000055c3c86c3ce6 in RelationBuildDesc (targetRelId=16430,
insertIt=true) at relcache.c:1185
#8 0x000055c3c86c5922 in RelationIdGetRelation (relationId=16430) at
relcache.c:2116
#9 0x000055c3c8428276 in ReorderBufferProcessTXN (...) at
reorderbuffer.c:2222
#10 0x000055c3c84290c5 in ReorderBufferReplay (...) at
reorderbuffer.c:2701
#11 0x000055c3c8429147 in ReorderBufferCommit (...) at
reorderbuffer.c:2725
#12 0x000055c3c8414350 in DecodeCommit (...) at decode.c:733
#13 0x000055c3c84135a1 in xact_decode (...) at decode.c:242
#14 0x000055c3c84130fb in LogicalDecodingProcessRecord (...) at
decode.c:116
#15 0x000055c3c841ce60 in pg_logical_slot_get_changes_guts (...) at
logicalfuncs.c:266
#16 0x000055c3c841cfd1 in pg_logical_slot_get_changes (...) at
logicalfuncs.c:333
...
Also, with tables created as "CREATE TABLE t$j(t1 text);" it produces:
WARNING: problem in alloc set text conversion context: bad block offset for
chunk 0x55bdb51ced18 in block 0x55bdb51ce0c8
(and other "problem in alloc" warnings)
and
TRAP: failed Assert("!HdrMaskIsExternal(chunk->hdrmask) ||
HdrMaskCheckMagic(chunk->hdrmask)"), File:
"../../../../src/include/utils/memutils_memorychunk.h", Line: 210, PID:
4188259
Reproduced on REL_12_STABLE .. master.
Re: BUG #18509: Logical decoding behaves badly when processing a change record for a table with altered column
From
Alexander Lakhin
Date:
14.06.2024 21:00, PG Bug reporting form wrote:
> The following script:
> ...
>
> produces errors like:
> 2024-06-14 17:10:58.349 UTC|law|regression|666c79a2.3fe3a4|ERROR: could not
> map filenumber "base/16384/16453" to relation OID
I've simplified that script to the following:
psql -c "CREATE TABLE t(t1 text, i2 int);"
for ((i=1;i<=100;i++)); do
echo "iteration $i";
cat << EOF | psql >/dev/null &
BEGIN;
SELECT txid_current();
SELECT pg_sleep(0.01);
EOF
cat << EOF | psql >/dev/null &
ALTER TABLE t RENAME COLUMN t1 TO i1;
ALTER TABLE t ALTER COLUMN i1 TYPE int4 USING (i1::int4);
SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
EOF
cat << EOF | psql >/dev/null &
SELECT 'init' FROM pg_create_logical_replication_slot(
'regression_slot_$i', 'test_decoding');
SELECT data FROM pg_logical_slot_get_changes(
'regression_slot_$i', NULL, NULL);
EOF
wait
grep 'ERROR' server.log && { break; }
cat << EOF | psql >/dev/null
SELECT pg_drop_replication_slot('regression_slot_$i');
ALTER TABLE t ALTER COLUMN i1 TYPE text USING (i1::text);
ALTER TABLE t RENAME COLUMN i1 TO t1;
EOF
done
It fails deterministically (though not on each run) for me as below:
...
iteration 93
ERROR: could not map filenumber "base/16384/17310" to relation OID
an excerpt from server.log (generated with log_min_messages = DEBUG3):
2024-07-07 09:15:36.167 UTC [324743:33] psql LOG: starting logical decoding for slot "regression_slot_93"
2024-07-07 09:15:36.167 UTC [324743:34] psql DETAIL: Streaming transactions committing after 0/2006458, reading WAL
from 0/1FFB820.
2024-07-07 09:15:36.167 UTC [324743:35] psql STATEMENT: SELECT data FROM pg_logical_slot_get_changes(
'regression_slot_93', NULL, NULL);
...
2024-07-07 09:15:36.169 UTC [324743:47] psql DEBUG: snapshot of 0+0 running transaction ids (lsn 0/20065A8 oldest xid
1666 latest complete 1665 next xid 1666)
2024-07-07 09:15:36.169 UTC [324743:48] psql DEBUG: purged committed transactions from 0 to 0, xmin: 1662, xmax: 1662
2024-07-07 09:15:36.169 UTC [324743:49] psql DEBUG: xmin: 1662, xmax: 1662, oldest running: 1662, oldest xmin: 1662
2024-07-07 09:15:36.169 UTC [324743:50] psql DEBUG: updated xmin: 1 restart: 0
2024-07-07 09:15:36.169 UTC [324743:51] psql DEBUG: xmin required by slots: data 0, catalog 1662
2024-07-07 09:15:36.169 UTC [324743:52] psql LOG: logical decoding found consistent point at 0/2006420
2024-07-07 09:15:36.169 UTC [324743:53] psql DETAIL: There are no running transactions.
2024-07-07 09:15:36.169 UTC [324743:54] psql STATEMENT: SELECT data FROM pg_logical_slot_get_changes(
'regression_slot_93', NULL, NULL);
2024-07-07 09:15:36.169 UTC [324743:55] psql DEBUG: aborting old transaction 1662
2024-07-07 09:15:36.170 UTC [324743:56] psql ERROR: could not map filenumber "base/16384/17310" to relation OID
2024-07-07 09:15:36.170 UTC [324743:57] psql STATEMENT: SELECT data FROM pg_logical_slot_get_changes(
'regression_slot_93', NULL, NULL);
The corresponding fragment of WAL:
rmgr: Transaction len (rec/tot): 353/ 353, tx: 1662, lsn: 0/02005B38, prev 0/02005B00, desc: INVALIDATION ;
inval msgs: catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache
6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 relcache 17310 snapshot
2608
rmgr: Transaction len (rec/tot): 1605/ 1605, tx: 1662, lsn: 0/02005CA0, prev 0/02005B38, desc: COMMIT
2024-07-07 09:15:36.150647 UTC; rels: base/16384/17305 base/16384/17308 base/16384/17309; dropped stats: 2/16384/17309
2/16384/17308 2/16384/17310; inval msgs: catcache 7 ... relcache 17310 ... relcache 17310 snapshot 2608
rmgr: Transaction len (rec/tot): 34/ 34, tx: 1661, lsn: 0/02006300, prev 0/02005CA0, desc: ABORT
2024-07-07
09:15:36.157644 UTC
rmgr: Standby len (rec/tot): 78/ 78, tx: 0, lsn: 0/02006328, prev 0/02006300, desc: LOCK xid 1662
db
16384 rel 17308 xid 1662 db 16384 rel 17309 xid 1662 db 16384 rel 16385 xid 1662 db 16384 rel 17310
rmgr: Standby len (rec/tot): 54/ 54, tx: 0, lsn: 0/02006378, prev 0/02006328, desc: RUNNING_XACTS
nextXid 1663 latestCompletedXid 1661 oldestRunningXid 1662; 1 xacts: 1662
rmgr: Heap len (rec/tot): 59/ 59, tx: 1663, lsn: 0/020063B0, prev 0/02006378, desc: INSERT+INIT
off:
1, flags: 0x08, blkref #0: rel 1663/16384/17310 blk 3
rmgr: Transaction len (rec/tot): 46/ 46, tx: 1663, lsn: 0/020063F0, prev 0/020063B0, desc: COMMIT
2024-07-07 09:15:36.162938 UTC
(The transaction 1662 performs table rewrite.)
What I'm observing with some debug logging added is:
ReorderBufferProcessTXN(), called during processing the commit record
0/02006328, gets reloid = 0 from RelidByRelfilenumber() because
systable_beginscan() chooses (via GetCatalogSnapshot()) HistoricSnapshot
with xmin = 1662, xmax = 1662. That snapshot was set inside
SnapBuildProcessChange(), via ReorderBufferSetBaseSnapshot(), from
builder->snapshot, which is built inside SnapBuildProcessChange(), via
SnapBuildBuildSnapshot(), from builder->xmin (builder->xmax), which is
set by SnapBuildProcessRunningXacts from running->oldestRunningXid = 1662.
Really, WAL contains RUNNING_XACTS oldestRunningXid 1662 before the record
being decoded.
So I wonder if the RUNNING_XACT record in WAL is correct or it should be
decoded differently?
Best regards,
Alexander
Re: BUG #18509: Logical decoding behaves badly when processing a change record for a table with altered column
From
Ajin Cherian
Date:
On Tue, Jun 24, 2025 at 9:57 AM Alexander Lakhin <exclusion@gmail.com> wrote:
>
> 14.06.2024 21:00, PG Bug reporting form wrote:
> > The following script:
> > ...
> >
> > produces errors like:
> > 2024-06-14 17:10:58.349 UTC|law|regression|666c79a2.3fe3a4|ERROR: could not
> > map filenumber "base/16384/16453" to relation OID
>
> I've simplified that script to the following:
> psql -c "CREATE TABLE t(t1 text, i2 int);"
>
> for ((i=1;i<=100;i++)); do
> echo "iteration $i";
>
> cat << EOF | psql >/dev/null &
> BEGIN;
> SELECT txid_current();
> SELECT pg_sleep(0.01);
> EOF
>
> cat << EOF | psql >/dev/null &
> ALTER TABLE t RENAME COLUMN t1 TO i1;
> ALTER TABLE t ALTER COLUMN i1 TYPE int4 USING (i1::int4);
> SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
> SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
> SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
> SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
> SELECT pg_sleep(0.001); INSERT INTO t VALUES (1);
> EOF
>
> cat << EOF | psql >/dev/null &
> SELECT 'init' FROM pg_create_logical_replication_slot(
> 'regression_slot_$i', 'test_decoding');
>
> SELECT data FROM pg_logical_slot_get_changes(
> 'regression_slot_$i', NULL, NULL);
> EOF
> wait
>
> grep 'ERROR' server.log && { break; }
>
> cat << EOF | psql >/dev/null
> SELECT pg_drop_replication_slot('regression_slot_$i');
> ALTER TABLE t ALTER COLUMN i1 TYPE text USING (i1::text);
> ALTER TABLE t RENAME COLUMN i1 TO t1;
> EOF
>
> done
>
> It fails deterministically (though not on each run) for me as below:
> ...
> iteration 93
> ERROR: could not map filenumber "base/16384/17310" to relation OID
>
> an excerpt from server.log (generated with log_min_messages = DEBUG3):
> 2024-07-07 09:15:36.167 UTC [324743:33] psql LOG: starting logical decoding for slot "regression_slot_93"
> 2024-07-07 09:15:36.167 UTC [324743:34] psql DETAIL: Streaming transactions committing after 0/2006458, reading WAL
> from 0/1FFB820.
> 2024-07-07 09:15:36.167 UTC [324743:35] psql STATEMENT: SELECT data FROM pg_logical_slot_get_changes(
> 'regression_slot_93', NULL, NULL);
> ...
> 2024-07-07 09:15:36.169 UTC [324743:47] psql DEBUG: snapshot of 0+0 running transaction ids (lsn 0/20065A8 oldest
xid
> 1666 latest complete 1665 next xid 1666)
> 2024-07-07 09:15:36.169 UTC [324743:48] psql DEBUG: purged committed transactions from 0 to 0, xmin: 1662, xmax:
1662
> 2024-07-07 09:15:36.169 UTC [324743:49] psql DEBUG: xmin: 1662, xmax: 1662, oldest running: 1662, oldest xmin: 1662
> 2024-07-07 09:15:36.169 UTC [324743:50] psql DEBUG: updated xmin: 1 restart: 0
> 2024-07-07 09:15:36.169 UTC [324743:51] psql DEBUG: xmin required by slots: data 0, catalog 1662
> 2024-07-07 09:15:36.169 UTC [324743:52] psql LOG: logical decoding found consistent point at 0/2006420
> 2024-07-07 09:15:36.169 UTC [324743:53] psql DETAIL: There are no running transactions.
> 2024-07-07 09:15:36.169 UTC [324743:54] psql STATEMENT: SELECT data FROM pg_logical_slot_get_changes(
> 'regression_slot_93', NULL, NULL);
> 2024-07-07 09:15:36.169 UTC [324743:55] psql DEBUG: aborting old transaction 1662
> 2024-07-07 09:15:36.170 UTC [324743:56] psql ERROR: could not map filenumber "base/16384/17310" to relation OID
> 2024-07-07 09:15:36.170 UTC [324743:57] psql STATEMENT: SELECT data FROM pg_logical_slot_get_changes(
> 'regression_slot_93', NULL, NULL);
>
> The corresponding fragment of WAL:
> rmgr: Transaction len (rec/tot): 353/ 353, tx: 1662, lsn: 0/02005B38, prev 0/02005B00, desc: INVALIDATION
;
> inval msgs: catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7
catcache
> 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 relcache 17310 snapshot
2608
> rmgr: Transaction len (rec/tot): 1605/ 1605, tx: 1662, lsn: 0/02005CA0, prev 0/02005B38, desc: COMMIT
> 2024-07-07 09:15:36.150647 UTC; rels: base/16384/17305 base/16384/17308 base/16384/17309; dropped stats:
2/16384/17309
> 2/16384/17308 2/16384/17310; inval msgs: catcache 7 ... relcache 17310 ... relcache 17310 snapshot 2608
> rmgr: Transaction len (rec/tot): 34/ 34, tx: 1661, lsn: 0/02006300, prev 0/02005CA0, desc: ABORT
2024-07-07
> 09:15:36.157644 UTC
> rmgr: Standby len (rec/tot): 78/ 78, tx: 0, lsn: 0/02006328, prev 0/02006300, desc: LOCK xid 1662
db
> 16384 rel 17308 xid 1662 db 16384 rel 17309 xid 1662 db 16384 rel 16385 xid 1662 db 16384 rel 17310
> rmgr: Standby len (rec/tot): 54/ 54, tx: 0, lsn: 0/02006378, prev 0/02006328, desc: RUNNING_XACTS
> nextXid 1663 latestCompletedXid 1661 oldestRunningXid 1662; 1 xacts: 1662
> rmgr: Heap len (rec/tot): 59/ 59, tx: 1663, lsn: 0/020063B0, prev 0/02006378, desc: INSERT+INIT
off:
> 1, flags: 0x08, blkref #0: rel 1663/16384/17310 blk 3
> rmgr: Transaction len (rec/tot): 46/ 46, tx: 1663, lsn: 0/020063F0, prev 0/020063B0, desc: COMMIT
> 2024-07-07 09:15:36.162938 UTC
> (The transaction 1662 performs table rewrite.)
>
> What I'm observing with some debug logging added is:
> ReorderBufferProcessTXN(), called during processing the commit record
> 0/02006328, gets reloid = 0 from RelidByRelfilenumber() because
> systable_beginscan() chooses (via GetCatalogSnapshot()) HistoricSnapshot
> with xmin = 1662, xmax = 1662. That snapshot was set inside
> SnapBuildProcessChange(), via ReorderBufferSetBaseSnapshot(), from
> builder->snapshot, which is built inside SnapBuildProcessChange(), via
> SnapBuildBuildSnapshot(), from builder->xmin (builder->xmax), which is
> set by SnapBuildProcessRunningXacts from running->oldestRunningXid = 1662.
>
> Really, WAL contains RUNNING_XACTS oldestRunningXid 1662 before the record
> being decoded.
>
> So I wonder if the RUNNING_XACT record in WAL is correct or it should be
> decoded differently?
Thanks for the bug report and the script to reproduce this. I was also
able to reproduce the problem using the script (not every run though).
While debugging the problem, I see that the failure is coming from
HeapTupleSatisfiesHistoricMVCC()
/* beyond our xmax horizon, i.e. invisible */
else if (TransactionIdFollowsOrEquals(xmin, snapshot->xmax))
{
return false;
}
The problem is that the snapshot we're using has an xmax which is the
same as the xmin of the tuple that has the relevant relfilenode, which
makes the relfilenode not visible. By adding logs, I can see that the
builder has in fact incremented its xmin and xmax beyond what was used
in the snapshot. So, why wasn't an updated snapshot used? While
debugging, I can see that the snapshot being used was actually built a
bit earlier, prior to the snapshot builder being in the
SNAPBUILD_CONSISTENT state. In fact, it was built when the builder was
in the SNAPBUILD_FULL_SNAPSHOT state in SnapBuildProcessChange(). In
SnapBuildProcessChange(), previously built snapshots are reused for
new transactions. Reusing previously built snapshots is fine when in
the SNAPBUILD_CONSISTENT state because subsequently all transactions
which have a catalog change rebuild the snapshot again. I've made a
small change to forget snapshots that are built in
SNAPBUILD_FULL_SNAPSHOT, so that transactions in
SNAPBUILD_FULL_SNAPSHOT rebuild the snapshot again with the updated
xmin and xmax, and this seems to fix the issue. Attaching a patch.
regards,
Ajin Cherian
Fujitsu Australia