On Tue, Apr 16, 2013 at 3:04 PM, Tom Lane <tgl@xxxxxxxxxxxxx> wrote:
Dale Fukami <dale.fukami@xxxxxxxxx> writes:That's peculiar. The most likely theories seem to be
> I'm having a problem on a standby server (streaming replication) where a
> table seems to exist but is not queryable. Essentially a select statement
> (and drop/insert/etc) fails but \d and pg_tables show it exists. The table
> exists on the master (and is queryable) and replication is still working in
> that changes to the master table don't cause errors on the standby and
> changes to other tables are replicated and verified to be on the standby.
(1) corruption in the standby's pg_class indexes, such that an index
search for relname = 'tracked_deductibles' fails to find the row,
although it is found by seqscans; or
(2) some type of visibility issue causing SnapshotNow operations to
think the row is invalid, though it is valid to MVCC queries.
Either way, if it's working on the master, then you've had a replication
failure since the standby's files evidently don't match the master's.
What PG version is this (and which versions have been installed since
the replication was set up)? Have you had any system-level crashes on
the standby?
My apologies: PostgreSQL 9.0.5 on x86_64-pc-linux-gnu, compiled by GCC gcc-4.4.real (Ubuntu 4.4.3-4ubuntu5) 4.4.3, 64-bit
This is the only version we've had since we've set up streaming replication.
We believe we've found the moment of corruption. It appears that the db was shutdown then restarted and didn't quite catch up to the master and then was shut down again. We use this standby to take snapshots on a regular basis but it looks like this one didn't quite get into a consistent state before the next one started. Logs pasted at the end of this email.
At this point I'm most concerned about:
1) We were quite lucky I think to have discovered this issue. I think the only other way we'd have noticed would have been if we'd failed over to it and our app stopped working. I'm worried now that we'll end up in a similar situation and won't have known it for many weeks. At some point we lose the ability to PITR based on how many backups are kept. Is there a way to be more confident in our standby machines?
2) Is there a way to recover from this? In the extreme case where we might have failed over to this standby, could we somehow figure out where exactly the corruption is and recover or are we talking about going back to an older snapshot and using our archived WALs? Note: we've already rebuilt this standby to be consistent with master last night. This is more a hypothetical at this point. We've kept the bad slave for experimentation in case anyone has thoughts on this.
Just to clear up the confusion that I had caused John. I had obscured the previous schema name by restoring from snapshots and altering the schema name itself. So, the queries and output are an exact copy/paste from my terminal. I get the same results on the Live standby when using the actual Live schema name but, obviously, it shows the Live schema name rather than 'someschema'.
Thanks,
Dale
Log snippet from what appears to be the time of corruption. We've confirmed this by restoring snapshots just prior and just following this time range. Note the lovely HINT that there may be corruption :)
2013-04-15 15:38:22 UTC @ DETAIL: last completed transaction was at log time 2013-04-15 15:37:07.621579+00
2013-04-15 15:38:22 UTC @ LOG: shutting down
2013-04-15 15:38:22 UTC @ LOG: database system is shut down
2013-04-15 15:39:21 UTC @ LOG: database system was shut down in recovery at 2013-04-15 15:38:22 UTC
2013-04-15 15:39:21 UTC [unknown]@[unknown] LOG: incomplete startup packet
cp: cannot stat `/var/lib/postgresql-archives/00000005.history': No such file or directory
2013-04-15 15:39:21 UTC @ LOG: entering standby mode
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000088': No such file or directory
2013-04-15 15:39:21 UTC postgres@postgres FATAL: the database system is starting up
2013-04-15 15:39:22 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000086': No such file or directory
2013-04-15 15:39:22 UTC @ LOG: redo starts at 1648/86ED4360
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000087': No such file or directory
2013-04-15 15:39:23 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000088': No such file or directory
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000089': No such file or directory
cp: cannot stat `/var/lib/postgresql-archives/00000005000016480000008A': No such file or directory
2013-04-15 15:39:23 UTC postgres@postgres FATAL: the database system is starting up
2013-04-15 15:39:23 UTC @ LOG: consistent recovery state reached at 1648/8A6460E0
2013-04-15 15:39:23 UTC @ LOG: invalid record length at 1648/8A6460E0
2013-04-15 15:39:23 UTC @ LOG: database system is ready to accept read only connections
cp: cannot stat `/var/lib/postgresql-archives/00000005000016480000008A': No such file or directory
2013-04-15 15:39:23 UTC @ LOG: streaming replication successfully connected to primary
2013-04-15 15:39:27 UTC @ LOG: restartpoint starting: xlog
2013-04-15 15:43:56 UTC @ LOG: restartpoint complete: wrote 13894 buffers (2.1%); write=48.569 s, sync=219.650 s, total=269.460 s
2013-04-15 15:43:56 UTC @ LOG: recovery restart point at 1648/8909ED50
2013-04-15 15:43:56 UTC @ DETAIL: last completed transaction was at log time 2013-04-15 15:40:48.449826+00
2013-04-15 15:43:56 UTC @ LOG: restartpoint starting: xlog time
2013-04-15 15:45:02 UTC @ LOG: received fast shutdown request
2013-04-15 15:45:02 UTC @ LOG: aborting any active transactions
2013-04-15 15:45:15 UTC @ FATAL: terminating walreceiver process due to administrator command
2013-04-15 15:45:25 UTC @ LOG: restartpoint complete: wrote 12759 buffers (1.9%); write=41.211 s, sync=47.518 s, total=88.759 s
2013-04-15 15:45:25 UTC @ LOG: recovery restart point at 1648/8FBEBAD8
2013-04-15 15:45:25 UTC @ DETAIL: last completed transaction was at log time 2013-04-15 15:44:30.43801+00
2013-04-15 15:45:25 UTC @ LOG: shutting down
2013-04-15 15:45:25 UTC @ LOG: restartpoint starting: shutdown immediate
2013-04-15 15:46:02 UTC @ LOG: received immediate shutdown request
2013-04-15 15:47:24 UTC @ LOG: database system was interrupted while in recovery at log time 2013-04-15 15:39:45 UTC
2013-04-15 15:47:24 UTC @ HINT: If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2013-04-15 15:47:24 UTC [unknown]@[unknown] LOG: incomplete startup packet
cp: cannot stat `/var/lib/postgresql-archives/00000005.history': No such file or directory
2013-04-15 15:47:24 UTC @ LOG: entering standby mode
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000091': No such file or directory
2013-04-15 15:47:24 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/00000005000016480000008F': No such file or directory
2013-04-15 15:47:25 UTC @ LOG: redo starts at 1648/8FBEBAD8
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000090': No such file or directory
2013-04-15 15:47:25 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000091': No such file or directory
2013-04-15 15:47:25 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000092': No such file or directory
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000093': No such file or directory
2013-04-15 15:47:26 UTC postgres@postgres FATAL: the database system is starting up
2013-04-15 15:47:26 UTC @ LOG: restartpoint starting: xlog
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000094': No such file or directory
2013-04-15 15:47:26 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000095': No such file or directory
2013-04-15 15:47:27 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000096': No such file or directory
2013-04-15 15:47:27 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000097': No such file or directory
2013-04-15 15:47:28 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000098': No such file or directory
2013-04-15 15:47:28 UTC postgres@postgres FATAL: the database system is starting up
cp: cannot stat `/var/lib/postgresql-archives/000000050000164800000099': No such file or directory
2013-04-15 15:47:29 UTC postgres@postgres FATAL: the database system is starting up
2013-04-15 15:47:29 UTC @ LOG: consistent recovery state reached at 1648/99E05F08
2013-04-15 15:47:29 UTC @ LOG: database system is ready to accept read only connections
cp: cannot stat `/var/lib/postgresql-archives/00000005000016480000009A': No such file or directory
2013-04-15 15:47:30 UTC @ LOG: unexpected pageaddr 1648/794E2000 in log file 5704, segment 154, offset 5120000
cp: cannot stat `/var/lib/postgresql-archives/00000005000016480000009A': No such file or directory
2013-04-15 15:47:30 UTC @ LOG: streaming replication successfully connected to primary
2013-04-15 15:52:34 UTC @ LOG: restartpoint complete: wrote 17096 buffers (2.6%); write=39.897 s, sync=264.845 s, total=307.746 s
2013-04-15 15:52:34 UTC @ LOG: recovery restart point at 1648/9196C3B0
2013-04-15 15:52:34 UTC @ DETAIL: last completed transaction was at log time 2013-04-15 15:48:44.049103+00
2013-04-15 15:52:34 UTC @ LOG: restartpoint starting: xlog time
2013-04-15 15:53:58 UTC @ LOG: restartpoint complete: wrote 27760 buffers (4.2%); write=43.305 s, sync=41.135 s, total=84.489 s
2013-04-15 15:53:58 UTC @ LOG: recovery restart point at 1648/A20E13E8
2013-04-15 15:53:58 UTC @ DETAIL: last completed transaction was at log time 2013-04-15 15:53:35.897601+00
2013-04-15 15:53:58 UTC @ LOG: restartpoint starting: xlog time
2013-04-15 15:55:04 UTC @ LOG: restartpoint complete: wrote 34572 buffers (5.3%); write=41.229 s, sync=24.578 s, total=65.855 s
2013-04-15 15:55:04 UTC @ LOG: recovery restart point at 1648/B1293B80
2013-04-15 15:55:04 UTC @ DETAIL: last completed transaction was at log time 2013-04-15 15:54:41.804552+00
2013-04-15 15:55:04 UTC @ LOG: restartpoint starting: xlog time
2013-04-15 15:55:58 UTC @ LOG: restartpoint complete: wrote 9283 buffers (1.4%); write=41.391 s, sync=12.263 s, total=53.805 s
2013-04-15 15:55:58 UTC @ LOG: recovery restart point at 1648/B371CFF0
2013-04-15 15:55:58 UTC @ DETAIL: last completed transaction was at log time 2013-04-15 15:55:35.627312+00
2013-04-15 15:55:58 UTC @ LOG: restartpoint starting: xlog
2013-04-15 15:56:51 UTC @ LOG: restartpoint complete: wrote 6459 buffers (1.0%); write=41.648 s, sync=11.185 s, total=52.856 s
2013-04-15 15:56:51 UTC @ LOG: recovery restart point at 1648/B6C1DF00
