1

I am trying to setup Postgres and WAL-E.

So far I have managed to install WAL-E and it appears to be working. I can make backups, WAL logs seem to be sent to S3, great. Here is what S3 looks like:

Root directory:

Root directory

basebackups_005 folder:

basebackups_005 folder

wal_005 folder:

wal_005 folder

As a test, I killed the Postgres instance and spun up another to ensure we were starting with 0 data, just Postgres and WAL-E installed.

I added my S3 credentials, fetched the latest backup from S3, and added a recovery.conf file so that Postgres would replay the WAL segments:

#!/usr/bin/env bash
echo "Fetching latest backup..."
rm -rf /var/lib/postgresql/9.3/main
envdir /etc/wal-e.d/env /usr/local/bin/wal-e backup-fetch /var/lib/postgresql/9.3/main LATEST
chown -R postgres:postgres /var/lib/postgresql/9.3/main
chmod 0700 /var/lib/postgresql/9.3/main

echo "Creating restore file..."
touch /var/lib/postgresql/9.3/main/recovery.conf
RESTORE_COMMAND='/usr/bin/envdir /etc/wal-e.d/env /usr/local/bin/wal-e wal-fetch %f %p'
echo "restore_command = '$RESTORE_COMMAND'" > /var/lib/postgresql/9.3/main/recovery.conf

echo "Backup fetched and restore file created."

Cool. When I restart Postgres, it seems to replay all the files correctly and I'm back in action - great! But now I want to start writing WAL files again from this 2nd instance, just like I did with the 1st instance.

Okay, so I configure WAL logging in postgresql.conf:

#!/usr/bin/env bash
echo "Configuring WAL push to S3..."

echo "wal_level = hot_standby" >> /etc/postgresql/9.3/main/postgresql.conf
echo "archive_mode = yes" >> /etc/postgresql/9.3/main/postgresql.conf
ARCHIVE_COMMAND="archive_command = 'envdir /etc/wal-e.d/env /usr/local/bin/wal-e wal-push %p'"
echo ${ARCHIVE_COMMAND} >> /etc/postgresql/9.3/main/postgresql.conf
echo "archive_timeout = 60" >> /etc/postgresql/9.3/main/postgresql.conf

echo "WAL push to S3 configured."

And restart Postgres. Now, WAL logs are being sent to S3, but they appear to have a different numbering scheme:

New WAL logs after restoring and restarting on the new/2nd instance:

New WAL logs after restart

Notice how there is that 2 number instead of a 1. So I inserted a few rows on the 2nd instance, and then repeated the new-instance-restore-restart process above to ensure the backups on the 2nd instance were working.

Killed the instance and made a new one, setup restoring with WAL-E just like above, etc. Our 3rd instance is now ready to replay the data created and backed up from the first 2 instances.

Here is the problem. The WAL logs are replayed on the 3rd instance up until those logs with the 2 numbers (the logs created by the 2nd instance), and then that's it. It doesn't replay the logs from the 2nd instance. The 3rd instance is restored to the same state as the end of the 1st instance/beginning of 2nd instance. It seems like WAL-E can't figure out that there are those additional WAL files at the end.

Here is the last few lines of logs from /var/log/postgresql/postgresql-9.3-main.log on the 3rd instance:

wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-03-27T19:31:26.410542-00 pid=426
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-03-27T19:31:26.662740-00 pid=426 action=wal-fetch key=s3://pickle-wal/wal_005/000000010000000000000018.lzo prefix= seg=000000010000000000000018 state=begin
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://pickle-wal/wal_005/000000010000000000000018.lzo.
        HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.
        STRUCTURED: time=2016-03-27T19:31:28.268220-00 pid=426
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-03-27T19:31:28.369974-00 pid=426 action=wal-fetch key=s3://pickle-wal/wal_005/000000010000000000000018.lzo prefix= seg=000000010000000000000018 state=complete
2016-03-27 19:31:28 UTC LOG:  redo done at 0/170000C8
2016-03-27 19:31:28 UTC LOG:  last completed transaction was at log time 2016-03-27 16:49:09.568954+00
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-03-27T19:31:29.608778-00 pid=442
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-03-27T19:31:29.827687-00 pid=442 action=wal-fetch key=s3://pickle-wal/wal_005/000000010000000000000017.lzo prefix= seg=000000010000000000000017 state=begin
wal_e.blobstore.s3.s3_util INFO     MSG: completed download and decompression
        DETAIL: Downloaded and decompressed "s3://pickle-wal/wal_005/000000010000000000000017.lzo" to "pg_xlog/RECOVERYXLOG"
        STRUCTURED: time=2016-03-27T19:31:31.850344-00 pid=442
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-03-27T19:31:31.851721-00 pid=442 action=wal-fetch key=s3://pickle-wal/wal_005/000000010000000000000017.lzo prefix= seg=000000010000000000000017 state=complete
2016-03-27 19:31:32 UTC LOG:  restored log file "000000010000000000000017" from archive
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-03-27T19:31:32.979935-00 pid=465
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-03-27T19:31:33.165372-00 pid=465 action=wal-fetch key=s3://pickle-wal/wal_005/00000002.history.lzo prefix= seg=00000002.history state=begin
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://pickle-wal/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-03-27T19:31:34.355366-00 pid=465
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-03-27T19:31:34.457207-00 pid=465 action=wal-fetch key=s3://pickle-wal/wal_005/00000002.history.lzo prefix= seg=00000002.history state=complete
2016-03-27 19:31:34 UTC LOG:  selected new timeline ID: 2
wal_e.main   INFO     MSG: starting WAL-E
        DETAIL: The subcommand is "wal-fetch".
        STRUCTURED: time=2016-03-27T19:31:35.207091-00 pid=483
wal_e.operator.backup INFO     MSG: begin wal restore
        STRUCTURED: time=2016-03-27T19:31:35.322521-00 pid=483 action=wal-fetch key=s3://pickle-wal/wal_005/00000001.history.lzo prefix= seg=00000001.history state=begin
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://pickle-wal/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-03-27T19:31:36.228126-00 pid=483
wal_e.operator.backup INFO     MSG: complete wal restore
        STRUCTURED: time=2016-03-27T19:31:36.329787-00 pid=483 action=wal-fetch key=s3://pickle-wal/wal_005/00000001.history.lzo prefix= seg=00000001.history state=complete
2016-03-27 19:31:36 UTC LOG:  archive recovery complete
2016-03-27 19:31:36 UTC LOG:  MultiXact member wraparound protections are now enabled
2016-03-27 19:31:36 UTC LOG:  database system is ready to accept connections
2016-03-27 19:31:36 UTC LOG:  autovacuum launcher started

I have tried multiple times and gotten the same result. It's really frustrating, and I can't seem to find other people having the same sort of problems.

Does anyone have an idea as to what I'm doing wrong?

1

The different numbers you see are log timeline IDs. When you had completed recovery of you database for the first time, a new log timeline started with ID 2.

However, when you again restore a backup, now into the third database, only logs from timeline 1 (the one that was active when the backup was taken) will be used for recovery by default. To use logs from timeline 2 you will probably need to add recovery_target_timeline = latest to recovery.conf. Alternatively, after completing recovery you may choose to take a fresh backup to establish a new recovery baseline.

  • Brilliant. That recovery_target_timeline = latest did the job perfectly - thank you so much. – dcgoss Mar 30 '16 at 1:15
  • One thing I noticed, for future reference: the existence of the .history files in S3 is essential for a correct restore. In order for the .history files to be archived/uploaded to S3, the archive/WAL logging settings in postgresql.conf (wal_level, archive_mode, archive_command, etc) must be configured prior to restoring the WAL files. After Postgres restores the WAL files, it starts the database and then uploads the .history files. The order is important - configuring archiving after restoring doesn't seem to result in uploading the .history files. – dcgoss Mar 30 '16 at 1:20

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.