Thread: streaming replication, "frozen snapshot backup on it" and missing relfile (postgres 9.2.3 on xfs + LVM)

On 14.05.2013 14:57, Benedikt Grundmann wrote:
> Today we have seen this on our testing database instance:
>
> ERROR:  could not open file "base/16416/291498116.3" (target block 431006):
> No such file or directory
>
> That database get's created by rsyncing the LVM snapshot of the standby,
> which is a readonly backup of proddb
> using streaming replication.
>
> We do not put the standby database into backup mode before rsyncing the LVM
> snapshot, trusting postgres ability to recover
> from crash.  Now we are not sure anymore...  Thoughts?  It's worth noting
> that we have been using this method of taking a backup
> for a long long time, but we only recently (after 9.2 came out we switched
> to doing a streaming replica and then to take the
> "frozen snapshot" backup method from the streaming replica).
>
> Let me know if there is more information you need, or if this is a known
> problem.

That certainly should work. I'd suggest that you narrow down the problem 
a bit more. Is the file present in the original system? Anything else 
that might be related in the logs?

- Heikki

On 14.05.2013 16:48, Benedikt Grundmann wrote:
> It's on the production database and the streaming replica.  But not on the
> snapshot.

So, the LVM snapshot didn't work correctly?

- Heikki

<div dir="ltr">That's one possible explanation.  It's worth noting that we haven't seen this before moving to streaming
repfirst and we have been using that method for a long time.<br /></div><div class="gmail_extra"><br /><br /><div
class="gmail_quote">OnTue, May 14, 2013 at 11:34 AM, Heikki Linnakangas <span dir="ltr"><<a
href="mailto:hlinnakangas@vmware.com"target="_blank">hlinnakangas@vmware.com</a>></span> wrote:<br /><blockquote
class="gmail_quote"style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="im">On 14.05.2013
16:48,Benedikt Grundmann wrote:<br /><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc
solid;padding-left:1ex">It's on the production database and the streaming replica.  But not on the<br /> snapshot.<br
/></blockquote><br/></div> So, the LVM snapshot didn't work correctly?<span class="HOEnZb"><font color="#888888"><br
/><br/> - Heikki<br /></font></span></blockquote></div><br /></div> 

On Tuesday, May 14, 2013 7:19 PM Benedikt Grundmann wrote:
>It's on the production database and the streaming replica.  But not on the
snapshot.

> production
> -rw------- 1 postgres postgres 312778752 May 13 21:28
/database/postgres/base/16416/291498116.3

> streaming replica
> -rw------- 1 postgres postgres 312778752 May 13 23:50
/database/postgres/base/16416/291498116.3
> Is there a way to find out what the file contains?

You can try with pageinspect module in contrib.

> We just got some more information.  All of the following was done / seen
in the logs of the snapshot database.

> After we saw this we run a vacuum full on the table we suspect to be
backed by this file.  This happened:

>WARNING:  concurrent insert in progress within table "js_equity_daily_diff"



> 2013-05-14 09:22:13.947 EDT,,,30911,,51919d78.78bf,1,,2013-05-13 22:12:08
EDT,,0,ERROR,XX000,"xlog flush request 1D08/9B57FCD0 is not satisfied ---
flushed only to 1CEE/31266090",,,,,"writing block 0
> of relation base/16416/291498116",,,,""
> 2013-05-14 09:22:14.964 EDT,,,30911,,51919d78.78bf,2,,2013-05-13 22:12:08
EDT,,0,ERROR,XX000,"xlog flush request 1D08/9B57FCD0 is not satisfied ---
flushed only to 1CEE/31266090",,,,,"writing block 0
> of relation base/16416/291498116",,,,""
> And after that these started appearing in logs (and they get repeated
every second now:

> [root@nyc-dbc-001 pg_log]# fgrep ERROR postgresql-2013-05-14.csv  | tail
-n 2
> 2013-05-14 09:47:43.301 EDT,,,30911,,51919d78.78bf,3010,,2013-05-13
22:12:08 EDT,,0,ERROR,XX000,"xlog flush request 1D08/9B57FCD0 is not
satisfied --- flushed only to 1CEE/3C869588",,,,,"writing block > 0 of
relation base/16416/291498116",,,,""
> 2013-05-14 09:47:44.317 EDT,,,30911,,51919d78.78bf,3012,,2013-05-13
22:12:08 EDT,,0,ERROR,XX000,"xlog flush request 1D08/9B57FCD0 is not
satisfied --- flushed only to 1CEE/3C869588",,,,,"writing block > 0 of
relation base/16416/291498116",,,,""
> There are no earlier ERROR's in the logs.
> 2013-05-14 09:38:03.115 EDT,,,30911,,51919d78.78bf,1868,,2013-05-13
22:12:08 EDT,,0,ERROR,XX000,"xlog flush request 1D08/9B57FCD0 is not
satisfied --- flushed only to 1CEE/3C869588",,,,,"writing block > 0 of
relation base/16416/291498116",,,,""
> 2013-05-14 09:38:03.115 EDT,,,30911,,51919d78.78bf,1869,,2013-05-13
22:12:08 EDT,,0,WARNING,58030,"could not write block 0 of
base/16416/291498116","Multiple failures --- write error might be
> permanent.",,,,,,,,""

> The disk is not full nor are there any messages in the kernel logs.

The reason for this is that system is not able to flush XLOG upto requested
point, most likely, the requested flush point is past end of XLOG.
This has been seen to occur when a disk page has a corrupted LSN. (I am
quoting this from comment in code where the above error message occur)

So if XLOG is not flushed checkpointer will not flush even data of file
291498116.

It seems to me that your database where these errors are observed is
corrupted.

With Regards,
Amit Kapila.

On 14.05.2013 23:47, Benedikt Grundmann wrote:
> The only thing that is *new* is that we took the snapshot from the
> streaming replica.  So again my best guess as of now is that if the
> database crashes while it is in streaming standby a invalid disk state can
> result during during the following startup (in rare and as of now unclear
> circumstances).

A bug is certainly possible. There isn't much detail here to debug with, 
I'm afraid. Can you share the full logs on all three systems? I'm 
particularly interest

> You seem to be quite convinced that it must be LVM can you elaborate why?

Well, you said that there was a file in the original filesystem, but not 
in the snapshot. If you didn't do anything in between, then surely the 
snapshot is broken, if it skipped a file. Or was the file created in the 
original filesystem after the snapshot was taken? You probably left out 
some crucial details on how exactly the snapshot and rsync are 
performed. Can you share the scripts you're using?

Can you reproduce this problem with a new snapshot? Do you still have 
the failed snapshot unchanged?

- Heikki

On 15.05.2013 15:42, David Powers wrote:
> First, thanks for the replies.  This sort of thing is frustrating and hard
> to diagnose at a distance, and any help is appreciated.
>
> Here is some more background:
>
> We have 3 9.2.4 databases using the following setup:

The subject says 9.2.3. Are you sure you're running 9.2.4 on all the 
servers? There was a fix to a bug related to starting a standby server 
from a filesystem snapshot. I don't think it was quite the case you 
have, but pretty close.

> - A primary box
> - A standby box running as a hot streaming replica from the primary
> - A testing box restored nightly from a static backup
>
> As noted, the static backup is taken off of the standby by taking an LVM
> snapshot of the database filesystem and rsyncing.  I don't think it's a
> likely problem but the rsync leverages the previous backup (using
> --link-dest) to make the rsync faster and the resulting backup smaller.

I guess that should work, as long as you make a full copy when you 
restore the backup, and never start a postgres server directly against a 
backup that contains the hardlinks.

> We've been using the same system for quite some time, but previously (~ 1
> month ago) had been taking the backup off of the primary (still using the
> LVM snapshot).  The replication is a recent addition, and a very helpful
> one.  LVM snapshots aren't lightweight in the face of writes and in some
> circumstances a long running rsync would spike the IO load on the
> production box.
>
> Results of some additional tests:
>
> After the user noticed that the test restore showed the original problem we
> ran `vacuum analyze` on all three testing databases thinking that it had a
> good chance of quickly touching most of the underlying files.  That gave us
> errors on two of the testing restores similar to:
>
> ERROR:  invalid page header in block 5427 of relation base/16417/199732075

Huh, that's surprising. You have to be quite unlucky to end with a 
corrupt page header, even if there's something wrong with the underlying 
storage or backup routines. Could you grab a copy of that block? 
Something like

dd skip=5427 bs=8192 count=1 if=base/16417/199732075 of=corrupt-block

I'm especially curious what the first 20 bytes or so look like. I'm 
guessing that it's all zeros, while some later part of the page contains 
data. Ie. the page was torn at some point in the process.

> I'm also running the vacuum analyze on the production machines to double
> check that the base databases don't have a subtle corruption that simply
> hasn't been noticed.  They run with normal autovacuum settings, so I
> suspect that they are fine/this won't show anything because we should have
> seen this from the autovacuum daemon before.

Vacuum analyze doesn't always scan the whole table with default 
settings, so that's no proof that are no missing pages. "set 
vacuum_freeze_table_age=0; vacuum <table>" will force a full scan of the 
table.

> I'm happy to share the scripts we use for the backup/restore process if the
> information above isn't enough, as well as the logs - though the postgres
> logs don't seem to contain much of interest (the database system doesn't
> really get involved).

Yeah, please share the scripts. What you've described seems correct to 
me, but maybe there's something I'm missing.

> I also have the rsyncs of the failed snapshots available and could restore
> them for testing purposes.  It's also easy to look in them (they are just
> saved as normal directories on a big SAN) if I know what to look for.

Great. Not sure what to look at right now, but good that you have kept 
the evidence.

- Heikki

On 15.05.2013 22:50, Benedikt Grundmann wrote:
> On Wed, May 15, 2013 at 2:50 PM, Heikki Linnakangas<hlinnakangas@vmware.com
>> The subject says 9.2.3. Are you sure you're running 9.2.4 on all the
>> servers? There was a fix to a bug related to starting a standby server from
>> a filesystem snapshot. I don't think it was quite the case you have, but
>> pretty close.
>
> So this is delightfully embarrassing I just went back to double check and
>
> - primary box is 9.2.3
> - standby is 9.2.4
> - testing is 9.2.4
>
> I guess that alone could possibly explain it?

Hmm, no, it should still work. There haven't been any changes in the WAL 
format. I do recommend upgrading the primary, of course, but I don't 
really see how that would explain what you're seeing.

- Heikki

On Tue, May 21, 2013 at 11:59 AM, Benedikt Grundmann
<bgrundmann@janestreet.com> wrote:
> We are seeing these errors on a regular basis on the testing box now.  We
> have even changed the backup script to
> shutdown the hot standby, take lvm snapshot, restart the hot standby, rsync
> the lvm snapshot.  It still happens.
>
> We have never seen this before we introduced the hot standby.  So we will
> now revert to taking the backups from lvm snapshots on the production
> database.  If you have ideas of what else we should try / what information
> we can give you to debug this let us know and we will try to so.
>
> Until then we will sadly operate on the assumption that the combination of
> hot standby and "frozen snapshot" backup of it is not production ready.

I'm pretty suspicious that your backup procedure is messed up in some
way.  The fact that you got invalid page headers is really difficult
to attribute to a PostgreSQL bug.  A number of the other messages that
you have posted also tend to indicate either corruption, or that WAL
replay has stopped early.  It would be interesting to see the logs
from when the clone was first started up, juxtaposed against the later
WAL flush error messages.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Tue, May 28, 2013 at 10:53 AM, Benedikt Grundmann
<bgrundmann@janestreet.com> wrote:
> Today we have seen
>
> 2013-05-28 04:11:12.300 EDT,,,30600,,51a41946.7788,1,,2013-05-27 22:41:10
> EDT,,0,ERROR,XX000,"xlog flush request 1E95/AFB2DB10 is not satisfied ---
> flushed only to 1E7E/21CB79A0",,,,,"writing block 9 of relation
> base/16416/293974676",,,,""
> 2013-05-28 04:11:13.316 EDT,,,30600,,51a41946.7788,2,,2013-05-27 22:41:10
> EDT,,0,ERROR,XX000,"xlog flush request 1E95/AFB2DB10 is not satisfied ---
> flushed only to 1E7E/21CB79A0",,,,,"writing block 9 of relation
> base/16416/293974676",,,,""
>
> while taking the backup of the primary.  We have been running for a few days
> like that and today is the first day where we see these problems again.  So
> it's not entirely deterministic / we don't know yet what we have to do to
> reproduce.
>
> So this makes Robert's theory more likely.  However we have also using this
> method (LVM + rsync with hardlinks from primary) for years without these
> problems.  So the big question is what changed?

Well... I don't know.  But my guess is there's something wrong with
the way you're using hardlinks.  Remember, a hardlink means two
logical pointers to the same file on disk.  So if either file gets
modified after the fact, then the other pointer is going to see the
changes.  The xlog flush request not satisfied stuff could happen if,
for example, the backup is pointing to a file, and the primary is
pointing to the same file, and the primary modifies the file after the
backup is taken (thus modifying the backup after-the-fact).

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company