Home > mailing lists

Thread: Restore postgres to specific time

Restore postgres to specific time

From

wd

Date:

22 November 2012, 14:28:58

hi,

I've try to restore Postgres to a specific time but failed.

The recovery.conf as bellow
restore_command='cp /t/xlog/%f %p'
recovery_target_time='2012-11-22 5:01:09 CST'
pause_at_recovery_target=true
recovery_target_inclusive=false

The basebackup was made at 2012-11-22 3:10 CST, I've copy wal log files at 3:00 to 5:10 into /t/xlog, but the recovery will not stop at 2012-11-22 5:01:09。

How to do this?

Re: Restore postgres to specific time

From

"Albe Laurenz"

Date:

22 November 2012, 17:40:27

wd wrote:
> I've try to restore Postgres to a specific time but failed.
> 
> The recovery.conf as bellow
> restore_command='cp /t/xlog/%f %p'
> recovery_target_time='2012-11-22 5:01:09 CST'
> pause_at_recovery_target=true
> recovery_target_inclusive=false
> 
> The basebackup was made at 2012-11-22 3:10 CST, I've copy wal log files at 3:00 to 5:10 into /t/xlog,
> but the recovery will not stop at 2012-11-22 5:01:09。
> 
> How to do this?

Looks ok.
What does the server log say during the restore?

Yours,
Laurenz Albe

Re: Restore postgres to specific time

From

wd

Date:

23 November 2012, 06:29:40

Thanks for your reply, the logs are something like bellow，postgres will restore every wal log I put in the xlog directory，and then continues waiting for next wal log. The postgres version is 9.1.6.

[    2012-11-22 18:49:24.175 CST 25744 50ae0334.6490 1 0]LOG: database system was shut down in recovery at 2012-11-22 18:49:22 CST
[    2012-11-22 18:49:24.176 CST 25744 50ae0334.6490 2 0]LOG: entering standby mode
[    2012-11-22 18:49:24.210 CST 25744 50ae0334.6490 3 0]LOG: restored log file "000000010000002800000023" from archive
[    2012-11-22 18:49:24.213 CST 25744 50ae0334.6490 4 0]LOG: redo starts at 28/23001900
[    2012-11-22 18:49:24.619 CST 25744 50ae0334.6490 5 0]LOG: consistent recovery state reached at 28/23FFFFC8
[    2012-11-22 18:49:24.620 CST 25736 50ae0333.6488 2 0]LOG: database system is ready to accept read only connections
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
[    2012-11-22 18:50:49.828 CST 25744 50ae0334.6490 6 0]LOG: restored log file "000000010000002800000024" from archive
[    2012-11-22 18:50:50.291 CST 25744 50ae0334.6490 7 0]LOG: restored log file "000000010000002800000025" from archive
[    2012-11-22 18:50:50.759 CST 25744 50ae0334.6490 8 0]LOG: restored log file "000000010000002800000026" from archive
[    2012-11-22 18:50:51.220 CST 25744 50ae0334.6490 9 0]LOG: restored log file "000000010000002800000027" from archive
[    2012-11-22 18:50:51.686 CST 25744 50ae0334.6490 10 0]LOG: restored log file "000000010000002800000028" from archive
[    2012-11-22 18:50:52.145 CST 25744 50ae0334.6490 11 0]LOG: restored log file "000000010000002800000029" from archive
[    2012-11-22 18:50:52.613 CST 25744 50ae0334.6490 12 0]LOG: restored log file "00000001000000280000002A" from archive
[    2012-11-22 18:50:53.073 CST 25744 50ae0334.6490 13 0]LOG: restored log file "00000001000000280000002B" from archive
[    2012-11-22 18:50:53.538 CST 25744 50ae0334.6490 14 0]LOG: restored log file "00000001000000280000002C" from archive
[    2012-11-22 18:50:53.999 CST 25744 50ae0334.6490 15 0]LOG: restored log file "00000001000000280000002D" from archive
[    2012-11-22 18:50:54.459 CST 25744 50ae0334.6490 16 0]LOG: restored log file "00000001000000280000002E" from archive
[    2012-11-22 18:50:54.920 CST 25744 50ae0334.6490 17 0]LOG: restored log file "00000001000000280000002F" from archive
cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory

On Thu, Nov 22, 2012 at 10:39 PM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote:

wd wrote:
> I've try to restore Postgres to a specific time but failed.
>
> The recovery.conf as bellow
> restore_command='cp /t/xlog/%f %p'
> recovery_target_time='2012-11-22 5:01:09 CST'
> pause_at_recovery_target=true
> recovery_target_inclusive=false
>
> The basebackup was made at 2012-11-22 3:10 CST, I've copy wal log files at 3:00 to 5:10 into /t/xlog,
> but the recovery will not stop at 2012-11-22 5:01:09。
>
> How to do this?

Looks ok.
What does the server log say during the restore?

Yours,
Laurenz Albe

Re: Restore postgres to specific time

From

raghu ram

Date:

23 November 2012, 12:02:32

On Fri, Nov 23, 2012 at 8:59 AM, wd <wd@wdicc.com> wrote:

Thanks for your reply, the logs are something like bellow，postgres will restore every wal log I put in the xlog directory，and then continues waiting for next wal log. The postgres version is 9.1.6.

[    2012-11-22 18:49:24.175 CST 25744 50ae0334.6490 1 0]LOG: database system was shut down in recovery at 2012-11-22 18:49:22 CST
[    2012-11-22 18:49:24.176 CST 25744 50ae0334.6490 2 0]LOG: entering standby mode
[    2012-11-22 18:49:24.210 CST 25744 50ae0334.6490 3 0]LOG: restored log file "000000010000002800000023" from archive
[    2012-11-22 18:49:24.213 CST 25744 50ae0334.6490 4 0]LOG: redo starts at 28/23001900
[    2012-11-22 18:49:24.619 CST 25744 50ae0334.6490 5 0]LOG: consistent recovery state reached at 28/23FFFFC8
[    2012-11-22 18:49:24.620 CST 25736 50ae0333.6488 2 0]LOG: database system is ready to accept read only connections
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
[    2012-11-22 18:50:49.828 CST 25744 50ae0334.6490 6 0]LOG: restored log file "000000010000002800000024" from archive
[    2012-11-22 18:50:50.291 CST 25744 50ae0334.6490 7 0]LOG: restored log file "000000010000002800000025" from archive
[    2012-11-22 18:50:50.759 CST 25744 50ae0334.6490 8 0]LOG: restored log file "000000010000002800000026" from archive
[    2012-11-22 18:50:51.220 CST 25744 50ae0334.6490 9 0]LOG: restored log file "000000010000002800000027" from archive
[    2012-11-22 18:50:51.686 CST 25744 50ae0334.6490 10 0]LOG: restored log file "000000010000002800000028" from archive
[    2012-11-22 18:50:52.145 CST 25744 50ae0334.6490 11 0]LOG: restored log file "000000010000002800000029" from archive
[    2012-11-22 18:50:52.613 CST 25744 50ae0334.6490 12 0]LOG: restored log file "00000001000000280000002A" from archive
[    2012-11-22 18:50:53.073 CST 25744 50ae0334.6490 13 0]LOG: restored log file "00000001000000280000002B" from archive
[    2012-11-22 18:50:53.538 CST 25744 50ae0334.6490 14 0]LOG: restored log file "00000001000000280000002C" from archive
[    2012-11-22 18:50:53.999 CST 25744 50ae0334.6490 15 0]LOG: restored log file "00000001000000280000002D" from archive
[    2012-11-22 18:50:54.459 CST 25744 50ae0334.6490 16 0]LOG: restored log file "00000001000000280000002E" from archive
[    2012-11-22 18:50:54.920 CST 25744 50ae0334.6490 17 0]LOG: restored log file "00000001000000280000002F" from archive
cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory

As per logs,it is working as a host-standby. For doing the point in time recovery,recovery.conf file requires only two settings:

restore_command='cp /t/xlog/%f %p'
recovery_target_time='2012-11-22 5:01:09 CST'

--Raghu Ram

Re: Restore postgres to specific time

From

"Albe Laurenz"

Date:

23 November 2012, 12:38:49

wd wrote:
>>> I've try to restore Postgres to a specific time but failed.
>>>
>>> The recovery.conf as bellow
>>> restore_command='cp /t/xlog/%f %p'
>>> recovery_target_time='2012-11-22 5:01:09 CST'
>>> pause_at_recovery_target=true
>>> recovery_target_inclusive=false
>>>
>>> The basebackup was made at 2012-11-22 3:10 CST, I've copy wal log files at 3:00 to 5:10 into /t/xlog,
>>> but the recovery will not stop at 2012-11-22 5:01:09。
>>>
>>> How to do this?
> 
> Thanks for your reply, the logs are something like bellow，postgres will restore every wal log I put
> in the xlog directory，and then continues waiting for next wal log. The postgres version is 9.1.6.
> 
> [    2012-11-22 18:49:24.176 CST 25744 50ae0334.6490 2 0]LOG:  entering standby mode
> [    2012-11-22 18:49:24.210 CST 25744 50ae0334.6490 3 0]LOG:  restored log file
> "000000010000002800000023" from archive
> [    2012-11-22 18:49:24.213 CST 25744 50ae0334.6490 4 0]LOG:  redo starts at 28/23001900
> [    2012-11-22 18:49:24.619 CST 25744 50ae0334.6490 5 0]LOG:  consistent recovery state reached at
> 28/23FFFFC8
> [    2012-11-22 18:49:24.620 CST 25736 50ae0333.6488 2 0]LOG:  database system is ready to accept read
> only connections
> cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
[...]
> cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
> [    2012-11-22 18:50:49.828 CST 25744 50ae0334.6490 6 0]LOG:  restored log file
> "000000010000002800000024" from archive
[...]
> [    2012-11-22 18:50:54.920 CST 25744 50ae0334.6490 17 0]LOG:  restored log file
> "00000001000000280000002F" from archive
> cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory
> cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory

Can you also show us postgresql.conf from the standby?

Try to find out where you are in log replay.

Connect to the standby and run the following query:

SELECT pg_last_xact_replay_timestamp();

It would be interesting what time that is.

Yours,
Laurenz Albe

Re: Restore postgres to specific time

From

Jeff Janes

Date:

23 November 2012, 23:24:11

On Thu, Nov 22, 2012 at 7:29 PM, wd <wd@wdicc.com> wrote:
> Thanks for your reply, the logs are something like bellow，postgres will
> restore every wal log I put in the xlog directory，and then continues waiting
> for next wal log. The postgres version is 9.1.6.
>
> [    2012-11-22 18:49:24.175 CST 25744 50ae0334.6490 1 0]LOG:  database
> system was shut down in recovery at 2012-11-22 18:49:22 CST
> [    2012-11-22 18:49:24.176 CST 25744 50ae0334.6490 2 0]LOG:  entering
> standby mode

Do you have standby_mode=on in your recovery.conf?  If so, remove it.

It is meaningless to specify both standy_mode, and recovery_target_time.

Cheers,

Jeff

Re: Restore postgres to specific time

From

wd

Date:

24 November 2012, 17:00:18

Yes, you are right, after set the two command, the recovery will stop at that time.

But there is an other question, how to make this recovered Postgres can be read and write? According to the manual, Postgres should be rename recovery.conf to recovery.done, but it didn't.

I've tried pg_ctl promote, delete recovery.conf, it's also not work.

And, I've set hot_standby='on' in postgres.conf, but still can't connect into this postgres ,why?

(sorry for the individual mail sent to you, I should send it to the list)

On Fri, Nov 23, 2012 at 5:02 PM, raghu ram <raghuchennuru@gmail.com> wrote:

On Fri, Nov 23, 2012 at 8:59 AM, wd <wd@wdicc.com> wrote:
Thanks for your reply, the logs are something like bellow，postgres will restore every wal log I put in the xlog directory，and then continues waiting for next wal log. The postgres version is 9.1.6.

[    2012-11-22 18:49:24.175 CST 25744 50ae0334.6490 1 0]LOG: database system was shut down in recovery at 2012-11-22 18:49:22 CST
[    2012-11-22 18:49:24.176 CST 25744 50ae0334.6490 2 0]LOG: entering standby mode
[    2012-11-22 18:49:24.210 CST 25744 50ae0334.6490 3 0]LOG: restored log file "000000010000002800000023" from archive
[    2012-11-22 18:49:24.213 CST 25744 50ae0334.6490 4 0]LOG: redo starts at 28/23001900
[    2012-11-22 18:49:24.619 CST 25744 50ae0334.6490 5 0]LOG: consistent recovery state reached at 28/23FFFFC8
[    2012-11-22 18:49:24.620 CST 25736 50ae0333.6488 2 0]LOG: database system is ready to accept read only connections
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000024': No such file or directory
[    2012-11-22 18:50:49.828 CST 25744 50ae0334.6490 6 0]LOG: restored log file "000000010000002800000024" from archive
[    2012-11-22 18:50:50.291 CST 25744 50ae0334.6490 7 0]LOG: restored log file "000000010000002800000025" from archive
[    2012-11-22 18:50:50.759 CST 25744 50ae0334.6490 8 0]LOG: restored log file "000000010000002800000026" from archive
[    2012-11-22 18:50:51.220 CST 25744 50ae0334.6490 9 0]LOG: restored log file "000000010000002800000027" from archive
[    2012-11-22 18:50:51.686 CST 25744 50ae0334.6490 10 0]LOG: restored log file "000000010000002800000028" from archive
[    2012-11-22 18:50:52.145 CST 25744 50ae0334.6490 11 0]LOG: restored log file "000000010000002800000029" from archive
[    2012-11-22 18:50:52.613 CST 25744 50ae0334.6490 12 0]LOG: restored log file "00000001000000280000002A" from archive
[    2012-11-22 18:50:53.073 CST 25744 50ae0334.6490 13 0]LOG: restored log file "00000001000000280000002B" from archive
[    2012-11-22 18:50:53.538 CST 25744 50ae0334.6490 14 0]LOG: restored log file "00000001000000280000002C" from archive
[    2012-11-22 18:50:53.999 CST 25744 50ae0334.6490 15 0]LOG: restored log file "00000001000000280000002D" from archive
[    2012-11-22 18:50:54.459 CST 25744 50ae0334.6490 16 0]LOG: restored log file "00000001000000280000002E" from archive
[    2012-11-22 18:50:54.920 CST 25744 50ae0334.6490 17 0]LOG: restored log file "00000001000000280000002F" from archive
cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory
cp: cannot stat `/export/t/xlog/000000010000002800000030': No such file or directory

As per logs,it is working as a host-standby. For doing the point in time recovery,recovery.conf file requires only two settings:

restore_command='cp /t/xlog/%f %p'
recovery_target_time='2012-11-22 5:01:09 CST'

--Raghu Ram

Re: Restore postgres to specific time

From

Jeff Janes

Date:

24 November 2012, 23:25:34

On Sat, Nov 24, 2012 at 6:00 AM, wd <wd@wdicc.com> wrote:
> Yes,  you are right, after set the two command, the recovery will stop at
> that time.
>
> But there is an other question, how to make this recovered Postgres can be
> read and write? According to the manual, Postgres should be rename
> recovery.conf to recovery.done, but it didn't.

This is after you removed "standby_mode=on"?

It should happen automatically.

What entries are you getting in the log file?

Cheers,

Jeff

Re: Restore postgres to specific time

From

wd

Date:

25 November 2012, 02:44:47

On Sun, Nov 25, 2012 at 4:25 AM, Jeff Janes <jeff.janes@gmail.com> wrote:

On Sat, Nov 24, 2012 at 6:00 AM, wd <wd@wdicc.com> wrote:
> Yes, you are right, after set the two command, the recovery will stop at
> that time.
>
> But there is an other question, how to make this recovered Postgres can be
> read and write? According to the manual, Postgres should be rename
> recovery.conf to recovery.done, but it didn't.

This is after you removed "standby_mode=on"?

Yes, the recovery file like this:

recovery_target_time='2012-11-24 03:35:09+8'
recovery_target_inclusive=true
restore_command='cp /export/t/xlog/%f %p'

It should happen automatically.

What entries are you getting in the log file?

Logs are something like this:

[    2012-11-24 21:51:33.374 CST 583 50b0d0e5.247 1 0]LOG: database system was shut down in recovery at 2012-11-24 21:51:32 CST
[    2012-11-24 21:51:33.375 CST 583 50b0d0e5.247 2 0]LOG: starting point-in-time recovery to 2012-11-24 03:35:09+08
[    2012-11-24 21:51:33.415 CST 583 50b0d0e5.247 3 0]LOG: restored log file "000000010000002B00000085" from archive
[    2012-11-24 21:51:33.457 CST 583 50b0d0e5.247 4 0]LOG: restored log file "000000010000002B00000084" from archive
[    2012-11-24 21:51:33.458 CST 583 50b0d0e5.247 5 0]LOG: redo starts at 2B/8401D6E8
[    2012-11-24 21:51:33.498 CST 583 50b0d0e5.247 6 0]LOG: restored log file "000000010000002B00000085" from archive
[    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 7 0]LOG: restored log file "000000010000002B00000086" from archive
[    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 8 0]LOG: recovery stopping before commit of transaction 1573829, time 2012-11-24 03:35:17.704521+08
[    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 9 0]LOG: recovery has paused
[    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 10 0]HINT: Execute pg_xlog_replay_resume() to continue.

Cheers,

Jeff

Re: Restore postgres to specific time

From

"Albe Laurenz"

Date:

26 November 2012, 11:33:13

wd wrote:
> Logs are something like this:
> [    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 9 0]LOG:  recovery
has paused
> [    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 10 0]HINT:  Execute
pg_xlog_replay_resume() to continue.

Well, try

SELECT pg_xlog_replay_resume();

Yours,
Laurenz Albe

Re: Restore postgres to specific time

From

wd

Date:

26 November 2012, 17:08:59

I can't connect to postgres at that time.

On Mon, Nov 26, 2012 at 4:33 PM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote:

wd wrote:
> Logs are something like this:
> [ 2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 9 0]LOG: recovery
has paused
> [ 2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 10 0]HINT: Execute
pg_xlog_replay_resume() to continue.

Well, try

SELECT pg_xlog_replay_resume();

Yours,
Laurenz Albe

Re: Restore postgres to specific time

From

"Albe Laurenz"

Date:

26 November 2012, 18:32:58

wd wrote:
>>> Logs are something like this:
>>>
>>> [    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 9 0]LOG:  recovery
has paused
>>> [    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 10 0]HINT:
Execute pg_xlog_replay_resume() to continue.
>>
>> Well, try
>>
>> SELECT pg_xlog_replay_resume();
>
> I can't connect to postgres at that time.

Duh.
Then the trick is not to pause at all.
Make sure that pause_at_recovery_target is not set in
recovery.conf.
Stop the recovering server, then start it again.
That should do the trick.

Yours,
Laurenz Albe

Re: Restore postgres to specific time

From

Jeff Janes

Date:

26 November 2012, 20:22:57

On Sat, Nov 24, 2012 at 3:44 PM, wd <wd@wdicc.com> wrote:
>>
>> What entries are you getting in the log file?
>>
> Logs are something like this:
>
> [    2012-11-24 21:51:33.374 CST 583 50b0d0e5.247 1 0]LOG:  database system
> was shut down in recovery at 2012-11-24 21:51:32 CST
> [    2012-11-24 21:51:33.375 CST 583 50b0d0e5.247 2 0]LOG:  starting
> point-in-time recovery to 2012-11-24 03:35:09+08
...
> [    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 8 0]LOG:  recovery
> stopping before commit of transaction 1573829, time 2012-11-24
> 03:35:17.704521+08
> [    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 9 0]LOG:  recovery has
> paused
> [    2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 10 0]HINT:  Execute
> pg_xlog_replay_resume() to continue.
>

Something is strange here.  There is no message about reaching a
consistent recovery point (which is why it doesn't start in hot
standby mode I guess).  But when I arrange for that to happen myself,
by specifying a time before consistent recovery would be reached, I
get this error:

FATAL:  requested recovery stop point is before consistent recovery point

I don't understand why are you not getting this message.  I wonder if
the earlier attempts you made at doing this left the system in some
inconsistent state.  If you start over again with a fresh restore of
the base backup and a recovery.conf which is correctly configured the
first time you try to use it, do you still see this?

Cheers,

Jeff

Re: Restore postgres to specific time

From

"Kevin Grittner"

Date:

26 November 2012, 23:33:39

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?

-Kevin

Re: Restore postgres to specific time

From

Jeff Janes

Date:

27 November 2012, 03:27:44

On Mon, Nov 26, 2012 at 12:23 PM, Kevin Grittner <kgrittn@mail.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.

Cheers,

Jeff

Re: Restore postgres to specific time

From

wd

Date:

27 November 2012, 05:41:37

On Mon, Nov 26, 2012 at 11:32 PM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote:

wd wrote:
>>> Logs are something like this:
>>>
>>> [ 2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 9 0]LOG: recovery
has paused
>>> [ 2012-11-24 21:51:33.591 CST 583 50b0d0e5.247 10 0]HINT:
Execute pg_xlog_replay_resume() to continue.
>>
>> Well, try
>>
>> SELECT pg_xlog_replay_resume();
>
> I can't connect to postgres at that time.

Duh.
Then the trick is not to pause at all.
Make sure that pause_at_recovery_target is not set in
recovery.conf.
Stop the recovering server, then start it again.
That should do the trick.

I've tried set pause_at_recovery_target to true, it's not work. and also tried comment out this setting it's the same.

Restart have no effect, the recovery.conf is always there, I think it's should be rename to recovery.done if it's work.

Yours,
Laurenz Albe

Re: Restore postgres to specific time

From

wd

Date:

27 November 2012, 06:43:22

On Tue, Nov 27, 2012 at 8:27 AM, Jeff Janes <jeff.janes@gmail.com> wrote:

On Mon, Nov 26, 2012 at 12:23 PM, Kevin Grittner <kgrittn@mail.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

Re: Restore postgres to specific time

From

"Kevin Grittner"

Date:

27 November 2012, 17:59:43

wd wrote:

> the time is between backup start and stop.

That is the problem -- until the point where pg_stop_backup() was
run PostgreSQL can't be sure of having a consistent database. It is
waiting from enough WAL to get it there. My practice is always to
keep the last two base backups and all WAL from the start of the
earlier one to current. If I want to recover to a point in time
which was during a backup, I use the previous base backup, which is
complete and usable.

It does seem that there is an opportunity here to make it more
clear what is happening.

-Kevin

Re: Restore postgres to specific time

From

Tom Lane

Date:

27 November 2012, 18:06:20

"Kevin Grittner" <kgrittn@mail.com> writes:
> That is the problem -- until the point where pg_stop_backup() was
> run PostgreSQL can't be sure of having a consistent database. It is
> waiting from enough WAL to get it there. My practice is always to
> keep the last two base backups and all WAL from the start of the
> earlier one to current. If I want to recover to a point in time
> which was during a backup, I use the previous base backup, which is
> complete and usable.

> It does seem that there is an opportunity here to make it more
> clear what is happening.

Seems like we could throw an error if the requested stop time is earlier
than the pg_stop_backup time.  (That should then allow some code
simplification --- I imagine currently we're doing a max() calculation
somewhere ...)

            regards, tom lane

Re: Restore postgres to specific time

From

Jeff Janes

Date:

27 November 2012, 20:40:36

On Tue, Nov 27, 2012 at 6:59 AM, Kevin Grittner <kgrittn@mail.com> wrote:
> wd wrote:
>
>> the time is between backup start and stop.
>
> That is the problem -- until the point where pg_stop_backup() was
> run PostgreSQL can't be sure of having a consistent database. It is
> waiting from enough WAL to get it there. My practice is always to
> keep the last two base backups and all WAL from the start of the
> earlier one to current. If I want to recover to a point in time
> which was during a backup, I use the previous base backup, which is
> complete and usable.
>
> It does seem that there is an opportunity here to make it more
> clear what is happening.

It seems like the code is already there to throw an error, it is just
that hot_standby=on somehow suppresses it during this window.

Cheers,

Jeff

Re: Restore postgres to specific time

From

Jeff Janes

Date:

28 November 2012, 08:26:53

On Tue, Nov 27, 2012 at 6:59 AM, Kevin Grittner <kgrittn@mail.com> wrote:
> wd wrote:
>
>> the time is between backup start and stop.
>
> That is the problem -- until the point where pg_stop_backup() was
> run PostgreSQL can't be sure of having a consistent database.

In 9.2, it seems to be willing to give it a shot anyway.

It will start up a hot standby as soon as the end-of-checkpoint record
(the one from the pg_start_backup) gets replayed.  I'm pretty sure
that this is a bug, but I have not been able to provoke hot standby
into given me wrong answers due to it.  I think it is another
manifestation of the same issue I reported to bugs list about commit
8366c7803ec3d059.

Or is this not a bug?  It certainly seems like it would be, because
the hot standby can now read data pages that were modified at a time
that is still "in the future" as far as the currently state of replay
is concerned.  Those changes will mostly be invisible because the xid
will also be in the future (which is probably why I haven't been able
to force inconsistencies) but it seems like there must be some
situations in which that is not enough to save us.

 Cheers,

Jeff