Re: Postgres WAL Recovery Fails... And Then Works...

>
> Also, which version of postgres are you using?

PostgreSQL 9.2.1 on Ubuntu 12.04

>
> Except in my case no number of restarts helped. You didn't say, were
> you explicitly copying $PGDATA or using some other mechanism to
> migrate the data elsewhere?

So we have a very large database (~5TB), so we use a script to do
parallel rsyncs to copy the data directory
(https://gist.github.com/4477190/#file-pmrcp-rb) The whole copy process
ended up taking ~3.5 hours. So we did a physical copy of $PGDATA (which
is located at /var/lib/postgresql/9.2/main/ on both machines.). We
followed the following process to do this:

1. Master archives WAL files to Backup Host.
2. Execute on Master: psql -c "select pg_start_backup('DATE-slave-restore')"
3. Execute on Master: RCP='rsync -cav --inplace -e rsh'
EXCLUDE='pg_xlog' pmrcp /var/lib/postgresql/9.2/main/
prd-db-01:/var/lib/postgresql/9.2/main/ > /tmp/backup.log
4. Execute on Master: psql -c "select pg_stop_backup()"
5. On Slave, setup recovery.conf to read WAL archive on Backup Host
6. Execute on Slave: pg_ctlcluster 9.2 main start (as described in
initial email)

Best,
Phil

Lonni J Friedman wrote:
>
> Your errors look somewhat similar to a problem I reported last week
> (no replies thus far):
> http://www.postgresql.org/message-id/CAP=oouE5niXgAO_34Q+FGq=tS6EsMHXXRRoByov3zn9pU4249w@mail.gmail.com
>
> Except in my case no number of restarts helped. You didn't say, were
> you explicitly copying $PGDATA or using some other mechanism to
> migrate the data elsewhere?
>
> Also, which version of postgres are you using?
>
> On Fri, Jan 11, 2013 at 6:32 PM, Phil Monroe<phil(at)identified(dot)com> wrote:
>>
>> Hi Everyone,
>>
>> So we had to failover and do a full base backup to get our slave database
>> back online and ran into a interesting scenario. After copying the data
>> directory, setting up the recovery.conf, and starting the slave database,
>> the database crashes while replaying xlogs. However, trying to start the
>> database again, the database is able to replay xlogs farther than it
>> initially got, but ultimately ended up failing out again. After
>> starting the
>> DB a third time, PostgreSQL replays even further and catches up to the
>> master to start streaming replication. Is this common and or acceptable?
>>
>> The error messages that cause PostgreSQL to stop replaying xlogs:
>>
>> ERROR #1:
>> 2013-01-12 00:17:17 UTC::@:[61150]: WARNING: page 2387476480 of relation
>> base/16408/18967399 does not exist
>> 2013-01-12 00:17:17 UTC::@:[61150]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892842; iblk 658355, heap 1663/16408/18967399;
>> 2013-01-12 00:17:17 UTC::@:[61150]: PANIC: WAL contains references to
>> invalid pages
>> 2013-01-12 00:17:17 UTC::@:[61150]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892842; iblk 658355, heap 1663/16408/18967399;
>> 2013-01-12 00:17:18 UTC::@:[61121]: LOG: startup process (PID 61150) was
>> terminated by signal 6: Aborted
>>
>> ERROR #2:
>> 2013-01-12 01:02:17 UTC::@:[36831]: WARNING: page 2387607552 of relation
>> base/16408/18967399 does not exist
>> 2013-01-12 01:02:17 UTC::@:[36831]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892841; iblk 1075350, heap 1663/16408/18967399;
>> 2013-01-12 01:02:17 UTC::@:[36831]: PANIC: WAL contains references to
>> invalid pages
>> 2013-01-12 01:02:17 UTC::@:[36831]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892841; iblk 1075350, heap 1663/16408/18967399;
>> 2013-01-12 01:02:20 UTC::@:[36796]: LOG: startup process (PID 36831) was
>> terminated by signal 6: Aborted
>>
>>
>> Fortunately, these errors only pertain to indexes, which can be rebuilt.
>> But is this a sign that the data directory on the slave is corrupt?
>>
>> Here is a full timeline of the logs highlighting the issues. :
>>
>> 1. Data Directory Copy Finishes.
>> 2. Recovery.conf Setup
>>
>> 3. Start #1:
>>
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: database system was shut down in
>> recovery at 2013-01-12 00:14:06 UTC
>> 2013-01-12 00:14:23 UTC:[local]:[unknown](at)[unknown]:[61151]: LOG:
>> incomplete startup packet
>> 2013-01-12 00:14:23 UTC:[local]:postgres(at)postgres:[61152]: FATAL: the
>> database system is starting up
>> unpigz: /mnt/db/wals/00000009.history does not exist -- skipping
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: entering standby mode
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: restored log file
>> "0000000900008E45000000B8" from archive
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: restored log file
>> "0000000900008E450000008B" from archive
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: could not open directory
>> "pg_snapshots": No such file or directory
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: redo starts at 8E45/8B173180
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: consistent recovery state
>> reached at 8E45/8B174840
>> 2013-01-12 00:14:23 UTC:[local]:postgres(at)postgres:[61175]: FATAL: the
>> database system is starting up
>> 2013-01-12 00:14:23 UTC::@:[61150]: LOG: restored log file
>> "0000000900008E450000008C" from archive
>> 2013-01-12 00:14:24 UTC::@:[61150]: LOG: restored log file
>> "0000000900008E450000008D" from archive
>>
>> *SNIP*
>>
>> 2013-01-12 00:17:17 UTC::@:[61150]: LOG: restored log file
>> "0000000900008E4800000066" from archive
>> 2013-01-12 00:17:17 UTC::@:[61150]: LOG: restored log file
>> "0000000900008E4800000067" from archive
>> 2013-01-12 00:17:17 UTC::@:[61150]: WARNING: page 2387476480 of relation
>> base/16408/18967399 does not exist
>> 2013-01-12 00:17:17 UTC::@:[61150]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892842; iblk 658355, heap 1663/16408/18967399;
>> 2013-01-12 00:17:17 UTC::@:[61150]: PANIC: WAL contains references to
>> invalid pages
>> 2013-01-12 00:17:17 UTC::@:[61150]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892842; iblk 658355, heap 1663/16408/18967399;
>> 2013-01-12 00:17:18 UTC::@:[61121]: LOG: startup process (PID 61150) was
>> terminated by signal 6: Aborted
>> 2013-01-12 00:17:18 UTC::@:[61121]: LOG: terminating any other active
>> server processes
>>
>>
>> 4. PostgreSQL shuts down...
>> 5. Debugging logs enabled in postgresql.conf.
>>
>>
>> 6. Start #2:
>>
>> 2013-01-12 00:51:48 UTC::@:[36831]: LOG: database system was interrupted
>> while in recovery at log time 2013-01-11 18:05:31 UTC
>> 2013-01-12 00:51:48 UTC::@:[36831]: HINT: If this has occurred more than
>> once some data might be corrupted and you might need to choose an earlier
>> recovery target.
>> 2013-01-12 00:51:48 UTC:[local]:[unknown](at)[unknown]:[36832]: LOG:
>> incomplete startup packet
>> 2013-01-12 00:51:48 UTC:[local]:postgres(at)postgres:[36833]: FATAL: the
>> database system is starting up
>> unpigz: /mnt/db/wals/00000009.history does not exist -- skipping
>> 2013-01-12 00:51:48 UTC::@:[36831]: LOG: entering standby mode
>> 2013-01-12 00:51:48 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E45000000B8" from archive
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: checkpoint record is at
>> 8E45/B80AF650
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: redo record is at
>> 8E45/8B173180; shutdown FALSE
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: next transaction ID:
>> 0/552803703; next OID: 24427698
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: next MultiXactId: 109027; next
>> MultiXactOffset: 2442921
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: oldest unfrozen transaction
>> ID: 3104202601, in database 16408
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: transaction ID wrap limit is
>> 956718952, limited by database with OID 16408
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: resetting unlogged relations:
>> cleanup 1 init 0
>> 2013-01-12 00:51:48 UTC::@:[36831]: LOG: could not open directory
>> "pg_snapshots": No such file or directory
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: initializing for hot standby
>> 2013-01-12 00:51:48 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E450000008B" from archive
>> 2013-01-12 00:51:48 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:51:48 UTC::@:[36831]: LOG: redo starts at 8E45/8B173180
>> 2013-01-12 00:51:49 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E450000008C" from archive
>>
>> *SNIP*
>>
>> 2013-01-12 00:54:45 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000062" from archive
>> 2013-01-12 00:54:45 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:45 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000063" from archive
>> 2013-01-12 00:54:45 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:45 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000064" from archive
>> 2013-01-12 00:54:45 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000065" from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000066" from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000067" from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: LOG: consistent recovery state
>> reached at 8E48/67AC4E28
>> 2013-01-12 00:54:46 UTC::@:[36796]: LOG: database system is ready to
>> accept read only connections
>> 2013-01-12 00:54:46 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000068" from archive
>> 2013-01-12 00:54:46 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:47 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4800000069" from archive
>> 2013-01-12 00:54:47 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:47 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E480000006A" from archive
>> 2013-01-12 00:54:47 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:47 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E480000006B" from archive
>> 2013-01-12 00:54:47 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 00:54:47 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E480000006C" from archive
>>
>> *SNIP*
>>
>> 2013-01-12 01:02:16 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4F00000079" from archive
>> 2013-01-12 01:02:16 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:02:17 UTC::@:[36831]: LOG: restored log file
>> "0000000900008E4F0000007A" from archive
>> 2013-01-12 01:02:17 UTC::@:[36831]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:02:17 UTC::@:[36831]: WARNING: page 2387607552 of relation
>> base/16408/18967399 does not exist
>> 2013-01-12 01:02:17 UTC::@:[36831]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892841; iblk 1075350, heap 1663/16408/18967399;
>> 2013-01-12 01:02:17 UTC::@:[36831]: PANIC: WAL contains references to
>> invalid pages
>> 2013-01-12 01:02:17 UTC::@:[36831]: CONTEXT: xlog redo delete: index
>> 1663/16408/22892841; iblk 1075350, heap 1663/16408/18967399;
>> 2013-01-12 01:02:20 UTC::@:[36796]: LOG: startup process (PID 36831) was
>> terminated by signal 6: Aborted
>> 2013-01-12 01:02:20 UTC::@:[36796]: LOG: terminating any other active
>> server processes
>>
>>
>> 7. PostgreSQL shuts down...
>>
>>
>> 8. Start #3:
>>
>> 2013-01-12 01:04:04 UTC::@:[61742]: LOG: database system was interrupted
>> while in recovery at log time 2013-01-11 19:50:31 UTC
>> 2013-01-12 01:04:04 UTC::@:[61742]: HINT: If this has occurred more than
>> once some data might be corrupted and you might need to choose an earlier
>> recovery target.
>> 2013-01-12 01:04:04 UTC:[local]:[unknown](at)[unknown]:[61743]: LOG:
>> incomplete startup packet
>> 2013-01-12 01:04:04 UTC:[local]:postgres(at)postgres:[61744]: FATAL: the
>> database system is starting up
>> unpigz: /mnt/db/wals/00000009.history does not exist -- skipping
>> 2013-01-12 01:04:04 UTC::@:[61742]: LOG: entering standby mode
>> 2013-01-12 01:04:04 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4A00000039" from archive
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: checkpoint record is at
>> 8E4A/39CD4BA0
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: redo record is at
>> 8E4A/19F0D210; shutdown FALSE
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: next transaction ID:
>> 0/552859005; next OID: 24427698
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: next MultiXactId: 109221; next
>> MultiXactOffset: 2443321
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: oldest unfrozen transaction
>> ID: 3104202601, in database 16408
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: transaction ID wrap limit is
>> 956718952, limited by database with OID 16408
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: resetting unlogged relations:
>> cleanup 1 init 0
>> 2013-01-12 01:04:04 UTC::@:[61742]: LOG: could not open directory
>> "pg_snapshots": No such file or directory
>> 2013-01-12 01:04:04 UTC::@:[61742]: DEBUG: initializing for hot standby
>> 2013-01-12 01:04:05 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4A00000019" from archive
>> 2013-01-12 01:04:05 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:04:05 UTC::@:[61742]: LOG: redo starts at 8E4A/19F0D210
>> 2013-01-12 01:04:05 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4A0000001A" from archive
>> 2013-01-12 01:04:05 UTC::@:[61742]: DEBUG: got WAL segment from archive
>>
>> *SNIP*
>>
>> 2013-01-12 01:09:37 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F00000077" from archive
>> 2013-01-12 01:09:37 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:09:37 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F00000078" from archive
>> 2013-01-12 01:09:37 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:09:37 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F00000079" from archive
>> 2013-01-12 01:09:37 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F0000007A" from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: LOG: consistent recovery state
>> reached at 8E4F/7A22BD08
>> 2013-01-12 01:09:38 UTC::@:[61729]: LOG: database system is ready to
>> accept read only connections
>> 2013-01-12 01:09:38 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F0000007B" from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F0000007C" from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F0000007D" from archive
>> 2013-01-12 01:09:38 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:09:39 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E4F0000007E" from archive
>>
>>
>> *SNIP*
>>
>> 2013-01-12 01:14:29 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E53000000D9" from archive
>> 2013-01-12 01:14:29 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:14:29 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E53000000DA" from archive
>> 2013-01-12 01:14:29 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:14:29 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E53000000DB" from archive
>> 2013-01-12 01:14:29 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:14:30 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E53000000DC" from archive
>> 2013-01-12 01:14:30 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> 2013-01-12 01:14:30 UTC::@:[61742]: LOG: restored log file
>> "0000000900008E53000000DD" from archive
>> 2013-01-12 01:14:30 UTC::@:[61742]: DEBUG: got WAL segment from archive
>> unpigz: /mnt/db/wals/0000000900008E53000000DE does not exist -- skipping
>> 2013-01-12 01:14:30 UTC::@:[61742]: LOG: unexpected pageaddr 8E4A/1000000
>> in log file 36435, segment 222, offset 0
>> unpigz: /mnt/db/wals/0000000900008E53000000DE does not exist -- skipping
>> 2013-01-12 01:14:30 UTC::@:[19504]: LOG: streaming replication
>> successfully connected to primary
>> 2013-01-12 01:18:08 UTC::@:[61772]: DEBUG: checkpoint sync: number=1
>> file=base/16408/22873432 time=2.538 msec
>> 2013-01-12 01:18:08 UTC::@:[61772]: DEBUG: checkpoint sync: number=2
>> file=base/16408/18967506 time=12.054 msec
>> 2013-01-12 01:18:08 UTC::@:[61772]: DEBUG: checkpoint sync: number=3
>> file=base/16408/18967506_fsm time=0.095 msec
>> 2013-01-12 01:18:08 UTC::@:[61772]: DEBUG: checkpoint sync: number=4
>> file=base/16408/22873244 time=0.144 msec
>> 2013-01-12 01:18:08 UTC::@:[61772]: DEBUG: checkpoint sync: number=5
>> file=base/16408/22892823 time=0.087 msec
>>
>> 9. Slave DB connected to streaming replication with Master DB and all
>> seems fine.
>>
>>
>> Any help would be appreciated. Thanks!