Skip to main content
RunBook Academy

← All break/fix scenarios in Backup & DR

advancedbdr-db-consistency~55 min

The nightly file copy of the live database has worked for four years

Reported symptoms

  • ●Nothing has failed. A pre-audit review of rbdr-wh-01, the order warehouse, asks what protects it, and the answer is a cron entry that has run cp -a over the live PostgreSQL data directory at 02:00 every night for four years
  • ●The cluster is never stopped, never quiesced, and never told a copy is happening; the copy runs against a database taking writes for its whole duration
  • ●Six restores have come out of that copy over four years - three developer refreshes, two storage migrations and one real incident - and all six started and served queries
  • ●The monthly restore validation starts the previous night copy on a scratch host, runs SELECT count(*) against the orders table, compares the number against a count taken from production, and records PASS; it has recorded PASS forty-seven times
  • ●The orders table carries an amount column that finance reconciles every month, and no restore has ever been compared against that reconciliation
  • ●pg_wal currently sits inside the data directory on the same volume, and a storage refresh scheduled for next quarter moves WAL to a dedicated volume where the new platform will snapshot the data volume only
  • ●The teams position is that four years and six restores are the evidence, and that changing the method would be change for its own sake

Evidence

  • · A live PGDATA copied with cp -a mid-workload, with no database involvement at all, then started: pg_ctl reported server started at exit code 0 and the copy returned all 45000 rows, the same count as the live database
  • · The start log records how it got there: database system was not properly shut down; automatic recovery in progress, then redo starts at 0/17615F8, then invalid record length at 0/256A8D8: expected at least 24, got 0, then redo done at 0/256A8B0
  • · The copy therefore did not open as a clean image of anything; it went through crash recovery exactly as it would after a power cut, and redo stopped at the point where the WAL inside the copy ran out
  • · The same data directory with pg_wal emptied - the separate-volume arrangement scheduled for next quarter - did not start at all: invalid checkpoint record, then PANIC: could not locate a valid checkpoint record at 0/2F20158, startup terminated by signal 6, exit code 1
  • · The capture states plainly what the successful start rested on: it happened to have every WAL record it needed inside the copy, and nothing there established that the copy is a transaction-consistent image of any instant
  • · A base backup taken instead with pg_basebackup -D /work/base -X stream -c fast exited 0 and contained 45000 rows, and its recovery log opens differently: starting backup recovery with redo LSN 0/3000028, then consistent recovery state reached at 0/3000120
  • · After an unqualified DELETE emptied the table, recovery of that base backup against archived WAL to a chosen time returned rows recovered : 50000 (expected 50000) and sum(amount) : 825025000 (expected 825025000)
  • · pg_stat_archiver on the source reported archived=6 failed=0 last=000000010000000000000005, with five WAL segments and one .backup file present in the archive
Diagnosis and resolutionclick to reveal

Root cause

Two defects. Neither has produced an incident yet, which is why both are still here. The immediate cause is that the copy is captured over an interval rather than at an instant. `cp -a` walks the data directory for as long as the tree takes to read, while the cluster writes pages underneath it, and the database is never asked to participate. The result is not crash-consistent: there is no single moment in the source history that the collected files jointly represent, because early files were read before later writes and late files after them. It is not application-consistent either, because nothing bracketed the copy with `pg_backup_start` and `pg_backup_stop` and nothing guaranteed that the WAL generated during the walk travelled with it. PostgreSQL documents that a plain file-system copy of a running cluster is not a valid backup unless it carries both. The control that should have caught this is the monthly validation, and it compares a row count. A row count is a single scalar that a torn image reproduces without effort: in the capture the naive copy returned 45000 rows and the live database returned 45000 rows, and that agreement established nothing about whether the copy corresponded to any instant. The validation also reads its number back out of the artefact it is validating, so it can report only that the cluster started and answered a query. It has no independently recorded property of the business data to disagree with, and a check that cannot fail in the way that matters is not a check. The plausible alternative - that the practice is safe because it works - is eliminated by naming what the successful start depended on. It depended on `pg_wal` sitting inside the copied tree, and on that WAL happening to contain a valid checkpoint record and every record redo needed. Remove `pg_wal` and the same directory does not start at all: the server PANICs with `could not locate a valid checkpoint record`. It also depended on crash recovery, which the copy announced when it logged `database system was not properly shut down`. None of those is a property of `cp`; they are properties of one volume layout and one traversal order, and the layout is scheduled to change next quarter.

Remediation

Do not remove the file copy first. It is the only protection the warehouse has, and it has served six restores; retire it after the replacement has been proven, not before. Add continuous WAL archiving on `rbdr-wh-01` and confirm the archiver is actually shipping segments before relying on it. `pg_stat_archiver` is the readback: the capture shows `archived=6 failed=0` alongside the segments present in the archive directory, and those two facts are checked together because a rising archived count with an unreadable archive is not a recovery source. Take the base backup with a tool the database participates in, writing into a dated directory under `/srv/rbdr-basebackup`. `pg_basebackup -D ... -X stream -c fast` exited 0 in the capture and produced a directory containing all 45000 rows, with `-X stream` carrying the WAL generated during the backup so the image does not depend on the archive being complete at that moment. Recover into an isolated instance on a spare port, never over the running warehouse. A recovery driven this way opens with `starting backup recovery with redo LSN`, restores the archived segments it needs, and reports `consistent recovery state reached` - a different and stronger opening sequence than the crash recovery the file copy performed. Record the business invariant from the source on a schedule, note the instant it was taken at, and store both outside the backup. In the capture the invariant was taken after the base backup and before the incident - 50000 rows and sum(amount)=825025000 at 2026-08-28 13:34:40.077562+00 - and the recovery target was set to that same instant. The comparison that follows is what turns a server that started into a restore that was demonstrated.

Verification

The recovery log of the restored instance contains `starting backup recovery with redo LSN` and `consistent recovery state reached`. It must not contain `database system was not properly shut down; automatic recovery in progress`, which is the signature of an image that had to be crash-recovered rather than opened at a known point. The restored cluster is compared against an invariant recorded independently from the source at a known instant, with the recovery target set to that instant - not against a number read out of the restore. In the capture that comparison reads `rows recovered : 50000 (expected 50000)` and `sum(amount) : 825025000 (expected 825025000)`, and both halves are read; the row count alone was the number that matched for the naive copy too. A recovery to a chosen point in time is exercised, not only a recovery to the end of the archive, because recovering past a destructive statement restores the damage. The capture stops with `recovery stopping before commit of transaction 836`, which is the evidence that the target was honoured. `pg_stat_archiver` reports `failed=0` and a `last` segment name that advances between checks, and the archive directory is listed so the segments are seen rather than assumed. The old file copy is restored once more alongside the new one and put through the same invariant comparison, so the retirement decision rests on measurement rather than on the new method being newer.

Prevention

**Back up a database with something the database knows about.** The distinction is not tooling preference. A file copy of a running cluster collects an interval; a base backup bracketed by the server collects a defined starting point plus the WAL that carries it forward to a consistent state. **Validate against a business invariant, not a row count.** The invariant is recorded from the source at a known instant, stored outside the backup, and the recovery target is chosen to match it. A restore that returns the expected total is a restore; a restore that returns the expected number of rows is a cluster that started. **Alert on the age of the last successful invariant comparison,** not on the exit code of the last copy. Forty-seven PASS results measured whether a server would start, and a server starting was never in doubt. **Write down what each success depended on.** Six successful restores over four years depended on `pg_wal` living inside the copied tree. That dependency was never recorded, so nobody connected the storage refresh to the backup at all. **Treat a WAL directory on separate storage as a change to the backup,** not only to the storage layout. A snapshot of the data volume without its WAL is the arrangement that produced the PANIC in the capture, and it is a common real arrangement. **Rehearse a recovery to a point in the past, on a schedule.** Restoring to the end of the archive answers a hardware question. Restoring to a chosen moment answers the question an unqualified `DELETE` actually asks.

Reported symptoms

Nothing is broken. That is the whole difficulty of this scenario.

A pre-audit review of rbdr-wh-01, the order warehouse, asks what protects it. The answer is a cron entry that has run at 02:00 every night for four years: cp -a over the live PostgreSQL data directory, then a tar of that folder offsite. The cluster is never stopped, never quiesced, and never told a copy is happening. Six restores have come out of it — three developer refreshes, two storage migrations, one real incident — and all six started and served queries. The monthly validation has recorded PASS forty-seven times.

Two facts are worth holding onto. The orders table carries an amount column that finance reconciles every month, and no restore has ever been compared against that reconciliation. And pg_wal sits inside the data directory on the same volume — a storage refresh next quarter moves WAL to a dedicated volume, where the new platform snapshots the data volume only.

Evidence provided

The course capture reproduces this practice exactly: a live data directory, copied with cp -a mid-workload, with no database involvement at all, then started.

Data-loss riskthe copy starts, completes crash recovery, and returns every row
$ pg_ctl -D /work/naive-copy start
  waiting for server to start.... done
server started
>>> exit code: 0

2026-08-28 13:34:37.611 UTC [94] LOG:  database system was interrupted; last known up at 2026-08-28 13:34:36 UTC
2026-08-28 13:34:37.613 UTC [94] LOG:  database system was not properly shut down; automatic recovery in progress
2026-08-28 13:34:37.613 UTC [94] LOG:  redo starts at 0/17615F8
2026-08-28 13:34:37.634 UTC [94] LOG:  invalid record length at 0/256A8D8: expected at least 24, got 0
2026-08-28 13:34:37.634 UTC [94] LOG:  redo done at 0/256A8B0 system usage: CPU: user: 0.01 s, system: 0.00 s, elapsed: 0.02 s
2026-08-28 13:34:37.639 UTC [88] LOG:  database system is ready to accept connections

rows readable from the naive copy : 45000
rows in the live database         : 45000

Then the same data directory with pg_wal emptied — data on one volume, WAL on another, and only the data volume captured. This is the arrangement rbdr-wh-01 moves to next quarter.

Data-loss riskthe same directory, without pg_wal, refuses to start at all
$ pg_ctl -D /work/nowal start
  waiting for server to start.... stopped waiting
pg_ctl: could not start server
Examine the log output.
>>> exit code: 1

2026-08-28 13:34:37.879 UTC [132] LOG:  creating missing WAL directory "pg_wal/archive_status"
2026-08-28 13:34:37.879 UTC [132] LOG:  creating missing WAL directory "pg_wal/summaries"
2026-08-28 13:34:37.879 UTC [132] LOG:  invalid checkpoint record
2026-08-28 13:34:37.879 UTC [132] PANIC:  could not locate a valid checkpoint record at 0/2F20158
2026-08-28 13:34:37.941 UTC [126] LOG:  startup process (PID 132) was terminated by signal 6: Aborted
2026-08-28 13:34:37.941 UTC [126] LOG:  terminating any other active server processes
2026-08-28 13:34:37.942 UTC [126] LOG:  shutting down due to startup process failure
2026-08-28 13:34:37.943 UTC [126] LOG:  database system is shut down

The monthly validation is a shell script that starts the copy, runs one count, and compares it. It has never compared anything against the finance reconciliation.

Work the evidence before reading on

  1. The copy started and returned all 45000 rows. Name three things that success depended on, none of which cp controls.
  2. Line two of the start log says the system was not properly shut down. The cluster it was copied from was running normally. What does that line describe, then?
  3. redo done at 0/256A8B0, one record short of the invalid record length at 0/256A8D8. What ended redo — the end of the source’s history, or the end of what was inside the copy?
  4. Forty-seven PASS results. Write down the one outcome that validation was capable of reporting as a failure.
  5. The row count from the copy and the row count from the live database are both 45000. What does that agreement establish?

Root cause

The copy was captured over an interval, not at an instant

cp -a walks the data directory for as long as the tree takes to read while the cluster writes pages underneath it: early files are read before later writes, late files after them, and the database is never asked to participate. No single moment in the source’s history is what the collected files jointly represent, so the image is not crash-consistent. Nor is it application-consistent — nothing bracketed the walk with pg_backup_start and pg_backup_stop, and nothing carried the WAL generated during it. PostgreSQL documents that a plain file-system copy of a running cluster is not a valid backup unless it has both.

The start log shows a cluster reconstructing itself. database system was not properly shut down; automatic recovery in progress is crash recovery, the path taken after a power cut. Redo ran from 0/17615F8 and stopped at 0/256A8B0, one record short of an invalid record length: redo running out of WAL inside the copy, not reaching the end of the source’s history.

The control compared a row count, not a business invariant

A row count is a single scalar, and a torn image reproduces it without effort — 45000 from the copy, 45000 from the live database. The numbers agreed and established nothing about whether the copy corresponded to any instant.

The validation also reads its number back out of the artefact it is validating, so it can report one thing only: that a cluster started and answered a query. It holds no independently recorded property of the business data to disagree with. Forty-seven PASS results measured whether a server would start, and a server starting was never in doubt.

Resolution

Do not remove the file copy first. It is the only protection the warehouse has. Retire it once the replacement is proven.

Enable continuous archiving as the documentation describes — wal_level, archive_mode, archive_command — then read back that the archiver is shipping. Read the counter and the directory together: a rising archived_count beside an empty archive is not a recovery source.

RBDR_ARCHIVE=/srv/rbdr-wal-archive
RBDR_BASE="/srv/rbdr-basebackup/$(date -u +%Y%m%dT%H%M%SZ)"
mkdir -p "$RBDR_ARCHIVE" "$RBDR_BASE"
psql -Atc 'SELECT archived_count, failed_count, last_archived_wal FROM pg_stat_archiver'
find "$RBDR_ARCHIVE" -maxdepth 1 -type f -printf '%f\n' | sort
pg_basebackup -D "$RBDR_BASE" -X stream -c fast

In the capture that readback was archived=6 failed=0 last=000000010000000000000005, against five WAL segments and one .backup file present in the archive. -X stream carries the WAL generated during the backup, so the image does not depend on the archive being complete at that moment. Recover into an isolated instance on a spare port — never over the running warehouse.

Service impact possiblewhat a database-aware recovery opens with
$ read the recovery log of the restored instance
  2026-08-28 13:35:12.701 UTC [631] LOG:  starting backup recovery with redo LSN 0/3000028, checkpoint LSN 0/3000080, on timeline ID 1
2026-08-28 13:35:12.707 UTC [631] LOG:  restored log file "000000010000000000000003" from archive
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:  completed backup recovery with redo LSN 0/3000028 and end LSN 0/3000120
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

Compare that opening to the file copy’s. One announces a defined starting point and reaches a consistent state; the other announces that it was not properly shut down.

Verification

Record the invariant from the source on a schedule, keep the instant it was taken at beside it, store both outside the backup, and set the recovery target to that instant. The capture did exactly this: it recorded 50000 rows and sum(amount)=825025000 after the base backup and before the unqualified DELETE, and recovered to 2026-08-28 13:34:40.077562+00.

RBDR_INV=/srv/rbdr-invariant
mkdir -p "$RBDR_INV"
psql -Atc 'SELECT now()' > "$RBDR_INV/current.at"
psql -Atc 'SELECT count(*), sum(amount) FROM orders' > "$RBDR_INV/current.txt"
# the isolated instance takes its recovery_target_time from current.at
psql -p 5434 -Atc 'SELECT count(*), sum(amount) FROM orders' > "$RBDR_INV/restored.txt"
diff "$RBDR_INV/current.txt" "$RBDR_INV/restored.txt"; echo "diff exit: $?"

diff must print nothing and report diff exit: 0. Any output at all is the restore disagreeing with the business data, and that disagreement is the whole point of the check.

Read-only / Safea restore compared against a property recorded before the incident
$ count rows and sum amounts on the recovered cluster, and compare with the invariant recorded beforehand
  rows recovered  : 50000   (expected 50000)
sum(amount)     : 825025000   (expected 825025000)
RECOVERED - row count and business checksum both match the pre-DELETE state

Read both halves. The row count alone is the number that matched for the naive copy too. Confirm the recovery log carries consistent recovery state reached and does not carry database system was not properly shut down. Confirm the target was honoured rather than overrun: the capture’s proof is recovery stopping before commit of transaction 836. Exercise a recovery to a chosen point, not only to the end of the archive — recovering past a destructive statement restores the damage. Finally, put the old file copy through the same invariant comparison, so the retirement decision rests on measurement.

Prevention

Back up a database with something the database knows about. A file copy of a running cluster collects an interval; a base backup collects a defined starting point plus the WAL that carries it to a consistent state.

Validate against a business invariant, not a row count, and alert on the age of the last successful comparison rather than on the exit code of the last copy.

Write down what each success depended on. Six restores depended on pg_wal living inside the copied tree. Nobody had recorded that, so nobody connected the storage refresh to the backup at all — which is why a WAL directory moving to separate storage has to be treated as a change to the backup. Capturing the data volume without its WAL is what produced the PANIC.

Rehearse a recovery to a point in the past, on a schedule. Recovering to the end of the archive answers a hardware question. Recovering to a chosen moment answers the question an unqualified DELETE actually asks.