Re: BUG #7753: Cannot promote out of hot standby

(cleaning up my inbox..)

Did you ever figure out this one?

On 12.12.2012 23:36, daniel@heroku.com wrote:
> The following bug has been logged on the website:
>
> Bug reference:      7753
> Logged by:          Daniel Farina
> Email address:      daniel@heroku.com
> PostgreSQL version: 9.1.6
> Operating system:   Ubuntu 10.04
> Description:
>
> Touching a trigger file will not cause promotion out of hot standby.
> Basically, an apparently normally-working hot-standby database will
> not leave hot standby.  The database emitting WAL is version 9.1.4.
>
> Everything appears normal in the log (downloads and restoring of
> archived segments), and the server seems to take no notice of the
> trigger file.
>
> To force the issue, I introduced an error into the configuration of
> the restoration program to cause it to exit.  Normally that's no
> problem; postgres would just keep on trying to restore a segment over
> and over until the error is fixed.
>
> Instead, the server crashes:
>
>   [413-1]  [COPPER] LOG:  restored log file "000000010000034D00000050" from
> archive
> wal_e.worker.s3_worker INFO     MSG: completed download and
> decompression#012        DETAIL: Downloaded and decompressed
> "s3://archive-root/wal_005/000000010000034D00000051.lzo" to
> "pg_xlog/RECOVERYXLOG"
>   [414-1]  [COPPER] LOG:  restored log file "000000010000034D00000051" from
> archive
> wal_e.worker.s3_worker INFO     MSG: completed download and
> decompression#012        DETAIL: Downloaded and decompressed
> "s3://archive-root/wal_005/000000010000034D00000052.lzo" to
> "pg_xlog/RECOVERYXLOG"
>   [415-1]  [COPPER] LOG:  restored log file "000000010000034D00000052" from
> archive
>
> # I introduce the failure here
>
> wal_e.main   ERROR    MSG: no AWS_SECRET_ACCESS_KEY defined#012        HINT:
> Define the environment variable AWS_SECRET_ACCESS_KEY.
> LOG:  trigger file found: /etc/postgresql/wal-e.d/pull-env/STANDBY_OFF
> LOG:  redo done at 34D/52248590
> LOG:  last completed transaction was at log time 2012-12-10 wal_e.main
> ERROR    MSG: no AWS_SECRET_ACCESS_KEY defined#012        HINT: Define the
> environment variable AWS_SECRET_ACCESS_KEY.
> PANIC:  could not open file "pg_xlog/000000010000034D00000052" (log file
> 845, segment 82): No such file or directory
> LOG:  startup process (PID 7) was terminated by signal 6: Aborted
> LOG:  terminating any other active server processes
> WARNING:  terminating connection because of crash of another server process
> WARNING:  terminating connection because of crash of another server process
> DETAIL:  The postmaster has commanded this server process to roll back the
> current transaction and exit, because another server process exited
> abnormally and possibly corrupted shared memory.
> DETAIL:  The postmaster has commanded this server process to roll back the
> current transaction and exit, because another server process exited
> abnormally and possibly corrupted shared memory.
>
> I can fix the configuration and restart the server, and everything is
> as fine as before.  Next, I try removing recovery.conf and restarting
> the server as an alternative way of promoting...but, no avail;
> however, a slightly different error message:
>
> # Server begins starting
> LOG:  loaded library "auto_explain"
> LOG:  loaded library "pg_stat_statements"
> LOG:  database system was interrupted while in recovery at log time
> 2012-12-10 15:20:03 UTC
> HINT:  If this has occurred more than once some data might be corrupted and
> you might need to choose an earlier recovery target.
> LOG:  could not open file "pg_xlog/000000010000034E0000001A" (log file 846,
> segment 26): No such file or directory
> LOG:  invalid primary checkpoint record
> LOG:  could not open file "pg_xlog/000000010000034D000000F2" (log file 845,
> segment 242): No such file or directory
> LOG:  invalid secondary checkpoint record
> PANIC:  could not locate a valid checkpoint record
> LOG:  startup process (PID 7) was terminated by signal 6: Aborted
> LOG:  aborting startup due to startup process failure
> main process (24284) terminated with status 1
>
> pg_control looks like this around the same time, for reference:
>
> pg_control version number:            903
> Catalog version number:               201105231
> Database cluster state:               in archive recovery
> pg_control last modified:             Wed 12 Dec 2012 09:22:30 PM UTC
> Latest checkpoint location:           351/1FE194C0
> Prior checkpoint location:            351/FD64A78
> Latest checkpoint's REDO location:    351/131848C8
> Latest checkpoint's TimeLineID:       1
> Latest checkpoint's NextXID:          0/652342033
> Latest checkpoint's NextOID:          103224
> Latest checkpoint's NextMultiXactId:  1
> Latest checkpoint's NextMultiOffset:  0
> Latest checkpoint's oldestXID:        455900714
> Latest checkpoint's oldestXID's DB:   16385
> Latest checkpoint's oldestActiveXID:  652311442
> Time of latest checkpoint:            Mon 10 Dec 2012 07:19:23 PM UTC
> Minimum recovery ending location:     351/4BFFFE20
> Backup start location:                0/0
> Current wal_level setting:            hot_standby
> Current max_connections setting:      500
> Current max_prepared_xacts setting:   500
> Current max_locks_per_xact setting:   64
> Maximum data alignment:               8
> Database block size:                  8192
> Blocks per segment of large relation: 131072
> WAL block size:                       8192
> Bytes per WAL segment:                16777216
> Maximum length of identifiers:        64
> Maximum columns in an index:          32
> Maximum size of a TOAST chunk:        1996
> Date/time type storage:               64-bit integers
> Float4 argument passing:              by value
> Float8 argument passing:              by value
>
> In the course of all this messing around, it has never been a problem to go
> back to archive recovery.
>
>
>


--
- Heikki