Fix race with timeline selection in logical decoding during promotion

During promotion, there is a window where RecoveryInProgress() returns
true but the WAL segments of the old timeline have already been removed.
A logical decoding could pick up the old timeline in this window when
reading a page, failing with the following error:
ERROR: requested WAL segment ... has already been removed

This issue does not lead to any data correctness issue, as retrying to
decode the data works in follow-up decoding attempts.  It impacts
availability, though.  Other WAL page read callbacks have a similar
issue, this commit takes care of what should be the noisiest code path:
logical decoding with START_REPLICATION in a WAL sender.

A TAP test, based on an injection point waiting in the startup process
after the segments have been removed/recycled, is added.  This part is
backpatched down to v17.

This issue has been causing sporadic failures in the buildfarm, and
was reproducible manually.  This issue happens since logical decoding on
standbys exists, down to v16.

Reported-by: Alexander Lakhin <exclusion@gmail.com>
Author: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Reviewed-by: Hayato Kuroda <kuroda.hayato@fujitsu.com>
Reviewed-by: Xuneng Zhou <xunengzhou@gmail.com>
Discussion: https://postgr.es/m/7daef094-abf3-4672-bc23-3df4763b16a3@gmail.com
Backpatch-through: 16

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 745276908d2faf0f38cef8272069ae9e8e61a612..f0e1e381f1fc34ee4893aa1c00b9931bf9adff55 100644 (file)
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6120,6 +6120,8 @@ StartupXLOG(void)
        if (ArchiveRecoveryRequested)
                CleanupAfterArchiveRecovery(EndOfLogTLI, EndOfLog, newTLI);
 
+       INJECTION_POINT("promotion-after-wal-segment-cleanup");
+
        /*
         * Local WAL inserts enabled, so it's time to finish initialization of
         * commit timestamp.

diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 5cf988122db79bc0b0a4102a4cec8fd64e11afde..69fbb038790d7ea226c1c7f0f87586b1c8df0db9 100644 (file)
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1091,7 +1091,29 @@ logical_read_xlog_page(XLogReaderState *state, XLogRecPtr targetPagePtr, int req
        am_cascading_walsender = RecoveryInProgress();
 
        if (am_cascading_walsender)
-               GetXLogReplayRecPtr(&currTLI);
+       {
+               TimeLineID      insertTLI;
+
+               /*
+                * If the insertion timeline has already been set, use it.
+                * InsertTimeLineID is set before the WAL segments of the old timeline
+                * are removed, before SharedRecoveryState switches to
+                * RECOVERY_STATE_DONE.
+                *
+                * There is a window where RecoveryInProgress() still returns true but
+                * the old timeline's WAL segments have already been removed or
+                * recycled.  Using the WAL insertion timeline avoids attempting to
+                * read from those removed segments, improving availability, and is a
+                * safe thing to do as promotion copies the contents in the last
+                * segment of the old timeline to the first segment of the new
+                * timeline, up to the switchpoint.
+                */
+               insertTLI = GetWALInsertionTimeLineIfSet();
+               if (insertTLI != 0)
+                       currTLI = insertTLI;
+               else
+                       GetXLogReplayRecPtr(&currTLI);
+       }
        else
                currTLI = GetWALInsertionTimeLine();
 

diff --git a/src/test/recovery/t/035_standby_logical_decoding.pl b/src/test/recovery/t/035_standby_logical_decoding.pl
index 9c5b1ba64a811345c74c1706f4fa7682a47c4e2e..7f63c72bd20eefdb28b86e8e30134dd2969c920c 100644 (file)
--- a/src/test/recovery/t/035_standby_logical_decoding.pl
+++ b/src/test/recovery/t/035_standby_logical_decoding.pl
@@ -1014,4 +1014,73 @@ is($cascading_stdout, $expected,
        'got same expected output from pg_recvlogical decoding session on cascading standby'
 );
 
+##################################################
+# Test that logical decoding on standby correctly handles a timeline
+# change during promotion.  This relies on an injection point that
+# waits between the moment the segments of the old timeline are removed
+# and the moment RecoveryInProgress() would set, catching that a WAL
+# sender is still able to decode changes across a promotion.
+##################################################
+
+# Create a logical slot on the cascading standby for this test.
+$node_cascading_standby->create_logical_slot_on_standby($node_standby,
+       'race_slot', 'testdb');
+
+$node_standby->safe_psql('testdb',
+       qq[INSERT INTO decoding_test(x,y) SELECT s, s::text FROM generate_series(10,13) s;]
+);
+$node_standby->wait_for_replay_catchup($node_cascading_standby);
+
+$expected = q{BEGIN
+table public.decoding_test: INSERT: x[integer]:10 y[text]:'10'
+table public.decoding_test: INSERT: x[integer]:11 y[text]:'11'
+table public.decoding_test: INSERT: x[integer]:12 y[text]:'12'
+table public.decoding_test: INSERT: x[integer]:13 y[text]:'13'
+COMMIT};
+
+$node_standby->safe_psql('testdb', 'CREATE EXTENSION injection_points;');
+$node_standby->wait_for_replay_catchup($node_cascading_standby);
+
+# Attach injection point to pause startup after WAL segment cleanup
+# but before RecoveryInProgress() flips to false.
+$node_cascading_standby->safe_psql('testdb',
+       "SELECT injection_points_attach('promotion-after-wal-segment-cleanup', 'wait');"
+);
+
+# Promote, wait for the removal of the segments on the old timeline.
+$node_cascading_standby->safe_psql('testdb', "SELECT pg_promote(false)");
+$node_cascading_standby->wait_for_event('startup',
+       'promotion-after-wal-segment-cleanup');
+
+# Start pg_recvlogical.
+my ($stdout2, $stderr2);
+my $handle2 = IPC::Run::start(
+       [
+               'pg_recvlogical',
+               '--dbname' => $node_cascading_standby->connstr('testdb'),
+               '--slot' => 'race_slot',
+               '--option' => 'include-xids=0',
+               '--option' => 'skip-empty-xacts=1',
+               '--file' => '-',
+               '--no-loop',
+               '--start',
+       ],
+       '>' => \$stdout2,
+       '2>' => \$stderr2,
+       IPC::Run::timeout($default_timeout));
+
+# Verify that pg_recvlogical successfully decodes the data while startup
+# is still paused in the injection point.
+$pump_timeout = IPC::Run::timer($default_timeout);
+ok( pump_until($handle2, $pump_timeout, \$stdout2, qr/COMMIT/s),
+       'pg_recvlogical works during promotion timeline switch');
+chomp($stdout2);
+is($stdout2, $expected,
+       'got expected output from pg_recvlogical during promotion timeline switch'
+);
+
+# Resume promotion.
+$node_cascading_standby->safe_psql('testdb',
+       "SELECT injection_points_wakeup('promotion-after-wal-segment-cleanup');");
+
 done_testing();