Database Recovery

Hi,

I have a corrupt database. I copied the database directory offsite and
restored from a backup. I'm now trying to recover data in the corrupt
database added since the last backup. Any advice on how to approach
this?

It looks like my SAN raid controllers failed (both of them) after
putting in new disks... very suspicious. Anyway. After the SAN failed,
we had to reboot it, and upon rebooting I successfuly brought up the
database. To test consistency, I decided to vacuum full some selective
tables (DB ~200GB). It looked ok, so started using it again, then a
few minutes later the database was corrupt and completely unusable. At
that point I did a restore from a backup.

Errors from SAN (Just in case it adds something):

Oct  1 09:26:44 dbserver kernel: qla2300 0000:05:01.0: LOOP DOWN detected (2).
Oct  1 09:27:47 dbserver kernel: qla2x00: no more failovers for
request - pid= 3300789468
Oct  1 09:27:47 dbserver kernel: SCSI error : <1 0 0 2> return code = 0x10000
Oct  1 09:27:47 dbserver kernel: end_request: I/O error, dev sdd,
sector 179425575
Oct  1 09:27:47 dbserver kernel: Buffer I/O error on device sdd1,
logical block 22428189
Oct  1 09:27:47 dbserver kernel: lost page write due to I/O error on sdd1
Oct  1 09:27:47 dbserver kernel: qla2x00: no more failovers for
request - pid= 3300789494
Oct  1 09:27:47 dbserver kernel: SCSI error : <1 0 0 2> return code = 0x10000
Oct  1 09:27:47 dbserver kernel: qla2x00: no more failovers for
request - pid= 3300789498
...
Oct  1 09:27:48 dbserver postgres_report[22657]: [2-1] LOG:  could not
close temporary statistics file "global/pgstat.tmp": Input/output
error
...
Oct  1 09:28:04 dbserver postgres_report[22657]: [4-1] LOG:  could not
open temporary statistics file "global/pgstat.tmp": Read-only file
system
...
Oct  1 09:28:04 dbserver kernel: ext3_abort called.
Oct  1 09:28:04 dbserver kernel: EXT3-fs error (device sdd1):
ext3_journal_start_sb: Detected aborted journal
Oct  1 09:28:04 dbserver kernel: Remounting filesystem read-only
...
Oct  1 09:28:40 dbserver postgres_report[22953]: [31-1] ERROR:  could
not read block 10636 of relation 1663/24576/24907: Input/output error
...
Oct  1 09:28:40 dbserver postgres_report[30277]: [1-1] ERROR:  could
not read block 207084 of relation 1663/24576/24977: Success
...
Oct  1 09:28:43 dbserver postgres_report[22655]: [2-1] ERROR:  could
not access status of transaction 0
Oct  1 09:28:43 dbserver postgres_report[22655]: [2-2] DETAIL:  could
not open file "pg_clog/013F": Read-only file system
...
Oct  1 09:29:15 dbserver postgres_report[22655]: [3-1] ERROR:  could
not access status of transaction 0
...
Oct  1 09:29:15 dbserver postgres_report[13902]: [2-1] LOG:
unexpected EOF on client connection
Oct  1 09:29:15 dbserver postgres_report[22657]: [6-1] LOG:  could not
open temporary statistics file "global/pgstat.tmp": Read-only file
system
Oct  1 09:29:15 dbserver postgres_report[22655]: [3-2] DETAIL:  could
not open file "pg_clog/013F": Read-only file system
...
Oct  1 09:29:28 dbserver kernel: EXT3-fs error (device sdd1) in
ext3_prepare_write: IO failure
Oct  1 09:29:28 dbserver kernel: EXT3-fs error (device sdd1) in
start_transaction: Journal has aborted
etc...

After (supposedly) fixing the SAN (Before restoring from backup), just
trying to get the original db to start:

Oct  1 11:28:47 dbserver postgres_report[20898]: [1-1] LOG:  database
system was interrupted at 2007-10-04 09:17:24 NZST
Oct  1 11:28:48 dbserver postgres_report[20898]: [2-1] LOG:
checkpoint record is at 51F/6CEF22C8
Oct  1 11:28:48 dbserver postgres_report[20898]: [3-1] LOG:  redo
record is at 51F/6CEE4410; undo record is at 0/0; shutdown FALSE
Oct  1 11:28:48 dbserver postgres_report[20898]: [4-1] LOG:  next
transaction ID: 334744042; next OID: 32829
Oct  1 11:28:48 dbserver postgres_report[20898]: [5-1] LOG:  next
MultiXactId: 1; next MultiXactOffset: 0
Oct  1 11:28:48 dbserver postgres_report[20898]: [6-1] LOG:  database
system was not properly shut down; automatic recovery in progress
Oct  1 11:28:48 dbserver postgres_report[20898]: [7-1] LOG:  redo
starts at 51F/6CEE4410
Oct  1 11:30:01 dbserver postgres_report[20997]: [1-1] FATAL:  the
database system is starting up
Oct  1 11:30:11 dbserver postgres_report[20898]: [8-1] LOG:  record
with zero length at 51F/73A75718
Oct  1 11:30:11 dbserver postgres_report[20898]: [9-1] LOG:  redo done
at 51F/73A756E8
Oct  1 11:30:11 dbserver postgres_report[20898]: [10-1] LOG:  database
system is ready
Oct  1 11:30:11 dbserver postgres_report[20898]: [11-1] LOG:
transaction ID wrap limit is 1407525850, limited by database "reports"

At which point I did a vacuum full on select tables. No errors
reported in psql so thought ok. Then this happens:

Oct  1 12:10:02 dbserver postgres_report[22636]: [1-1] ERROR:  failed
to re-find parent key in "table_1_idx3" for split pages 230790/263989
Oct  1 12:10:10 dbserver postgres_report[22636]: [2-1] PANIC:  right
sibling's left-link doesn't match
Oct  1 12:10:10 dbserver postgres_report[22636]: [2-2] STATEMENT:
insert into TABLE_1 [blah blah blah]
Oct  1 12:10:10 dbserver postgres_report[20897]: [1-1] LOG:  server
process (PID 22636) was terminated by signal 6
Oct  1 12:10:10 dbserver postgres_report[20897]: [2-1] LOG:
terminating any other active server processes
Oct  1 12:10:10 dbserver postgres_report[22659]: [1-1] WARNING:
terminating connection because of crash of another server process
Oct  1 12:10:10 dbserver postgres_report[22662]: [1-1] WARNING:
terminating connection because of crash of another server process
Oct  1 12:10:10 dbserver postgres_report[22659]: [1-2] DETAIL:  The
postmaster has commanded this server process to roll back the current
transaction and exit, because another server
Oct  1 12:10:10 dbserver postgres_report[22659]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:10 dbserver postgres_report[22662]: [1-2] DETAIL:  The
postmaster has commanded this server process to roll back the current
transaction and exit, because another server
Oct  1 12:10:10 dbserver postgres_report[22659]: [1-4] HINT:  In a
moment you should be able to reconnect to the database and repeat your
command.
Oct  1 12:10:10 dbserver postgres_report[22662]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:10 dbserver postgres_report[22661]: [1-1] WARNING:
terminating connection because of crash of another server process
Oct  1 12:10:10 dbserver postgres_report[22662]: [1-4] HINT:  In a
moment you should be able to reconnect to the database and repeat your
command.
Oct  1 12:10:10 dbserver postgres_report[22660]: [1-1] WARNING:
terminating connection because of crash of another server process
Oct  1 12:10:10 dbserver postgres_report[22658]: [1-1] WARNING:
terminating connection because of crash of another server process
Oct  1 12:10:10 dbserver postgres_report[22653]: [1-1] WARNING:
terminating connection because of crash of another server process
Oct  1 12:10:10 dbserver postgres_report[22591]: [1-1] WARNING:
terminating connection because of crash of another server process
...
Oct  1 12:10:10 dbserver postgres_report[22661]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:10 dbserver postgres_report[22660]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:11 dbserver postgres_report[22658]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:11 dbserver postgres_report[22653]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:11 dbserver postgres_report[22675]: [3-1] FATAL:  the
database system is in recovery mode
Oct  1 12:10:11 dbserver postgres_report[22591]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:11 dbserver postgres_report[22647]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
Oct  1 12:10:11 dbserver postgres_report[22646]: [1-3]  process exited
abnormally and possibly corrupted shared memory.
...
Oct  1 12:10:12 dbserver postgres_report[22644]: [1-4] HINT:  In a
moment you should be able to reconnect to the database and repeat your
command.
Oct  1 12:10:12 dbserver postgres_report[22677]: [3-1] FATAL:  the
database system is in recovery mode
Oct  1 12:10:12 dbserver postgres_report[22637]: [1-4] HINT:  In a
moment you should be able to reconnect to the database and repeat your
command.
...
Oct  1 12:10:14 dbserver postgres_report[20897]: [3-1] LOG:  all
server processes terminated; reinitializing
Oct  1 12:10:14 dbserver postgres_report[22696]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22697]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22695]: [4-1] LOG:  database
system was interrupted at 2007-10-04 12:09:25 NZST
Oct  1 12:10:14 dbserver postgres_report[22698]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22699]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22695]: [5-1] LOG:
checkpoint record is at 520/66DDD00
Oct  1 12:10:14 dbserver postgres_report[22700]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22701]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22695]: [6-1] LOG:  redo
record is at 520/66DDD00; undo record is at 0/0; shutdown FALSE
Oct  1 12:10:14 dbserver postgres_report[22695]: [7-1] LOG:  next
transaction ID: 334746303; next OID: 32829
Oct  1 12:10:14 dbserver postgres_report[22702]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22695]: [8-1] LOG:  next
MultiXactId: 1; next MultiXactOffset: 0
Oct  1 12:10:14 dbserver postgres_report[22703]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:14 dbserver postgres_report[22695]: [9-1] LOG:  database
system was not properly shut down; automatic recovery in progress
Oct  1 12:10:14 dbserver postgres_report[22704]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:15 dbserver postgres_report[22705]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:15 dbserver postgres_report[22695]: [10-1] LOG:  redo
starts at 520/66DDD50
Oct  1 12:10:15 dbserver postgres_report[22706]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:15 dbserver postgres_report[22707]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:15 dbserver postgres_report[22708]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:15 dbserver postgres_report[22709]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:15 dbserver postgres_report[22710]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:15 dbserver postgres_report[22695]: [11-1] LOG:  record
with zero length at 520/6E2D130
Oct  1 12:10:15 dbserver postgres_report[22695]: [12-1] LOG:  redo
done at 520/6E2D100
...
Oct  1 12:10:34 dbserver postgres_report[22888]: [4-1] FATAL:  the
database system is starting up
Oct  1 12:10:34 dbserver postgres_report[22695]: [13-1] PANIC:  failed
to re-find parent key in "24977" for split pages 230790/263989
Oct  1 12:10:34 dbserver postgres_report[20897]: [4-1] LOG:  startup
process (PID 22695) was terminated by signal 6
Oct  1 12:10:34 dbserver postgres_report[20897]: [5-1] LOG:  aborting
startup due to startup process failure

...

Tried to restart again:

Oct  1 12:28:44 dbserver postgres_report[23728]: [1-1] LOG:  database
system was interrupted while in recovery at 2007-10-04 12:10:15 NZST
Oct  1 12:28:44 dbserver postgres_report[23728]: [1-2] HINT:  This
probably means that some data is corrupted and you will have to use
the last backup for recovery.
Oct  1 12:28:44 dbserver postgres_report[23728]: [2-1] LOG:
checkpoint record is at 520/66DDD00
Oct  1 12:28:44 dbserver postgres_report[23728]: [3-1] LOG:  redo
record is at 520/66DDD00; undo record is at 0/0; shutdown FALSE
Oct  1 12:28:44 dbserver postgres_report[23728]: [4-1] LOG:  next
transaction ID: 334746303; next OID: 32829
Oct  1 12:28:44 dbserver postgres_report[23728]: [5-1] LOG:  next
MultiXactId: 1; next MultiXactOffset: 0
Oct  1 12:28:44 dbserver postgres_report[23728]: [6-1] LOG:  database
system was not properly shut down; automatic recovery in progress
Oct  1 12:28:44 dbserver postgres_report[23728]: [7-1] LOG:  redo
starts at 520/66DDD50
Oct  1 12:28:51 dbserver postgres_report[23728]: [8-1] LOG:  record
with zero length at 520/6E2D130
Oct  1 12:28:51 dbserver postgres_report[23728]: [9-1] LOG:  redo done
at 520/6E2D100
Oct  1 12:29:06 dbserver postgres_report[23728]: [10-1] PANIC:  failed
to re-find parent key in "24977" for split pages 230790/263989
Oct  1 12:29:06 dbserver postgres_report[23727]: [1-1] LOG:  startup
process (PID 23728) was terminated by signal 6
Oct  1 12:29:06 dbserver postgres_report[23727]: [2-1] LOG:  aborting
startup due to startup process failure

I see the HINT about restoring and do, but first fsck several times
over while various problems are fixed (corrupt/lost inodes etc).


So, back to my original problem. Based on what I've shown here, do you
think there is anything I can do to recover some of the data in the
corrupt copy? (I literally just did a mv data data.old then initdb'd
the new database and restored from backup). I guess the WAL files are
useless because of the vacuum I did used them all (or the recover
process from postgres itself)?

Regards,

Mike