Re: Restore postgres to specific time

On Tue, Nov 27, 2012 at 8:27 AM, Jeff Janes <jeff(dot)janes(at)gmail(dot)com> wrote:

> On Mon, Nov 26, 2012 at 12:23 PM, Kevin Grittner <kgrittn(at)mail(dot)com> wrote:
> > Jeff Janes wrote:
> >
> >> FATAL: requested recovery stop point is before consistent recovery point
> >>
> >> I don't understand why are you not getting this message.
> >
> > Is it before the point where pg_stop_backup() was run?
>
> It turns out that the I had requested a time before even
> pg_start_backup was run.
>
> If I pick a time between start and stop, then I see the original
> poster's symptoms. The database does not start, but gives no notice
> of the problem.
>
>
I've tried after your mail, full log as below:

Extract PGDATA from a basebakup, and write a recovery.conf:
recovery_target_time='2012-11-27 03:20:09+8'
recovery_target_inclusive=false
restore_command='cp /export/t/xlog/%f %p'

The basebackup info:
START WAL LOCATION: 30/94000020 (file 000000010000003000000094)
STOP WAL LOCATION: 30/9A014DB0 (file 00000001000000300000009A)
CHECKPOINT LOCATION: 30/94000058
BACKUP METHOD: pg_start_backup
START TIME: 2012-11-27 03:00:05 CST
LABEL: omnipitr_slave_backup_with_master_callback
STOP TIME: 2012-11-27 03:34:45 CST

You can see, the time is between backup start and stop.

Now start postgres.

[ 2012-11-27 11:15:20.071 CST 8166 50b43048.1fe6 1 0]LOG: database
system was interrupted while in recovery at log time 2012-11-27 03:00:02 CST
[ 2012-11-27 11:15:20.071 CST 8166 50b43048.1fe6 2 0]HINT: If this has
occurred more than once some data might be corrupted and you might need to
choose an earlier recovery target.
[ 2012-11-27 11:15:20.072 CST 8166 50b43048.1fe6 3 0]LOG: starting
point-in-time recovery to 2012-11-27 03:20:09+08
[ 2012-11-27 11:15:20.109 CST 8166 50b43048.1fe6 4 0]LOG: restored log
file "000000010000003000000094" from archive
[ 2012-11-27 11:15:20.120 CST 8166 50b43048.1fe6 5 0]LOG: redo starts
at 30/94000020
[ 2012-11-27 11:15:20.178 CST 8166 50b43048.1fe6 6 0]LOG: restored log
file "000000010000003000000095" from archive
[ 2012-11-27 11:15:20.226 CST 8166 50b43048.1fe6 7 0]LOG: restored log
file "000000010000003000000096" from archive
[ 2012-11-27 11:15:20.271 CST 8166 50b43048.1fe6 8 0]LOG: restored log
file "000000010000003000000097" from archive
[ 2012-11-27 11:15:20.319 CST 8166 50b43048.1fe6 9 0]LOG: restored log
file "000000010000003000000098" from archive
[ 2012-11-27 11:15:20.320 CST 8166 50b43048.1fe6 10 0]LOG: recovery
stopping before commit of transaction 1799510, time 2012-11-27
03:20:51.98131+08
[ 2012-11-27 11:15:20.320 CST 8166 50b43048.1fe6 11 0]LOG: recovery has
paused
[ 2012-11-27 11:15:20.320 CST 8166 50b43048.1fe6 12 0]HINT: Execute
pg_xlog_replay_resume() to continue.

Restore will stop here, I've tried to connect, but failed.

[[unknown] [unknown] [unknown] 2012-11-27 11:15:31.519 CST 8174
50b43053.1fee 1 0]LOG: connection received: host=[local]
[postgres qads_product [unknown] [local] 2012-11-27 11:15:31.519 CST 8174
50b43053.1fee 2 0]FATAL: the database system is starting up

Then restart the Postgres, and wish it will stop recovery and let me login.

[ 2012-11-27 11:15:38.554 CST 8144 50b43047.1fd0 2 0]LOG: received
smart shutdown request
[ 2012-11-27 11:15:38.555 CST 8168 50b43048.1fe8 1 0]LOG: shutting down
[ 2012-11-27 11:15:38.579 CST 8168 50b43048.1fe8 2 0]LOG: database
system is shut down
[ 2012-11-27 11:15:41.423 CST 8189 50b4305d.1ffd 1 0]LOG: database
system was shut down in recovery at 2012-11-27 11:15:38 CST
[ 2012-11-27 11:15:41.423 CST 8189 50b4305d.1ffd 2 0]LOG: starting
point-in-time recovery to 2012-11-27 03:20:09+08
[ 2012-11-27 11:15:41.466 CST 8189 50b4305d.1ffd 3 0]LOG: restored log
file "000000010000003000000098" from archive
[ 2012-11-27 11:15:41.510 CST 8189 50b4305d.1ffd 4 0]LOG: restored log
file "000000010000003000000097" from archive
[ 2012-11-27 11:15:41.510 CST 8189 50b4305d.1ffd 5 0]LOG: redo starts
at 30/9701A2A8
[ 2012-11-27 11:15:41.552 CST 8189 50b4305d.1ffd 6 0]LOG: restored log
file "000000010000003000000098" from archive
[ 2012-11-27 11:15:41.554 CST 8189 50b4305d.1ffd 7 0]LOG: recovery
stopping before commit of transaction 1799510, time 2012-11-27
03:20:51.98131+08
[ 2012-11-27 11:15:41.554 CST 8189 50b4305d.1ffd 8 0]LOG: recovery has
paused
[ 2012-11-27 11:15:41.554 CST 8189 50b4305d.1ffd 9 0]HINT: Execute
pg_xlog_replay_resume() to continue.

The recovery.done is not there, change the settings in recovery.conf:
recovery_target_time='2012-11-27 03:40:09+8'

The time is after the base backup stop. Start postgres:

[ 2012-11-27 11:15:47.851 CST 8181 50b4305d.1ff5 2 0]LOG: received
smart shutdown request
[ 2012-11-27 11:15:47.852 CST 8191 50b4305d.1fff 1 0]LOG: shutting down
[ 2012-11-27 11:15:47.861 CST 8191 50b4305d.1fff 2 0]LOG: database
system is shut down
[ 2012-11-27 11:16:12.802 CST 8429 50b4307c.20ed 1 0]LOG: database
system was shut down in recovery at 2012-11-27 11:15:47 CST
[ 2012-11-27 11:16:12.803 CST 8429 50b4307c.20ed 2 0]LOG: starting
point-in-time recovery to 2012-11-27 03:40:09+08
[ 2012-11-27 11:16:12.845 CST 8429 50b4307c.20ed 3 0]LOG: restored log
file "000000010000003000000098" from archive
[ 2012-11-27 11:16:12.893 CST 8429 50b4307c.20ed 4 0]LOG: restored log
file "000000010000003000000097" from archive
[ 2012-11-27 11:16:12.893 CST 8429 50b4307c.20ed 5 0]LOG: redo starts
at 30/9701A2A8
[ 2012-11-27 11:16:12.935 CST 8429 50b4307c.20ed 6 0]LOG: restored log
file "000000010000003000000098" from archive
[ 2012-11-27 11:16:12.983 CST 8429 50b4307c.20ed 7 0]LOG: restored log
file "000000010000003000000099" from archive
[ 2012-11-27 11:16:13.030 CST 8429 50b4307c.20ed 8 0]LOG: restored log
file "00000001000000300000009A" from archive
[ 2012-11-27 11:16:13.032 CST 8429 50b4307c.20ed 9 0]LOG: consistent
recovery state reached at 30/9B000000
[ 2012-11-27 11:16:13.032 CST 8421 50b4307c.20e5 2 0]LOG: database
system is ready to accept read only connections
[ 2012-11-27 11:16:13.076 CST 8429 50b4307c.20ed 10 0]LOG: restored log
file "00000001000000300000009B" from archive
[ 2012-11-27 11:16:13.161 CST 8429 50b4307c.20ed 11 0]LOG: restored log
file "00000001000000300000009C" from archive
[ 2012-11-27 11:16:13.170 CST 8429 50b4307c.20ed 12 0]LOG: recovery
stopping before commit of transaction 1799547, time 2012-11-27
03:40:20.90089+08
[ 2012-11-27 11:16:13.170 CST 8429 50b4307c.20ed 13 0]LOG: recovery has
paused
[ 2012-11-27 11:16:13.170 CST 8429 50b4307c.20ed 14 0]HINT: Execute
pg_xlog_replay_resume() to continue.

Recovery stop again, and I can login, but I forgot the pass, so change the
pg_hba.conf, and restart again.

[[unknown] [unknown] [unknown] 2012-11-27 11:16:23.677 CST 8448
50b43087.2100 1 0]LOG: connection received: host=[local]
[[unknown] [unknown] [unknown] 2012-11-27 11:16:27.387 CST 8467
50b4308b.2113 1 0]LOG: connection received: host=[local]
[[unknown] [unknown] [unknown] 2012-11-27 11:16:56.638 CST 8523
50b430a8.214b 1 0]LOG: connection received: host=[local]
[[unknown] [unknown] [unknown] 2012-11-27 11:16:57.884 CST 8525
50b430a9.214d 1 0]LOG: connection received: host=[local]
[ 2012-11-27 11:17:24.844 CST 8421 50b4307c.20e5 3 0]LOG: received
smart shutdown request
[ 2012-11-27 11:17:24.845 CST 8431 50b4307c.20ef 1 0]LOG: shutting down
[ 2012-11-27 11:17:24.868 CST 8431 50b4307c.20ef 2 0]LOG: database
system is shut down
[ 2012-11-27 11:17:36.937 CST 8570 50b430d0.217a 1 0]LOG: database
system was shut down in recovery at 2012-11-27 11:17:24 CST
[ 2012-11-27 11:17:36.938 CST 8570 50b430d0.217a 2 0]LOG: starting
point-in-time recovery to 2012-11-27 03:40:09+08
[ 2012-11-27 11:17:36.979 CST 8570 50b430d0.217a 3 0]LOG: restored log
file "00000001000000300000009C" from archive
[ 2012-11-27 11:17:36.982 CST 8570 50b430d0.217a 4 0]LOG: redo starts
at 30/9C000650
[ 2012-11-27 11:17:36.982 CST 8570 50b430d0.217a 5 0]LOG: consistent
recovery state reached at 30/9C000CE0
[ 2012-11-27 11:17:36.983 CST 8570 50b430d0.217a 6 0]LOG: recovery
stopping before commit of transaction 1799547, time 2012-11-27
03:40:20.90089+08
[ 2012-11-27 11:17:36.983 CST 8570 50b430d0.217a 7 0]LOG: recovery has
paused
[ 2012-11-27 11:17:36.983 CST 8570 50b430d0.217a 8 0]HINT: Execute
pg_xlog_replay_resume() to continue.
[ 2012-11-27 11:17:36.983 CST 8561 50b430d0.2171 2 0]LOG: database
system is ready to accept read only connections

Connect again, Try to rename recovery.conf to recovery.done, but not work.
Postgres can't start.

[[unknown] [unknown] [unknown] 2012-11-27 11:18:24.206 CST 8696
50b43100.21f8 1 0]LOG: connection received: host=[local]
[postgres qads_product [unknown] [local] 2012-11-27 11:18:24.208 CST 8696
50b43100.21f8 2 0]LOG: connection authorized: user=postgres
database=qads_product
[postgres qads_product psql [local] 2012-11-27 11:18:27.691 CST 8696
50b43100.21f8 3 0]LOG: disconnection: session time: 0:00:03.485
user=postgres database=qads_product host=[local]
[ 2012-11-27 11:18:37.134 CST 8561 50b430d0.2171 3 0]LOG: received
smart shutdown request
[ 2012-11-27 11:18:37.135 CST 8572 50b430d0.217c 1 0]LOG: shutting down
[ 2012-11-27 11:18:37.143 CST 8572 50b430d0.217c 2 0]LOG: database
system is shut down
[ 2012-11-27 11:19:11.842 CST 8899 50b4312f.22c3 1 0]LOG: database
system was shut down in recovery at 2012-11-27 11:18:37 CST
[ 2012-11-27 11:19:11.843 CST 8899 50b4312f.22c3 2 0]LOG: could not
open file "pg_xlog/00000001000000300000009C" (log file 48, segment 156): No
such file or directory
[ 2012-11-27 11:19:11.843 CST 8899 50b4312f.22c3 3 0]LOG: invalid
primary checkpoint record
[ 2012-11-27 11:19:11.843 CST 8899 50b4312f.22c3 4 0]LOG: could not
open file "pg_xlog/00000001000000300000009C" (log file 48, segment 156): No
such file or directory
[ 2012-11-27 11:19:11.843 CST 8899 50b4312f.22c3 5 0]LOG: invalid
secondary checkpoint record
[ 2012-11-27 11:19:11.843 CST 8899 50b4312f.22c3 6 0]PANIC: could not
locate a valid checkpoint record
[ 2012-11-27 11:19:11.843 CST 8891 50b4312f.22bb 2 0]LOG: startup
process (PID 8899) was terminated by signal 6: Aborted
[ 2012-11-27 11:19:11.843 CST 8891 50b4312f.22bb 3 0]LOG: aborting
startup due to startup process failure

Reanme back the recovery.conf, and start it agagin.

[ 2012-11-27 11:19:35.110 CST 8939 50b43147.22eb 1 0]LOG: database
system was shut down in recovery at 2012-11-27 11:18:37 CST
[ 2012-11-27 11:19:35.111 CST 8939 50b43147.22eb 2 0]LOG: starting
point-in-time recovery to 2012-11-27 03:40:09+08
[ 2012-11-27 11:19:35.153 CST 8939 50b43147.22eb 3 0]LOG: restored log
file "00000001000000300000009C" from archive
[ 2012-11-27 11:19:35.156 CST 8939 50b43147.22eb 4 0]LOG: redo starts
at 30/9C000650
[ 2012-11-27 11:19:35.157 CST 8939 50b43147.22eb 5 0]LOG: consistent
recovery state reached at 30/9C000CE0
[ 2012-11-27 11:19:35.157 CST 8939 50b43147.22eb 6 0]LOG: recovery
stopping before commit of transaction 1799547, time 2012-11-27
03:40:20.90089+08
[ 2012-11-27 11:19:35.157 CST 8939 50b43147.22eb 7 0]LOG: recovery has
paused
[ 2012-11-27 11:19:35.157 CST 8939 50b43147.22eb 8 0]HINT: Execute
pg_xlog_replay_resume() to continue.
[ 2012-11-27 11:19:35.157 CST 8931 50b43146.22e3 2 0]LOG: database
system is ready to accept read only connections

Connect and execute 'select pg_xlog_replay_resume()'

[[unknown] [unknown] [unknown] 2012-11-27 11:19:56.946 CST 8964
50b4315c.2304 1 0]LOG: connection received: host=[local]
[postgres qads_product [unknown] [local] 2012-11-27 11:19:56.947 CST 8964
50b4315c.2304 2 0]LOG: connection authorized: user=postgres
database=qads_product
[postgres qads_product psql [local] 2012-11-27 11:20:05.567 CST 8964
50b4315c.2304 3 0]LOG: statement: select pg_xlog_replay_resume();
[ 2012-11-27 11:20:06.361 CST 8939 50b43147.22eb 9 0]LOG: redo done at
30/9C000CE0
cp: cannot stat `/export/t/xlog/00000002.history': No such file or directory
[ 2012-11-27 11:20:06.366 CST 8939 50b43147.22eb 10 0]LOG: selected new
timeline ID: 2
cp: cannot stat `/export/t/xlog/00000001.history': No such file or directory
[ 2012-11-27 11:20:06.372 CST 8939 50b43147.22eb 11 0]LOG: archive
recovery complete
[ 2012-11-27 11:20:06.479 CST 8931 50b43146.22e3 3 0]LOG: database
system is ready to accept connections
[ 2012-11-27 11:20:06.479 CST 8998 50b43166.2326 1 0]LOG: autovacuum
launcher started
[postgres qads_product psql [local] 2012-11-27 11:20:12.382 CST 8964
50b4315c.2304 4 0]LOG: disconnection: session time: 0:00:15.436
user=postgres database=qads_product host=[local]

The recovery is done.

Thanks for every helped me. :)

>
> Cheers,
>
> Jeff
>