search

deis / postgres

A PostgreSQL database used by Deis Workflow.
https://deis.com
MIT License
36 stars 21 forks source link

Possible bug: Recovery from s3 is missing apps when complete #97

Closed krancour closed 8 years ago

krancour commented 8 years ago

Logs captured during recovery:

[kent@mbp ~]$ k logs -f deis-database-qvcas
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-05-11 18:24:19 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
LOG:  received smart shutdown request
LOG:  autovacuum launcher shutting down
waiting for server to shut 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-05-11 18:24:21 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...
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
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "backup-fetch".
        STRUCTURED: time=2016-05-11T18:24:26.589272-00 pid=108
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7fd9a40bd790>)
        STRUCTURED: time=2016-05-11T18:24:26.653643-00 pid=108
botocore.credentials INFO     Found credentials in environment variables.
boto3.resources.collection INFO     Calling paginated s3:list_objects with {'Prefix': 'basebackups_005/', u'Bucket': 'kents-database'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7fd9a40bd790>)
        STRUCTURED: time=2016-05-11T18:24:27.448421-00 pid=108
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (None)
        STRUCTURED: time=2016-05-11T18:24:27.452896-00 pid=108
boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': 'basebackups_005/base_000000010000000000000002_00000040_backup_stop_sentinel.json'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7fd9a40bd790>)
        STRUCTURED: time=2016-05-11T18:24:28.032651-00 pid=108
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7fd9a40bd790>)
        STRUCTURED: time=2016-05-11T18:24:28.036525-00 pid=108
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7fd9a40bd790>)
        STRUCTURED: time=2016-05-11T18:24:28.040552-00 pid=108
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7fd9a40bd790>)
        STRUCTURED: time=2016-05-11T18:24:28.043416-00 pid=108
boto3.resources.collection INFO     Calling paginated s3:list_objects with {'Prefix': 'basebackups_005/base_000000010000000000000002_00000040/tar_partitions/', u'Bucket': 'kents-database'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
wal_e.worker.s3.s3_worker INFO     MSG: beginning partition download
        DETAIL: The partition being downloaded is part_00000000.tar.lzo.
        HINT: The absolute S3 key is basebackups_005/base_000000010000000000000002_00000040/tar_partitions/part_00000000.tar.lzo.
        STRUCTURED: time=2016-05-11T18:24:28.795161-00 pid=108
boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': u'basebackups_005/base_000000010000000000000002_00000040/tar_partitions/part_00000000.tar.lzo'}

waiting for server to start....LOG:  database system was interrupted; last known up at 2016-05-11 16:56:13 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-05-11T18:24:48.210640-00 pid=136
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-05-11T18:24:48.280646-00 pid=136 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000002.lzo prefix= seg=000000010000000000000002 state=begin
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7f36205b8810>)
        STRUCTURED: time=2016-05-11T18:24:48.392752-00 pid=136
botocore.credentials INFO     Found credentials in environment variables.
FATAL:  the database system is starting up
.boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': 'wal_005/000000010000000000000002.lzo'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
FATAL:  the database system is starting up
.FATAL:  the database system is starting up
.wal_e.blobstore.s3.s3_util INFO     MSG: completed download and decompression
        DETAIL: Downloaded and decompressed "s3://kents-database/wal_005/000000010000000000000002.lzo" to "pg_xlog/RECOVERYXLOG"
        STRUCTURED: time=2016-05-11T18:24:50.940014-00 pid=136
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-05-11T18:24:50.941717-00 pid=136 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000002.lzo prefix= seg=000000010000000000000002 state=complete
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
.wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:24:52.639754-00 pid=174
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-05-11T18:24:53.500313-00 pid=174 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000003.lzo prefix= seg=000000010000000000000003 state=begin
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7f929adc3810>)
        STRUCTURED: time=2016-05-11T18:24:53.603401-00 pid=174
botocore.credentials INFO     Found credentials in environment variables.
FATAL:  the database system is starting up
.boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': 'wal_005/000000010000000000000003.lzo'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
FATAL:  the database system is starting up
.FATAL:  the database system is starting up
.wal_e.blobstore.s3.s3_util INFO     MSG: completed download and decompression
        DETAIL: Downloaded and decompressed "s3://kents-database/wal_005/000000010000000000000003.lzo" to "pg_xlog/RECOVERYXLOG"
        STRUCTURED: time=2016-05-11T18:24:56.213157-00 pid=174
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-05-11T18:24:56.214547-00 pid=174 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000003.lzo prefix= seg=000000010000000000000003 state=complete
LOG:  restored log file "000000010000000000000003" 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-05-11T18:24:57.039151-00 pid=243
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:24:57.123611-00 pid=243 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000004.lzo prefix= seg=000000010000000000000004
LOG:  restored log file "000000010000000000000004" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:24:57.511175-00 pid=260
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:24:57.877530-00 pid=260 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000005.lzo prefix= seg=000000010000000000000005
LOG:  restored log file "000000010000000000000005" 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-05-11T18:24:58.313237-00 pid=285
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:24:58.461879-00 pid=285 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000006.lzo prefix= seg=000000010000000000000006
LOG:  restored log file "000000010000000000000006" 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-05-11T18:24:59.175219-00 pid=297
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:24:59.489640-00 pid=297 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000007.lzo prefix= seg=000000010000000000000007
LOG:  restored log file "000000010000000000000007" 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-05-11T18:25:00.659396-00 pid=308
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:00.978623-00 pid=308 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000008.lzo prefix= seg=000000010000000000000008
LOG:  restored log file "000000010000000000000008" 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-05-11T18:25:01.686771-00 pid=327
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:01.945314-00 pid=327 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000009.lzo prefix= seg=000000010000000000000009
LOG:  restored log file "000000010000000000000009" 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-05-11T18:25:02.746397-00 pid=349
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:02.915079-00 pid=349 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000000A.lzo prefix= seg=00000001000000000000000A
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-05-11T18:25:03.761808-00 pid=364
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:03.985677-00 pid=364 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000000B.lzo prefix= seg=00000001000000000000000B
LOG:  restored log file "00000001000000000000000B" 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-05-11T18:25:04.731851-00 pid=383
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:04.869509-00 pid=383 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000000C.lzo prefix= seg=00000001000000000000000C
LOG:  restored log file "00000001000000000000000C" 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-05-11T18:25:05.611564-00 pid=398
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:05.696798-00 pid=398 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000000D.lzo prefix= seg=00000001000000000000000D
LOG:  restored log file "00000001000000000000000D" 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-05-11T18:25:06.671727-00 pid=417
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:06.872224-00 pid=417 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000000E.lzo prefix= seg=00000001000000000000000E
LOG:  restored log file "00000001000000000000000E" 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-05-11T18:25:07.170934-00 pid=435
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:07.237637-00 pid=435 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000000F.lzo prefix= seg=00000001000000000000000F
LOG:  restored log file "00000001000000000000000F" 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-05-11T18:25:08.445664-00 pid=448
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:08.887894-00 pid=448 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000010.lzo prefix= seg=000000010000000000000010
LOG:  restored log file "000000010000000000000010" 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-05-11T18:25:09.482535-00 pid=476
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:09.645153-00 pid=476 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000011.lzo prefix= seg=000000010000000000000011
LOG:  restored log file "000000010000000000000011" 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-05-11T18:25:11.019512-00 pid=490
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:11.091233-00 pid=490 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000012.lzo prefix= seg=000000010000000000000012
LOG:  restored log file "000000010000000000000012" 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-05-11T18:25:12.167946-00 pid=507
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:12.508643-00 pid=507 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000013.lzo prefix= seg=000000010000000000000013
LOG:  restored log file "000000010000000000000013" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:13.072956-00 pid=532
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:13.347457-00 pid=532 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000014.lzo prefix= seg=000000010000000000000014
LOG:  restored log file "000000010000000000000014" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:14.181084-00 pid=552
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:14.461921-00 pid=552 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000015.lzo prefix= seg=000000010000000000000015
LOG:  restored log file "000000010000000000000015" 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-05-11T18:25:15.254303-00 pid=569
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:15.550136-00 pid=569 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000016.lzo prefix= seg=000000010000000000000016
LOG:  restored log file "000000010000000000000016" 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-05-11T18:25:16.446540-00 pid=587
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:16.636657-00 pid=587 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000017.lzo prefix= seg=000000010000000000000017
LOG:  restored log file "000000010000000000000017" 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-05-11T18:25:17.467758-00 pid=605
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:17.839222-00 pid=605 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000018.lzo prefix= seg=000000010000000000000018
LOG:  restored log file "000000010000000000000018" 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-05-11T18:25:18.707984-00 pid=631
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:19.026279-00 pid=631 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000019.lzo prefix= seg=000000010000000000000019
LOG:  restored log file "000000010000000000000019" 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-05-11T18:25:19.924047-00 pid=651
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:20.693125-00 pid=651 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000001A.lzo prefix= seg=00000001000000000000001A
LOG:  restored log file "00000001000000000000001A" 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-05-11T18:25:21.560208-00 pid=676
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:21.771462-00 pid=676 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000001B.lzo prefix= seg=00000001000000000000001B
LOG:  restored log file "00000001000000000000001B" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:22.381049-00 pid=694
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:22.598867-00 pid=694 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000001C.lzo prefix= seg=00000001000000000000001C
LOG:  restored log file "00000001000000000000001C" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:22.925082-00 pid=703
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:23.261869-00 pid=703 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000001D.lzo prefix= seg=00000001000000000000001D
LOG:  restored log file "00000001000000000000001D" 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-05-11T18:25:24.490610-00 pid=717
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:24.901647-00 pid=717 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000001E.lzo prefix= seg=00000001000000000000001E
LOG:  restored log file "00000001000000000000001E" 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-05-11T18:25:25.662005-00 pid=736
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:25.913267-00 pid=736 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000001F.lzo prefix= seg=00000001000000000000001F
LOG:  restored log file "00000001000000000000001F" 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-05-11T18:25:26.505339-00 pid=759
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:26.665055-00 pid=759 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000020.lzo prefix= seg=000000010000000000000020
LOG:  restored log file "000000010000000000000020" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:27.152252-00 pid=776
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:27.373959-00 pid=776 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000021.lzo prefix= seg=000000010000000000000021
LOG:  restored log file "000000010000000000000021" 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-05-11T18:25:28.349717-00 pid=791
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:28.526140-00 pid=791 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000022.lzo prefix= seg=000000010000000000000022
LOG:  restored log file "000000010000000000000022" 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-05-11T18:25:29.695886-00 pid=813
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:30.039723-00 pid=813 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000023.lzo prefix= seg=000000010000000000000023
LOG:  restored log file "000000010000000000000023" 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-05-11T18:25:31.654059-00 pid=838
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:31.895388-00 pid=838 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000024.lzo prefix= seg=000000010000000000000024
LOG:  restored log file "000000010000000000000024" 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-05-11T18:25:32.851005-00 pid=859
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:33.180054-00 pid=859 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000025.lzo prefix= seg=000000010000000000000025
LOG:  restored log file "000000010000000000000025" 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-05-11T18:25:34.115101-00 pid=879
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:34.373204-00 pid=879 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000026.lzo prefix= seg=000000010000000000000026
LOG:  restored log file "000000010000000000000026" 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-05-11T18:25:35.222247-00 pid=898
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:35.520083-00 pid=898 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000027.lzo prefix= seg=000000010000000000000027
LOG:  restored log file "000000010000000000000027" 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-05-11T18:25:36.392569-00 pid=909
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:36.677114-00 pid=909 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000028.lzo prefix= seg=000000010000000000000028
LOG:  restored log file "000000010000000000000028" 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-05-11T18:25:37.512467-00 pid=935
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:37.858010-00 pid=935 action=wal-fetch key=s3://kents-database/wal_005/000000010000000000000029.lzo prefix= seg=000000010000000000000029
LOG:  restored log file "000000010000000000000029" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:38.416869-00 pid=961
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:38.578931-00 pid=961 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002A.lzo prefix= seg=00000001000000000000002A
LOG:  restored log file "00000001000000000000002A" 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-05-11T18:25:39.403968-00 pid=971
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:39.583803-00 pid=971 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002B.lzo prefix= seg=00000001000000000000002B
LOG:  restored log file "00000001000000000000002B" 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-05-11T18:25:41.100913-00 pid=992
wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:41.392850-00 pid=992 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002C.lzo prefix= seg=00000001000000000000002C
LOG:  restored log file "00000001000000000000002C" 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-05-11T18:25:42.446989-00 pid=1016
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:42.884920-00 pid=1016 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002D.lzo prefix= seg=00000001000000000000002D
LOG:  restored log file "00000001000000000000002D" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:43.786869-00 pid=1039
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: promoted prefetched wal segment
        STRUCTURED: time=2016-05-11T18:25:44.162999-00 pid=1039 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002E.lzo prefix= seg=00000001000000000000002E
LOG:  restored log file "00000001000000000000002E" 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-05-11T18:25:45.282564-00 pid=1060
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-05-11T18:25:45.552528-00 pid=1060 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002F.lzo prefix= seg=00000001000000000000002F state=begin
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7f07dafd9810>)
        STRUCTURED: time=2016-05-11T18:25:45.656116-00 pid=1060
botocore.credentials INFO     Found credentials in environment variables.
FATAL:  the database system is starting up
.boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': 'wal_005/00000001000000000000002F.lzo'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
FATAL:  the database system is starting up
.wal_e.blobstore.s3.s3_util WARNING  MSG: could no longer locate object while performing wal restore
        DETAIL: The absolute URI that could not be located is s3://kents-database/wal_005/00000001000000000000002F.lzo.
        HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.
        STRUCTURED: time=2016-05-11T18:25:46.989328-00 pid=1060
lzop: <stdin>: not a lzop file
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-05-11T18:25:47.092295-00 pid=1060 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002F.lzo prefix= seg=00000001000000000000002F state=complete
LOG:  redo done at 0/2E0025B0
LOG:  last completed transaction was at log time 2016-05-11 17:58:15.89371+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-05-11T18:25:48.759125-00 pid=1101
FATAL:  the database system is starting up
.wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-05-11T18:25:49.070206-00 pid=1101 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002E.lzo prefix= seg=00000001000000000000002E state=begin
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7f01659a1810>)
        STRUCTURED: time=2016-05-11T18:25:49.173300-00 pid=1101
botocore.credentials INFO     Found credentials in environment variables.
boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': 'wal_005/00000001000000000000002E.lzo'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
FATAL:  the database system is starting up
.wal_e.blobstore.s3.s3_util INFO     MSG: completed download and decompression
        DETAIL: Downloaded and decompressed "s3://kents-database/wal_005/00000001000000000000002E.lzo" to "pg_xlog/RECOVERYXLOG"
        STRUCTURED: time=2016-05-11T18:25:50.674482-00 pid=1101
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-05-11T18:25:50.676542-00 pid=1101 action=wal-fetch key=s3://kents-database/wal_005/00000001000000000000002E.lzo prefix= seg=00000001000000000000002E state=complete
FATAL:  the database system is starting up
.LOG:  restored log file "00000001000000000000002E" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:51.351075-00 pid=1151
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-05-11T18:25:51.770923-00 pid=1151 action=wal-fetch key=s3://kents-database/wal_005/00000002.history.lzo prefix= seg=00000002.history state=begin
wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7f7276e8b7d0>)
        STRUCTURED: time=2016-05-11T18:25:51.880044-00 pid=1151
botocore.credentials INFO     Found credentials in environment variables.
FATAL:  the database system is starting up
.boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': 'wal_005/00000002.history.lzo'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
FATAL:  the database system is starting up
.lzop: <stdin>: not a lzop file
wal_e.blobstore.s3.s3_util WARNING  MSG: could no longer locate object while performing wal restore
        DETAIL: The absolute URI that could not be located is s3://kents-database/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-05-11T18:25:53.066192-00 pid=1151
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-05-11T18:25:53.167801-00 pid=1151 action=wal-fetch key=s3://kents-database/wal_005/00000002.history.lzo prefix= seg=00000002.history state=complete
LOG:  selected new timeline ID: 2
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-05-11T18:25:53.644487-00 pid=1183
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-05-11T18:25:53.920052-00 pid=1183 action=wal-fetch key=s3://kents-database/wal_005/00000001.history.lzo prefix= seg=00000001.history state=begin
FATAL:  the database system is starting up
.wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with creds (<botocore.credentials.Credentials object at 0x7f4c244bb7d0>)
        STRUCTURED: time=2016-05-11T18:25:54.020989-00 pid=1183
botocore.credentials INFO     Found credentials in environment variables.
boto3.resources.action INFO     Calling s3:get_object with {u'Bucket': 'kents-database', u'Key': 'wal_005/00000001.history.lzo'}
botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTPS connection (1): kents-database.s3.amazonaws.com
lzop: <stdin>: not a lzop file
wal_e.blobstore.s3.s3_util WARNING  MSG: could no longer locate object while performing wal restore
        DETAIL: The absolute URI that could not be located is s3://kents-database/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-05-11T18:25:54.844895-00 pid=1183
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-05-11T18:25:54.952383-00 pid=1183 action=wal-fetch key=s3://kents-database/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

/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/004_setup_backup_restore.sh

/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/005_run_backups.sh

waiting for server to shut down...LOG:  received fast shutdown request
.LOG:  aborting any active transactions
LOG:  autovacuum launcher shutting down
LOG:  shutting down
LOG:  database system is shut down
 done
server stopped

PostgreSQL init process complete; ready for start up.

LOG:  database system was shut down at 2016-05-11 18:25:56 UTC
LOG:  MultiXact member wraparound protections are now enabled
LOG:  database system is ready to accept connections
LOG:  autovacuum launcher started

cc @bacongobbler

mboersma commented 8 years ago

Sounds somewhat similar to #94, which we didn't get to the bottom of (yet).

bacongobbler commented 8 years ago

yep. definitely a duplicate of #94. I intend to rewrite the restore process for rc1 via https://github.com/deis/postgres/issues/95. There was no changes made this release, so it's not anything new. @sgoings and @slack are aware of this issue.