BUG #19839: Assert in ReorderBufferRestoreCleanup for aborted, spilled transaction

The following bug has been logged on the website:

Bug reference: 19839
Logged by: Atish Prakash
Email address: 125atishprak(at)gmail(dot)com
PostgreSQL version: 18.6
Operating system: Linux x86_64 (kernel 7.0.0, glibc 2.43)
Description:

On an assert-enabled build, logical decoding can fail this assertion and
take
the server through crash recovery:

TRAP: failed Assert("XLogRecPtrIsValid(txn->final_lsn)"), File:
"reorderbuffer.c", Line: 5001

Expected: decoding discards the aborted transaction and continues.

The sequence is:

1. A transaction has a subtransaction with an XID but no decoded changes,
for
example one that only ran SELECT ... FOR UPDATE.
2. The parent exceeds logical_decoding_work_mem while still in progress.
ReorderBufferSerializeTXN() recurses into the subtransaction, writes
nothing,
and still sets RBTXN_IS_SERIALIZED on it. Its final_lsn stays invalid.
3. The parent aborts while the decoder is behind.
4. The parent is chosen for eviction before its abort record is decoded.
ReorderBufferCheckAndTruncateAbortedTXN() finds it aborted and truncates
it,
and ReorderBufferRestoreCleanup() fails on the subtransaction's
final_lsn.

ReorderBufferCheckAndTruncateAbortedTXN() came in with 072ee847ad, so I
expect
17 and earlier are not affected, but I have not tested them.

From reading the code, a non-assert build goes through an empty cleanup loop
for
this subtransaction, so I expect no user-visible effect there. I have not
run a
non-assert build.

I found this with a stress test of REPACK (CONCURRENTLY), where the REPACK
decoding worker failed in the same way, on both a plain assert build and an
ASan
build. It does not need REPACK: the attached script uses only
pg_recvlogical. It
stalls pg_recvlogical with SIGSTOP so that the decoder is behind when the
transaction aborts.

Proposed fix, attached as 0001-fix-aborted-spilled-txn-assert.patch: set
RBTXN_IS_SERIALIZED only if something was written. With the patch, on
master:
- the script no longer fails
- all test_decoding tests and all 239 core regression tests pass
- a spilled transaction with an empty subtransaction, a rolled-back
subtransaction
and a released one decodes the expected rows
TAP tests were not run, because my build has them disabled. The patch has no
regression test, because the script depends on stalling a live consumer. It
applies cleanly to REL_18_STABLE and REL_19_STABLE, but I only built and
tested it
on master.

I found this with a fuzzer, and AI tools helped me build it, write the
script
and patch, and draft this report.

Versions where the script fails:
- 18.6 (REL_18_STABLE at 813a74bc5a; the assertion reads txn->final_lsn !=
InvalidXLogRecPtr)
- 19rc1 (REL_19_STABLE at 0b1eb8b917)
- master at 72b9498df9, plus my unrelated uncommitted patch to ruleutils.c
The patch was built on master at b58a9a97fe.
Platform: Linux 7.0.0-42-generic x86_64, glibc 2.43, Intel i9-13900HX, 14
GiB RAM
Build: clang 21.1.8, CFLAGS=-O1 -g, --enable-cassert --enable-debug
--without-icu --without-readline --without-libxml --without-openssl
Settings set by the script: wal_level=logical,
logical_decoding_work_mem=64kB

Stack from 19rc1, with addr2line for the static functions:

ReorderBufferRestoreCleanup reorderbuffer.c:5001
ReorderBufferTruncateTXN reorderbuffer.c:1749
(subtransaction)
ReorderBufferTruncateTXN reorderbuffer.c:1665 (parent)
ReorderBufferCheckAndTruncateAbortedTXN reorderbuffer.c:1819
ReorderBufferQueueChange
DecodeInsert decode.c:956
LogicalDecodingProcessRecord

Reproducer, run as: logical-decoding-assert-repro.sh <bin dir of an assert
build>

#!/bin/bash
# Usage: logical-decoding-assert-repro.sh <postgres bin dir, built with
--enable-cassert> [work dir]
# Assertion failure in ReorderBufferRestoreCleanup during logical decoding,
without REPACK.
set -u
BIN=$1; WORK=${2:-$(mktemp -d)}; PORT=${PORT:-6399}; D=$WORK/data; rm -rf
"$D"; mkdir -p "$WORK"
export PGHOST=$WORK PGPORT=$PORT PGDATABASE=postgres
"$BIN/initdb" -D "$D" -A trust --no-sync >/dev/null
cat >> "$D/postgresql.conf" <<CONF
listen_addresses = ''
unix_socket_directories = '$WORK'
port = $PORT
wal_level = logical
logical_decoding_work_mem = 64kB
CONF
"$BIN/pg_ctl" -D "$D" -l "$WORK/server.log" -w start >/dev/null
P="$BIN/psql -X -q -v ON_ERROR_STOP=1"
$P -c "CREATE TABLE t (a text)" -c "INSERT INTO t VALUES ('locked')" \
-c "SELECT pg_create_logical_replication_slot('s', 'test_decoding')"
>/dev/null

"$BIN/pg_recvlogical" -d postgres -S s --start -f /dev/null -F 0 -s 1 &
RECV=$!

# Session A stays open throughout.
FIFO=$WORK/a.fifo; rm -f "$FIFO"; mkfifo "$FIFO"; $P < "$FIFO" > /dev/null &
APSQL=$!; exec 9> "$FIFO"
# A: a subtransaction with an XID but no decoded change, then enough to
exceed the limit.
cat >&9 <<SQL
BEGIN;
INSERT INTO t VALUES ('first');
SAVEPOINT sp;
SELECT * FROM t WHERE a = 'locked' FOR UPDATE;
RELEASE sp;
INSERT INTO t SELECT repeat('a', 100) FROM generate_series(1, 2000);
SELECT 1;
SQL
sleep 2 # the walsender decodes this and spills A; A is still in progress

# Stall the walsender in the middle of sending a large committed
transaction.
kill -STOP $RECV
$P -c "INSERT INTO t SELECT repeat('c', 1000) FROM generate_series(1,
200000)"
for i in $(seq 1 120); do
w=$($P -Atc "SELECT wait_event FROM pg_stat_activity WHERE backend_type =
'walsender'")
[ "$w" = "WalSenderWriteData" ] && break
sleep 0.5
done
echo "walsender wait event: $w"

# Behind the stalled walsender: more of A, then another transaction that
crosses the limit, then A aborts.
echo "INSERT INTO t SELECT repeat('a', 100) FROM generate_series(1, 200);
SELECT 1;" >&9
sleep 0.5
$P <<SQL &
BEGIN;
INSERT INTO t SELECT repeat('d', 100) FROM generate_series(1, 120);
SELECT pg_sleep(4);
COMMIT;
SQL
DS=$!
sleep 1
echo "ROLLBACK;" >&9
exec 9>&-
wait $APSQL
kill -CONT $RECV # decoding resumes; A's abort record has not been read
but CLOG says aborted
sleep 8
wait $DS 2>/dev/null
kill $RECV 2>/dev/null
echo "--- server log"
grep -E 'TRAP|terminated by signal|was terminated' "$WORK/server.log" | cut
-c1-200
"$BIN/pg_ctl" -D "$D" -m immediate stop >/dev/null 2>&1