How does WAL-E backup-fetch work ...

[Matt Wise]

I haven't seen a lot of documentation on this.. if I take a fresh box and run WAL-E backup-fetch, what is the expected behavior. Does it just pull down the base-backup and end? Should it also pull down the rest of the WAL logs to pg_xlog? Should it create the recovery.conf that tells Postgres how to get the rest of the WAL logs? It seems unclear.

—Matt

[Cody Caughlan]

Yeah I agree the documentation in this department could use some love.

This Gist contains the documentation that I have put together on our internal Wiki.

Let me know if you have any questions or it needs clarification.

https://gist.github.com/2293434

Cheers
/Cody

[Cody Caughlan]

Sorry if my Gist doesn't give you exact answers to your questions. Let me try again.

> if I take a fresh box and run WAL-E backup-fetch, what is the expected behavior.

By running

envdir /etc/wal-e.d/env wal-e backup-fetch $PGDATA LATEST

and assuming $PGDATA is set to something like

/data/postgresql/9.1/main/

Then backup-fetch will put the latest base backup and write it and its sub-directory structure to $PGDATA.

>Should it also pull down the rest of the WAL logs to pg_xlog

No it doesn't do this. This is done by WAL-E during the recovery phase. So you pull down the base backup to $PGDATA and then implement a $PGDATA/recovery.conf (see my gist) and then when you start up PG and it goes into recovery mode it then starts pulling down WAL segments and applying them.

> Should it create the recovery.conf

WAL-E right now doesn't create recovery.conf, you will need to do this manually.

Hope this helps.

Gist: https://gist.github.com/2293434

/Cody

On Apr 2, 2012, at 8:05 AM, Matt Wise wrote:

[Matt Wise]

Thanks for the details, I think I was on the right page then... The bad news is that I've tried two restores now and both have failed. The first one failed I think due to corrupt WAL logs. The second failure was less clear. I'm re-running the restore again, and this time if it fails I'll send out logs of the failure. I'm concerned that we're not getting accurate files from our master-DB up to S3... or that the downloads are having problems. I see random SSL problems rather consistently in the download.

(Will send logs of the download errors as soon as I have one... 2 hours or less)

—Matt

[Matt Wise]

A bit more followup... Digging around I see other people have had similar problems using pg_lesslog and LZOP for compression:

http://forums.postgresql.com.au/viewtopic.php?f=30&t=67482#p290574

Another possible issue is that we had fsync=off and full_page_writes=off. I've enabled these, and am doing a full new backup. Is it possible that with these settings off, the WAL logs were corrupt/incomplete?

—Matt

On Apr 4, 2012, at 7:26 AM, Matt Wise wrote:

Followup... Here are the errors I ran into starting up postgres after the initial backup fetch:

2012-04-04 06:11:35.260 GMT,,,3206,,4f7be617.c86,1,,2012-04-04 06:11:35 GMT,,0,LOG,00000,"database system was interrupted; last known up at 2012-04-03 08:44:08 GMT",,,,,,,,,""

2012-04-04 06:11:35.260 GMT,,,3206,,4f7be617.c86,2,,2012-04-04 06:11:35 GMT,,0,LOG,00000,"creating missing WAL directory ""pg_xlog/archive_status""",,,,,,,,,""

2012-04-04 06:11:35.500 GMT,,,3206,,4f7be617.c86,3,,2012-04-04 06:11:35 GMT,,0,LOG,00000,"starting archive recovery",,,,,,,,,""

2012-04-04 06:11:37.879 GMT,,,3206,,4f7be617.c86,4,,2012-04-04 06:11:35 GMT,,0,LOG,00000,"restored log file ""00000002000001E100000017"" from archive",,,,,,,,,""

2012-04-04 06:11:37.889 GMT,,,3206,,4f7be617.c86,5,,2012-04-04 06:11:35 GMT,1/0,0,LOG,00000,"consistent recovery state reached at 1E1/171F4748",,,,,,,,,""

2012-04-04 06:11:37.889 GMT,,,3206,,4f7be617.c86,6,,2012-04-04 06:11:35 GMT,1/0,0,LOG,00000,"redo starts at 1E1/171BB888",,,,,,,,,""

2012-04-04 06:11:37.940 GMT,,,3204,,4f7be608.c84,1,,2012-04-04 06:11:20 GMT,,0,LOG,00000,"database system is ready to accept read only connections",,,,,,,,,""

2012-04-04 06:11:40.445 GMT,,,3206,,4f7be617.c86,7,,2012-04-04 06:11:35 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E100000018"" from archive",,,,,,,,,""

2012-04-04 06:11:43.714 GMT,,,3206,,4f7be617.c86,8,,2012-04-04 06:11:35 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E100000019"" from archive",,,,,,,,,""

2012-04-04 06:11:43.859 GMT,,,3206,,4f7be617.c86,9,,2012-04-04 06:11:35 GMT,1/0,0,WARNING,01000,"specified item offset is too large",,,,,"xlog redo insert: rel 1663/23661/2329081; tid 547/401",,,,""

2012-04-04 06:11:43.859 GMT,,,3206,,4f7be617.c86,10,,2012-04-04 06:11:35 GMT,1/0,0,PANIC,XX000,"btree_insert_redo: failed to add item",,,,,"xlog redo insert: rel 1663/23661/2329081; tid 547/401",,,,""

2012-04-04 06:11:43.862 GMT,,,3204,,4f7be608.c84,2,,2012-04-04 06:11:20 GMT,,0,LOG,00000,"startup process (PID 3206) was terminated by signal 6: Aborted",,,,,,,,,""

2012-04-04 06:11:43.862 GMT,,,3204,,4f7be608.c84,3,,2012-04-04 06:11:20 GMT,,0,LOG,00000,"terminating any other active server processes",,,,,,,,,""

2012-04-04T06:11:35.486+00 pid=3209 wal_e.worker.s3_worker INFO     MSG: could not locate object while performing wal restore

        DETAIL: The absolute URI that could not be located is s3://xyz/uswest1-wal-logs/wal_005/00000002.history.lzo.

        HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.

2012-04-04T06:11:37.863+00 pid=3213 wal_e.worker.s3_worker INFO     MSG: completed download and decompression

        DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E100000017.lzo" to "pg_xlog/RECOVERYXLOG"

2012-04-04T06:11:40.428+00 pid=3220 wal_e.worker.s3_worker INFO     MSG: completed download and decompression

        DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E100000018.lzo" to "pg_xlog/RECOVERYXLOG"

2012-04-04T06:11:43.697+00 pid=3225 wal_e.worker.s3_worker INFO     MSG: completed download and decompression

        DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E100000019.lzo" to "pg_xlog/RECOVERYXLOG"

Our restored DB size is around 400GB, so the process takes a while.. ~3-4 hours. Its difficult to troubleshoot. There is plenty of disk space though, and this time I saw no indications of a failed download. Any thoughts?

—Matt

[Daniel Farina]

On Wed, Apr 4, 2012 at 9:04 AM, Matt Wise <ma...@nextdoor.com> wrote:
> A bit more followup... Digging around I see other people have had similar
> problems using pg_lesslog and LZOP for compression:
>
> http://forums.postgresql.com.au/viewtopic.php?f=30&t=67482#p290574
>
>
> Another possible issue is that we had fsync=off and full_page_writes=off.
> I've enabled these, and am doing a full new backup. Is it possible that with
> these settings off, the WAL logs were corrupt/incomplete?

Hmm. That should only affect things when there is a crash. If you
were willing to, say, never engage in crash recovery after an OS
lockup or power outage then turning off fsync has no effect.

full page writes are forced to 'on' for a while when start_backup is called.

Are you using multiple/non-default tablespaces?

Also, are you absolutely sure your servers have unique prefixes, so
that there is no chance of WAL-overwrite? (I'm not even sure what that
looks like, I just hear it can lead to incredible confusion, so I
designed wal-e to make that pretty difficult to do)

--
fdr

[Matt Wise]

We have 4 DB servers... for simplicity-sake lets call them DB1,DB2,DB3 and DB4. DB1 is the master, DB2/3/4 are all slaves. They all have the WAL-E archive_command set, but since DB2/3/4 are slaves, they do not ever call that command. I'm trying a full backup-push again after turning fsync and full_page_writes on, but as you said .. it shouldnt make any difference.

Any other ideas?

—Matt

[Daniel Farina]

On Wed, Apr 4, 2012 at 10:20 AM, Matt Wise <ma...@nextdoor.com> wrote:
> We have 4 DB servers... for simplicity-sake lets call them DB1,DB2,DB3 and DB4. DB1 is the master, DB2/3/4 are all slaves. They all have the WAL-E archive_command set,  but since DB2/3/4 are slaves, they do not ever call that command. I'm trying a full backup-push again after turning fsync and full_page_writes on, but as you said .. it shouldnt make any difference.

An archive command is fine, just make sure that the wal-e prefix is
never set to be the same; I suggest making them unique for all-time.

Have you tried on a smaller database so you can work this out without
waiting for such a large backup?

Are you using extra tablespaces?

--
fdr

[Daniel Farina]

Here's another one, and one that is rectifiable with some programming:

Is your default PG (if you type "psql") the one that you want to back
up? (specified via path?) If there is a mismatch, then this could
result.

--
fdr

[Matt Wise]

Thats interesting, ours is not in the default path. Its in /opt/postgresql-9.1/bin/psql. There is not a 'psql' binary installed on the system anywhere else though.

root@prod-db1-uswest1-i-dd88819a:/mnt/pgdata/pg_log# which psql

root@prod-db1-uswest1-i-dd88819a:/mnt/pgdata/pg_log# /opt/postgresql-9.1/bin/psql 

psql: FATAL:  role "root" does not exist

root@prod-db1-uswest1-i-dd88819a:/mnt/pgdata/pg_log# 

—Matt

[Daniel Farina]

On Wed, Apr 4, 2012 at 10:32 AM, Matt Wise <ma...@nextdoor.com> wrote:
> Thats interesting, ours is not in the default path. Its in
> /opt/postgresql-9.1/bin/psql. There is not a 'psql' binary installed on the
> system anywhere else though.

Hmm. The path is not so much the issue, as issuing the commands
pg_start_backup/stop_backup against the wrong cluster, then copying
some unrelated cluster (which was not ready to be backed-up).

That would be https://github.com/heroku/WAL-E/issues/14 , but I'm not
sure if this is your issue. Are you running things on a non-default
port, for example? wal-e just execs psql, so it is sensitive to
PGHOST/PGPORT et al environment variables.

--
fdr

[Matt Wise]

I did just confirm that when the wal_e code runs, it brings in a path that includes the psql binary properly. Otherwise, it probably wouldn't work at all.

Are there any known issues with different Boto versions? I saw at one point that Boto 2.2.2 was not handled well. I was running this with 2.2.1 originally, though I'm now testing with 2.3.0.

—Matt

[Matt Wise]

Looking at the logs, it looks like its reaching the DB properly:

> postgresql-2012-04-04_045018.csv:Query Text: COPY (SELECT file_name, lpad(file_offset::text, 8, '0') AS file_offset FROM pg_xlogfile_name_offset( pg_start_backup('freeze_start_2012-04-04T05:00:01.692962+00:00'))) TO STDOUT WITH CSV HEADER;
> postgresql-2012-04-04_045018.csv:2012-04-04 05:03:29.310 GMT,"postgres","postgres",7824,"[local]",4f7bd551.1e90,2,"COPY",2012-04-04 05:00:01 GMT,184/0,0,LOG,00000,"duration: 207603.477 ms statement: COPY (SELECT file_name, lpad(file_offset::text, 8, '0') AS file_offset FROM pg_xlogfile_name_offset( pg_start_backup('freeze_start_2012-04-04T05:00:01.692962+00:00'))) TO STDOUT WITH CSV HEADER;",,,,,,,,,"psql"
> postgresql-2012-04-04_045018.csv:Query Text: COPY (SELECT file_name, lpad(file_offset::text, 8, '0') AS file_offset FROM pg_xlogfile_name_offset( pg_stop_backup())) TO STDOUT WITH CSV HEADER;

Right?

[Daniel Farina]

On Wed, Apr 4, 2012 at 10:47 AM, Matt Wise <ma...@nextdoor.com> wrote:
> Looking at the logs, it looks like its reaching the DB properly:

mmm yeah, and I imagine you picked the right directory to back up
(which here would be the same one with your logs, /mnt/pgdata, I
presume). A quick way to find out for sure is to psql into the
database of choice and write:

select current_setting('data_directory');

(This just looks things up in the pg_settings catalog table, which is
a really useful one...)

There are no more known issues after boto 2.2.2, but 2.3 is so new
that that's not saying much. In 2.2.2 we had to do was rewind a file
descriptor before submitting it to boto (I'm a little bit shocked they
changed that behavior in a point release, even if the new behavior is
better, I'd think it could break everyone using temp files).

You could try to regress the boto version and see-what-happens, the
latest point release of wal-e is known to work with 2.2.2, at least.
I am, however, a little bit skeptical because I'd think lzop would get
angry about corrupted compressed files.

What's also bizarre is that handful of WAL (okay, maybe one or two
segments) replayed fine. Is there any possibility you are mismatching
operating systems or architectures? ex, a m1.small (which is 32bit)
with a m1.large (64)? I unfortunately don't know the exact boundaries
of error checks that WAL replay makes to prevent errors like that,
whether they are cryptic or fit-to-purpose.

--
fdr

[Matt Wise]

Another backup and restore, and another fail.. :/

> 2012-04-05 04:20:59.023 GMT,,,15039,,4f7d1dab.3abf,1,,2012-04-05 04:20:59 GMT,,0,LOG,00000,"database system was interrupted while in recovery at log time 2012-04-04 19:25:54 GMT",,"If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.",,,,,,,""
> 2012-04-05 04:20:59.242 GMT,,,15039,,4f7d1dab.3abf,2,,2012-04-05 04:20:59 GMT,,0,LOG,00000,"starting archive recovery",,,,,,,,,""
> 2012-04-05 04:21:03.252 GMT,,,15039,,4f7d1dab.3abf,3,,2012-04-05 04:20:59 GMT,,0,LOG,00000,"restored log file ""00000002000001E1000000B8"" from archive",,,,,,,,,""
> 2012-04-05 04:21:03.259 GMT,,,15039,,4f7d1dab.3abf,4,,2012-04-05 04:20:59 GMT,1/0,0,LOG,00000,"consistent recovery state reached at 1E1/B8C6D240",,,,,,,,,""
> 2012-04-05 04:21:03.259 GMT,,,15039,,4f7d1dab.3abf,5,,2012-04-05 04:20:59 GMT,1/0,0,LOG,00000,"redo starts at 1E1/B86A1320",,,,,,,,,""
> 2012-04-05 04:21:03.259 GMT,,,15039,,4f7d1dab.3abf,6,,2012-04-05 04:20:59 GMT,1/0,0,FATAL,XX000,"could not access status of transaction 290886488","Could not read from file ""pg_clog/0115"" at offset 106496: Success.",,,,"xlog redo commit: 2012-04-04 19:25:54.571453+00; subxacts: 290886489 290886490 290886491",,,,""
> 2012-04-05 04:21:03.260 GMT,,,15037,,4f7d1da9.3abd,1,,2012-04-05 04:20:57 GMT,,0,LOG,00000,"startup process (PID 15039) exited with exit code 1",,,,,,,,,""
> 2012-04-05 04:21:03.260 GMT,,,15037,,4f7d1da9.3abd,2,,2012-04-05 04:20:57 GMT,,0,LOG,00000,"terminating any other active server processes",,,,,,,,,""

> 2012-04-05T04:20:59.227+00 pid=15042 wal_e.worker.s3_worker INFO MSG: could not locate object while performing wal restore

> DETAIL: The absolute URI that could not be located is s3://xyz/uswest1-wal-logs/wal_005/00000002.history.lzo.
> HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.

> 2012-04-05T04:21:03.233+00 pid=15046 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E1000000B8.lzo" to "pg_xlog/RECOVERYXLOG"

:/

—Matt

[Daniel Farina]

On Wed, Apr 4, 2012 at 9:23 PM, Matt Wise <ma...@nextdoor.com> wrote:
> Another backup and restore, and another fail.. :/

What version of Postgres? That particular message was tracked down as
a bug, fixed in 9.0.7/9.1.3.

--
fdr

[Matt Wise]

Interesting.. that was backed-up from 9.1.2, and restored on 9.1.3. I'm actually doing a re-fetch now on a 9.1.2 server to see if that fixes it. Is it possible that we need to get to 9.1.3 on our backup-push server first?

[Daniel Farina]

On Thu, Apr 5, 2012 at 10:57 AM, Matt Wise <ma...@nextdoor.com> wrote:
> Interesting.. that was backed-up from 9.1.2, and restored on 9.1.3. I'm actually doing a re-fetch now on a 9.1.2 server to see if that fixes it. Is it possible that we need to get to 9.1.3 on our backup-push server first?

Ah, no, it should only matter on the recovering side for that bug, not
the source-side, and point releases are binary compatible as a rule --
given the project's maintenance policy, one should use the new ones
whenever possible. However, the WAL stream is neither operating
system nor architecture dependent.

Okay, if you are absolutely sure that no wires are crossed (because
these kinds of error message can result from backing up a database
that is not the one that wal-e runs "pg_start_backup" and
"pg_stop_backup" with, then it's time to start hauling out some system
information and dependency numbers, such as:

* OS and version
* uname -a
* Python version
* Boto version
* gevent version

If you want to express paranoia about connecting to the proper
database, you can try setting PGHOST/PGPORT et al environment
variables to ensure you are connecting to the right database, instead
of relying on the default that is burned into libpq at compile time.

Are you running multiple databases per machine? If you are using, say,
debian, you may have a little vestigial "main" cluster that could be
eating the start/stop backup.

--
fdr

[Matt Wise]

I'll be damned... downgrading to Postgresql 9.1.2 seems to have worked. I know it shouldn't have, but it did. Check out this log, everything worked perfectly:

> 2012-04-05 21:29:54.352 GMT,,,10244,,4f7e0ed2.2804,1,,2012-04-05 21:29:54 GMT,,0,LOG,00000,"database system was interrupted; last known up at 2012-04-05 08:00:52 GMT",,,,,,,,,""
> 2012-04-05 21:29:54.353 GMT,,,10244,,4f7e0ed2.2804,2,,2012-04-05 21:29:54 GMT,,0,LOG,00000,"creating missing WAL directory ""pg_xlog/archive_status""",,,,,,,,,""
> 2012-04-05 21:29:55.322 GMT,,,10244,,4f7e0ed2.2804,3,,2012-04-05 21:29:54 GMT,,0,LOG,00000,"starting archive recovery",,,,,,,,,""
> 2012-04-05 21:29:58.551 GMT,,,10244,,4f7e0ed2.2804,4,,2012-04-05 21:29:54 GMT,,0,LOG,00000,"restored log file ""00000002000001E200000027"" from archive",,,,,,,,,""
> 2012-04-05 21:29:58.558 GMT,,,10244,,4f7e0ed2.2804,5,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"consistent recovery state reached at 1E2/27029510",,,,,,,,,""
> 2012-04-05 21:29:58.558 GMT,,,10244,,4f7e0ed2.2804,6,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"redo starts at 1E2/270000C0",,,,,,,,,""
> 2012-04-05 21:29:58.612 GMT,,,10242,,4f7e0ecf.2802,1,,2012-04-05 21:29:51 GMT,,0,LOG,00000,"database system is ready to accept read only connections",,,,,,,,,""
> 2012-04-05 21:30:01.428 GMT,,,10244,,4f7e0ed2.2804,7,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000028"" from archive",,,,,,,,,""
> 2012-04-05 21:30:04.294 GMT,,,10244,,4f7e0ed2.2804,8,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000029"" from archive",,,,,,,,,""
> 2012-04-05 21:30:07.667 GMT,,,10244,,4f7e0ed2.2804,9,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000002A"" from archive",,,,,,,,,""
> 2012-04-05 21:30:08.506 GMT,,,10244,,4f7e0ed2.2804,10,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000002B"" from archive",,,,,,,,,""
> 2012-04-05 21:30:12.531 GMT,,,10244,,4f7e0ed2.2804,11,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000002C"" from archive",,,,,,,,,""
> 2012-04-05 21:30:15.615 GMT,,,10244,,4f7e0ed2.2804,12,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000002D"" from archive",,,,,,,,,""
> 2012-04-05 21:30:18.794 GMT,,,10244,,4f7e0ed2.2804,13,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000002E"" from archive",,,,,,,,,""
> 2012-04-05 21:30:21.253 GMT,,,10244,,4f7e0ed2.2804,14,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000002F"" from archive",,,,,,,,,""
> 2012-04-05 21:30:23.514 GMT,,,10244,,4f7e0ed2.2804,15,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000030"" from archive",,,,,,,,,""
> 2012-04-05 21:30:25.731 GMT,,,10244,,4f7e0ed2.2804,16,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000031"" from archive",,,,,,,,,""
> 2012-04-05 21:30:27.969 GMT,,,10244,,4f7e0ed2.2804,17,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000032"" from archive",,,,,,,,,""
> 2012-04-05 21:30:30.681 GMT,,,10244,,4f7e0ed2.2804,18,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000033"" from archive",,,,,,,,,""
> 2012-04-05 21:30:32.763 GMT,,,10244,,4f7e0ed2.2804,19,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000034"" from archive",,,,,,,,,""
> 2012-04-05 21:30:35.490 GMT,,,10244,,4f7e0ed2.2804,20,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000035"" from archive",,,,,,,,,""
> 2012-04-05 21:30:38.677 GMT,,,10244,,4f7e0ed2.2804,21,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000036"" from archive",,,,,,,,,""
> 2012-04-05 21:30:42.865 GMT,,,10244,,4f7e0ed2.2804,22,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000037"" from archive",,,,,,,,,""
> 2012-04-05 21:30:45.429 GMT,,,10244,,4f7e0ed2.2804,23,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000038"" from archive",,,,,,,,,""
> 2012-04-05 21:30:48.994 GMT,,,10244,,4f7e0ed2.2804,24,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000039"" from archive",,,,,,,,,""
> 2012-04-05 21:30:51.454 GMT,,,10244,,4f7e0ed2.2804,25,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000003A"" from archive",,,,,,,,,""
> 2012-04-05 21:30:52.058 GMT,,,10244,,4f7e0ed2.2804,26,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000003B"" from archive",,,,,,,,,""
> 2012-04-05 21:30:52.673 GMT,,,10244,,4f7e0ed2.2804,27,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000003C"" from archive",,,,,,,,,""
> 2012-04-05 21:30:53.347 GMT,,,10244,,4f7e0ed2.2804,28,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000003D"" from archive",,,,,,,,,""
> 2012-04-05 21:30:54.037 GMT,,,10244,,4f7e0ed2.2804,29,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000003E"" from archive",,,,,,,,,""
> 2012-04-05 21:30:54.687 GMT,,,10244,,4f7e0ed2.2804,30,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000003F"" from archive",,,,,,,,,""
> 2012-04-05 21:30:55.737 GMT,,,10244,,4f7e0ed2.2804,31,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000040"" from archive",,,,,,,,,""
> 2012-04-05 21:30:56.716 GMT,,,10244,,4f7e0ed2.2804,32,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000041"" from archive",,,,,,,,,""
> 2012-04-05 21:31:00.789 GMT,,,10244,,4f7e0ed2.2804,33,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000042"" from archive",,,,,,,,,""
> 2012-04-05 21:31:05.872 GMT,,,10244,,4f7e0ed2.2804,34,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000043"" from archive",,,,,,,,,""
> 2012-04-05 21:31:10.431 GMT,,,10244,,4f7e0ed2.2804,35,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000044"" from archive",,,,,,,,,""
> 2012-04-05 21:31:14.253 GMT,,,10244,,4f7e0ed2.2804,36,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000045"" from archive",,,,,,,,,""
> 2012-04-05 21:31:14.959 GMT,,,10244,,4f7e0ed2.2804,37,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000046"" from archive",,,,,,,,,""
> 2012-04-05 21:31:15.618 GMT,,,10244,,4f7e0ed2.2804,38,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000047"" from archive",,,,,,,,,""
> 2012-04-05 21:31:16.267 GMT,,,10244,,4f7e0ed2.2804,39,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000048"" from archive",,,,,,,,,""
> 2012-04-05 21:31:16.932 GMT,,,10244,,4f7e0ed2.2804,40,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000049"" from archive",,,,,,,,,""
> 2012-04-05 21:31:17.705 GMT,,,10244,,4f7e0ed2.2804,41,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000004A"" from archive",,,,,,,,,""
> 2012-04-05 21:31:18.518 GMT,,,10244,,4f7e0ed2.2804,42,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000004B"" from archive",,,,,,,,,""
> 2012-04-05 21:31:23.840 GMT,,,10244,,4f7e0ed2.2804,43,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000004C"" from archive",,,,,,,,,""
> 2012-04-05 21:31:27.157 GMT,,,10244,,4f7e0ed2.2804,44,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000004D"" from archive",,,,,,,,,""
> 2012-04-05 21:31:30.718 GMT,,,10244,,4f7e0ed2.2804,45,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000004E"" from archive",,,,,,,,,""
> 2012-04-05 21:31:34.076 GMT,,,10244,,4f7e0ed2.2804,46,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000004F"" from archive",,,,,,,,,""
> 2012-04-05 21:31:38.063 GMT,,,10244,,4f7e0ed2.2804,47,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000050"" from archive",,,,,,,,,""
> 2012-04-05 21:31:54.395 GMT,,,10244,,4f7e0ed2.2804,48,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000051"" from archive",,,,,,,,,""
> 2012-04-05 21:31:56.861 GMT,,,10244,,4f7e0ed2.2804,49,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000052"" from archive",,,,,,,,,""
> 2012-04-05 21:32:00.108 GMT,,,10244,,4f7e0ed2.2804,50,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000053"" from archive",,,,,,,,,""
> 2012-04-05 21:32:03.333 GMT,,,10244,,4f7e0ed2.2804,51,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000054"" from archive",,,,,,,,,""
> 2012-04-05 21:32:06.308 GMT,,,10244,,4f7e0ed2.2804,52,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000055"" from archive",,,,,,,,,""
> 2012-04-05 21:32:09.427 GMT,,,10244,,4f7e0ed2.2804,53,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000056"" from archive",,,,,,,,,""
> 2012-04-05 21:32:12.513 GMT,,,10244,,4f7e0ed2.2804,54,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000057"" from archive",,,,,,,,,""
> 2012-04-05 21:32:16.885 GMT,,,10244,,4f7e0ed2.2804,55,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000058"" from archive",,,,,,,,,""
> 2012-04-05 21:32:19.756 GMT,,,10244,,4f7e0ed2.2804,56,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000059"" from archive",,,,,,,,,""
> 2012-04-05 21:32:35.944 GMT,,,10244,,4f7e0ed2.2804,57,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000005A"" from archive",,,,,,,,,""
> 2012-04-05 21:32:36.732 GMT,,,10244,,4f7e0ed2.2804,58,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000005B"" from archive",,,,,,,,,""
> 2012-04-05 21:32:38.494 GMT,,,10244,,4f7e0ed2.2804,59,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000005C"" from archive",,,,,,,,,""
> 2012-04-05 21:32:39.270 GMT,,,10244,,4f7e0ed2.2804,60,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000005D"" from archive",,,,,,,,,""
> 2012-04-05 21:32:43.123 GMT,,,10244,,4f7e0ed2.2804,61,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000005E"" from archive",,,,,,,,,""
> 2012-04-05 21:32:47.472 GMT,,,10244,,4f7e0ed2.2804,62,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E20000005F"" from archive",,,,,,,,,""
> 2012-04-05 21:32:51.459 GMT,,,10244,,4f7e0ed2.2804,63,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000060"" from archive",,,,,,,,,""
> 2012-04-05 21:32:55.971 GMT,,,10244,,4f7e0ed2.2804,64,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000061"" from archive",,,,,,,,,""
> 2012-04-05 21:32:59.871 GMT,,,10244,,4f7e0ed2.2804,65,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000062"" from archive",,,,,,,,,""
> 2012-04-05 21:33:03.800 GMT,,,10244,,4f7e0ed2.2804,66,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000063"" from archive",,,,,,,,,""
> 2012-04-05 21:33:13.377 GMT,,,10244,,4f7e0ed2.2804,67,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000064"" from archive",,,,,,,,,""
> 2012-04-05 21:33:13.863 GMT,,,10244,,4f7e0ed2.2804,68,,2012-04-05 21:29:54 GMT,1/0,0,LOG,58P01,"could not open file ""pg_xlog/00000002000001E200000065"" (log file 482, segment 101): No such file or directory",,,,,,,,,""
> 2012-04-05 21:33:13.863 GMT,,,10244,,4f7e0ed2.2804,69,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"redo done at 1E2/64FF2FF8",,,,,,,,,""
> 2012-04-05 21:33:13.863 GMT,,,10244,,4f7e0ed2.2804,70,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"last completed transaction was at log time 2012-04-05 21:30:01.031707+00",,,,,,,,,""
> 2012-04-05 21:33:18.274 GMT,,,10244,,4f7e0ed2.2804,71,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"restored log file ""00000002000001E200000064"" from archive",,,,,,,,,""
> 2012-04-05 21:33:18.457 GMT,,,10244,,4f7e0ed2.2804,72,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"selected new timeline ID: 3",,,,,,,,,""
> 2012-04-05 21:33:18.657 GMT,,,10244,,4f7e0ed2.2804,73,,2012-04-05 21:29:54 GMT,1/0,0,LOG,00000,"archive recovery complete",,,,,,,,,""
> 2012-04-05 21:33:18.661 GMT,,,10254,,4f7e0ed6.280e,1,,2012-04-05 21:29:58 GMT,,0,LOG,00000,"checkpoint starting: end-of-recovery immediate wait",,,,,,,,,""
> 2012-04-05 21:33:33.656 GMT,,,10254,,4f7e0ed6.280e,2,,2012-04-05 21:29:58 GMT,,0,LOG,00000,"checkpoint complete: wrote 65652 buffers (5.9%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=1.000 s, sync=13
> .815 s, total=14.999 s; sync files=617, longest=1.674 s, average=0.022 s",,,,,,,,,""
> 2012-04-05 21:33:33.836 GMT,,,10242,,4f7e0ecf.2802,2,,2012-04-05 21:29:51 GMT,,0,LOG,00000,"database system is ready to accept connections",,,,,,,,,""
> 2012-04-05 21:53:18.002 GMT,,,10254,,4f7e0ed6.280e,3,,2012-04-05 21:29:58 GMT,,0,LOG,00000,"checkpoint starting: time",,,,,,,,,""
> 2012-04-05 21:53:18.205 GMT,,,10254,,4f7e0ed6.280e,4,,2012-04-05 21:29:58 GMT,,0,LOG,00000,"checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.011 s, sync=0.000
> s, total=0.202 s; sync files=0, longest=0.000 s, average=0.000 s",,,,,,,,,""
> 2012-04-05 22:03:18.010 GMT,,,10254,,4f7e0ed6.280e,5,,2012-04-05 21:29:58 GMT,,0,LOG,00000,"checkpoint starting: time",,,,,,,,,""
> 2012-04-05 22:03:18.034 GMT,,,10254,,4f7e0ed6.280e,6,,2012-04-05 21:29:58 GMT,,0,LOG,00000,"checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.011 s, sync=0.000
> s, total=0.023 s; sync files=0, longest=0.000 s, average=0.000 s",,,,,,,,,""
> 2012-04-05T21:29:55.305+00 pid=10247 wal_e.worker.s3_worker INFO MSG: could not locate object while performing wal restore

> DETAIL: The absolute URI that could not be located is s3://xyz/uswest1-wal-logs/wal_005/00000002.history.lzo.
> HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.

> 2012-04-05T21:29:58.534+00 pid=10251 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000027.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:01.407+00 pid=10258 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000028.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:04.276+00 pid=10263 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000029.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:07.650+00 pid=10268 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000002A.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:08.489+00 pid=10273 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000002B.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:12.514+00 pid=10278 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000002C.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:15.598+00 pid=10283 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000002D.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:18.776+00 pid=10288 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000002E.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:21.236+00 pid=10293 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wall_005/00000002000001E20000002F.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:23.495+00 pid=10298 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000030.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:25.715+00 pid=10303 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000031.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:27.953+00 pid=10308 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000032.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:30.662+00 pid=10313 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000033.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:32.747+00 pid=10318 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000034.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:35.469+00 pid=10323 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000035.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:38.660+00 pid=10328 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000036.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:42.848+00 pid=10333 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000037.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:45.408+00 pid=10338 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000038.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:48.975+00 pid=10343 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000039.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:51.434+00 pid=10348 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000003A.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:52.040+00 pid=10353 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000003B.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:52.657+00 pid=10358 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000003C.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:53.328+00 pid=10363 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000003D.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:54.021+00 pid=10368 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000003E.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:54.668+00 pid=10373 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000003F.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:55.718+00 pid=10378 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000040.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:30:56.698+00 pid=10383 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000041.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:00.766+00 pid=10388 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000042.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:05.855+00 pid=10393 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000043.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:10.413+00 pid=10398 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000044.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:14.233+00 pid=10403 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000045.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:14.939+00 pid=10408 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000046.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:15.600+00 pid=10413 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000047.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:16.250+00 pid=10418 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000048.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:16.914+00 pid=10423 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000049.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:17.688+00 pid=10428 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000004A.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:18.502+00 pid=10433 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000004B.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:23.820+00 pid=10438 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000004C.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:27.140+00 pid=10443 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000004D.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:30.701+00 pid=10448 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000004E.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:34.060+00 pid=10453 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000004F.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:38.046+00 pid=10458 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000050.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:54.375+00 pid=10463 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000051.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:31:56.842+00 pid=10468 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000052.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:00.090+00 pid=10473 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000053.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:03.315+00 pid=10478 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000054.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:06.289+00 pid=10483 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000055.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:09.409+00 pid=10488 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000056.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:12.496+00 pid=10493 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000057.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:16.866+00 pid=10498 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000058.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:19.739+00 pid=10503 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000059.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:35.926+00 pid=10508 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000005A.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:36.709+00 pid=10513 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000005B.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:38.476+00 pid=10518 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000005C.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:39.251+00 pid=10523 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000005D.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:43.105+00 pid=10528 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000005E.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:47.452+00 pid=10533 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E20000005F.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:51.442+00 pid=10538 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000060.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:55.953+00 pid=10543 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000061.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:32:59.852+00 pid=10548 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000062.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:33:03.781+00 pid=10553 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000063.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:33:13.357+00 pid=10558 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000064.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:33:13.848+00 pid=10563 wal_e.worker.s3_worker INFO MSG: could not locate object while performing wal restore
> DETAIL: The absolute URI that could not be located is s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000065.lzo.

> HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.

> 2012-04-05T21:33:18.256+00 pid=10567 wal_e.worker.s3_worker INFO MSG: completed download and decompression
> DETAIL: Downloaded and decompressed "s3://xyz/uswest1-wal-logs/wal_005/00000002000001E200000064.lzo" to "pg_xlog/RECOVERYXLOG"
> 2012-04-05T21:33:18.438+00 pid=10572 wal_e.worker.s3_worker INFO MSG: could not locate object while performing wal restore
> DETAIL: The absolute URI that could not be located is s3://xyz/uswest1-wal-logs/wal_005/00000003.history.lzo.

> HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.

> 2012-04-05T21:33:18.627+00 pid=10576 wal_e.worker.s3_worker INFO MSG: could not locate object while performing wal restore

> DETAIL: The absolute URI that could not be located is s3://xyz/uswest1-wal-logs/wal_005/00000002.history.lzo.
> HINT: This can be normal when Postgres is trying to detect what timelines are available during restoration.

—matt

[Daniel Farina]

On Thu, Apr 5, 2012 at 3:14 PM, Matt Wise <ma...@nextdoor.com> wrote:
> I'll be damned... downgrading to Postgresql 9.1.2 seems to have worked. I know it shouldn't have, but it did. Check out this log, everything worked perfectly:

That's very suspicious: we always use the latest point release when
someone requests a replica.

I see that you are anonymizing your bucket name, but are you also
stripping out information about the path you are using for databases?
I feel like some of these issues could be the result of base backups
and/or wal being archived to the same WALE_S3_PREFIX.

--
fdr

[Matt Wise]

Oh ... wait, thats interesting. So I have the same WALE_S3_PREFIX set for both my backup-push and my wal-push. They end up in paths like this:

s3://xyz/uswest1-wal-logs/basebackup_005
s3://xyz/uswest1-wal-logs/wal_005

Is it possible that they're conflicting somehow?

—Matt

[Daniel Farina]

On Thu, Apr 5, 2012 at 10:39 PM, Matt Wise <ma...@nextdoor.com> wrote:
> Oh ... wait, thats interesting. So I have the same WALE_S3_PREFIX set for both my backup-push and my wal-push. They end up in paths like this:

Ah, that is intended, as long as they are unique per database. My
wording was ambiguous.

--
fdr