I am testing out point in time recovery from a hot physical backup in a disaster recovery situation - I turned on archiving of files, created a hot physical backup, then (after letting it run for a few days) issued a "DROP DATABASE". The pg_log file shows the DROP DATABASE command was issued at '2014-11-28 10:20:00.010 PST'. I shut down the server, moved the pgdata directory to pgdata_backup ... restored the files in the hot physical backup I made, copied the wal archive files from pgdata_backup to the (new) pgdata archive, cleared out the new pg_xlog dir and copied the files from the old pg_xlog into the new.. Set up a recovery.conf file as such:
restore_command = 'gunzip -c /home/pg2dev/joshtest/pgdata/archive/%f.gz > %p'
recovery_target_time = '2014-11-28 10:20:00.010 PST'
recovery_target_inclusive = false
then I started the server up. the pg_log shows the following:restore_command = 'gunzip -c /home/pg2dev/joshtest/pgdata/archive/%f.gz > %p'
recovery_target_time = '2014-11-28 10:20:00.010 PST'
recovery_target_inclusive = false
2014-11-28 14:22:55.059 PST LOG: database system was interrupted; last known up at 2014-11-24 11:34:14 PST
2014-11-28 14:22:55.060 PST LOG: starting point-in-time recovery to 2014-11-28 10:20:00.01-08
2014-11-28 14:22:55.239 PST LOG: restored log file "0000000100000000000000A0" from archive
2014-11-28 14:22:55.243 PST LOG: redo starts at 0/A0000080
2014-11-28 14:22:55.244 PST LOG: consistent recovery state reached at 0/A1000000
2014-11-28 14:22:55.412 PST LOG: restored log file "0000000100000000000000A1" from archive
2014-11-28 14:22:55.674 PST LOG: restored log file "0000000100000000000000A2" from archive
2014-11-28 14:22:55.777 PST LOG: recovery stopping before commit of transaction 235078, time 2014-11-28 10:20:00.179303-08
2014-11-28 14:22:55.777 PST LOG: redo done at 0/A2F0F4B0
2014-11-28 14:22:55.777 PST LOG: last completed transaction was at log time 2014-11-28 09:47:07.132608-08
2014-11-28 14:22:55.060 PST LOG: starting point-in-time recovery to 2014-11-28 10:20:00.01-08
2014-11-28 14:22:55.239 PST LOG: restored log file "0000000100000000000000A0" from archive
2014-11-28 14:22:55.243 PST LOG: redo starts at 0/A0000080
2014-11-28 14:22:55.244 PST LOG: consistent recovery state reached at 0/A1000000
2014-11-28 14:22:55.412 PST LOG: restored log file "0000000100000000000000A1" from archive
2014-11-28 14:22:55.674 PST LOG: restored log file "0000000100000000000000A2" from archive
2014-11-28 14:22:55.777 PST LOG: recovery stopping before commit of transaction 235078, time 2014-11-28 10:20:00.179303-08
2014-11-28 14:22:55.777 PST LOG: redo done at 0/A2F0F4B0
2014-11-28 14:22:55.777 PST LOG: last completed transaction was at log time 2014-11-28 09:47:07.132608-08
Which looks fine and dandy. I connect to database with psql and list the databases with \l ... the database that WAS dropped is listed, which looks fine and dandy.
I try to connect to the database and it gives:
psql: FATAL: database "jasperserver_restore" does not exist
DETAIL: The database subdirectory "base/907110" is missing.
psql: FATAL: database "jasperserver_restore" does not exist
DETAIL: The database subdirectory "base/907110" is missing.
And then I look in pgdata/base .. and sure enough, that directory is missing. I examine my hot physical backup file and that directory exists within it.
So .... even though the recovery SAYS "recovery stopping before commit of transaction 235078" ... it doesn't appear that it's 100% accurate. It didn't commit the transaction, clearly, because the database is still listed in the data dictionary ... however, the filesystem files are gone. Please - am I doing something wrong, or would this be considered a bug?
--
Joshua Boyd
