XFS CRC errors after a crash

XFS CRC errors after a crash

[Jan Kara]

  Hello,

  so I've been crash-testing XFS (just killing KVM with XFS filesystem
mounted) a bit with V5 superblock enabled in 3.16-rc1 and I can pretty
easily hit CRC mismatches after that. Kernel complains like:
[518184.794175] XFS (sdb3): Mounting V5 Filesystem
[518184.902898] XFS (sdb3): Starting recovery (logdev: internal)
[518187.118860] XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
[518187.118870] XFS (sdb3): Unmount and run xfs_repair
[518187.118875] XFS (sdb3): First 64 bytes of corrupted metadata buffer:
[518187.118882] ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
[518187.118887] ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
[518187.118891] ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
[518187.118895] ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
[518187.118923] XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1

So it seem like the checksum doesn't get updated properly in all the cases.
Looking into the logdump, there doesn't seem to be any modifications for
this AGF block in unrelayed part of the log but there are some modifications
in the older parts of the log - the latest LSN where block 1 was updated is
1,4639 (and the buffer contents in the log corresponds to the data I see in
block 1). However the lsn field in AGF structure in that block shows 1,3616
so that really seems stale (and I've checked and in that transaction the
block has been modified as well).

I'm looking into how the mismatch could happen but if anybody more
knowledgeable wants to have a look I have an unmodified fs image available
(however it has ~20G so if there's a way to make that smaller it would be
good).

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: XFS CRC errors after a crash

[Dave Chinner]

On Wed, Jun 25, 2014 at 06:49:39PM +0200, Jan Kara wrote:
>   Hello,
> 
>   so I've been crash-testing XFS (just killing KVM with XFS filesystem
> mounted) a bit with V5 superblock enabled in 3.16-rc1 and I can pretty
> easily hit CRC mismatches after that. Kernel complains like:

Yes, we had that reported yesterday by another person, using virtual
box. I've been unable to reproduce it on my local KVM VMs, so I'm
wondering what your configuration KVM configuration is?

> [518184.794175] XFS (sdb3): Mounting V5 Filesystem
> [518184.902898] XFS (sdb3): Starting recovery (logdev: internal)
> [518187.118860] XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
> [518187.118870] XFS (sdb3): Unmount and run xfs_repair
> [518187.118875] XFS (sdb3): First 64 bytes of corrupted metadata buffer:
> [518187.118882] ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
> [518187.118887] ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
> [518187.118891] ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
> [518187.118895] ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
> [518187.118923] XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1
> 
> So it seem like the checksum doesn't get updated properly in all the cases.
> Looking into the logdump, there doesn't seem to be any modifications for
> this AGF block in unrelayed part of the log but there are some modifications
> in the older parts of the log - the latest LSN where block 1 was updated is
> 1,4639 (and the buffer contents in the log corresponds to the data I see in
> block 1). However the lsn field in AGF structure in that block shows 1,3616
> so that really seems stale (and I've checked and in that transaction the
> block has been modified as well).

That tallies with what has been reported -it was the AGI block,
however. What I know so far is that the CRC matches for the version
of the structure logged at the apparent LSN, but the data is more
recent.

Now the only way I can see the data getting updated without the LSN
being updates is through log recovery, the analysis is here:

http://oss.sgi.com/pipermail/xfs/2014-June/036938.html

At the bottom of the email is a request for a information resulting
from a reproduction cycle. Can you run that cycle and provide the
metadumps and dmesg when a problem is first found?

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: XFS CRC errors after a crash

[Jan Kara]

On Thu 26-06-14 07:59:52, Dave Chinner wrote:
> On Wed, Jun 25, 2014 at 06:49:39PM +0200, Jan Kara wrote:
> >   Hello,
> > 
> >   so I've been crash-testing XFS (just killing KVM with XFS filesystem
> > mounted) a bit with V5 superblock enabled in 3.16-rc1 and I can pretty
> > easily hit CRC mismatches after that. Kernel complains like:
> 
> Yes, we had that reported yesterday by another person, using virtual
> box. I've been unable to reproduce it on my local KVM VMs, so I'm
> wondering what your configuration KVM configuration is?
  I'm running the qemu as:
qemu-kvm -m 2048 -smp 6 -drive file=/dev/sdb,if=virtio,cache=none -net
nic,macaddr=00:16:3e:32:96:20,model=virtio -net
tap,script=/root/tests/bin/qemu-setup-net -vnc :1 -serial file:serial.log
-kernel /boot/vmlinuz-autotest -initrd /boot/initrd-autotest -append
'root=/dev/vda3 rootflags=relatime'

> > [518184.794175] XFS (sdb3): Mounting V5 Filesystem
> > [518184.902898] XFS (sdb3): Starting recovery (logdev: internal)
> > [518187.118860] XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
> > [518187.118870] XFS (sdb3): Unmount and run xfs_repair
> > [518187.118875] XFS (sdb3): First 64 bytes of corrupted metadata buffer:
> > [518187.118882] ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
> > [518187.118887] ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
> > [518187.118891] ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
> > [518187.118895] ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
> > [518187.118923] XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1
> > 
> > So it seem like the checksum doesn't get updated properly in all the cases.
> > Looking into the logdump, there doesn't seem to be any modifications for
> > this AGF block in unrelayed part of the log but there are some modifications
> > in the older parts of the log - the latest LSN where block 1 was updated is
> > 1,4639 (and the buffer contents in the log corresponds to the data I see in
> > block 1). However the lsn field in AGF structure in that block shows 1,3616
> > so that really seems stale (and I've checked and in that transaction the
> > block has been modified as well).
> 
> That tallies with what has been reported -it was the AGI block,
> however. What I know so far is that the CRC matches for the version
> of the structure logged at the apparent LSN, but the data is more
> recent.
  Yes, this is the case with my corruption as well.

> Now the only way I can see the data getting updated without the LSN
> being updates is through log recovery, the analysis is here:
  Yes, that's what I originally though as well but for me:
log tail: 8960 head: 10080 state: <DIRTY>
  and the problematic AGF has last been modified in lsn 1,4639 (and it
contains data logged there, while agf_lsn field is set to 1,3616). So it
seems recovery shouldn't replay lsn 4639? And since in my case kernel
complains about CRC mismatch during log recovery and log tail is updated
only after successful replay, we should see log as it was before an attempt
to mount the fs? Anyway, I'll try to reproduce with the procedure you
describe in the email below to make things clearer.

> http://oss.sgi.com/pipermail/xfs/2014-June/036938.html
> 
> At the bottom of the email is a request for a information resulting
> from a reproduction cycle. Can you run that cycle and provide the
> metadumps and dmesg when a problem is first found?

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: XFS CRC errors after a crash

[Dave Chinner]

On Thu, Jun 26, 2014 at 10:20:46PM +0200, Jan Kara wrote:
> On Thu 26-06-14 07:59:52, Dave Chinner wrote:
> > On Wed, Jun 25, 2014 at 06:49:39PM +0200, Jan Kara wrote:
> > >   Hello,
> > > 
> > >   so I've been crash-testing XFS (just killing KVM with XFS filesystem
> > > mounted) a bit with V5 superblock enabled in 3.16-rc1 and I can pretty
> > > easily hit CRC mismatches after that. Kernel complains like:
> > 
> > Yes, we had that reported yesterday by another person, using virtual
> > box. I've been unable to reproduce it on my local KVM VMs, so I'm
> > wondering what your configuration KVM configuration is?
>   I'm running the qemu as:
> qemu-kvm -m 2048 -smp 6 -drive file=/dev/sdb,if=virtio,cache=none -net
> nic,macaddr=00:16:3e:32:96:20,model=virtio -net
> tap,script=/root/tests/bin/qemu-setup-net -vnc :1 -serial file:serial.log
> -kernel /boot/vmlinuz-autotest -initrd /boot/initrd-autotest -append
> 'root=/dev/vda3 rootflags=relatime'

Ok, so you are testing directly on a block device via virtio, using
direct IO. Hmmm _ I'm using virtio,cache=none on image files on XFS,
so I can't see that there's be much difference there. Nothing else
stands out - I'm assuming that you're not using the "nobarrier"
mount option?

> > > [518184.794175] XFS (sdb3): Mounting V5 Filesystem
> > > [518184.902898] XFS (sdb3): Starting recovery (logdev: internal)
> > > [518187.118860] XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
> > > [518187.118870] XFS (sdb3): Unmount and run xfs_repair
> > > [518187.118875] XFS (sdb3): First 64 bytes of corrupted metadata buffer:
> > > [518187.118882] ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
> > > [518187.118887] ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
> > > [518187.118891] ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
> > > [518187.118895] ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
> > > [518187.118923] XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1
> > > 
> > > So it seem like the checksum doesn't get updated properly in all the cases.
> > > Looking into the logdump, there doesn't seem to be any modifications for
> > > this AGF block in unrelayed part of the log but there are some modifications
> > > in the older parts of the log - the latest LSN where block 1 was updated is
> > > 1,4639 (and the buffer contents in the log corresponds to the data I see in
> > > block 1). However the lsn field in AGF structure in that block shows 1,3616
> > > so that really seems stale (and I've checked and in that transaction the
> > > block has been modified as well).
> > 
> > That tallies with what has been reported -it was the AGI block,
> > however. What I know so far is that the CRC matches for the version
> > of the structure logged at the apparent LSN, but the data is more
> > recent.
>   Yes, this is the case with my corruption as well.
> 
> > Now the only way I can see the data getting updated without the LSN
> > being updates is through log recovery, the analysis is here:
>   Yes, that's what I originally though as well but for me:
> log tail: 8960 head: 10080 state: <DIRTY>
>   and the problematic AGF has last been modified in lsn 1,4639 (and it
> contains data logged there, while agf_lsn field is set to 1,3616). So it
> seems recovery shouldn't replay lsn 4639?

No, what that tells me is that a previous log recovery replayed the
change at lsn 4639. Log recovery does not update the lsn in the
object because if log recovery fails we need to run it completely
from tail to head again, and we want it to rewrite all the changes
appropriately. If we update the lsn each time we recover a change,
then this won't happen.

Hence a sign of an object that has been recovered is that there is
newer data than the LSN indicates. The issue here is that the CRC
does not appear to have been updated, and I can't work out how that
can occur - log recovery of a buffer will see the appropriate magic
number, add the correct verifier, and when the recovered data is
written it will recalc the CRC first.

That's why I send the debug patch to catch buffer writes that didn't
have verifier ops attached. (attached below again for you). If that
fires at any time, then we have a smoking gun. But if it doesn't
fire and you still see CRC mismatches then we've got something
extremely subtle

> And since in my case kernel
> complains about CRC mismatch during log recovery and log tail is updated
> only after successful replay, we should see log as it was before an attempt
> to mount the fs?

It depends. The log should be unchanged if it fails in the first phase of
recovery. It's not until the first checkpoint during the second
phase that the log tail gets updated on disk (after EFI recovery),
so a failure in EFI or unlinked inode recovery can result in the log
tail moving.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

xfs: spew warnings when writing cached buffers without a verifier

Signed-off-by: Dave Chinner <dchinner@redhat.com>
---
 fs/xfs/xfs_buf.c | 6 ++++++
 fs/xfs/xfs_log.c | 7 ++++++-
 2 files changed, 12 insertions(+), 1 deletion(-)

diff --git a/fs/xfs/xfs_buf.c b/fs/xfs/xfs_buf.c
index a6dc83e..95e5516 100644
--- a/fs/xfs/xfs_buf.c
+++ b/fs/xfs/xfs_buf.c
@@ -1330,6 +1330,12 @@ _xfs_buf_ioapply(
 						   SHUTDOWN_CORRUPT_INCORE);
 				return;
 			}
+		} else if (bp->b_bn != -1LL) {
+			xfs_warn(bp->b_target->bt_mount,
+				"%s: no ops on block 0x%llx/0x%llx",
+				__func__, bp->b_bn, bp->b_maps[0].bm_bn);
+			xfs_hex_dump(bp->b_addr, 64);
+			dump_stack();
 		}
 	} else if (bp->b_flags & XBF_READ_AHEAD) {
 		rw = READA;
diff --git a/fs/xfs/xfs_log.c b/fs/xfs/xfs_log.c
index 7647818..ecf2048 100644
--- a/fs/xfs/xfs_log.c
+++ b/fs/xfs/xfs_log.c
@@ -1369,8 +1369,13 @@ xlog_alloc_log(
 
 	xlog_get_iclog_buffer_size(mp, log);
 
+	/*
+	 * Use a block number of -1 for the extra log buffer used during splits
+	 * so that it will trigger errors if we ever try to do IO on it without
+	 * first having set it up properly.
+	 */
 	error = -ENOMEM;
-	bp = xfs_buf_alloc(mp->m_logdev_targp, 0, BTOBB(log->l_iclog_size), 0);
+	bp = xfs_buf_alloc(mp->m_logdev_targp, -1LL, BTOBB(log->l_iclog_size), 0);
 	if (!bp)
 		goto out_free_log;
 

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: XFS CRC errors after a crash

[Jan Kara]

[-- Attachment #1: Type: text/plain, Size: 5825 bytes --]

On Fri 27-06-14 09:18:43, Dave Chinner wrote:
> On Thu, Jun 26, 2014 at 10:20:46PM +0200, Jan Kara wrote:
> > On Thu 26-06-14 07:59:52, Dave Chinner wrote:
> > > On Wed, Jun 25, 2014 at 06:49:39PM +0200, Jan Kara wrote:
> > > >   Hello,
> > > > 
> > > >   so I've been crash-testing XFS (just killing KVM with XFS filesystem
> > > > mounted) a bit with V5 superblock enabled in 3.16-rc1 and I can pretty
> > > > easily hit CRC mismatches after that. Kernel complains like:
> > > 
> > > Yes, we had that reported yesterday by another person, using virtual
> > > box. I've been unable to reproduce it on my local KVM VMs, so I'm
> > > wondering what your configuration KVM configuration is?
> >   I'm running the qemu as:
> > qemu-kvm -m 2048 -smp 6 -drive file=/dev/sdb,if=virtio,cache=none -net
> > nic,macaddr=00:16:3e:32:96:20,model=virtio -net
> > tap,script=/root/tests/bin/qemu-setup-net -vnc :1 -serial file:serial.log
> > -kernel /boot/vmlinuz-autotest -initrd /boot/initrd-autotest -append
> > 'root=/dev/vda3 rootflags=relatime'
> 
> Ok, so you are testing directly on a block device via virtio, using
> direct IO. Hmmm _ I'm using virtio,cache=none on image files on XFS,
> so I can't see that there's be much difference there. Nothing else
> stands out - I'm assuming that you're not using the "nobarrier"
> mount option?
  No, I'm not using nobarrier.

> > > > [518184.794175] XFS (sdb3): Mounting V5 Filesystem
> > > > [518184.902898] XFS (sdb3): Starting recovery (logdev: internal)
> > > > [518187.118860] XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
> > > > [518187.118870] XFS (sdb3): Unmount and run xfs_repair
> > > > [518187.118875] XFS (sdb3): First 64 bytes of corrupted metadata buffer:
> > > > [518187.118882] ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
> > > > [518187.118887] ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
> > > > [518187.118891] ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
> > > > [518187.118895] ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
> > > > [518187.118923] XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1
> > > > 
> > > > So it seem like the checksum doesn't get updated properly in all the cases.
> > > > Looking into the logdump, there doesn't seem to be any modifications for
> > > > this AGF block in unrelayed part of the log but there are some modifications
> > > > in the older parts of the log - the latest LSN where block 1 was updated is
> > > > 1,4639 (and the buffer contents in the log corresponds to the data I see in
> > > > block 1). However the lsn field in AGF structure in that block shows 1,3616
> > > > so that really seems stale (and I've checked and in that transaction the
> > > > block has been modified as well).
> > > 
> > > That tallies with what has been reported -it was the AGI block,
> > > however. What I know so far is that the CRC matches for the version
> > > of the structure logged at the apparent LSN, but the data is more
> > > recent.
> >   Yes, this is the case with my corruption as well.
> > 
> > > Now the only way I can see the data getting updated without the LSN
> > > being updates is through log recovery, the analysis is here:
> >   Yes, that's what I originally though as well but for me:
> > log tail: 8960 head: 10080 state: <DIRTY>
> >   and the problematic AGF has last been modified in lsn 1,4639 (and it
> > contains data logged there, while agf_lsn field is set to 1,3616). So it
> > seems recovery shouldn't replay lsn 4639?
> 
> No, what that tells me is that a previous log recovery replayed the
> change at lsn 4639. Log recovery does not update the lsn in the
> object because if log recovery fails we need to run it completely
> from tail to head again, and we want it to rewrite all the changes
> appropriately. If we update the lsn each time we recover a change,
> then this won't happen.
> 
> Hence a sign of an object that has been recovered is that there is
> newer data than the LSN indicates. The issue here is that the CRC
> does not appear to have been updated, and I can't work out how that
> can occur - log recovery of a buffer will see the appropriate magic
> number, add the correct verifier, and when the recovered data is
> written it will recalc the CRC first.
> 
> That's why I send the debug patch to catch buffer writes that didn't
> have verifier ops attached. (attached below again for you). If that
> fires at any time, then we have a smoking gun. But if it doesn't
> fire and you still see CRC mismatches then we've got something
> extremely subtle
  OK, so I've reproduced the issue again and after some investigation found
at least one issue in log recovery code (your debug assertions have
tripped): In the case reproduced now, I had a log with one transaction
containing the AGF buffer however the AGF buffer on disk already had the data
from that transaction written (and had agf_lsn set appropriately). Log
replay then read-ahead the buffer (that leaves b_ops at NULL), then after
investigation of the log item found it shouldn't be replayed and never
ended up calling xlog_recover_validate_buf_type() to set proper b_ops.
Later when we removed orphan inodes (I'm not sure about proper xfs
terminology), AGF was modified and written without proper verifiers set.

The attached patch fixes the problem for me (at least this particular case
of corruption). Since I'm on vacation already and it's late I'll leave it for
now. If the problem needs to be fixed differently, feel free to modify /
discard the attached patch (since I will be scarcely on email for following
two weeks).

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

[-- Attachment #2: 0001-xfs-Fix-CRC-errors-after-unclean-umount.patch --]
[-- Type: text/x-patch, Size: 1648 bytes --]

>From 7d1c4c0ee7f8b6734d41d857b7c8dd94e6b55b4e Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.cz>
Date: Fri, 27 Jun 2014 23:27:11 +0200
Subject: [PATCH] xfs: Fix CRC errors after unclean umount

After unclean shutdown and log recovery filesystem checker reports CRC
errors in AGI or AGF blocks. The problem is that we don't properly set
buffer verifiers when replay of some log item is skipped because the lsn
of the transaction is less than or equal to lsn stored in the
corresponding AGI / AGF. Thus next time the AGI / AGF buffer is modified
(e.g. during unlinked inode removal) it is written to disk without updating
the CRC and lsn.

Fix the problem by setting proper buffer verifiers even if we skip
replay of the log item.

Signed-off-by: Jan Kara <jack@suse.cz>
---
 fs/xfs/xfs_log_recover.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

diff --git a/fs/xfs/xfs_log_recover.c b/fs/xfs/xfs_log_recover.c
index 981af0f6504b..feb9330962f1 100644
--- a/fs/xfs/xfs_log_recover.c
+++ b/fs/xfs/xfs_log_recover.c
@@ -2508,8 +2508,15 @@ xlog_recover_buffer_pass2(
 	 * the lsn of the transaction we are replaying.
 	 */
 	lsn = xlog_recover_get_buf_lsn(mp, bp);
-	if (lsn && lsn != -1 && XFS_LSN_CMP(lsn, current_lsn) >= 0)
+	if (lsn && lsn != -1 && XFS_LSN_CMP(lsn, current_lsn) >= 0) {
+		if (xfs_sb_version_hascrc(&mp->m_sb)) {
+			if (buf_f->blf_flags & XFS_BLF_INODE_BUF)
+				bp->b_ops = &xfs_inode_buf_ops;
+			else
+				xlog_recover_validate_buf_type(mp, bp, buf_f);
+		}
 		goto out_release;
+	}
 
 	if (buf_f->blf_flags & XFS_BLF_INODE_BUF) {
 		error = xlog_recover_do_inode_buffer(mp, item, bp, buf_f);
-- 
1.8.1.4


[-- Attachment #3: Type: text/plain, Size: 121 bytes --]

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: XFS CRC errors after a crash

[Dave Chinner]

On Fri, Jun 27, 2014 at 11:35:24PM +0200, Jan Kara wrote:
> On Fri 27-06-14 09:18:43, Dave Chinner wrote:
> > On Thu, Jun 26, 2014 at 10:20:46PM +0200, Jan Kara wrote:
> > > On Thu 26-06-14 07:59:52, Dave Chinner wrote:
> > > > On Wed, Jun 25, 2014 at 06:49:39PM +0200, Jan Kara wrote:
> > > > >   Hello,
> > > > > 
> > > > >   so I've been crash-testing XFS (just killing KVM with XFS filesystem
> > > > > mounted) a bit with V5 superblock enabled in 3.16-rc1 and I can pretty
> > > > > easily hit CRC mismatches after that. Kernel complains like:
> > > > 
> > > > Yes, we had that reported yesterday by another person, using virtual
> > > > box. I've been unable to reproduce it on my local KVM VMs, so I'm
> > > > wondering what your configuration KVM configuration is?
> > >   I'm running the qemu as:
> > > qemu-kvm -m 2048 -smp 6 -drive file=/dev/sdb,if=virtio,cache=none -net
> > > nic,macaddr=00:16:3e:32:96:20,model=virtio -net
> > > tap,script=/root/tests/bin/qemu-setup-net -vnc :1 -serial file:serial.log
> > > -kernel /boot/vmlinuz-autotest -initrd /boot/initrd-autotest -append
> > > 'root=/dev/vda3 rootflags=relatime'
> > 
> > Ok, so you are testing directly on a block device via virtio, using
> > direct IO. Hmmm _ I'm using virtio,cache=none on image files on XFS,
> > so I can't see that there's be much difference there. Nothing else
> > stands out - I'm assuming that you're not using the "nobarrier"
> > mount option?
>   No, I'm not using nobarrier.
> 
> > > > > [518184.794175] XFS (sdb3): Mounting V5 Filesystem
> > > > > [518184.902898] XFS (sdb3): Starting recovery (logdev: internal)
> > > > > [518187.118860] XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
> > > > > [518187.118870] XFS (sdb3): Unmount and run xfs_repair
> > > > > [518187.118875] XFS (sdb3): First 64 bytes of corrupted metadata buffer:
> > > > > [518187.118882] ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
> > > > > [518187.118887] ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
> > > > > [518187.118891] ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
> > > > > [518187.118895] ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
> > > > > [518187.118923] XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1
> > > > > 
> > > > > So it seem like the checksum doesn't get updated properly in all the cases.
> > > > > Looking into the logdump, there doesn't seem to be any modifications for
> > > > > this AGF block in unrelayed part of the log but there are some modifications
> > > > > in the older parts of the log - the latest LSN where block 1 was updated is
> > > > > 1,4639 (and the buffer contents in the log corresponds to the data I see in
> > > > > block 1). However the lsn field in AGF structure in that block shows 1,3616
> > > > > so that really seems stale (and I've checked and in that transaction the
> > > > > block has been modified as well).
> > > > 
> > > > That tallies with what has been reported -it was the AGI block,
> > > > however. What I know so far is that the CRC matches for the version
> > > > of the structure logged at the apparent LSN, but the data is more
> > > > recent.
> > >   Yes, this is the case with my corruption as well.
> > > 
> > > > Now the only way I can see the data getting updated without the LSN
> > > > being updates is through log recovery, the analysis is here:
> > >   Yes, that's what I originally though as well but for me:
> > > log tail: 8960 head: 10080 state: <DIRTY>
> > >   and the problematic AGF has last been modified in lsn 1,4639 (and it
> > > contains data logged there, while agf_lsn field is set to 1,3616). So it
> > > seems recovery shouldn't replay lsn 4639?
> > 
> > No, what that tells me is that a previous log recovery replayed the
> > change at lsn 4639. Log recovery does not update the lsn in the
> > object because if log recovery fails we need to run it completely
> > from tail to head again, and we want it to rewrite all the changes
> > appropriately. If we update the lsn each time we recover a change,
> > then this won't happen.
> > 
> > Hence a sign of an object that has been recovered is that there is
> > newer data than the LSN indicates. The issue here is that the CRC
> > does not appear to have been updated, and I can't work out how that
> > can occur - log recovery of a buffer will see the appropriate magic
> > number, add the correct verifier, and when the recovered data is
> > written it will recalc the CRC first.
> > 
> > That's why I send the debug patch to catch buffer writes that didn't
> > have verifier ops attached. (attached below again for you). If that
> > fires at any time, then we have a smoking gun. But if it doesn't
> > fire and you still see CRC mismatches then we've got something
> > extremely subtle
>   OK, so I've reproduced the issue again and after some investigation found
> at least one issue in log recovery code (your debug assertions have
> tripped):

Ok, I am going to make that debug patch a permanent "feature" seeing
as it proved useful in tracking down this bug.

> In the case reproduced now, I had a log with one transaction
> containing the AGF buffer however the AGF buffer on disk already had the data
> from that transaction written (and had agf_lsn set appropriately). Log
> replay then read-ahead the buffer (that leaves b_ops at NULL), then after
> investigation of the log item found it shouldn't be replayed and never
> ended up calling xlog_recover_validate_buf_type() to set proper b_ops.
> Later when we removed orphan inodes (I'm not sure about proper xfs
> terminology), AGF was modified and written without proper verifiers set.

Ok, that also explains why we've been seeing it in AGF, AGI and
related ABT/IBT buffers and not in any other type of buffer. So you
analysis definitely fits the symptoms reported.

> The attached patch fixes the problem for me (at least this particular case
> of corruption). Since I'm on vacation already and it's late I'll leave it for
> now. If the problem needs to be fixed differently, feel free to modify /
> discard the attached patch (since I will be scarcely on email for following
> two weeks).

I might end up fixing it differently, but you'll get the credit for
finding debugging the problem. Many thanks, Jan, I owe you a beer or
two for finding this. :)

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: XFS CRC errors after a crash

[Jan Kara]

On Sat 28-06-14 10:29:47, Dave Chinner wrote:
> On Fri, Jun 27, 2014 at 11:35:24PM +0200, Jan Kara wrote:
> > On Fri 27-06-14 09:18:43, Dave Chinner wrote:
> > > On Thu, Jun 26, 2014 at 10:20:46PM +0200, Jan Kara wrote:
> > > > On Thu 26-06-14 07:59:52, Dave Chinner wrote:
> > > > > On Wed, Jun 25, 2014 at 06:49:39PM +0200, Jan Kara wrote:
> > > > > >   Hello,
> > > > > > 
> > > > > >   so I've been crash-testing XFS (just killing KVM with XFS filesystem
> > > > > > mounted) a bit with V5 superblock enabled in 3.16-rc1 and I can pretty
> > > > > > easily hit CRC mismatches after that. Kernel complains like:
> > > > > 
> > > > > Yes, we had that reported yesterday by another person, using virtual
> > > > > box. I've been unable to reproduce it on my local KVM VMs, so I'm
> > > > > wondering what your configuration KVM configuration is?
> > > >   I'm running the qemu as:
> > > > qemu-kvm -m 2048 -smp 6 -drive file=/dev/sdb,if=virtio,cache=none -net
> > > > nic,macaddr=00:16:3e:32:96:20,model=virtio -net
> > > > tap,script=/root/tests/bin/qemu-setup-net -vnc :1 -serial file:serial.log
> > > > -kernel /boot/vmlinuz-autotest -initrd /boot/initrd-autotest -append
> > > > 'root=/dev/vda3 rootflags=relatime'
> > > 
> > > Ok, so you are testing directly on a block device via virtio, using
> > > direct IO. Hmmm _ I'm using virtio,cache=none on image files on XFS,
> > > so I can't see that there's be much difference there. Nothing else
> > > stands out - I'm assuming that you're not using the "nobarrier"
> > > mount option?
> >   No, I'm not using nobarrier.
> > 
> > > > > > [518184.794175] XFS (sdb3): Mounting V5 Filesystem
> > > > > > [518184.902898] XFS (sdb3): Starting recovery (logdev: internal)
> > > > > > [518187.118860] XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
> > > > > > [518187.118870] XFS (sdb3): Unmount and run xfs_repair
> > > > > > [518187.118875] XFS (sdb3): First 64 bytes of corrupted metadata buffer:
> > > > > > [518187.118882] ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
> > > > > > [518187.118887] ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
> > > > > > [518187.118891] ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
> > > > > > [518187.118895] ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
> > > > > > [518187.118923] XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1
> > > > > > 
> > > > > > So it seem like the checksum doesn't get updated properly in all the cases.
> > > > > > Looking into the logdump, there doesn't seem to be any modifications for
> > > > > > this AGF block in unrelayed part of the log but there are some modifications
> > > > > > in the older parts of the log - the latest LSN where block 1 was updated is
> > > > > > 1,4639 (and the buffer contents in the log corresponds to the data I see in
> > > > > > block 1). However the lsn field in AGF structure in that block shows 1,3616
> > > > > > so that really seems stale (and I've checked and in that transaction the
> > > > > > block has been modified as well).
> > > > > 
> > > > > That tallies with what has been reported -it was the AGI block,
> > > > > however. What I know so far is that the CRC matches for the version
> > > > > of the structure logged at the apparent LSN, but the data is more
> > > > > recent.
> > > >   Yes, this is the case with my corruption as well.
> > > > 
> > > > > Now the only way I can see the data getting updated without the LSN
> > > > > being updates is through log recovery, the analysis is here:
> > > >   Yes, that's what I originally though as well but for me:
> > > > log tail: 8960 head: 10080 state: <DIRTY>
> > > >   and the problematic AGF has last been modified in lsn 1,4639 (and it
> > > > contains data logged there, while agf_lsn field is set to 1,3616). So it
> > > > seems recovery shouldn't replay lsn 4639?
> > > 
> > > No, what that tells me is that a previous log recovery replayed the
> > > change at lsn 4639. Log recovery does not update the lsn in the
> > > object because if log recovery fails we need to run it completely
> > > from tail to head again, and we want it to rewrite all the changes
> > > appropriately. If we update the lsn each time we recover a change,
> > > then this won't happen.
> > > 
> > > Hence a sign of an object that has been recovered is that there is
> > > newer data than the LSN indicates. The issue here is that the CRC
> > > does not appear to have been updated, and I can't work out how that
> > > can occur - log recovery of a buffer will see the appropriate magic
> > > number, add the correct verifier, and when the recovered data is
> > > written it will recalc the CRC first.
> > > 
> > > That's why I send the debug patch to catch buffer writes that didn't
> > > have verifier ops attached. (attached below again for you). If that
> > > fires at any time, then we have a smoking gun. But if it doesn't
> > > fire and you still see CRC mismatches then we've got something
> > > extremely subtle
> >   OK, so I've reproduced the issue again and after some investigation found
> > at least one issue in log recovery code (your debug assertions have
> > tripped):
> 
> Ok, I am going to make that debug patch a permanent "feature" seeing
> as it proved useful in tracking down this bug.
> 
> > In the case reproduced now, I had a log with one transaction
> > containing the AGF buffer however the AGF buffer on disk already had the data
> > from that transaction written (and had agf_lsn set appropriately). Log
> > replay then read-ahead the buffer (that leaves b_ops at NULL), then after
> > investigation of the log item found it shouldn't be replayed and never
> > ended up calling xlog_recover_validate_buf_type() to set proper b_ops.
> > Later when we removed orphan inodes (I'm not sure about proper xfs
> > terminology), AGF was modified and written without proper verifiers set.
> 
> Ok, that also explains why we've been seeing it in AGF, AGI and
> related ABT/IBT buffers and not in any other type of buffer. So you
> analysis definitely fits the symptoms reported.
> 
> > The attached patch fixes the problem for me (at least this particular case
> > of corruption). Since I'm on vacation already and it's late I'll leave it for
> > now. If the problem needs to be fixed differently, feel free to modify /
> > discard the attached patch (since I will be scarcely on email for following
> > two weeks).
> 
> I might end up fixing it differently, but you'll get the credit for
> finding debugging the problem. Many thanks, Jan, I owe you a beer or
> two for finding this. :)
  Dave, I don't see my or any alternative fix in XFS git tree. Did this get
missed? I think it would be good to include the fix with the batch of fixes
you're planning to send to Linus...

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: XFS CRC errors after a crash

[Dave Chinner]

On Wed, Jul 16, 2014 at 10:32:10PM +0200, Jan Kara wrote:
> On Sat 28-06-14 10:29:47, Dave Chinner wrote:
> > On Fri, Jun 27, 2014 at 11:35:24PM +0200, Jan Kara wrote:
> > > On Fri 27-06-14 09:18:43, Dave Chinner wrote:
> > > > On Thu, Jun 26, 2014 at 10:20:46PM +0200, Jan Kara wrote:
> > > The attached patch fixes the problem for me (at least this particular case
> > > of corruption). Since I'm on vacation already and it's late I'll leave it for
> > > now. If the problem needs to be fixed differently, feel free to modify /
> > > discard the attached patch (since I will be scarcely on email for following
> > > two weeks).
> > 
> > I might end up fixing it differently, but you'll get the credit for
> > finding debugging the problem. Many thanks, Jan, I owe you a beer or
> > two for finding this. :)
>   Dave, I don't see my or any alternative fix in XFS git tree. Did this get
> missed? I think it would be good to include the fix with the batch of fixes
> you're planning to send to Linus...

No, it hasn't been missed, I have a different fix that I'm testing,
but I've kind of had bigger issues to sort out over the past couple
of weeks. I've also had trouble reproducing the issue, so it's been
slow testing that it actually works correctly. And it's got to go
back to -stable kernels, which means a couple of weeks here or there
doesn't make much difference.

The patch I'm testing is below.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

xfs: ensure verifiers are attached to recovered buffers

From: Dave Chinner <dchinner@redhat.com>

Crash testing of CRC enabled filesystems has resulted in a number of
reports of bad CRCs being detected after the filesystem was mounted.
Errors such as the following were being seen:

XFS (sdb3): Mounting V5 Filesystem
XFS (sdb3): Starting recovery (logdev: internal)
XFS (sdb3): Metadata CRC error detected at xfs_agf_read_verify+0x5a/0x100 [xfs], block 0x1
XFS (sdb3): Unmount and run xfs_repair
XFS (sdb3): First 64 bytes of corrupted metadata buffer:
ffff880136ffd600: 58 41 47 46 00 00 00 01 00 00 00 00 00 0f aa 40  XAGF...........@
ffff880136ffd610: 00 02 6d 53 00 02 77 f8 00 00 00 00 00 00 00 01  ..mS..w.........
ffff880136ffd620: 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 03  ................
ffff880136ffd630: 00 00 00 04 00 08 81 d0 00 08 81 a7 00 00 00 00  ................
XFS (sdb3): metadata I/O error: block 0x1 ("xfs_trans_read_buf_map") error 74 numblks 1

The errors were typically being seen in AGF, AGI and their related
btree block buffers some time after log recovery had run. Often it
wasn't until later subsequent mounts that the problem was
discovered. The common symptom was a buffer with the correct
contents, but a CRC and an LSN that matched an older version of the
contents.

Some debug added to _xfs_buf_ioapply() indicated that buffers were
being written without verifiers attached to them from log recovery,
and Jan Kara isolated the cause to log recovery readahead an dit's
interactions with buffers that had a more recent LSN on disk than
the transaction being recovered. In this case, the buffer did not
get a verifier attached, and os when the second phase of log
recovery ran and recovered EFIs and unlinked inodes, the buffers
were modified and written without the verifier running. Hence they
had up to date contents, but stale LSNs and CRCs.

Fix it by attaching verifiers to buffers we skip due to future LSN
values so they don't escape into the buffer cache without the
correct verifier attached.

This patch is based on analysis and a patch from Jan Kara.

Reported-by: Jan Kara <jack@suse.cz>
Reported-by: Fanael Linithien <fanael4@gmail.com>
Reported-by: Grozdan <neutrino8@gmail.com>
Signed-off-by: Dave Chinner <dchinner@redhat.com>
---
 fs/xfs/xfs_log_recover.c | 47 +++++++++++++++++++++++++++++++----------------
 1 file changed, 31 insertions(+), 16 deletions(-)

diff --git a/fs/xfs/xfs_log_recover.c b/fs/xfs/xfs_log_recover.c
index 981af0f..3ce28c5 100644
--- a/fs/xfs/xfs_log_recover.c
+++ b/fs/xfs/xfs_log_recover.c
@@ -2125,6 +2125,17 @@ xlog_recover_validate_buf_type(
 	__uint16_t		magic16;
 	__uint16_t		magicda;
 
+	/*
+	 * We can only do post recovery validation on items on CRC enabled
+	 * fielsystems as we need to know when the buffer was written to be able
+	 * to determine if we should have replayed the item. If we replay old
+	 * metadata over a newer buffer, then it will enter a temporarily
+	 * inconsistent state resulting in verification failures. Hence for now
+	 * just avoid the verification stage for non-crc filesystems
+	 */
+	if (!xfs_sb_version_hascrc(&mp->m_sb))
+		return;
+
 	magic32 = be32_to_cpu(*(__be32 *)bp->b_addr);
 	magic16 = be16_to_cpu(*(__be16*)bp->b_addr);
 	magicda = be16_to_cpu(info->magic);
@@ -2196,10 +2207,6 @@ xlog_recover_validate_buf_type(
 #endif
 		break;
 	case XFS_BLFT_DINO_BUF:
-		/*
-		 * we get here with inode allocation buffers, not buffers that
-		 * track unlinked list changes.
-		 */
 		if (magic16 != XFS_DINODE_MAGIC) {
 			xfs_warn(mp, "Bad INODE block magic!");
 			ASSERT(0);
@@ -2387,16 +2394,7 @@ xlog_recover_do_reg_buffer(
 	/* Shouldn't be any more regions */
 	ASSERT(i == item->ri_total);
 
-	/*
-	 * We can only do post recovery validation on items on CRC enabled
-	 * fielsystems as we need to know when the buffer was written to be able
-	 * to determine if we should have replayed the item. If we replay old
-	 * metadata over a newer buffer, then it will enter a temporarily
-	 * inconsistent state resulting in verification failures. Hence for now
-	 * just avoid the verification stage for non-crc filesystems
-	 */
-	if (xfs_sb_version_hascrc(&mp->m_sb))
-		xlog_recover_validate_buf_type(mp, bp, buf_f);
+	xlog_recover_validate_buf_type(mp, bp, buf_f);
 }
 
 /*
@@ -2504,12 +2502,29 @@ xlog_recover_buffer_pass2(
 	}
 
 	/*
-	 * recover the buffer only if we get an LSN from it and it's less than
+	 * Recover the buffer only if we get an LSN from it and it's less than
 	 * the lsn of the transaction we are replaying.
+	 *
+	 * Note that we have to be extremely careful of readahead here.
+	 * Readahead does not attach verfiers to the buffers so if we don't
+	 * actually do any replay after readahead because of the LSN we found
+	 * in the buffer if more recent than that current transaction then we
+	 * need to attach the verifier directly. Failure to do so can lead to
+	 * future recovery actions (e.g. EFI and unlinked list recovery) can
+	 * operate on the buffers and they won't get the verifier attached. This
+	 * can lead to blocks on disk having the correct content but a stale
+	 * CRC.
+	 *
+	 * It is safe to assume these clean buffers are currently up to date.
+	 * If the buffer is dirtied by a later transaction being replayed, then
+	 * the verifier will be reset to match whatever recover turns that
+	 * buffer into.
 	 */
 	lsn = xlog_recover_get_buf_lsn(mp, bp);
-	if (lsn && lsn != -1 && XFS_LSN_CMP(lsn, current_lsn) >= 0)
+	if (lsn && lsn != -1 && XFS_LSN_CMP(lsn, current_lsn) >= 0) {
+		xlog_recover_validate_buf_type(mp, bp, buf_f);
 		goto out_release;
+	}
 
 	if (buf_f->blf_flags & XFS_BLF_INODE_BUF) {
 		error = xlog_recover_do_inode_buffer(mp, item, bp, buf_f);

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs