How to verify that a PostgreSQL base + WAL backup has been restored correctly

Question

Coworkers were trying to extract a PostgreSQL database copy from a backup made at a hot standby in version 9.1, but it wasn't reliable - we would run it daily, but usually it would end up with various errors while running queries against the copy.

Sadly I hadn't been able to find a definitive answer as to why on the web, and it took a kind soul in the PostgreSQL IRC channel to set me straight - taking a backup like that from a standby isn't supported out-of-the-box in that version.

So for the benefit of others who may run into the same problem and try to google it, I'm going to write up our notes in an answer below.

Answer 1

The answer will contain two sections - first, what's acceptable to see in the logs after the restore, and second a few examples of what is not. The first section should be fairly deterministic, while the second one is basically a random assortment of whatever happened to us that indicated we had a problem.

Acceptable log output

at the start:

2015-07-23 06:51:24 UTC LOG: database system was interrupted; last known up at 2015-07-23 02:10:42 UTC

It's important to see that the restoring PostgreSQL knows when it was last up. I think that's so because that means it's starting from a checkpoint.

xlog min recovery request ... is past current point

Right at the beginning, a few of these can happen:

2015-07-23 06:51:30 UTC WARNING:  xlog min recovery request 1027/B0A28D98 is past current point 1027/2BE36DA8
2015-07-23 06:51:30 UTC CONTEXT:  writing block 0 of relation base/117264/9551898_vm
       xlog redo insert: rel 1663/117264/8310261; tid 68622/40

But according to http://www.postgresql.org/message-id/CAB7nPqTd43hqpuC+M8fo+xkqHv1WtFe_16NUttu1pHcBtZhZmw@mail.gmail.com that is harmless

FATAL: the database system is starting up

Any number of these can happen:

2015-07-23 06:51:24 UTC FATAL:  the database system is starting up

This should actually be harmless because they were in our case the result of automated SELECT 1 ping-like queries that scripts run to check that PostgreSQL is ready.

unexpected pageaddr ... in log file ..., segment ..., offset ...

At the end, there's this:

2015-07-23 06:52:21 UTC LOG:  restored log file "0000000100001027000000B2" from archive
2015-07-23 06:52:21 UTC LOG:  consistent recovery state reached at 1027/B2F8F2F8
sh: 1: cannot open ../../../wal_backup/0000000100001027000000B3: No such file
2015-07-23 06:52:21 UTC LOG:  unexpected pageaddr 1027/AA000000 in log file 4135, segment 179, offset 0
2015-07-23 06:52:21 UTC LOG:  redo done at 1027/B2F8F2F8
2015-07-23 06:52:21 UTC LOG:  last completed transaction was at log time 2015-07-23 02:17:33.842307+00

But according to http://www.postgresql.org/message-id/CAGrpgQ-BbXUNErrAtToYhRyUef9_GdUQz1T3CXbpTMLTnuKANQ@mail.gmail.com that's also harmless

Note that there may be more of the WAL restorations after that point:

2015-07-23 06:52:21 UTC LOG:  restored log file "0000000100001027000000B2" from archive

That would merely mean that you supplied more WAL files via recovery.conf than strictly necessary.

00000002.history: No such file

At the very end of the WAL unroll process there's this:

sh: 1: cannot open ../../../wal_backup/00000002.history: No such file
2015-07-23 06:52:21 UTC LOG:  selected new timeline ID: 2
sh: 1: cannot open ../../../wal_backup/00000001.history: No such file
2015-07-23 06:52:21 UTC LOG:  archive recovery complete

This is apparently/hopefully irrelevant, because that's where the restored database (clone) starts a new life (timeline).

Unacceptable log output

at the start:

2015-07-20 12:38:31 UTC LOG: database system was interrupted while in recovery at log time 2015-07-20 01:41:22 UTC

This is critical - it means that the backup process did not start at the right time - after a pg_start_backup(...) checkpoint - rather that the database was working normally and was at some random point, which means that this restore is more akin to restoring a crashed database.

missing chunk in pg_toast...

This indicates that the restore wasn't right. As a quick fix, we tried the recipe from http://postgresql.nabble.com/select-table-indicate-missing-chunk-number-0-for-toast-value-96635-in-pg-toast-2619-td5682176.html

mydb=# vacuum analyze mytable; -- trigger the error to see the problem toast
ERROR:  missing chunk number 0 for toast value 13044178 in pg_toast_2619
mydb=# reindex table pg_toast.pg_toast_2619;
REINDEX

This could sometimes get the table back in a working state, but it would also sometimes not have that effect. After that we poked at it some more, and thought we found it's just pg_statistic which is disposable:

mydb=# reindex table pg_statistic;
ERROR:  could not create unique index "pg_statistic_relid_att_inh_index"
DETAIL:  Key (starelid, staattnum, stainherit)=(884792, 34, f) is duplicated.
mydb=# delete from pg_statistic;
DELETE 188540
mydb=# reindex table pg_statistic;
REINDEX
mydb=# vacuum analyze mytable;
VACUUM

right sibling's left-link doesn't match

CREATE TABLE "myschema"."mytable" ( ... )
ERROR: right sibling's left-link doesn't match: block 27 links to 21379 instead of expected 21393 in index "pg_depend_reference_index"

We tried to quickly bypass this by doing:

mydb=# set zero_damaged_pages=on;
SET
mydb=# reindex table pg_depend;
REINDEX
mydb=# set zero_damaged_pages=off;
SET

could not read block in file ...

2015-05-12 13:32:53 UTC ERROR:  could not read block 76408 in file "pg_tblspc/4606764/PG_9.1_201105231/117264/4614269": read only 0 of 8192 bytes

This was obviously a bummer. We couldn't quickly hack our way around this:

mydb=# select cl.relfilenode, nsp.nspname as schema_name, cl.relname, cl.relkind from pg_class cl join pg_namespace nsp on cl.relnamespace = nsp.oid where relfilenode = 4614269;
 relfilenode | schema_name | relname | relkind
-------------+-------------+---------+---------
     4614269 | myschema    | mytable | r
(1 row)

mydb=# select pg_relation_filepath('myschema.mytable');
               pg_relation_filepath
---------------------------------------------------
 pg_tblspc/4606764/PG_9.1_201105231/117264/4614269
(1 row)

% sudo ls -lah /var/lib/postgresql/9.1/main/pg_tblspc/4606764/PG_9.1_201105231/117264/4614269
-rw------- 1 postgres postgres 597M May 11 19:22 /var/lib/postgresql/9.1/main/pg_tblspc/4606764/PG_9.1_201105231/117264/4614269

That was a good indicator that too much data was getting "lost".

duplicate key value violates unique constraint "pg_type_typname_nsp_index"

This was another indicator that the restore was broken:

CREATE TABLE "myschema"."mytable" ( ... )
ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index" DETAIL: Key (typname, typnamespace)=(mytable_mycolumn_seq, 3780903) already exists.

The quick hack for this was to move the sequence position:

SELECT setval('mytable_id_seq', (SELECT MAX(id) FROM mytable));