Re: 'full_page_writes=off' , VACUUM and crashing streaming slaves...

> So that explains the crashes, but it doesn't (directly) explain why you
> had data corruption.

The first crash message:

Oct 5 15:00:21 db01 postgres[75852]: [6406-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/18770": Too many open files in system
Oct 5 15:00:22 db01 postgres[75852]: [6413-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/20259": Too many open files in system
Oct 5 15:00:23 db01 postgres[75852]: [6424-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/20218": Too many open files in system
Oct 5 15:00:23 db01 postgres[75852]: [6431-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/20218": Too many open files in system
Oct 5 15:00:24 db01 postgres[75852]: [6442-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/20218": Too many open files in system
Oct 5 15:00:24 db01 postgres[75852]: [6449-1] failjava(at)dbcluster 75852 0: ERROR: could not open file "base/16387/20302": Too many open files in system
Oct 5 15:00:24 db01 postgres[75852]: [6456-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/20013": Too many open files in system
Oct 5 15:00:24 db01 postgres[75852]: [6463-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/20259": Too many open files in system
Oct 5 15:00:24 db01 postgres[75852]: [6470-1] failjava(at)dbcluster 75852 0: ERROR: could not seek to end of file "base/16387/20259": Too many open files in system
Oct 5 15:00:24 db01 postgres[75852]: [6480-1] failjava(at)dbcluster 75852 0: ERROR: could not open file "base/16387/20275": Too many open files in system
Oct 5 15:00:25 db01 postgres[75852]: [6481-1] failjava(at)dbcluster 75852 0: ERROR: current transaction is aborted, commands ignored until end of transaction block
Oct 5 15:00:25 db01 postgres[76648]: [5944-1] failjava(at)dbcluster 76648 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:00:25 db01 postgres[76649]: [5944-1] failjava(at)dbcluster 76649 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:00:25 db01 postgres[76407]: [5894-1] failjava(at)dbcluster 76407 0: WARNING: terminating connection because of crash of another server process

For the sake of completeness, I looked to correlate the above relations with the tables that had problems, and there is zero correlation between seek(2) errors and tables that had VACUUM reported invalid pages.

nspname | relname | relnamespace | relfilenode | relkind | oid
-----------------+-----------------+--------------+-------------+---------+-------
failjava_master | tbl_F | 16388 | 16402 | r | 16402
failjava_db1 | tbl_D | 16417 | 18473 | r | 18473
failjava_db1 | tbl_E | 16417 | 20179 | r | 20179
failjava_db1 | tbl_C | 16417 | 20187 | r | 20187
failjava_db1 | tbl_B | 16417 | 20200 | r | 20200
failjava_db1 | tbl_A | 16417 | 41731 | r | 19533

But I'm wondering if it died a second time before the system had finished its recovery:

Oct 5 15:01:31 db01 postgres[76888]: [6503-1] @ 76888 0: WARNING: could not open statistics file "pg_stat_tmp/pgstat.stat": Too many open files in system
Oct 5 15:01:31 db01 postgres[77571]: [5978-1] @ 77571 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:01:31 db01 postgres[77572]: [5979-1] failjava(at)dbcluster 77572 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:01:31 db01 postgres[77572]: [5980-1] failjava(at)dbcluster 77572 0: WARNING: terminating connection because of crash of another server process
Oct 5 15:01:31 db01 postgres[77544]: [7490-1] failjava(at)dbcluster 77544 0: WARNING: terminating connection because of crash of another server process

Unfortunately the logs that I have for the first set of crashes are limited to WARNING+ and don't include INFO log levels (though I have it later on. Due to various IRL constraints - hardware failure of the intended host - the provisioning of the master was a bit of a cannonball dash).

> I think the uninitialized pages are showing up because you had crashes
> in the midst of relation-extension operations, ie, some other backend
> had successfully done an smgrextend but hadn't yet laid down any valid
> data in the new page. However, this theory would not explain more than
> one uninitialized page per crash, and your previous message seems to
> show rather a lot of uninitialized pages. How many pipe-failed crashes
> did you have?

Assuming ~1min per recovery, it looks like around 38.

Oct 5 15:00:25 db01 postgres[76648]: [5944-1] failjava(at)dbcluster 76648 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:00:25 db01 postgres[76649]: [5944-1] failjava(at)dbcluster 76649 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:01:31 db01 postgres[77571]: [5978-1] @ 77571 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:01:31 db01 postgres[77572]: [5979-1] failjava(at)dbcluster 77572 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:02:20 db01 postgres[78473]: [5987-1] failjava(at)dbcluster 78473 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:03:47 db01 postgres[79408]: [6005-1] failjava(at)dbcluster 79408 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:05:06 db01 postgres[80440]: [6112-1] failjava(at)dbcluster 80440 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:06:09 db01 postgres[81276]: [6117-1] @ 81276 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:07:04 db01 postgres[82102]: [6131-1] failjava(at)dbcluster 82102 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:08:19 db01 postgres[82336]: [6136-1] @ 82336 0: FATAL: could not open archive status directory "pg_xlog/archive_status": Too many open files in system
Oct 5 15:08:20 db01 postgres[83084]: [6161-1] @ 83084 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:08:22 db01 postgres[83091]: [6184-1] failjava(at)dbcluster 83091 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:09:36 db01 postgres[84096]: [6218-1] failjava(at)dbcluster 84096 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:10:50 db01 postgres[85064]: [6226-1] failjava(at)dbcluster 85064 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:12:05 db01 postgres[86106]: [6233-1] failjava(at)dbcluster 86106 0: FATAL: could not open relation mapping file "global/pg_filenode.map": Too many open files in system
Oct 5 15:12:05 db01 postgres[86107]: [6233-1] failjava(at)dbcluster 86107 0: FATAL: could not open relation mapping file "global/pg_filenode.map": Too many open files in system
Oct 5 15:12:05 db01 postgres[86108]: [6233-1] failjava(at)dbcluster 86108 0: FATAL: could not open relation mapping file "global/pg_filenode.map": Too many open files in system
Oct 5 15:12:05 db01 postgres[86109]: [6233-1] failjava(at)dbcluster 86109 0: FATAL: could not open relation mapping file "global/pg_filenode.map": Too many open files in system
Oct 5 15:12:05 db01 postgres[86105]: [6234-1] failjava(at)dbcluster 86105 0: FATAL: could not open file "base/16387/PG_VERSION": Too many open files in system
Oct 5 15:12:08 db01 postgres[86119]: [6252-1] failjava(at)dbcluster 86119 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:13:36 db01 postgres[87126]: [6295-1] failjava(at)dbcluster 87126 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:14:23 db01 postgres[88122]: [6364-1] failjava(at)dbcluster 88122 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:15:31 db01 postgres[88370]: [6369-1] @ 88370 0: FATAL: could not open archive status directory "pg_xlog/archive_status": Too many open files in system
Oct 5 15:15:31 db01 postgres[89057]: [6398-1] @ 89057 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:15:34 db01 postgres[89067]: [6426-1] failjava(at)dbcluster 89067 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:16:38 db01 postgres[90080]: [6430-1] @ 90080 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:17:19 db01 postgres[90941]: [6446-1] failjava(at)dbcluster 90941 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:18:43 db01 postgres[91898]: [6484-1] failjava(at)dbcluster 91898 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:20:02 db01 postgres[93068]: [6514-1] failjava(at)dbcluster 93068 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:22:03 db01 postgres[94275]: [6519-1] failjava(at)dbcluster 94275 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:22:03 db01 postgres[94276]: [6519-1] failjava(at)dbcluster 94276 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:23:39 db01 postgres[95392]: [6525-1] failjava(at)dbcluster 95392 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:24:52 db01 postgres[96371]: [6533-1] failjava(at)dbcluster 96371 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:26:22 db01 postgres[97337]: [6570-1] failjava(at)dbcluster 97337 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:27:48 db01 postgres[98419]: [6607-1] failjava(at)dbcluster 98419 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:29:02 db01 postgres[99379]: [6706-1] failjava(at)dbcluster 99379 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:30:20 db01 postgres[467]: [6719-1] failjava(at)dbcluster 467 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:32:08 db01 postgres[1479]: [6769-1] failjava(at)dbcluster 1479 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:33:28 db01 postgres[2714]: [6776-1] failjava(at)dbcluster 2714 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:34:18 db01 postgres[3600]: [6870-1] failjava(at)dbcluster 3600 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:36:07 db01 postgres[4608]: [6896-1] failjava(at)dbcluster 4608 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:37:18 db01 postgres[5652]: [6944-1] failjava(at)dbcluster 5652 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:38:56 db01 postgres[6640]: [7018-1] failjava(at)dbcluster 6640 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:39:46 db01 postgres[7680]: [7025-1] failjava(at)dbcluster 7680 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:41:08 db01 postgres[8609]: [7081-1] failjava(at)dbcluster 8609 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:42:20 db01 postgres[9546]: [7095-1] failjava(at)dbcluster 9546 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:43:53 db01 postgres[10468]: [7127-1] failjava(at)dbcluster 10468 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:45:32 db01 postgres[11634]: [7159-1] failjava(at)dbcluster 11634 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:47:10 db01 postgres[12721]: [7184-1] failjava(at)dbcluster 12721 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:48:47 db01 postgres[13831]: [7194-1] failjava(at)dbcluster 13831 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:49:47 db01 postgres[14912]: [7217-1] failjava(at)dbcluster 14912 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:51:32 db01 postgres[15928]: [7223-1] failjava(at)dbcluster 15928 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:52:34 db01 postgres[16954]: [7231-1] failjava(at)dbcluster 16954 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:53:49 db01 postgres[17963]: [7247-1] failjava(at)dbcluster 17963 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:55:36 db01 postgres[19309]: [7269-1] failjava(at)dbcluster 19309 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:57:08 db01 postgres[20273]: [7286-1] failjava(at)dbcluster 20273 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:58:34 db01 postgres[20616]: [7291-1] @ 20616 0: FATAL: could not open archive status directory "pg_xlog/archive_status": Too many open files in system
Oct 5 15:58:34 db01 postgres[21404]: [7293-1] @ 21404 0: FATAL: could not open archive status directory "pg_xlog/archive_status": Too many open files in system
Oct 5 15:58:47 db01 postgres[21442]: [7294-1] @ 21442 0: FATAL: pipe() failed: Too many open files in system
Oct 5 15:58:49 db01 postgres[21450]: [7318-1] failjava(at)dbcluster 21450 0: FATAL: pipe() failed: Too many open files in system
[ Once I setup monitoring, I became aware that the app (in a 100% idle state) was consuming ~80K fds because the app's initialization procedure touches nearly all 500 tables across it's ~2K connections ]

<rant>It would be exceptionally nice if JDBC grew a brain and be written in an intelligent manner such that pgbouncer could be used in transaction mode, thereby allowing exceptionally poorly written apps and database connection code which establish 5-20 connections per thread could be parked on the front of pgbouncer instead of needing to talk directly to a backend process. Use of duplicate names for prepared statements, or preparing statements outside of a transaction really ties the hands of folk who are attempting to insert additional layers in the stack to scale up applications that are effectively in an immutable and broken state of disrepair. <pipedream>A more realistic but disgusting solution would be to teach pgbouncer to intercept all prepared statements from a given client and on-the-fly rewrite the names to something that acts as a unique cookie and could be reused across backends if a given backend hasn't seen a unique prepared statement before.</pipedream></rant>

I'm trying to determine that now. I actually only included a small snippet of the uninitialized pages. It looks like there are 28 total uninitialized pages that VACUUM discovered:

[ autovacuum appears to have caught these two, however the slave wasn't turned up at this point ]
Oct 5 19:42:44 db01 postgres[37748]: [8908-1] @ 37748 0: WARNING: relation "tbl_E" page 4263 is uninitialized --- fixing
Oct 5 19:43:03 db01 postgres[37324]: [8908-1] @ 37324 0: WARNING: relation "tbl_B" page 2628 is uninitialized --- fixing

[ And the remaining 26 were caught via an explicitly executed `vacuumdb -az` ]
Oct 6 17:03:24 db01 postgres[73864]: [8911-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_F" page 65722 is uninitialized --- fixing
Oct 6 17:03:43 db01 postgres[73864]: [8912-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_D" page 3563 is uninitialized --- fixing
Oct 6 17:03:43 db01 postgres[73864]: [8913-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_D" page 3564 is uninitialized --- fixing
Oct 6 17:03:43 db01 postgres[73864]: [8914-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_D" page 3565 is uninitialized --- fixing
Oct 6 17:03:49 db01 postgres[73864]: [8915-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 65305 is uninitialized --- fixing
Oct 6 17:03:50 db01 postgres[73864]: [8916-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 70927 is uninitialized --- fixing
Oct 6 17:03:50 db01 postgres[73864]: [8917-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 75286 is uninitialized --- fixing
Oct 6 17:03:50 db01 postgres[73864]: [8918-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 86601 is uninitialized --- fixing
Oct 6 17:03:50 db01 postgres[73864]: [8919-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 91434 is uninitialized --- fixing
Oct 6 17:03:50 db01 postgres[73864]: [8920-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 91435 is uninitialized --- fixing
Oct 6 17:03:51 db01 postgres[73864]: [8921-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 95639 is uninitialized --- fixing
Oct 6 17:03:51 db01 postgres[73864]: [8922-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 105638 is uninitialized --- fixing
Oct 6 17:03:51 db01 postgres[73864]: [8923-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 114550 is uninitialized --- fixing
Oct 6 17:03:51 db01 postgres[73864]: [8924-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 118380 is uninitialized --- fixing
Oct 6 17:03:51 db01 postgres[73864]: [8925-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 121478 is uninitialized --- fixing
Oct 6 17:03:51 db01 postgres[73864]: [8926-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 122098 is uninitialized --- fixing
Oct 6 17:03:52 db01 postgres[73864]: [8927-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 127195 is uninitialized --- fixing
Oct 6 17:03:53 db01 postgres[73864]: [8928-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 152416 is uninitialized --- fixing
Oct 6 17:03:55 db01 postgres[73864]: [8929-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 230192 is uninitialized --- fixing
Oct 6 17:03:56 db01 postgres[73864]: [8930-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_C" page 241091 is uninitialized --- fixing
Oct 6 17:20:31 db01 postgres[73864]: [8931-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_A" page 32379133 is uninitialized --- fixing
Oct 6 17:20:32 db01 postgres[73864]: [8932-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_A" page 32385954 is uninitialized --- fixing
Oct 6 17:20:32 db01 postgres[73864]: [8933-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_A" page 32393740 is uninitialized --- fixing
Oct 6 17:20:32 db01 postgres[73864]: [8934-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_A" page 32394599 is uninitialized --- fixing
Oct 6 17:20:32 db01 postgres[73864]: [8935-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_A" page 32402510 is uninitialized --- fixing
Oct 6 17:20:33 db01 postgres[73864]: [8936-1] pgsql(at)dbcluster 73864 0: WARNING: relation "tbl_A" page 32409328 is uninitialized --- fixing

>> What's odd to me is not the failure scenarios that come from a system running out of FDs (though seek(2)'ing consuming an FD seems odd), it's more that it's still possible for a master DB's VACUUM to clean up a bogus or partial page write, and have the slave crash when the WAL entry is shipped over.
>
> It looks to me like vacuumlazy.c doesn't bother to emit a WAL record at
> all when fixing an all-zeroes heap page. I'm not sure if that's a
> problem or not. The first actual use of such a page ought to result in
> re-init'ing it anyway (cf XLOG_HEAP_INIT_PAGE logic in heap_insert),
> so right offhand I don't see a path from this to the slave-side failures
> you saw. (But on the other hand I'm only firing on one cylinder today
> because of a head cold, so maybe I'm just missing it.)

(Good luck w/ the recovery)

> Do the slave-side failures correspond to pages that were reported as
> "fixed" on the master?

It doesn't appear so.

Oct 6 17:12:03 db02 postgres[15191]: [13-1] @ 15191 0: WARNING: page 2943 of relation base/16387/20196 is uninitialized

I do see a few other odd or related messages on the slave, however:

[ from a recovery ]
Oct 6 07:14:50 db02 postgres[11972]: [12-1] @ 11972 0: LOG: record with zero length at 9E/699842C0
Oct 6 07:14:50 db02 postgres[11972]: [13-1] @ 11972 0: LOG: redo done at 9E/69984290
Oct 6 07:14:50 db02 postgres[11972]: [14-1] @ 11972 0: LOG: last completed transaction was at log time 2012-10-06 07:12:11.87694+00
Oct 6 07:14:50 db02 postgres[11972]: [15-1] @ 11972 0: LOG: checkpoint starting: end-of-recovery immediate

[ Best to let sleeping dragons lie, I shut the slave down for the night in case there was some form of feedback that could be sent back that could hang the master ]
Oct 6 07:51:32 db02 postgres[15505]: [16-1] @ 15505 0: LOG: database system is shut down

[ I think this is from trying to connect to an ipv6 addr for localhost, but IPv6 has been disabled. Including because the verbosity level seems excessive. ]
Oct 6 16:36:06 db02 postgres[4529]: [7-1] @ 4529 0: LOG: could not create socket for statistics collector: Protocol not supported
Oct 6 16:36:06 db02 postgres[4529]: [8-1] @ 4529 0: LOG: trying another address for the statistics collector

[ Here the database noted the bogus page, but it was still able to start up ]
Oct 6 16:36:06 db02 postgres[4535]: [9-1] @ 4535 0: LOG: database system was interrupted; last known up at 2012-10-06 08:07:41 UTC
Oct 6 16:36:06 db02 postgres[4535]: [10-1] @ 4535 0: LOG: entering standby mode
Oct 6 16:36:06 db02 postgres[4535]: [11-1] @ 4535 0: LOG: unexpected pageaddr 88/EE000000 in log file 158, segment 110, offset 0

[ Including this as a small nit: there are two lines emitted for the following log entry, which seems incorrect ]
Oct 6 16:41:31 db02 postgres[6416]: [9-1] @ 6416 0: FATAL: could not connect to the primary server: fe_sendauth: no password supplied
Oct 6 16:41:31 db02 postgres[6416]: [9-2]

Oct 6 16:41:36 db02 postgres[6445]: [9-1] @ 6445 0: LOG: streaming replication successfully connected to primary
Oct 6 16:41:37 db02 postgres[4535]: [12-1] @ 4535 0: LOG: redo starts at 9E/6E000020
Oct 6 16:41:37 db02 postgres[4535]: [13-1] @ 4535 0: LOG: consistent recovery state reached at 9E/6E003E10
Oct 6 16:41:37 db02 postgres[4529]: [9-1] @ 4529 0: LOG: database system is ready to accept read only connections

[ Here's what the slave sees on a crash ]
Oct 6 17:09:17 db02 postgres[15561]: [10-1] pgsql(at)postgres 15561 0: FATAL: the database system is starting up
Oct 6 17:11:52 db02 postgres[15191]: [12-1] @ 15191 0: LOG: consistent recovery state reached at 9E/E3DDE2B0
Oct 6 17:11:52 db02 postgres[15185]: [9-1] @ 15185 0: LOG: database system is ready to accept read only connections
Oct 6 17:12:03 db02 postgres[15191]: [13-1] @ 15191 0: WARNING: page 2943 of relation base/16387/20196 is uninitialized
Oct 6 17:12:03 db02 postgres[15191]: [13-2] @ 15191 0: CONTEXT: xlog redo vacuum: rel 1663/16387/20196; blk 2944, lastBlockVacuumed 2403
Oct 6 17:12:03 db02 postgres[15191]: [14-1] @ 15191 0: PANIC: WAL contains references to invalid pages
Oct 6 17:12:03 db02 postgres[15191]: [14-2] @ 15191 0: CONTEXT: xlog redo vacuum: rel 1663/16387/20196; blk 2944, lastBlockVacuumed 2403
Oct 6 17:12:03 db02 postgres[15185]: [10-1] @ 15185 0: LOG: startup process (PID 15191) was terminated by signal 6: Abort trap
[ /me scratches head for a bit ]
Oct 6 17:21:34 db02 postgres[19614]: [9-1] @ 19614 0: LOG: database system was interrupted while in recovery at log time 2012-10-06 08:07:24 UTC
Oct 6 17:21:34 db02 postgres[19614]: [9-2] @ 19614 0: HINT: If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
Oct 6 17:21:34 db02 postgres[19614]: [10-1] @ 19614 0: LOG: entering standby mode
Oct 6 17:21:34 db02 postgres[19614]: [11-1] @ 19614 0: LOG: redo starts at 9E/6E000020

[ This is the point that I came up with my hypothesis and enabled full_page_writes ]
Oct 6 17:24:14 db02 postgres[19608]: [9-1] @ 19608 0: LOG: received SIGHUP, reloading configuration files
Oct 6 17:24:14 db02 postgres[19608]: [10-1] @ 19608 0: LOG: parameter "full_page_writes" changed to "on"
Oct 6 17:26:34 db02 postgres[19614]: [12-1] @ 19614 0: LOG: consistent recovery state reached at 9E/E3DDE2B0
Oct 6 17:26:34 db02 postgres[19608]: [11-1] @ 19608 0: LOG: database system is ready to accept read only connections
Oct 6 17:26:44 db02 postgres[19614]: [13-1] @ 19614 0: WARNING: page 2943 of relation base/16387/20196 is uninitialized
Oct 6 17:26:44 db02 postgres[19614]: [13-2] @ 19614 0: CONTEXT: xlog redo vacuum: rel 1663/16387/20196; blk 2944, lastBlockVacuumed 2403
Oct 6 17:26:44 db02 postgres[19614]: [14-1] @ 19614 0: PANIC: WAL contains references to invalid pages
Oct 6 17:26:44 db02 postgres[19614]: [14-2] @ 19614 0: CONTEXT: xlog redo vacuum: rel 1663/16387/20196; blk 2944, lastBlockVacuumed 2403
Oct 6 17:26:44 db02 postgres[19608]: [12-1] @ 19608 0: LOG: startup process (PID 19614) was terminated by signal 6: Abort trap
Oct 6 17:26:44 db02 postgres[19608]: [13-1] @ 19608 0: LOG: terminating any other active server processes
[ Given things were still panic'ing on the same page of data, I enabled full_page_writes on the master, performed a VACUUM, CHECKPOINT and begin resync'ing data to the slave ]

[ And here I started up the slave again ]
Oct 7 00:32:00 db02 postgres[66904]: [9-1] @ 66904 0: LOG: database system was interrupted; last known up at 2012-10-06 17:48:10 UTC
Oct 7 00:32:00 db02 postgres[66904]: [10-1] @ 66904 0: LOG: entering standby mode
Oct 7 00:32:00 db02 postgres[66904]: [11-1] @ 66904 0: LOG: unexpected pageaddr 89/B9000000 in log file 159, segment 55, offset 0
Oct 7 00:32:00 db02 postgres[66906]: [9-1] [unknown](at)[unknown] 66906 0: LOG: connection received: host=[local]
Oct 7 00:32:00 db02 postgres[66906]: [10-1] pgsql(at)postgres 66906 0: FATAL: the database system is starting up
Oct 7 00:32:00 db02 postgres[66905]: [9-1] @ 66905 0: LOG: streaming replication successfully connected to primary
Oct 7 00:32:01 db02 postgres[66913]: [9-1] [unknown](at)[unknown] 66913 0: LOG: connection received: host=[local]
Oct 7 00:32:01 db02 postgres[66913]: [10-1] pgsql(at)postgres 66913 0: FATAL: the database system is starting up
Oct 7 00:32:01 db02 postgres[66904]: [12-1] @ 66904 0: LOG: redo starts at 9F/36000020
Oct 7 00:32:01 db02 postgres[66904]: [13-1] @ 66904 0: LOG: consistent recovery state reached at 9F/36003FD8
Oct 7 00:32:02 db02 postgres[66897]: [9-1] @ 66897 0: LOG: database system is ready to accept read only connections

[ At this point I initiated a VACUUM and rebuilt a 400GB table using pg_reorg(1) to evict all WAL files that would contain possibly poisonous data ]

And that's about all I know at this point in time. Things have been up and running successfully and without issue ever since. I'm tempted to pg_reorg(1) all of the tables in order to guarantee that all tables are 100% intact since I can't easily VACUUM FULL these tables (several of the largest, most frequently used are several TB in size). LMK if there's anything else you're interested in seeing or having outlined. Again, the master recovered gracefully, didn't require any manual intervention other than increasing kern.maxfiles, and hasn't skipped a beat once since kern.maxfiles was increased. Having the slaves crap out when the master executed a VACUUM, however, is of interest. When running the manual VACUUM, I had a window open to both db01 and db02 and db02's backend panic'ing was clearly linked to the VACUUM warnings on the db01.

In the regression testing environments, is it possible to enable a test mode that runs with full_page_writes disabled in order to push the boundaries of disabling full_page_writes? The IO bandwidth savings are substantial for small mutations, and for folks lucky enough to run on ZFS (i.e. not ufs, ext*), it'd be really cool to be able to realize those bandwidth savings. As is, it appears that standalone instances of Pg are full_page_writes safe, but that slaves are still making assumptions about full page WAL entries being the MTU during some corner cases. My observations lead me to believe that replication works fine with full_page_writes disabled until the master cleans up a zero-filled or damaged page.

For the archives (if anyone makes it this far to the bottom of the note), what I did to operationally "fix" things:

1) On the master I re-enabled full_page_writes and HUP'ed pg to reload the setting.
2) Fired off a VACUUM ANALYZE to generate some WAL data. This step isn't necessary, but I wanted to make sure that there was something to CHECKPOINT.
3) Issue a CHECKPOINT & wait until this is completed.
4) Re-sync data to the slave (via rsync(1) or whatever your tool of choice is).
5) Restarted the slave.
6) Verify that the slave is in fact replicating via pg_stat_replication

-sc

--
Sean Chittenden
sean(at)chittenden(dot)org