| From: | Masahiko Sawada <sawada(dot)mshk(at)gmail(dot)com> |
|---|---|
| To: | Srinath Reddy Sadipiralla <srinath2133(at)gmail(dot)com> |
| Cc: | pgsql-hackers <pgsql-hackers(at)postgresql(dot)org> |
| Subject: | Re: Fix "unexpected logical decoding status change" error; from concurrent logical decoding activation |
| Date: | 2026-07-14 21:02:39 |
| Message-ID: | CAD21AoA_pRC3UOz_x9-iL65V9b5NVVRbcDtJ6MamfnN3ZA0n_Q@mail.gmail.com |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-hackers |
On Thu, Jul 9, 2026 at 9:23 PM Srinath Reddy Sadipiralla
<srinath2133(at)gmail(dot)com> wrote:
>
>
>
> ---------- Forwarded message ---------
> From: Srinath Reddy Sadipiralla <srinath2133(at)gmail(dot)com>
> Date: Fri, Jul 10, 2026 at 9:48 AM
> Subject: Fix "unexpected logical decoding status change" error; from concurrent logical decoding activation
> To: PostgreSQL Hackers <pgsql-hackers(at)lists(dot)postgresql(dot)org>
> Cc: Masahiko Sawada <sawada(dot)mshk(at)gmail(dot)com>
>
>
> Hi,
>
> While stress-testing REPACK CONCURRENTLY, I was in that
> area looking at BUG #19519 (REPACK failing with "missingchunk
> number N for toast value" [0]; note that one reproduces with plain
> REPACK too, since it's the shared copy_table_data() path, so
> it's independent of what follows), I hit a different, reproducible
> failure under high concurrency:
> ERROR: unexpected logical decoding status change 1
>
> I believe this is a race bug in the on-demand logical decoding
> activation machinery (logicalctl.c), exposed by
> REPACK CONCURRENTLY but not actually specific to it, as
> this can be reproduced using pg_create_logical_replication_slot and CREATE_REPLICATION_SLOT.
>
> At wal_level = 'replica', logical decoding is toggled on the first time a
> logical slot is created. EnableLogicalDecoding() sets the shared
> logical_decoding_enabled flag and writes an
> XLOG_LOGICAL_DECODING_STATUS_CHANGE record so standbys
> learn about the change. On the decoding side, xlog_decode() treats
> that record as unreachable:
> elog(ERROR, "unexpected logical decoding status change %d", ...);
>
> The reasoning (per the comment there) is that no running decoder can ever
> have such a record within the LSN range it scans: there is exactly one
> enable record per disabled->enabled transition, and it precedes the
> decoding start point reserved by any slot.
>
> That case does not hold under concurrency. EnableLogicalDecoding()
> does:
>
> LWLockAcquire(LogicalDecodingControlLock, EXCLUSIVE);
> if (logical_decoding_enabled) /* already on? -> done */
> { ... return; }
> LWLockRelease(...);
>
> WaitForProcSignalBarrier(...); /* lock released here */
>
> LWLockAcquire(LogicalDecodingControlLock, EXCLUSIVE);
> logical_decoding_enabled = true;
> write_logical_decoding_status_update_record(true); /* the record */
> LWLockRelease(...);
>
> The "already enabled?" check and the record write happen under two
> separate lock acquisitions, with the barrier wait in between. The lock
> must be dropped across the barrier; backends absorbing the barrier
> take LogicalDecodingControlLock in shared mode (via
> IsXLogLogicalInfoEnabled()), so holding it across WaitForProcSignalBarrier()
> would deadlock.
>
> So if two backends create the first logical slot(s) at the same time,
> both can pass the initial check while the flag is still false, and both
> end up writing a status-change record. The second (redundant) record
> lands after the decoding start point the other slot already reserved,
> so that slot scans it and trips the elog() above.
>
> REPACK CONCURRENTLY makes this easy to hit because each operation
> creates a temporary logical slot (max_repack_replication_slots), so firing
> many REPACKs in parallel from the disabled state gives you many backends
> racing to perform the very first activation. But nothing here is REPACK-specific.
>
> To reproduce this i have added a test using logical-decoding-activation
> injection point in 051_effective_wal_level.pl
>
> I also hit it with a stress script [1] which was again related to the
> BUG #19519, instead of vacuum full i replaced it with REPACK (concurrently).
>
> To fix this I re-checked the flag after re-acquiring the lock and skipped
> the state change/WAL write if another backend had already completed
> the transition.
>
> LWLockAcquire(LogicalDecodingControlLock, EXCLUSIVE);
>
> if (LogicalDecodingCtl->logical_decoding_enabled)
> {
> LogicalDecodingCtl->pending_disable = false;
> LWLockRelease(LogicalDecodingControlLock);
> return;
> }
>
> START_CRIT_SECTION();
>
> With this, only the backend that actually performs the disabled->enabled
> transition writes a record, and every slot's start point stays at or after
> it, restoring the case xlog_decode() depends on.
>
> Patch attached. It fixes logicalctl.c and adds a regression test to
> 051_effective_wal_level.pl reusing the existing injection-point
> infrastructure. With the fix the test passes; without it it fails with
> the exact error above.
Thank you for the report and the patch!
I agree with your analysis and the patch basically looks good to me.
Here are some review comments:
+ # Let the released backend finish creating its slot: feed running-xacts
+ # records until it reaches a consistent point (poll_query_until re-runs the
+ # query, so pg_log_standby_snapshot() is called until the slot is created).
+ $primary->poll_query_until(
+ 'postgres', qq[
+select (pg_log_standby_snapshot() is not null)
+ and exists (select 1 from pg_replication_slots
+ where slot_name = 'slot_stray' and confirmed_flush_lsn
is not null)
+]);
I don't think we need to call pg_log_standby_snapshot() until the slot
is created since the slot creation writes the running-xacts record
during the slot creation.
---
+ # Decoding the first slot must not stumble over a stray status-change record.
+ my ($decode_rc, $decode_out, $decode_err) = $primary->psql(
+ 'postgres',
+ qq[select count(*) from pg_logical_slot_get_changes('slot_first',
null, null)],
+ on_error_die => 0);
+ is($decode_rc, 0, "decoding a concurrently-created slot succeeds");
+ unlike(
+ $decode_err,
+ qr/unexpected logical decoding status change/,
+ "no redundant status-change record was decoded");
We can use safe_psql() to check if the query successfully completes.
I've made some cosmetic changes to the comment and the new test
including the above comments. Please review it.
Regards,
--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com
| Attachment | Content-Type | Size |
|---|---|---|
| v2-0001-Fix-race-condition-when-enabling-logical-decoding.patch | application/x-patch | 6.0 KB |
| From | Date | Subject | |
|---|---|---|---|
| Next Message | Andrew Dunstan | 2026-07-14 21:23:40 | meson: avoid PATH bloat from NLS .mo targets in tmp_install test setup |
| Previous Message | Khoa Nguyen | 2026-07-14 20:53:45 | Re: pg_buffercache: Add per-relation summary stats |