PITRTools: Bring up warm standby -> unexpected pageaddr

Hi,

I'm trying to setup a warm standby using PITRTools. Environment is
CentOS 5.2 x86_64 and PG 8.3.6 from yum.pgsqlrpms.org.

As far as I can tell everything seems to work as expected. After a
successful base backup and issuing cmd_standby -S the standby goes into
constant recovery mode and happily consumes WAL segments shipped form
the master. The corresponding log looks like this:

2009-03-26 17:55:04 CET::@:[2901]: LOG: database system was
interrupted; last known up at 2009-03-26 17:09:49 CET
2009-03-26 17:55:04 CET::@:[2901]: LOG: starting archive recovery
2009-03-26 17:55:04 CET::@:[2901]: LOG: restore_command =
'/usr/bin/pg_standby /data/pgsql_archive -s5 -w0 -c %f %p %r'
cp: cannot stat `/data/pgsql_archive/00000001.history': No such file or
directory
cp: cannot stat `/data/pgsql_archive/00000001.history': No such file or
directory
cp: cannot stat `/data/pgsql_archive/00000001.history': No such file or
directory
2009-03-26 17:55:20 CET::@:[2901]: LOG: restored log file
"000000010000004E000000DF" from archive
2009-03-26 17:55:20 CET::@:[2901]: LOG: automatic recovery in progress
2009-03-26 17:55:20 CET::@:[2901]: LOG: redo starts at 4E/DF0001B8
2009-03-26 17:55:20 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E0" from archive
2009-03-26 17:55:20 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E1" from archive
2009-03-26 17:55:21 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E2" from archive
2009-03-26 17:55:21 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E3" from archive
2009-03-26 17:55:21 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E4" from archive
2009-03-26 17:55:22 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E5" from archive
2009-03-26 17:55:22 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E6" from archive
2009-03-26 17:55:22 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E7" from archive
2009-03-26 17:55:22 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E8" from archive
2009-03-26 17:55:22 CET::@:[2901]: LOG: restored log file
"000000010000004E000000E9" from archive
2009-03-26 17:55:22 CET::@:[2901]: LOG: restored log file
"000000010000004E000000EA" from archive
2009-03-26 17:56:37 CET::@:[2901]: LOG: restored log file
"000000010000004E000000EB" from archive

As soon as I issue cmd_standby -F999 I get the following log entry:

2009-03-26 17:59:37 CET::@:[2874]: LOG: received fast shutdown request
2009-03-26 17:59:37 CET::@:[2901]: FATAL: could not restore file
"000000010000004E000000EC" from archive: return code 15
2009-03-26 17:59:37 CET::@:[2874]: LOG: startup process (PID 2901)
exited with exit code 1
2009-03-26 17:59:37 CET::@:[2874]: LOG: aborting startup due to startup
process failure

What I'm worried about now is that it reapplies all WAL segments it has
already consumed in warm standby mode again and always ends with
"unexpected pageaddr".

2009-03-26 17:59:39 CET::@:[5721]: LOG: database system was interrupted
while in recovery at log time 2009-03-26 17:09:49 CET
2009-03-26 17:59:39 CET::@:[5721]: HINT: If this has occurred more than
once some data might be corrupted and you might need to choose an
earlier recovery target.
2009-03-26 17:59:39 CET::@:[5721]: LOG: starting archive recovery
2009-03-26 17:59:39 CET::@:[5721]: LOG: restore_command = 'cp
/data/pgsql_archive/%f "%p"'
cp: cannot stat `/data/pgsql_archive/00000001.history': No such file or
directory
2009-03-26 17:59:39 CET::@:[5721]: LOG: restored log file
"000000010000004E000000DF" from archive
2009-03-26 17:59:39 CET::@:[5721]: LOG: automatic recovery in progress
2009-03-26 17:59:39 CET::@:[5721]: LOG: redo starts at 4E/DF0001B8
2009-03-26 17:59:39 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E0" from archive
2009-03-26 17:59:39 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E1" from archive
2009-03-26 17:59:39 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E2" from archive
2009-03-26 17:59:39 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E3" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E4" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E5" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E6" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E7" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E8" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000E9" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000EA" from archive
2009-03-26 17:59:40 CET::@:[5721]: LOG: restored log file
"000000010000004E000000EB" from archive
cp: cannot stat `/data/pgsql_archive/000000010000004E000000EC': No such
file or directory
2009-03-26 17:59:40 CET::@:[5721]: LOG: unexpected pageaddr 4C/61000000
in log file 78, segment 236, offset 0
2009-03-26 17:59:40 CET::@:[5721]: LOG: redo done at 4E/EB000080
2009-03-26 17:59:41 CET::@:[5721]: LOG: last completed transaction was
at log time 2009-03-26 17:54:31.209657+01
2009-03-26 17:59:41 CET::@:[5721]: LOG: restored log file
"000000010000004E000000EB" from archive
cp: cannot stat `/data/pgsql_archive/00000002.history': No such file or
directory
2009-03-26 17:59:41 CET::@:[5721]: LOG: selected new timeline ID: 2
cp: cannot stat `/data/pgsql_archive/00000001.history': No such file or
directory
2009-03-26 17:59:41 CET::@:[5721]: LOG: archive recovery complete
2009-03-26 17:59:41 CET::@:[5721]: LOG: checkpoint starting: shutdown
immediate
2009-03-26 17:59:41 CET::@:[5721]: LOG: checkpoint complete: wrote 5515
buffers (1.6%); 0 transaction log file(s) added, 0 removed, 14 recycled;
write=0.272 s, sync=0.123 s, total=0.489 s
2009-03-26 17:59:41 CET::@:[5773]: LOG: autovacuum launcher started
2009-03-26 17:59:41 CET::@:[5712]: LOG: database system is ready to
accept connections

I tried all that multiple times from scratch and always got exactly the
same behaviour. Especially I have no idea why it is reapplying all WAL
segments again. One time that was over 400 segments. I feel I missed
some simple detail. Any hint is really appreciated.