Dev & EngARTICLE

PostgreSQL's restore_command confuses network failure with the end of the WAL archive

PostgreSQL's restore_command confuses network failure with the end of the WAL archive
Image: Roberto Diniz
Article · Dev & Eng
Reading
6 min
Code
1
In short

When the restore command fails, PostgreSQL assumes by definition that the WAL archive ended right there, even when the real cause was network instability. Christophe Pettus shows how this exit code confusion can end a recovery silently, with no error in the log.

The file ends where the shell says it ends

PostgreSQL doesn't store anywhere what the last WAL segment in the archive is. During recovery from archive, it finds this out the only way it can: it asks the restore_command for the next segment, receives it, asks for the following one, and so on, until the command fails. That failure is, by definition, the end of the archive, regardless of what actually caused it.

That's the central point of "All Your GUCs in a Row: restore_command," published by Christophe Pettus (a consultant at PGX Inc.) on Planet PostgreSQL. Pettus had already taken apart archive_command in an earlier entry in the same series; here the problem is its mirror image, and the risk is more serious because the confusion between "I couldn't find the file" and "I couldn't even ask" stays invisible in the log.

restore_command has been a sighup-context GUC since PostgreSQL 14; before that it only changed with a server restart, and before version 12 it lived in recovery.conf, read just once. Whether it's mandatory depends on the signal file: with recovery.signal and no restore_command, the server refuses to start. With standby.signal the parameter is optional, because the replica can use primary_conninfo for streaming. With neither of the two, the server warns and the replica ends up endlessly polling pg_wal, which is a configuration, not a plan.

What each exit code actually means

The command runs under the shell, as the operating system user that owns the server, with the data directory as the working directory, once per request. %f is the name of the requested file, a 16 MB segment or a timeline history file. %p is always the same destination path (pg_wal/RECOVERYXLOG for segments, pg_wal/RECOVERYHISTORY for history). %r indicates the segment of the last restartpoint, used today mainly by whoever configures archive_cleanup_command.

The server reads the command's exit code in three ranges, plus one special case:

  • 0 means "the file is at %p." PostgreSQL checks the size, which must match wal_segment_size exactly; a wrong size is FATAL in a point-in-time restore.
  • From 1 to 125 means "it's not in the archive." On a standby the loop keeps trying; in a point-in-time restore, it means recovery ended right there, with a new timeline and the database opened for writes.
  • 126, 127, any value above 125 (with one exception) or death by signal mean "something broke": FATAL: could not restore file, the startup process terminates and pg_controldata keeps showing in archive recovery.
  • The exception is 143, the code the shell uses to report a process killed by SIGTERM: PostgreSQL interprets this as the start of a normal shutdown and doesn't even log it.

When "recovery complete" doesn't mean complete recovery

The problem, as Pettus demonstrates, is that the 1 to 125 range mixes two events with no relation to each other: "the archive doesn't have this segment" and "I couldn't even ask the archive." The cp command returns 1 both for a missing file and for an I/O error. aws s3 cp documents that the 1 code means only "the transfer failed," without saying why. For PostgreSQL, the two cases are identical: end of archive.

If a recovery_target is configured, PostgreSQL 13 and later at least notices the difference: recovery stops before the target and the server dies with FATAL: recovery ended before configured recovery target was reached, leaving the cluster in recovery for a new attempt. But when the goal is simply to restore everything that exists, with no target defined (the most common case in disaster recovery), there's nothing to compare against.

Pettus shows a real log from a restore of 43 segments whose restore_command returned 1 for one specific segment, just once, on the twenty-first:

LOG: restored log file "000000010000000000000014" from archive
LOG: redo done at 0/149A4388 ...
LOG: last completed transaction was at log time 2026-10-27 05:00:28.654215-07
LOG: selected new timeline ID: 2
LOG: archive recovery complete
...
LOG: database system is ready to accept connections

Twenty-two segments were never even requested. Nothing in that log is an error. The database comes up, accepts connections, and any superficial check of "it finished without FATAL" passes without suspicion.

In short: without recovery_target, PostgreSQL has no way of knowing it should keep asking for segments. The difference between a complete restore and one that lost hours of transactions lies only in comparing the LSN from redo done at against the last expected segment, something that has to be checked manually, outside the status log.

There's a small relief starting with PostgreSQL 15, with recovery_prefetch enabled (Linux, and macOS from version 18 on, with maintenance_io_concurrency above zero): the first request for a segment usually comes from the read-ahead, and if it fails, the ordinary blocking read tries again about ten milliseconds later. It's an implementation detail, not a retry policy: with recovery_prefetch = off, the first failure is already the last chance.

Why restoring is slower than it looks

restore_command is serial and synchronous: the startup process calls the shell, waits for the response, and never runs two requests at the same time. Any fixed cost per call multiplies by the number of segments. In a test cited by Pettus, a restore of 43 segments with local cp took 3.1 seconds; the same restore with an artificial 250 ms delay per call rose to 13.7 seconds, with the startup process spending most of its time in the RestoreCommand wait_event, available since PostgreSQL 15.

At scale this hurts: a day of WAL on a busy system easily goes past 20 thousand segments. At 250 ms per call, an optimistic estimate for aws s3 cp (which pays for a Python interpreter and a TLS handshake on every execution), that's about 83 minutes of startup process stalled before a single byte is replayed. That's why pgBackRest (archive-async = y), WAL-G (wal-fetch with automatic prefetch) and Barman (barman-wal-restore --parallel N) exist: they fetch the next segments ahead of time, into a local spool, so that each call to restore_command is served without waiting on the network.

What to do about it

Pettus's recommendation, which works as a checklist for anyone designing a recovery plan, is direct:

  1. Prefer the tool that wrote the archive to read it back, with prefetch turned on, instead of writing a hand-rolled restore_command.
  2. If the command is yours, keep the three real outcomes separate: exit 1 only for "the archive doesn't have this file," and something above 127 (255 is the traditional value) for any other failure, from network to permissions.
  3. Never use 126, 127 or 143 on purpose: the first two make the log lie by saying the command doesn't exist; the third is silently treated as a normal shutdown.
  4. After any recovery, compare the redo done at LSN in the log with the last segment you expected to be applied, before releasing the database for use.

None of this shows up as FATAL if there's no recovery_target configured. archive recovery complete is a sentence about the shell having stopped responding, not about the archive having truly ended. That distinction, made inside the command, is the only thing protecting a disaster recovery plan from a cp that chokes on the network and never warns.

Translated from the Brazilian Portuguese original · Read the original