MIME-Version: 1.0
From: =?UTF-8?B?S2FzcGVyIEbDuG5z?= <kasper.fons@cloudkitchens.com>
Date: Mon, 24 Nov 2025 14:46:26 +0100
Message-ID: 
 <CANOng2i1G_57nvZ4ip4uKKU87jtt+fzqWUFV_ou6L8N3bteSXQ@mail.gmail.com>
Subject: restore_command on high-throughput cluster never switches to
 streaming replication
To: pgsql-admin@lists.postgresql.org
Content-Type: multipart/alternative; boundary="0000000000006006810644576481"
Archived-At: 
 <https://www.postgresql.org/message-id/CANOng2i1G_57nvZ4ip4uKKU87jtt%2BfzqWUFV_ou6L8N3bteSXQ%40mail.gmail.com>
Precedence: bulk

--0000000000006006810644576481
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

Hi PostgreSQL community.

I debugged an instance where a PostgreSQL standby would not switch to
streaming replication when the `restore_command` fails.

*Expectation*
I expect PostgreSQL to try switching to streaming replication if the
`restore_command` fails.

*What happens*
PostgreSQL attempts to restore the previously restored WAL segment and then
retries the failed segment. However, because the primary produces WAL at a
high rate, the WAL file now exists and PostgreSQL does not try to switch to
streaming replication.

*Context*
Running PostgreSQL 15.7 in Kubernetes using CloudNative PostgreSQL Operator=
.

*Logs*
I configured PostgreSQL to emit DEBUG3 level logs. Newest logs first,
oldest last.

got WAL segment from archive
executing restore command "/controller/manager wal-restore
--log-destination /controller/log/postgres.json *000000410000A7BA00000058*
pg_wal/RECOVERYXLOG"
got WAL segment from archive
executing restore command "/controller/manager wal-restore
--log-destination /controller/log/postgres.json *000000410000A7BA00000057*
pg_wal/RECOVERYXLOG"
could not open file "pg_wal/*000000410000A7BA00000058*": No such file or
directory
could not restore file "*000000410000A7BA00000058*" from archive: child
process exited with exit code 1
executing restore command "/controller/manager wal-restore
--log-destination /controller/log/postgres.json *000000410000A7BA00000058*
pg_wal/RECOVERYXLOG"
got WAL segment from archive
executing restore command "/controller/manager wal-restore
--log-destination /controller/log/postgres.json *000000410000A7BA00000057*
pg_wal/RECOVERYXLOG"

Notice that when *000000410000A7BA00000058* failed, PostgreSQL asked for
*000000410000A7BA00000057* which it had already restored. Aftwards, it asks
about *000000410000A7BA00000058* once again.

*Problem*
This is problematic because the standby will never switch to streaming
replication.

*Workaround*
We can get the PostgreSQL replica to become in-sync if we change the
command to `/bin/false` when we are withing `wal_keep_size`.

*Question*
Is this the expected behaviour?

I expect the function `WaitForWALToBecomeAvailable` to switch to streaming
replication once a single `restore_command` fails. This also happens when
`/bin/false` is used instead.

Any help would be greatly appreciated
/Kasper F=C3=B8ns

--0000000000006006810644576481
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr">Hi PostgreSQL community.<div><br></div><div>I debugged an =
instance where a PostgreSQL standby would not switch to streaming replicati=
on when the `restore_command` fails.</div><div><br></div><div><b>Expectatio=
n</b></div><div>I expect PostgreSQL to try switching to streaming replicati=
on if the `restore_command` fails.</div><div><br></div><div><b>What happens=
</b></div><div>PostgreSQL attempts to restore the previously restored WAL s=
egment and then retries the failed segment. However, because the primary pr=
oduces WAL at a high rate, the WAL file now exists and PostgreSQL does not =
try to switch to streaming replication.</div><div><br></div><div><b>Context=
</b></div><div>Running PostgreSQL 15.7 in Kubernetes using CloudNative Post=
greSQL Operator.</div><div><br></div><div><b>Logs</b></div><div>I configure=
d PostgreSQL to emit DEBUG3 level logs. Newest logs first, oldest last.</di=
v><div><br></div><div><font face=3D"times new roman, serif">got WAL segment=
 from archive<br>executing restore command &quot;/controller/manager wal-re=
store --log-destination /controller/log/postgres.json <b>000000410000A7BA00=
000058</b> pg_wal/RECOVERYXLOG&quot;<br>got WAL segment from archive<br>exe=
cuting restore command &quot;/controller/manager wal-restore --log-destinat=
ion /controller/log/postgres.json <b>000000410000A7BA00000057</b> pg_wal/RE=
COVERYXLOG&quot;<br>could not open file &quot;pg_wal/<b>000000410000A7BA000=
00058</b>&quot;: No such file or directory<br>could not restore file &quot;=
<b>000000410000A7BA00000058</b>&quot; from archive: child process exited wi=
th exit code 1<br>executing restore command &quot;/controller/manager wal-r=
estore --log-destination /controller/log/postgres.json <b>000000410000A7BA0=
0000058</b> pg_wal/RECOVERYXLOG&quot;<br>got WAL segment from archive<br>ex=
ecuting restore command &quot;/controller/manager wal-restore --log-destina=
tion /controller/log/postgres.json <b>000000410000A7BA00000057</b> pg_wal/R=
ECOVERYXLOG&quot;<br></font></div><div><br></div><div>Notice that when=C2=
=A0<b>000000410000A7BA00000058</b> failed, PostgreSQL asked for=C2=A0<b>000=
000410000A7BA00000057</b> which it had already restored. Aftwards, it asks =
about=C2=A0<b>000000410000A7BA00000058</b> once again.</div><div><br></div>=
<div><b>Problem</b></div><div><div>This is problematic because the standby =
will never switch to streaming replication.</div><div><br></div><div><b>Wor=
karound</b></div><div>We can get the PostgreSQL replica to become in-sync i=
f we change the command to `/bin/false` when we are withing `wal_keep_size`=
.</div><div><br></div><div><b>Question</b></div><div>Is this the expected b=
ehaviour?</div></div><div><br></div><div>I expect the function `WaitForWALT=
oBecomeAvailable` to switch to streaming replication once a single `restore=
_command` fails. This also happens when `/bin/false` is used instead.</div>=
<div><br></div><div>Any help would be greatly appreciated</div><div>/Kasper=
 F=C3=B8ns</div></div>

--0000000000006006810644576481--