figuring out a streaming replication failure

The standby log:

->  2010-11-14 17:40:16 MST - 887 -LOG:  database system was shut down in recovery at 2010-11-14 17:40:10 MST
->  2010-11-14 17:40:16 MST - 887 -LOG:  entering standby mode
->  2010-11-14 17:40:16 MST - 887 -LOG:  consistent recovery state reached at 3/3988FF8
->  2010-11-14 17:40:16 MST - 887 -LOG:  redo starts at 3/3988F68
->  2010-11-14 17:40:16 MST - 887 -LOG:  invalid record length at 3/3988FF8
->  2010-11-14 17:40:16 MST - 885 -LOG:  database system is ready to accept read only connections
->  2010-11-14 17:40:16 MST - 890 -LOG:  streaming replication successfully connected to primary
->  2010-11-15 02:24:26 MST - 890 -FATAL:  could not receive data from WAL stream: FATAL:  requested WAL segment 000000010000000300000004 has already been removed
	
->  2010-11-15 02:24:26 MST - 887 -LOG:  unexpected pageaddr 2/B9BF2000 in log file 3, segment 4, offset 12525568
->  2010-11-15 02:24:27 MST - 2790 -LOG:  streaming replication successfully connected to primary
->  2010-11-15 02:24:27 MST - 2790 -FATAL:  could not receive data from WAL stream: FATAL:  requested WAL segment 000000010000000300000004 has already been removed
	
->  2010-11-15 02:24:32 MST - 2791 -LOG:  streaming replication successfully connected to primary
->  2010-11-15 02:24:32 MST - 2791 -FATAL:  could not receive data from WAL stream: FATAL:  requested WAL segment 000000010000000300000004 has already been removed

...

Now, the standby is geographically isolated from the master, so it's over an internet connection, so it's not a shock that with a large enough update and wal_keep_segments not large enough, speed of disk would outrun speed of network sufficiently for this to happen.

But as far as I know there was almost no write activity at 2am, no active users at all, no batch processing. There is a pg_dumpall that kicks off at 2am and these errors start about the same time that it finished. I also did the original synch and standby launch immediately after a mass update before autovacuum had a chance to run, so at some point there would be a lot of tuples marked dead.

wal_keep_segments was at 64, the first segment still around was 000000010000000300000010, checkpoint_segments was 16. In the midst of the pg_dumpall the master logs do show messages about checkpoint flushing too often. The 70ish log segments still around show mod times right around 2:23, progressing a second or so each, whereas they were created over a much longer period going back to the day before.

1 question: what happened here? Why were log files created the day before updated?

1 suggestion: would it be possible to not delete wal segments that are needed by a currently attached standby?

-- 
Scott Ribe
scott_ribe@elevated-dev.com
http://www.elevated-dev.com/
(303) 722-0567 voice