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.klaver@aklaver.com