Re: PG 9.3 Switch streaming to wal shipping

On 09/29/2014 02:17 PM, Andy Colson wrote:
> Crap! Is this a problem?!
>
> I switched back to cp, all was going well, here are some logs:
>
> Sep 29 16:07:10 webserv postgres[17735]: [590-1] ,,2014-09-29
> 16:07:10.888 CDT,: LOG: restored log file "00000002000000B900000023"
> from archive
> Sep 29 16:07:13 webserv postgres[17734]: [3-1] ,,2014-09-29 16:07:13.971
> CDT,: LOG: received fast shutdown request
> Sep 29 16:07:13 webserv postgres[17734]: [4-1] ,,2014-09-29 16:07:13.971
> CDT,: LOG: aborting any active transactions
> Sep 29 16:07:13 webserv postgres[17739]: [2-1] ,,2014-09-29 16:07:13.995
> CDT,: LOG: shutting down
> Sep 29 16:07:13 webserv postgres[17739]: [3-1] ,,2014-09-29 16:07:13.995
> CDT,: LOG: database system is shut down
>
> So it was at 00000002000000B900000023.
>
> I switched recovery.conf to:
>
> restore_command = '/usr/local/pg93/bin/pg_standby -d /pub/archive %f %p
> 2>>/tmp/standby.log'
>
> and restart PG. PG log shows:
> Sep 29 16:08:56 webserv postgres[19054]: [2-1] ,,2014-09-29 16:08:56.002
> CDT,: LOG: database system was shut down in recovery at 2014-09-29
> 16:07:13 CDT
> Sep 29 16:08:56 webserv postgres[19054]: [3-1] ,,2014-09-29 16:08:56.002
> CDT,: LOG: entering standby mode
> Sep 29 16:08:56 webserv postgres[19054]: [4-1] ,,2014-09-29 16:08:56.017
> CDT,: LOG: restored log file "00000002.history" from archive
> Sep 29 16:08:56 webserv postgres[19054]: [5-1] ,,2014-09-29 16:08:56.042
> CDT,: LOG: restored log file "00000002000000B900000015" from archive
>
> I was at 23! Did it really replay 15? How bad is that?
> /tmp/standby.log makes no sense at all:
>
> Trigger file: <not set>
> Waiting for WAL file: 00000002.history
> WAL file path: /pub/archive/00000002.history
> Restoring to: pg_xlog/RECOVERYHISTORY
> Sleep interval: 5 seconds
> Max wait interval: 0 forever
> Command for restore: cp "/pub/archive/00000002.history"
> "pg_xlog/RECOVERYHISTORY"
> Keep archive history: no cleanup required
> running restore: OK
> Trigger file: <not set>
> Waiting for WAL file: 00000002000000B900000015
> WAL file path: /pub/archive/00000002000000B900000015
> Restoring to: pg_xlog/RECOVERYXLOG
> Sleep interval: 5 seconds
> Max wait interval: 0 forever
> Command for restore: cp "/pub/archive/00000002000000B900000015"
> "pg_xlog/RECOVERYXLOG"
> Keep archive history: no cleanup required
> running restore: OK
> Trigger file: <not set>
> Waiting for WAL file: 00000002000000B900000006
> WAL file path: /pub/archive/00000002000000B900000006
> Restoring to: pg_xlog/RECOVERYXLOG
> Sleep interval: 5 seconds
> Max wait interval: 0 forever
> Command for restore: cp "/pub/archive/00000002000000B900000006"
> "pg_xlog/RECOVERYXLOG"
> Keep archive history: no cleanup required
> WAL file not present yet.
> WAL file not present yet.
> WAL file not present yet.
>
>
> Why did it jump from 15 back to 6? Why did it even start at 15? Am I
> hosed at this point? I really don't want to make another base backup.

Not sure. Some observations:

In the above you have a .history file which seems to indicate you have
wandered into timelines:

http://www.postgresql.org/docs/9.3/static/continuous-archiving.html

24.3.5. Timelines

You might want to look at the pg_xlog directory on the master and the
archive directory to see if the WAL file numbers match what you are seeing.

>
> -Andy
>
>
>
>

--
Adrian Klaver
adrian(dot)klaver(at)aklaver(dot)com