Skip to main content
RunBook Academy

← All break/fix scenarios in Backup & DR

advancedbdr-wal-archive~50 min

Point-in-time recovery stopped short because the archive had a gap

Reported symptoms

  • ●A release at 09:05 on 2026-08-27 ran a migration with a wrong predicate and rewrote most of the orders table on the rbdr-orders cluster
  • ●Point-in-time recovery is requested to 2026-08-27 08:55:00+00, ten minutes before the migration and inside a working day of ordinary traffic
  • ●The recovering instance starts, restores three segments from the archive, reaches a consistent state and accepts read-only connections
  • ●Recovery then ends without reaching the requested target, and the log reports the last completed transaction at 02:41:07 - six hours and fourteen minutes earlier than asked for
  • ●No message names the recovery target as invalid, out of range or unparseable, and the base backup produced no error at any point
  • ●The archive directory is not empty and not small: it holds forty-one thousand segments and its newest file was written at 09:31 that morning
  • ●The nightly base backup job for 2026-08-27 had exited zero, and the archive filesystem free-space check was green at the time of the recovery

Evidence

  • · pg_stat_archiver on the primary reports archived_count 41892, last_archived_wal 0000000100000012000000E4 archived at 09:31:14, failed_count 1914, and last_failed_wal 0000000100000012000000A3 with last_failed_time 04:11:52
  • · A sorted listing of /srv/rbdr-wal-archive runs 0000000100000012000000A0, A1, A2 and then jumps to B8: twenty-one names between A3 and B7 are absent from the destination
  • · The recovery log restores A0, A1 and A2, records consistent recovery state reached, then reports cp: cannot stat the A3 segment, and ends with redo done and a last completed transaction time of 02:41:07
  • · The recovery log contains no "recovery stopping before commit of transaction" line, which is the line the validated capture of a successful point-in-time recovery does contain
  • · The validated PostgreSQL 18.6 capture of a healthy archive and a successful recovery is reproduced below as the contrast: archived=6 failed=0, a contiguous segment sequence, and a recovery that stopped because it reached its target
  • · The primary log for 2026-08-27 shows repeated archive command failures from 02:41 to 04:38, coincident with a storage maintenance window that took the NFS export behind /srv/rbdr-wal-archive offline
  • · The on-call ticket for that night records a free-space alert on the WAL volume at 03:58 and its closure at 04:14, with the action described as removing segment files and their archive_status markers to reclaim space
  • · The monitoring repository contains a check for the nightly base backup exit status and a check for archive filesystem free space, and no check that reads failed_count, last_failed_wal, or the modification time of the newest archived segment
Diagnosis and resolutionclick to reveal

Root cause

Two defects. The archive lost a run of segments, and nothing in the estate was positioned to notice. The immediate cause is a hole in the middle of the segment sequence. Between 02:41 and 04:38 the NFS export behind `/srv/rbdr-wal-archive` was offline for a storage maintenance the database team had not been told about. The archive command failed on every attempt during that window, which is what `failed_count` 1914 and `last_failed_wal` 0000000100000012000000A3 record. The primary kept serving transactions throughout, because archiving failure does not stop a cluster; it stops the recycling of write-ahead log files, so `pg_wal` grew instead. At 03:58 that growth raised a free-space alert on the WAL volume, and at 04:14 the alert was closed by deleting segment files from `pg_wal` together with their markers under `pg_wal/archive_status`. Those markers are what the archiver walks. Removing them removed the instruction to archive those segments, so when the export returned at 04:38 archiving resumed cleanly at the next segment and never went back. Twenty-one segments exist in no copy anywhere. A recovery cannot step over a hole. Write-ahead log replay is sequential by construction: each segment continues the one before it, so the first missing file is the end of the reachable timeline regardless of how many later files the archive holds. The base backup of 01:00 was intact, the archive held segments up to 09:31, and the recovery still could not pass 02:41. The second defect is why a two-hour archiving outage on 27 August was first discovered during a recovery on 27 August. The monitoring repository holds a check on the nightly base backup's exit status and a check on free space in the archive filesystem. Neither can see this. A base backup exits zero whether or not the segments that make it useful arrive at the destination, and the archive filesystem was never short of space - the volume that filled was `pg_wal` on the primary. The two readings that would have named the fault within minutes, `failed_count` and the age of the newest archived segment, were not collected by anything.

Remediation

Treat the recovering instance as evidence before treating it as a service. It holds the only assembled copy of the pre-incident data and it must not be promoted or overwritten while the reachable window is still being established. First establish where the timeline actually ends, from the destination rather than from the database's opinion of the destination: ```bash RBDR_ARCHIVE=/srv/rbdr-wal-archive ls -1 "$RBDR_ARCHIVE" | grep -E '^[0-9A-F]{24}$' | sort > /tmp/rbdr-segments.txt wc -l < /tmp/rbdr-segments.txt ``` The first hole in that list bounds every recovery that starts from a base backup older than it. Here the bound is 0000000100000012000000A3, and the last transaction before it committed at 02:41:07. Then ask whether a later starting point exists. A base backup taken after 04:38 is anchored beyond the hole and can reach any target after that time; the 2026-08-28 base backup is such a backup, and it is later than the incident, so it does not serve this request. There is no base backup between 04:38 and 09:05, so no route to 08:55 exists from physical recovery. The recoverable position is therefore 2026-08-27 02:41:07, and the shortfall against the requested target is six hours fourteen minutes of orders. That number is reported to the business as a number, together with the logical dump taken at 06:00 if the application can accept a table-level reconstruction from it. Nothing is promoted until someone with the authority to accept that loss has accepted it. Once the recovery decision is made, take a fresh base backup immediately. Every base backup older than the hole is now only usable for targets before 02:41, and a new one re-anchors the estate on the continuous part of the archive.

Verification

A recovery is verified by what the log says about why it stopped, not by whether the server came up. A successful point-in-time recovery ends because it reached its target and saw a transaction beyond it. In the validated PostgreSQL 18.6 capture that reads `recovery stopping before commit of transaction 836, time 2026-08-28 13:34:42.096745+00`, followed by a last completed transaction time earlier than that commit and later than the requested target. A recovery that ends without such a line ended because it ran out of input, and the difference between the two is the difference between a restore and a partial one. The archive is verified by contiguity, not by size. `rbdr-archive-gap-check` walks the sorted segment names and exits non-zero on the first discontinuity; on the repaired archive it reports zero holes from the newest base backup forward. The archiver is verified by two readings taken twice, ten minutes apart: `failed_count` must be unchanged between them, and `last_archived_wal` must have advanced or the newest file in the archive must be younger than `archive_timeout` plus a margin. Finally the recovered data is verified against a property recorded before the incident: the row count and the sum of the amount column for the orders written before 02:41:07, compared with the figures in the pre-release report. A structurally perfect recovery to the wrong point matches neither.

Prevention

**Alert on the archiver, not on the archive directory.** Two checks would have made this a ticket at 02:45 instead of an incident at 12:04: the delta in `pg_stat_archiver.failed_count` over an interval, and the age of the newest file in the archive. Both are cheap, both are independent of each other, and neither existed. **Audit continuity on a schedule.** Free space and file count say nothing about whether the sequence has a hole. A sequence audit over the archive turns an unreachable recovery window into a failed job, days before anyone needs it. **Never reclaim space on a WAL volume by removing segments or their archive_status markers.** That converts a recoverable backlog into a permanent hole, and it does so silently: archiving resumes, the counters look healthy, and only a recovery finds out. The correct responses are to fix the archive destination, to extend the volume, or to accept the cluster stopping - all of which are reversible. **Make the archive command fail loudly and never lie.** A command that returns zero without the bytes being durable at the destination produces exactly this hole with no failure count at all, which is strictly worse than the case documented here. **Take a base backup after any archiving interruption.** A hole retires every earlier base backup for every target after it, and the estate should not discover that during an incident. **Tell the storage team which exports a database depends on.** The maintenance that started this was routine, announced, and invisible to the people whose recovery window it consumed.

Reported symptoms

At 09:05 on 2026-08-27 a release ran a migration whose predicate was wrong and rewrote most of the orders table on the rbdr-orders cluster. The team asks for a point-in-time recovery to 08:55:00+00, ten minutes earlier.

The recovering instance starts. It restores three segments, reaches a consistent state, accepts read-only connections — and then stops. Its last statement about time is 02:41:07. Nothing says the target was invalid or out of range.

The archive is neither empty nor small: forty-one thousand segments, the newest written at 09:31 that morning. Every check the team runs on it was green.

Evidence provided

Start with the database’s own account of what it handed off.

Read-only / Safethe archiver's statistics on the primary
$ psql -x -c 'SELECT * FROM pg_stat_archiver'
-[ RECORD 1 ]------+------------------------------
archived_count     | 41892
last_archived_wal  | 0000000100000012000000E4
last_archived_time | 2026-08-27 09:31:14.882431+00
failed_count       | 1914
last_failed_wal    | 0000000100000012000000A3
last_failed_time   | 2026-08-27 04:11:52.104663+00
stats_reset        | 2026-06-01 00:00:00.117402+00

Illustrative output

Then the destination’s account of what exists.

Read-only / Safethe archive around the segment recovery could not restore
$ ls -1 /srv/rbdr-wal-archive | sort
0000000100000012000000A0
0000000100000012000000A1
0000000100000012000000A2
0000000100000012000000B8
0000000100000012000000B9
0000000100000012000000BA

Illustrative output

And the recovery log itself.

Service impact possiblerecovery to 08:55 ends at 02:41
$ pg_ctl -D /srv/rbdr-pitr start
2026-08-27 12:04:18.331 UTC [2214] LOG:  starting point-in-time recovery to 2026-08-27 08:55:00+00
2026-08-27 12:04:18.402 UTC [2214] LOG:  restored log file "0000000100000012000000A0" from archive
2026-08-27 12:04:18.560 UTC [2214] LOG:  consistent recovery state reached at 12/A0000120
2026-08-27 12:04:18.560 UTC [2208] LOG:  database system is ready to accept read-only connections
2026-08-27 12:04:18.744 UTC [2214] LOG:  restored log file "0000000100000012000000A1" from archive
2026-08-27 12:04:19.011 UTC [2214] LOG:  restored log file "0000000100000012000000A2" from archive
cp: cannot stat '/srv/rbdr-wal-archive/0000000100000012000000A3': No such file or directory
2026-08-27 12:04:19.088 UTC [2214] LOG:  redo done at 12/A2FFE118
2026-08-27 12:04:19.088 UTC [2214] LOG:  last completed transaction was at log time 2026-08-27 02:41:07.556218+00

Illustrative output

The contrast is measured: a recovery over a continuous archive on the same major version, captured for this course.

Read-only / Safea healthy archive, measured
$ psql -Atc 'SELECT archived_count, failed_count, last_archived_wal FROM pg_stat_archiver'
  pg_stat_archiver:
  archived=6 failed=0 last=000000010000000000000005
WAL segments in the archive   : 5
  000000010000000000000001
  000000010000000000000002
  000000010000000000000003
  000000010000000000000003.00000028.backup
  000000010000000000000004
  000000010000000000000005
Read-only / Safewhat a recovery that reaches its target looks like
$ pg_ctl -D /work/base -o '-p 5434' start
  2026-08-28 13:35:12.708 UTC [631] LOG:  starting point-in-time recovery to 2026-08-28 13:34:40.077562+00
2026-08-28 13:35:12.708 UTC [631] LOG:  redo starts at 0/3000028
2026-08-28 13:35:12.713 UTC [631] LOG:  restored log file "000000010000000000000004" from archive
2026-08-28 13:35:12.713 UTC [631] LOG:  consistent recovery state reached at 0/3000120
2026-08-28 13:35:12.713 UTC [625] LOG:  database system is ready to accept read-only connections
2026-08-28 13:35:12.726 UTC [631] LOG:  restored log file "000000010000000000000005" from archive
2026-08-28 13:35:12.735 UTC [631] LOG:  recovery stopping before commit of transaction 836, time 2026-08-28 13:34:42.096745+00
2026-08-28 13:35:12.735 UTC [631] LOG:  redo done at 0/52EBC90 system usage: CPU: user: 0.01 s, system: 0.00 s, elapsed: 0.02 s
2026-08-28 13:35:12.735 UTC [631] LOG:  last completed transaction was at log time 2026-08-28 13:34:38.041366+00

The primary’s log shows archive command failures from 02:41 to 04:38, matching a storage maintenance on the NFS export. The on-call ticket for that night records a free-space alert on the WAL volume at 03:58, closed at 04:14 by removing segment files and their archive_status markers.

Work the evidence before reading on

  1. last_archived_wal is E4 and last_failed_wal is A3. What does it mean that one is far ahead of the other?
  2. Recovery reached a consistent state and then stopped. Which component does that clear, and which does it leave?
  3. Compare the two recovery logs. One line present in the measured capture is absent from the incident. Which, and what does its absence assert?
  4. The archive’s newest file was written at 09:31 and recovery stopped at 02:41. What would have to be true for a wrong target to produce that pair?
  5. Two monitoring checks existed. Name, for each, what it measured and what it would have had to measure instead.

Root cause

The alternative had to be eliminated first

The obvious reading is that the target was wrong: mistyped, in the wrong timezone, or later than anything the archive holds. Three pieces of evidence eliminate it.

Recovery reached consistent recovery state reached and accepted read-only connections, so the base backup is sound.

Recovery stopped at 02:41 while the archive’s newest segment was written at 09:31 and last_archived_wal reads E4. A target beyond the end of the archive drives replay to the end of the archive; this replay stopped twenty-one files short of it.

And the measured capture shows what reaching a target looks like: recovery stopping before commit of transaction 836, time 2026-08-28 13:34:42.096745+00. Replay saw a commit later than the target and declined it. The incident log has no such line; it has redo done immediately after a failed restore, which is what running out of input looks like.

Twenty-one segments were never written and cannot be recreated

Between 02:41 and 04:38 the NFS export behind /srv/rbdr-wal-archive was offline for a storage maintenance the database team had not been told about. The archive command failed on every attempt, which is what failed_count 1914 and last_failed_wal 0000000100000012000000A3 record. The primary carried on serving, because a failure to archive does not stop a cluster — it stops write-ahead log files being recycled, so pg_wal grew instead. At 03:58 that raised a free-space alert, closed at 04:14 by deleting segment files and their archive_status markers. When the export returned at 04:38 archiving resumed at the current segment and never went back, because the markers that would have told it to were gone.

The two checks that existed could not see any of it

The monitoring repository holds two checks: the nightly base backup’s exit status, and free space in the archive filesystem.

A base backup exits zero whether or not the segments that make it useful reach the destination, so that status does not mean the cluster is recoverable to a chosen time. The free-space check watched the wrong volume: the archive filesystem was never short of space, and the one that filled was pg_wal. The single alert this incident produced fired there, and was closed by the action that made the damage permanent. Neither failed_count nor the age of the newest archived segment was collected.

Resolution

The recovering instance holds the only assembled copy of the pre-incident data, so it is neither promoted nor overwritten until the reachable window is known.

RBDR_ARCHIVE=/srv/rbdr-wal-archive
ls -1 "$RBDR_ARCHIVE" | grep -E '^[0-9A-F]{24}$' | sort > /tmp/rbdr-segments.txt
wc -l < /tmp/rbdr-segments.txt

The first discontinuity bounds every recovery starting from a base backup older than it. Here the bound is 0000000100000012000000A3, and the last transaction before it committed at 02:41:07. A base backup taken after 04:38 is anchored beyond the hole; the 2026-08-28 one qualifies but postdates the incident, and there is none between 04:38 and 09:05, so 08:55 is unreachable by physical recovery.

The recoverable position is 2026-08-27 02:41:07, six hours fourteen minutes short of what was asked for. That goes to the business as a number of minutes and a number of orders, alongside the 06:00 logical dump if the application can accept a table-level reconstruction. Nobody promotes anything until someone with the authority to accept that loss has accepted it — then a fresh base backup, immediately, because every base backup older than the hole now serves only targets before 02:41.

Verification

A recovery is verified by why it stopped, not by whether the server came up. One that reached its target logs a recovery stopping before commit line naming a later transaction; one that ends with redo done straight after a failed restore ran out of input.

The archive is verified by contiguity:

set -euo pipefail
RBDR_ARCHIVE=/srv/rbdr-wal-archive
prev=""
holes=0
while read -r seg; do
  cur=$((16#${seg:8:16}))
  if [ -n "$prev" ] && [ "$cur" -ne $((prev + 1)) ]; then
    printf 'GAP: %s segment(s) absent before %s\n' "$((cur - prev - 1))" "$seg" >&2
    holes=$((holes + 1))
  fi
  prev="$cur"
done < <(ls -1 "$RBDR_ARCHIVE" | grep -E '^[0-9A-F]{24}$' | sort)
[ "$holes" -eq 0 ] || exit 1

The archiver is verified by two readings ten minutes apart: failed_count unchanged, and last_archived_wal advanced or the newest archived file younger than archive_timeout plus a margin.

The recovered data is verified against a property recorded before the incident: the row count and the sum of the amount column for orders written before 02:41:07, against the pre-release report. A recovery to the wrong point matches neither figure.

Prevention

Alert on the archiver. The delta in pg_stat_archiver.failed_count over an interval, and the age of the newest file in the archive. Either would have raised a ticket at 02:45.

Audit continuity on a schedule: size and free space say nothing about holes.

Never reclaim space on a WAL volume by removing segments or their archive_status markers. Fix the destination, extend the volume, or accept the cluster stopping — all three are reversible; that one is not.

Make the archive command fail loudly, and take a base backup after every archiving interruption, because a hole retires every earlier base backup for every target after it.