Skip to content

Instantly share code, notes, and snippets.

@mboersma

mboersma/wal-e-restore.log

Created April 28, 2016 03:08
Show Gist options
  • Save mboersma/90799b42d29375fdcf0f7ddf4c5bc17e to your computer and use it in GitHub Desktop.
Save mboersma/90799b42d29375fdcf0f7ddf4c5bc17e to your computer and use it in GitHub Desktop.
Download ZIP
wal-e-restore.log
Raw
wal-e-restore.log
$ kd logs -f deis-database-a9p62
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.
The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
fixing permissions on existing directory /var/lib/postgresql/data ... ok
creating subdirectories ... ok
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting dynamic shared memory implementation ... posix
creating configuration files ... ok
creating template1 database in /var/lib/postgresql/data/base/1 ... ok
initializing pg_authid ... ok
initializing dependencies ... ok
creating system views ... ok
loading system objects' descriptions ... ok
creating collations ... ok
creating conversions ... ok
creating dictionaries ... ok
setting privileges on built-in objects ... ok
creating information schema ... ok
loading PL/pgSQL server-side language ... ok
vacuuming database template1 ... ok
copying template1 to template0 ... ok
copying template1 to postgres ... ok
WARNING: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.
syncing data to disk ... ok
Success. You can now start the database server using:
postgres -D /var/lib/postgresql/data
or
pg_ctl -D /var/lib/postgresql/data -l logfile start
waiting for server to start....LOG: database system was shut down at 2016-04-28 03:03:39 UTC
LOG: MultiXact member wraparound protections are now enabled
LOG: database system is ready to accept connections
LOG: autovacuum launcher started
done
server started
CREATE DATABASE
CREATE ROLE
/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/001_setup_envdir.sh
/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/002_create_bucket.sh
/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/003_restore_from_backup.sh
Rebooting postgres to enable archive mode
waiting for server to shut down...LOG: received smart shutdown request
LOG: autovacuum launcher shutting down
.LOG: shutting down
LOG: database system is shut down
done
server stopped
waiting for server to start....LOG: database system was shut down at 2016-04-28 03:03:41 UTC
LOG: MultiXact member wraparound protections are now enabled
LOG: database system is ready to accept connections
LOG: autovacuum launcher started
done
server started
Found backups. Restoring from backup...
LOG: received smart shutdown request
waiting for server to shut down....LOG: autovacuum launcher shutting down
LOG: shutting down
LOG: database system is shut down
done
server stopped
wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "backup-fetch".
STRUCTURED: time=2016-04-28T03:03:45.799115-00 pid=99
oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
wal_e.worker.gs.gs_worker INFO MSG: beginning partition download
DETAIL: The partition being downloaded is part_00000000.tar.lzo.
HINT: The absolute GCS key is basebackups_005/base_000000010000000000000002_00000040/tar_partitions/part_00000000.tar.lzo.
STRUCTURED: time=2016-04-28T03:03:46.927427-00 pid=99
oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
waiting for server to start....LOG: database system was interrupted; last known up at 2016-04-28 02:22:54 UTC
LOG: creating missing WAL directory "pg_xlog/archive_status"
LOG: starting archive recovery
wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:03:50.129002-00 pid=119
wal_e.operator.backup INFO MSG: begin wal restore
STRUCTURED: time=2016-04-28T03:03:50.204386-00 pid=119 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000002.lzo prefix= seg=000000010000000000000002 state=begin
FATAL: the database system is starting up
.oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
FATAL: the database system is starting up
.wal_e.blobstore.gs.utils INFO MSG: completed download and decompression
DETAIL: Downloaded and decompressed "gs://mb-workflow-database-bucket/wal_005/000000010000000000000002.lzo" to "pg_xlog/RECOVERYXLOG"
STRUCTURED: time=2016-04-28T03:03:52.900928-00 pid=119
wal_e.operator.backup INFO MSG: complete wal restore
STRUCTURED: time=2016-04-28T03:03:52.901285-00 pid=119 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000002.lzo prefix= seg=000000010000000000000002 state=complete
FATAL: the database system is starting up
.LOG: restored log file "000000010000000000000002" from archive
LOG: redo starts at 0/2000090
LOG: consistent recovery state reached at 0/20000B8
FATAL: the database system is starting up
.FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:03:55.290536-00 pid=155
FATAL: the database system is starting up
.wal_e.operator.backup INFO MSG: begin wal restore
STRUCTURED: time=2016-04-28T03:03:55.992695-00 pid=155 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000003.lzo prefix= seg=000000010000000000000003 state=begin
oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
FATAL: the database system is starting up
.wal_e.blobstore.gs.utils INFO MSG: completed download and decompression
DETAIL: Downloaded and decompressed "gs://mb-workflow-database-bucket/wal_005/000000010000000000000003.lzo" to "pg_xlog/RECOVERYXLOG"
STRUCTURED: time=2016-04-28T03:03:57.452078-00 pid=155
wal_e.operator.backup INFO MSG: complete wal restore
STRUCTURED: time=2016-04-28T03:03:57.452349-00 pid=155 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000003.lzo prefix= seg=000000010000000000000003 state=complete
LOG: restored log file "000000010000000000000003" from archive
FATAL: the database system is starting up
.FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:03:59.226156-00 pid=184
wal_e.operator.backup INFO MSG: begin wal restore
STRUCTURED: time=2016-04-28T03:03:59.439137-00 pid=184 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000004.lzo prefix= seg=000000010000000000000004 state=begin
oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
FATAL: the database system is starting up
.wal_e.blobstore.gs.utils INFO MSG: completed download and decompression
DETAIL: Downloaded and decompressed "gs://mb-workflow-database-bucket/wal_005/000000010000000000000004.lzo" to "pg_xlog/RECOVERYXLOG"
STRUCTURED: time=2016-04-28T03:04:00.581060-00 pid=184
wal_e.operator.backup INFO MSG: complete wal restore
STRUCTURED: time=2016-04-28T03:04:00.581316-00 pid=184 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000004.lzo prefix= seg=000000010000000000000004 state=complete
LOG: restored log file "000000010000000000000004" from archive
wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:00.915604-00 pid=227
wal_e.operator.backup INFO MSG: promoted prefetched wal segment
STRUCTURED: time=2016-04-28T03:04:00.999608-00 pid=227 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000005.lzo prefix= seg=000000010000000000000005
FATAL: the database system is starting up
.LOG: restored log file "000000010000000000000005" from archive
wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:01.795660-00 pid=236
wal_e.operator.backup INFO MSG: promoted prefetched wal segment
STRUCTURED: time=2016-04-28T03:04:01.976964-00 pid=236 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000006.lzo prefix= seg=000000010000000000000006
FATAL: the database system is starting up
.LOG: restored log file "000000010000000000000006" from archive
wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:02.772491-00 pid=252
wal_e.operator.backup INFO MSG: promoted prefetched wal segment
STRUCTURED: time=2016-04-28T03:04:02.997669-00 pid=252 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000007.lzo prefix= seg=000000010000000000000007
LOG: restored log file "000000010000000000000007" from archive
FATAL: the database system is starting up
.FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:04.358208-00 pid=265
wal_e.operator.backup INFO MSG: promoted prefetched wal segment
STRUCTURED: time=2016-04-28T03:04:04.796443-00 pid=265 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000008.lzo prefix= seg=000000010000000000000008
LOG: restored log file "000000010000000000000008" from archive
FATAL: the database system is starting up
.FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:06.137642-00 pid=278
wal_e.operator.backup INFO MSG: promoted prefetched wal segment
STRUCTURED: time=2016-04-28T03:04:06.538337-00 pid=278 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/000000010000000000000009.lzo prefix= seg=000000010000000000000009
LOG: restored log file "000000010000000000000009" from archive
FATAL: the database system is starting up
.FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:08.511068-00 pid=297
wal_e.operator.backup INFO MSG: promoted prefetched wal segment
STRUCTURED: time=2016-04-28T03:04:08.625376-00 pid=297 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000001000000000000000A.lzo prefix= seg=00000001000000000000000A
LOG: restored log file "00000001000000000000000A" from archive
FATAL: the database system is starting up
.FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:10.971158-00 pid=324
FATAL: the database system is starting up
.wal_e.operator.backup INFO MSG: begin wal restore
STRUCTURED: time=2016-04-28T03:04:11.526720-00 pid=324 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000001000000000000000B.lzo prefix= seg=00000001000000000000000B state=begin
FATAL: the database system is starting up
.oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
wal_e.blobstore.gs.utils WARNING MSG: could no longer locate object while performing wal restore
DETAIL: The absolute URI that could not be located is gs://mb-workflow-database-bucket/wal_005/00000001000000000000000B.lzo.
HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.
STRUCTURED: time=2016-04-28T03:04:13.052042-00 pid=324
lzop: <stdin>: not a lzop file
wal_e.operator.backup INFO MSG: complete wal restore
STRUCTURED: time=2016-04-28T03:04:13.153432-00 pid=324 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000001000000000000000B.lzo prefix= seg=00000001000000000000000B state=complete
FATAL: the database system is starting up
.LOG: redo done at 0/A000090
LOG: last completed transaction was at log time 2016-04-28 02:28:37.826007+00
FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:14.782230-00 pid=354
FATAL: the database system is starting up
.wal_e.operator.backup INFO MSG: begin wal restore
STRUCTURED: time=2016-04-28T03:04:15.397167-00 pid=354 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000001000000000000000A.lzo prefix= seg=00000001000000000000000A state=begin
FATAL: the database system is starting up
.oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
wal_e.blobstore.gs.utils INFO MSG: completed download and decompression
DETAIL: Downloaded and decompressed "gs://mb-workflow-database-bucket/wal_005/00000001000000000000000A.lzo" to "pg_xlog/RECOVERYXLOG"
STRUCTURED: time=2016-04-28T03:04:17.071932-00 pid=354
wal_e.operator.backup INFO MSG: complete wal restore
STRUCTURED: time=2016-04-28T03:04:17.072186-00 pid=354 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000001000000000000000A.lzo prefix= seg=00000001000000000000000A state=complete
FATAL: the database system is starting up
.LOG: restored log file "00000001000000000000000A" from archive
FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:18.527067-00 pid=394
wal_e.operator.backup INFO MSG: begin wal restore
STRUCTURED: time=2016-04-28T03:04:18.928949-00 pid=394 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000002.history.lzo prefix= seg=00000002.history state=begin
oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
FATAL: the database system is starting up
.lzop: <stdin>: not a lzop file
wal_e.blobstore.gs.utils WARNING MSG: could no longer locate object while performing wal restore
DETAIL: The absolute URI that could not be located is gs://mb-workflow-database-bucket/wal_005/00000002.history.lzo.
HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.
STRUCTURED: time=2016-04-28T03:04:19.535065-00 pid=394
wal_e.operator.backup INFO MSG: complete wal restore
STRUCTURED: time=2016-04-28T03:04:19.636857-00 pid=394 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000002.history.lzo prefix= seg=00000002.history state=complete
LOG: selected new timeline ID: 2
FATAL: the database system is starting up
.wal_e.main INFO MSG: starting WAL-E
DETAIL: The subcommand is "wal-fetch".
STRUCTURED: time=2016-04-28T03:04:20.438667-00 pid=416
wal_e.operator.backup INFO MSG: begin wal restore
STRUCTURED: time=2016-04-28T03:04:20.633180-00 pid=416 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000001.history.lzo prefix= seg=00000001.history state=begin
oauth2client.client INFO Attempting refresh to obtain initial access_token
oauth2client.client INFO Refreshing access_token
wal_e.blobstore.gs.utils WARNING MSG: could no longer locate object while performing wal restore
DETAIL: The absolute URI that could not be located is gs://mb-workflow-database-bucket/wal_005/00000001.history.lzo.
HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.
STRUCTURED: time=2016-04-28T03:04:21.238400-00 pid=416
lzop: <stdin>: not a lzop file
wal_e.operator.backup INFO MSG: complete wal restore
STRUCTURED: time=2016-04-28T03:04:21.341126-00 pid=416 action=wal-fetch key=gs://mb-workflow-database-bucket/wal_005/00000001.history.lzo prefix= seg=00000001.history state=complete
FATAL: the database system is starting up
.LOG: archive recovery complete
LOG: MultiXact member wraparound protections are now enabled
LOG: database system is ready to accept connections
LOG: autovacuum launcher started
done
server started
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment