Metadata CRC error upon unclean unmount

Metadata CRC error upon unclean unmount

[Fanael Linithien]

XFS V5 can become unmountable after an unclean unmount. Zeroing the
log and running xfs_repair fixes the filesystem.

The following kernel messages are from Linux 3.14.4, but the same
thing happens in 3.15.1.

SGI XFS with ACLs, security attributes, realtime, large block/inode
numbers, no debug enabled
XFS (sda2): Version 5 superblock detected. This kernel has
EXPERIMENTAL support enabled!
Use of these features in this kernel is at your own risk!
XFS (sda2): Using inode cluster size of 16384 bytes
XFS (sda2): Mounting Filesystem
XFS (sda2): Starting recovery (logdev: internal)
XFS (sda2): Version 5 superblock detected. This kernel has
EXPERIMENTAL support enabled!
Use of these features in this kernel is at your own risk!
ffff880063e85000: 41 42 33 42 00 00 00 2b ff ff ff ff ff ff ff ff
AB3B...+........
ffff880063e85010: 00 00 00 00 01 f3 6a 00 00 00 00 01 00 00 06 c9
......j.........
ffff880063e85020: 30 c1 4d f1 3a e2 44 7d a7 bb 25 1f a5 65 5a 7f
0.M.:.D}..%..eZ.
ffff880063e85030: 00 00 00 01 4d 5f 10 db 00 00 00 01 00 00 00 07
....M_..........
XFS (sda2): Internal error xfs_allocbt_read_verify at line 362 of file
fs/xfs/xfs_alloc_btree.c.  Caller 0xffffffffa0527be5
CPU: 0 PID: 93 Comm: kworker/0:1H Not tainted 3.14.4-1-ARCH #1
Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
Workqueue: xfslogd xfs_buf_iodone_work [xfs]
 0000000000000000 00000000cebb8ca3 ffff88006e927d90 ffffffff8150996e
 ffff880067064800 ffff88006e927dd0 ffffffffa052ae00 ffffffffa0527be5
 ffffffffa05ab718 ffff8800672132a0 ffff880067213200 ffffffffa0527be5
Call Trace:
 [<ffffffff8150996e>] dump_stack+0x4d/0x6f
 [<ffffffffa052ae00>] xfs_corruption_error+0x90/0xa0 [xfs]
 [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
 [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
 [<ffffffffa0546ed9>] xfs_allocbt_read_verify+0x69/0xe0 [xfs]
 [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
 [<ffffffffa0527be5>] xfs_buf_iodone_work+0x75/0xa0 [xfs]
 [<ffffffff81088068>] process_one_work+0x168/0x450
 [<ffffffff81088ac2>] worker_thread+0x132/0x3e0
 [<ffffffff81088990>] ? manage_workers.isra.23+0x2d0/0x2d0
 [<ffffffff8108f2ea>] kthread+0xea/0x100
 [<ffffffff811b0000>] ? __mem_cgroup_try_charge+0x6a0/0x8a0
 [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
 [<ffffffff815176bc>] ret_from_fork+0x7c/0xb0
 [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
XFS (sda2): Corruption detected. Unmount and run xfs_repair
XFS (sda2): metadata I/O error: block 0x1f36a00
("xfs_trans_read_buf_map") error 117 numblks 8
XFS (sda2): Failed to recover EFIs
XFS (sda2): log mount finish failed

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

Re: Metadata CRC error upon unclean unmount

[Grozdan]

On Tue, Jun 24, 2014 at 6:01 PM, Fanael Linithien <fanael4@gmail.com> wrote:
> XFS V5 can become unmountable after an unclean unmount. Zeroing the
> log and running xfs_repair fixes the filesystem.
>
> The following kernel messages are from Linux 3.14.4, but the same
> thing happens in 3.15.1.
>
> SGI XFS with ACLs, security attributes, realtime, large block/inode
> numbers, no debug enabled
> XFS (sda2): Version 5 superblock detected. This kernel has
> EXPERIMENTAL support enabled!
> Use of these features in this kernel is at your own risk!
> XFS (sda2): Using inode cluster size of 16384 bytes
> XFS (sda2): Mounting Filesystem
> XFS (sda2): Starting recovery (logdev: internal)
> XFS (sda2): Version 5 superblock detected. This kernel has
> EXPERIMENTAL support enabled!
> Use of these features in this kernel is at your own risk!
> ffff880063e85000: 41 42 33 42 00 00 00 2b ff ff ff ff ff ff ff ff
> AB3B...+........
> ffff880063e85010: 00 00 00 00 01 f3 6a 00 00 00 00 01 00 00 06 c9
> ......j.........
> ffff880063e85020: 30 c1 4d f1 3a e2 44 7d a7 bb 25 1f a5 65 5a 7f
> 0.M.:.D}..%..eZ.
> ffff880063e85030: 00 00 00 01 4d 5f 10 db 00 00 00 01 00 00 00 07
> ....M_..........
> XFS (sda2): Internal error xfs_allocbt_read_verify at line 362 of file
> fs/xfs/xfs_alloc_btree.c.  Caller 0xffffffffa0527be5
> CPU: 0 PID: 93 Comm: kworker/0:1H Not tainted 3.14.4-1-ARCH #1
> Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
> Workqueue: xfslogd xfs_buf_iodone_work [xfs]
>  0000000000000000 00000000cebb8ca3 ffff88006e927d90 ffffffff8150996e
>  ffff880067064800 ffff88006e927dd0 ffffffffa052ae00 ffffffffa0527be5
>  ffffffffa05ab718 ffff8800672132a0 ffff880067213200 ffffffffa0527be5
> Call Trace:
>  [<ffffffff8150996e>] dump_stack+0x4d/0x6f
>  [<ffffffffa052ae00>] xfs_corruption_error+0x90/0xa0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0546ed9>] xfs_allocbt_read_verify+0x69/0xe0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0527be5>] xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffff81088068>] process_one_work+0x168/0x450
>  [<ffffffff81088ac2>] worker_thread+0x132/0x3e0
>  [<ffffffff81088990>] ? manage_workers.isra.23+0x2d0/0x2d0
>  [<ffffffff8108f2ea>] kthread+0xea/0x100
>  [<ffffffff811b0000>] ? __mem_cgroup_try_charge+0x6a0/0x8a0
>  [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
>  [<ffffffff815176bc>] ret_from_fork+0x7c/0xb0
>  [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
> XFS (sda2): Corruption detected. Unmount and run xfs_repair
> XFS (sda2): metadata I/O error: block 0x1f36a00
> ("xfs_trans_read_buf_map") error 117 numblks 8
> XFS (sda2): Failed to recover EFIs
> XFS (sda2): log mount finish failed

I've also experienced this so I went back to V4. I was not able to
find a workaround.

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



-- 
Yours truly

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

Re: Metadata CRC error upon unclean unmount

[Eric Sandeen]

On 6/24/14, 11:01 AM, Fanael Linithien wrote:
> XFS V5 can become unmountable after an unclean unmount. Zeroing the
> log and running xfs_repair fixes the filesystem.
> 
> The following kernel messages are from Linux 3.14.4, but the same
> thing happens in 3.15.1.

Do you have any kind of reproducer for this?  Any chance you created
an xfs_metadump before the xfs_repair?

What constitutes an "unclean unmount" in your case; a VM reset?  A host
crash?

(This is a VM, right?)  What sort of block device configuration does it have?

-Eric

> SGI XFS with ACLs, security attributes, realtime, large block/inode
> numbers, no debug enabled
> XFS (sda2): Version 5 superblock detected. This kernel has
> EXPERIMENTAL support enabled!
> Use of these features in this kernel is at your own risk!
> XFS (sda2): Using inode cluster size of 16384 bytes
> XFS (sda2): Mounting Filesystem
> XFS (sda2): Starting recovery (logdev: internal)
> XFS (sda2): Version 5 superblock detected. This kernel has
> EXPERIMENTAL support enabled!
> Use of these features in this kernel is at your own risk!
> ffff880063e85000: 41 42 33 42 00 00 00 2b ff ff ff ff ff ff ff ff
> AB3B...+........
> ffff880063e85010: 00 00 00 00 01 f3 6a 00 00 00 00 01 00 00 06 c9
> ......j.........
> ffff880063e85020: 30 c1 4d f1 3a e2 44 7d a7 bb 25 1f a5 65 5a 7f
> 0.M.:.D}..%..eZ.
> ffff880063e85030: 00 00 00 01 4d 5f 10 db 00 00 00 01 00 00 00 07
> ....M_..........
> XFS (sda2): Internal error xfs_allocbt_read_verify at line 362 of file
> fs/xfs/xfs_alloc_btree.c.  Caller 0xffffffffa0527be5
> CPU: 0 PID: 93 Comm: kworker/0:1H Not tainted 3.14.4-1-ARCH #1
> Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
> Workqueue: xfslogd xfs_buf_iodone_work [xfs]
>  0000000000000000 00000000cebb8ca3 ffff88006e927d90 ffffffff8150996e
>  ffff880067064800 ffff88006e927dd0 ffffffffa052ae00 ffffffffa0527be5
>  ffffffffa05ab718 ffff8800672132a0 ffff880067213200 ffffffffa0527be5
> Call Trace:
>  [<ffffffff8150996e>] dump_stack+0x4d/0x6f
>  [<ffffffffa052ae00>] xfs_corruption_error+0x90/0xa0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0546ed9>] xfs_allocbt_read_verify+0x69/0xe0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0527be5>] xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffff81088068>] process_one_work+0x168/0x450
>  [<ffffffff81088ac2>] worker_thread+0x132/0x3e0
>  [<ffffffff81088990>] ? manage_workers.isra.23+0x2d0/0x2d0
>  [<ffffffff8108f2ea>] kthread+0xea/0x100
>  [<ffffffff811b0000>] ? __mem_cgroup_try_charge+0x6a0/0x8a0
>  [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
>  [<ffffffff815176bc>] ret_from_fork+0x7c/0xb0
>  [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
> XFS (sda2): Corruption detected. Unmount and run xfs_repair
> XFS (sda2): metadata I/O error: block 0x1f36a00
> ("xfs_trans_read_buf_map") error 117 numblks 8
> XFS (sda2): Failed to recover EFIs
> XFS (sda2): log mount finish failed
> 
> _______________________________________________
> xfs mailing list
> xfs@oss.sgi.com
> http://oss.sgi.com/mailman/listinfo/xfs
> 

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

2014-06-24 18:08 GMT+02:00 Eric Sandeen <sandeen@sandeen.net>:
> Do you have any kind of reproducer for this?

The closest thing to a reliable reproducer I found is:
dd if=/dev/urandom of=some.file
<VM reset while dd is still running>

> Any chance you created an xfs_metadump before the xfs_repair?

I still have the broken FS, but the dump is 225 MB. Will it be OK if I
repro it on a clean FS?

> What constitutes an "unclean unmount" in your case; a VM reset?  A host
> crash?

A VM reset.

> (This is a VM, right?)

Right.

> What sort of block device configuration does it have?

What do you mean?

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

Re: Metadata CRC error upon unclean unmount

[Eric Sandeen]

On 6/24/14, 11:19 AM, Fanael Linithien wrote:
> 2014-06-24 18:08 GMT+02:00 Eric Sandeen <sandeen@sandeen.net>:
>> Do you have any kind of reproducer for this?
> 
> The closest thing to a reliable reproducer I found is:
> dd if=/dev/urandom of=some.file
> <VM reset while dd is still running>
> 
>> Any chance you created an xfs_metadump before the xfs_repair?
> 
> I still have the broken FS, but the dump is 225 MB. Will it be OK if I
> repro it on a clean FS?

absolutely, if you have a recipe starting at mkfs and ending with corruption,
that's even better.

>> What constitutes an "unclean unmount" in your case; a VM reset?  A host
>> crash?
> 
> A VM reset.
> 
>> (This is a VM, right?)
> 
> Right.
> 
>> What sort of block device configuration does it have?
> 
> What do you mean?

Is the VM using a host block device or an image file?
What type of image file, VDI, QCOW, or?
If an image, what type of filesystem hosts the image?
Have you done any "VBoxManage storagectl"-type modifications to virtualbox defaults?

Since this was a guest reset, not a host reset, it doesn't
matter as much, but it's worth getting the details I think.

Thanks,
-Eric

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

2014-06-24 18:24 GMT+02:00 Eric Sandeen <sandeen@sandeen.net>:
> Is the VM using a host block device or an image file?
> What type of image file, VDI, QCOW, or?
> If an image, what type of filesystem hosts the image?
> Have you done any "VBoxManage storagectl"-type modifications to virtualbox defaults?

VDI image, hosted on NTFS, using defaults.

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

Re: Metadata CRC error upon unclean unmount

[Eric Sandeen]

On 6/24/14, 11:19 AM, Fanael Linithien wrote:
> 2014-06-24 18:08 GMT+02:00 Eric Sandeen <sandeen@sandeen.net>:
>> Do you have any kind of reproducer for this?
> 
> The closest thing to a reliable reproducer I found is:
> dd if=/dev/urandom of=some.file
> <VM reset while dd is still running>
> 
>> Any chance you created an xfs_metadump before the xfs_repair?
> 
> I still have the broken FS, but the dump is 225 MB. Will it be OK if I
> repro it on a clean FS?
> 
>> What constitutes an "unclean unmount" in your case; a VM reset?  A host
>> crash?
> 
> A VM reset.
> 
>> (This is a VM, right?)
> 
> Right.

FWIW, I've been unable to reproduce this in about 4 attempts, using
virtualbox, and doing a guest reset.

-Eric

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

2014-06-24 20:48 GMT+02:00 Eric Sandeen <sandeen@sandeen.net>:
> FWIW, I've been unable to reproduce this in about 4 attempts, using
> virtualbox, and doing a guest reset.

Same here. The most breakage I can get is a log record CRC mismatch
(still a bug, I think). I will report if I run across a metadata CRC
error ever again.

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

Re: Metadata CRC error upon unclean unmount

[Eric Sandeen]

On 6/24/14, 2:00 PM, Fanael Linithien wrote:
> 2014-06-24 20:48 GMT+02:00 Eric Sandeen <sandeen@sandeen.net>:
>> FWIW, I've been unable to reproduce this in about 4 attempts, using
>> virtualbox, and doing a guest reset.
> 
> Same here. The most breakage I can get is a log record CRC mismatch
> (still a bug, I think). I will report if I run across a metadata CRC
> error ever again.

The trouble with VMs is that we depend on the VM doing the right thing,
as well.  I can't blame VirtualBox here, but it definitely adds a layer
of complexity that we can't control.

I've still not been able to make anything go wrong in my testing.

-Eric

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Tue, Jun 24, 2014 at 06:01:16PM +0200, Fanael Linithien wrote:
> XFS V5 can become unmountable after an unclean unmount. Zeroing the
> log and running xfs_repair fixes the filesystem.
> 
> The following kernel messages are from Linux 3.14.4, but the same
> thing happens in 3.15.1.
> 
> SGI XFS with ACLs, security attributes, realtime, large block/inode
> numbers, no debug enabled
> XFS (sda2): Version 5 superblock detected. This kernel has
> EXPERIMENTAL support enabled!
> Use of these features in this kernel is at your own risk!
> XFS (sda2): Using inode cluster size of 16384 bytes
> XFS (sda2): Mounting Filesystem
> XFS (sda2): Starting recovery (logdev: internal)
> XFS (sda2): Version 5 superblock detected. This kernel has
> EXPERIMENTAL support enabled!
> Use of these features in this kernel is at your own risk!
> ffff880063e85000: 41 42 33 42 00 00 00 2b ff ff ff ff ff ff ff ff
> AB3B...+........
> ffff880063e85010: 00 00 00 00 01 f3 6a 00 00 00 00 01 00 00 06 c9
> ......j.........
> ffff880063e85020: 30 c1 4d f1 3a e2 44 7d a7 bb 25 1f a5 65 5a 7f
> 0.M.:.D}..%..eZ.
> ffff880063e85030: 00 00 00 01 4d 5f 10 db 00 00 00 01 00 00 00 07
> ....M_..........
> XFS (sda2): Internal error xfs_allocbt_read_verify at line 362 of file
> fs/xfs/xfs_alloc_btree.c.  Caller 0xffffffffa0527be5
> CPU: 0 PID: 93 Comm: kworker/0:1H Not tainted 3.14.4-1-ARCH #1

OK, that doesn't tell us that the problem is a CRC error, just that
the btree block on disk has problems. I'd recommend an upgrade to
3.15 which has much better error reporting in situations like this,
and it is no longer experimental...

> Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
> Workqueue: xfslogd xfs_buf_iodone_work [xfs]
>  0000000000000000 00000000cebb8ca3 ffff88006e927d90 ffffffff8150996e
>  ffff880067064800 ffff88006e927dd0 ffffffffa052ae00 ffffffffa0527be5
>  ffffffffa05ab718 ffff8800672132a0 ffff880067213200 ffffffffa0527be5
> Call Trace:
>  [<ffffffff8150996e>] dump_stack+0x4d/0x6f
>  [<ffffffffa052ae00>] xfs_corruption_error+0x90/0xa0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0546ed9>] xfs_allocbt_read_verify+0x69/0xe0 [xfs]
>  [<ffffffffa0527be5>] ? xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffffa0527be5>] xfs_buf_iodone_work+0x75/0xa0 [xfs]
>  [<ffffffff81088068>] process_one_work+0x168/0x450
>  [<ffffffff81088ac2>] worker_thread+0x132/0x3e0
>  [<ffffffff81088990>] ? manage_workers.isra.23+0x2d0/0x2d0
>  [<ffffffff8108f2ea>] kthread+0xea/0x100
>  [<ffffffff811b0000>] ? __mem_cgroup_try_charge+0x6a0/0x8a0
>  [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
>  [<ffffffff815176bc>] ret_from_fork+0x7c/0xb0
>  [<ffffffff8108f200>] ? kthread_create_on_node+0x1a0/0x1a0
> XFS (sda2): Corruption detected. Unmount and run xfs_repair
> XFS (sda2): metadata I/O error: block 0x1f36a00
> ("xfs_trans_read_buf_map") error 117 numblks 8
> XFS (sda2): Failed to recover EFIs
> XFS (sda2): log mount finish failed

We do see this sort of freespace btree corruption being reported
during EFI recovery on V4 filesystems semi-regularly. This is the
first time I've seen it on a V5 filesystem. Because log recovery
didn't flag a error on this block, it means that either:

	1. it wasn't recovered and hence was corrupt before the crash,
	2. it was recovered and passed a verifier check during
	   writeback, but then failed the verifier on re-read.

I don't think that 2) is likely, so I suspect that the corruption
was present before the system crashed. If you do reproduce this,
I'd really like to see a metadump of the filesystem to identify what
the corruption actually is...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

2014-06-24 22:19 GMT+02:00 Dave Chinner <david@fromorbit.com>:
>
> OK, that doesn't tell us that the problem is a CRC error, just that
> the btree block on disk has problems. I'd recommend an upgrade to
> 3.15 which has much better error reporting in situations like this,
> and it is no longer experimental...

The original error was caused by 3.15, but the error messages were
from 3.14 because that's what Arch install CD uses, and I had to use
the CD because the hosed filesystem was /.
Now that I think about it, setting up another 3.15 installation to try
to recover that FS would be a better idea, but now it's too late.

At any rate, I'm still trying to reproduce this and will surely report
if I succeed. So far, the only thing I've managed to found is that log
record CRC mismatch thing.

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

Managed to get the "metadata CRC error" again. Trying to get useful
info from an initramfs recovery shell is fun.

dmesg:

[    4.215841] SGI XFS with ACLs, security attributes, realtime, large
block/inode numbers, no debug enabled
[    4.224047] XFS (sda1): Mounting V5 Filesystem
[    4.527156] XFS (sda1): Starting recovery (logdev: internal)
[    4.546698] XFS (sda1): Metadata CRC error detected at
xfs_agi_read_verify+0x5e/0x110 [xfs], block 0x2
[    4.547083] XFS (sda1): Unmount and run xfs_repair
[    4.547347] XFS (sda1): First 64 bytes of corrupted metadata buffer:
[    4.547670] ffff8800364d3600: 58 41 47 49 00 00 00 01 00 00 00 00
00 13 d0 00  XAGI............
[    4.548027] ffff8800364d3610: 00 00 17 40 00 00 00 03 00 00 00 01
00 00 00 2b  ...@...........+
[    4.548382] ffff8800364d3620: 00 0c 95 40 ff ff ff ff ff ff ff ff
ff ff ff ff  ...@............
[    4.548752] ffff8800364d3630: ff ff ff ff ff ff ff ff ff ff ff ff
ff ff ff ff  ................
[    4.549420] XFS (sda1): metadata I/O error: block 0x2
("xfs_trans_read_buf_map") error 74 numblks 1


Metadata dump (xz + base64): https://clbin.com/4KYSR

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Tue, Jun 24, 2014 at 11:50:52PM +0200, Fanael Linithien wrote:
> Managed to get the "metadata CRC error" again. Trying to get useful
> info from an initramfs recovery shell is fun.

What kernel are you running? (uname -a, please)

> dmesg:
> 
> [    4.215841] SGI XFS with ACLs, security attributes, realtime, large
> block/inode numbers, no debug enabled
> [    4.224047] XFS (sda1): Mounting V5 Filesystem
> [    4.527156] XFS (sda1): Starting recovery (logdev: internal)
> [    4.546698] XFS (sda1): Metadata CRC error detected at
> xfs_agi_read_verify+0x5e/0x110 [xfs], block 0x2
> [    4.547083] XFS (sda1): Unmount and run xfs_repair
> [    4.547347] XFS (sda1): First 64 bytes of corrupted metadata buffer:
> [    4.547670] ffff8800364d3600: 58 41 47 49 00 00 00 01 00 00 00 00
> 00 13 d0 00  XAGI............
> [    4.548027] ffff8800364d3610: 00 00 17 40 00 00 00 03 00 00 00 01
> 00 00 00 2b  ...@...........+
> [    4.548382] ffff8800364d3620: 00 0c 95 40 ff ff ff ff ff ff ff ff
> ff ff ff ff  ...@............
> [    4.548752] ffff8800364d3630: ff ff ff ff ff ff ff ff ff ff ff ff
> ff ff ff ff  ................
> [    4.549420] XFS (sda1): metadata I/O error: block 0x2
> ("xfs_trans_read_buf_map") error 74 numblks 1
> 
> 
> Metadata dump (xz + base64): https://clbin.com/4KYSR

Yup, the CRC on disk is clearly wrong. Without mounting the
filesystem, it has a value of:

crc = 0x4e28030d (bad)

And after re-writing a field in it with xfs_db to the same value:

crc = 0x86a5538a (correct)

And then it mounts and recovers just fine.

But there's CRC errors in every AGI (all 4 on disk) and every inode
btree block, too.

Ok, dig further in to AGI 0 - the important bits form xfs_db:

length = 1298432
count = 5952
root = 3
level = 1
freecount = 43
lsn = 0x30000017e

Ok, so this version should match what is in the log checkpoint at
lsn = 0x30000017e. What do we have there:

LOG REC AT LSN cycle 3 block 382 (0x3, 0x17e)
============================================================================
TRANS: tid:0xc7ad5835  type:CHECKPOINT  #items:25  trans:0xc7ad5835  q:0x660a40
INO: cnt:2 total:2 a:0x668c10 len:56 a:0x660ac0 len:176 
        INODE: #regs:2   ino:0x85cee  flags:0x1   dsize:0
        CORE inode:
BUF: cnt:2 total:2 a:0x64f290 len:24 a:0x668c50 len:128 
        BUF:  #regs:2   start blkno:0x2   len:1   bmap size:1   flags:0x3800
        AGI Buffer: (XAGI)
                ver:1  seq#:0  len:1298432  cnt:5952  root:3
                level:1  free#:0x2c  newino:0xc9540
                         ^^^^^^^^^^
.....

0x2c = 44. The value on disk is *43*. It must have been logged again...

LOG REC AT LSN cycle 3 block 414 (0x3, 0x19e)
============================================================================
TRANS: tid:0x73c82586  type:CHECKPOINT  #items:23  trans:0x73c82586  q:0x660a40
INO: cnt:2 total:2 a:0x668c50 len:56 a:0x669880 len:176 
        INODE: #regs:2   ino:0xc9553  flags:0x1   dsize:0
        CORE inode:
BUF: cnt:2 total:2 a:0x66a110 len:24 a:0x6693d0 len:128 
        BUF:  #regs:2   start blkno:0x2   len:1   bmap size:1   flags:0x3800
        AGI Buffer: (XAGI)
                ver:1  seq#:0  len:1298432  cnt:5952  root:3
                level:1  free#:0x2b  newino:0xc9540

Yup, there it is - value 0x2b, which is 43. But if that value was
written to disk, then why is the LSN stamped in the buffer the
previous LSN? I can't see how that is possible, nor is the CRC in
the buffer consistent with just an updated LSN to match this
transaction.

OK:

$ xfs_db -x -c "agi 0" -c "write freecount 44" -c "p crc" -f agi-crc-bad.img 
Metadata CRC error detected at block 0x2/0x200
xfs_db: cannot init perag data (74). Continuing anyway.
freecount = 44
crc = 0x4e28030d (correct)
$

Ok, so the CRC corresponds to the version of the AGI that was logged
at lsn = 0x30000017e. That means the version on disk is a partial
update without a CRC recalculation. Ok, so how can that happen?

Given the lsn mismatch, I suspect log recovery has played a part as
it will not update the LSN when replaying changes in the log. It
should, however, always be attaching the appropriate verifier to
the buffers being recovered so the CRC should be recalculated
correctly.

Given that the CRC errors seem to propagate through the XAGI and
inode btree blocks *only*, it makes me think that unlinked inode
list recovery *might* have caused this, but I cannot yet see the
underlying cause of the initial corruption. What is clear, however,
is that you are now tripping over a problem caused by a previous
crash+recover cycle.

Can you reproduce the problem on demand from a brand new filesystem?
If so, can you run the cycle:

	mount
	write
	crash
	<restart>
	take metadump
	mount
	unmount
	run xfs_repair -n <dev>
	if clean
		do another iteration
	otherwise, something is wrong.
	record dmesg
	take a post-mount metadump
	post the pre- and post-mount metadumps for me to look at
	post the entire dmesg so I can look at it.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

2014-06-25 3:21 GMT+02:00 Dave Chinner <david@fromorbit.com>:
> What kernel are you running? (uname -a, please)

Linux (none) 3.15.1-1-ARCH #1 SMP PREEMPT Tue Jun 17 09:32:20 CEST
2014 x86_64 GNU/Linux

> Can you reproduce the problem on demand from a brand new filesystem?
> If so, can you run the cycle:
>
>         mount
>         write
>         crash
>         <restart>
>         take metadump
>         mount
>         unmount
>         run xfs_repair -n <dev>
>         if clean
>                 do another iteration
>         otherwise, something is wrong.
>         record dmesg
>         take a post-mount metadump
>         post the pre- and post-mount metadumps for me to look at
>         post the entire dmesg so I can look at it.

I can try.

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

First try, and something is wrong already.

Dmesg: https://clbin.com/e8HwM
Pre-mount metadata: https://clbin.com/0thyz
Post-mount metadata: https://clbin.com/WTIuF

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Wed, Jun 25, 2014 at 06:09:07PM +0200, Fanael Linithien wrote:
> First try, and something is wrong already.
> 
> Dmesg: https://clbin.com/e8HwM
> Pre-mount metadata: https://clbin.com/0thyz
> Post-mount metadata: https://clbin.com/WTIuF

Ok, that's the log crc error, which is likely a different problem
(probably an incomplete write due to the VM being terminated).  I'll
concentrate on that one after the one originally reported in this
thread.

Can you try to reproduce the AGI or AGF/freespace corruption issue
and post the results?

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

2014-06-26 0:03 GMT+02:00 Dave Chinner <david@fromorbit.com>:
> Can you try to reproduce the AGI or AGF/freespace corruption issue
> and post the results?

Sure, looks like the bug heard you and decided to manifest itself right now.

dmesg: https://clbin.com/g52eu (the second mount error is because I
typo'd and tried to mount wrong partition)
Metadata before an attempt to mount: https://clbin.com/YDZBV
Metadata after an attempt to mount: https://clbin.com/2jayF

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Thu, Jun 26, 2014 at 12:33:06AM +0200, Fanael Linithien wrote:
> 2014-06-26 0:03 GMT+02:00 Dave Chinner <david@fromorbit.com>:
> > Can you try to reproduce the AGI or AGF/freespace corruption issue
> > and post the results?
> 
> Sure, looks like the bug heard you and decided to manifest itself right now.
> 
> dmesg: https://clbin.com/g52eu (the second mount error is because I
> typo'd and tried to mount wrong partition)
> Metadata before an attempt to mount: https://clbin.com/YDZBV

Curious. Completely clean log. head/tail at 2/16292. Yet the AGF
head and a couple of btree blocks are have bad CRCs. They were on
disk *before* the system crashed.

> Metadata after an attempt to mount: https://clbin.com/2jayF

Dirty log. tail at 2/16292, head at 2/16332.

The before-mount image shows the CRC error, so it didn't come from
log recovery. It may have come from recovery in the previous
iteration, - do you still have the pre-mount images from the prior
iteration before the crash error was detected?

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Fanael Linithien]

2014-06-26 1:22 GMT+02:00 Dave Chinner <david@fromorbit.com>:
> The before-mount image shows the CRC error, so it didn't come from
> log recovery. It may have come from recovery in the previous
> iteration, - do you still have the pre-mount images from the prior
> iteration before the crash error was detected?

I don't have anything from between that log CRC eror and these. Should
I try again?

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Thu, Jun 26, 2014 at 01:32:56AM +0200, Fanael Linithien wrote:
> 2014-06-26 1:22 GMT+02:00 Dave Chinner <david@fromorbit.com>:
> > The before-mount image shows the CRC error, so it didn't come from
> > log recovery. It may have come from recovery in the previous
> > iteration, - do you still have the pre-mount images from the prior
> > iteration before the crash error was detected?
> 
> I don't have anything from between that log CRC eror and these. Should
> I try again?

It would be aprreciated if you could - I'm trying to reproduce it
here but I'm having no luck. I've been crashing CRC enabled
filesystems for the past 18 months and I can count on one hand the
number of times I've had a CRC error of any time during/after
recovery, so I'm not really surprised that...

Cheers,

Dave
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Wed, Jun 25, 2014 at 11:21:44AM +1000, Dave Chinner wrote:
> On Tue, Jun 24, 2014 at 11:50:52PM +0200, Fanael Linithien wrote:
> Ok, so the CRC corresponds to the version of the AGI that was logged
> at lsn = 0x30000017e. That means the version on disk is a partial
> update without a CRC recalculation. Ok, so how can that happen?
> 
> Given the lsn mismatch, I suspect log recovery has played a part as
> it will not update the LSN when replaying changes in the log. It
> should, however, always be attaching the appropriate verifier to
> the buffers being recovered so the CRC should be recalculated
> correctly.

Ok, I have confirmed that this is occurring and behaving correctly.

[   24.437878] XFS (vdb): Mounting V5 Filesystem
[   24.554429] XFS (vdb): Starting recovery (logdev: internal)
[   24.623466] XFS (vdb): xfs_agi_write_verify: lsn reset block 0x2
[   24.625263] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x8
[   24.627307] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x10
[   24.628729] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x18
[   24.630085] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20000
[   24.631504] XFS (vdb): xfs_da3_node_write_verify: lsn reset block 0x20008
[   24.632935] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20010
[   24.634360] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20018
[   24.635622] XFS (vdb): xfs_dir3_free_write_verify: lsn reset block 0x201e0
[   24.636656] XFS (vdb): __write_verify: lsn reset block 0x201e8
[   24.637510] XFS (vdb): __write_verify: lsn reset block 0x201f0
[   24.638365] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x201f8
[   24.639378] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202c0
[   24.640397] XFS (vdb): __write_verify: lsn reset block 0x202c8
[   24.641260] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202d0
[   24.664330] XFS (vdb): Ending recovery (logdev: internal)

But that also confirms that log recovery is recalculating the CRC
after replaying changes into that block:

# xfs_db -c "agi 0" -c "p lsn" -c "p crc" /dev/vdb
lsn = 0xffffffffffffffff
crc = 0x788c4f63 (correct)

So the common log recovery path for buffers is working as it is
designed to do.

What I still don't understand yet is how changes after this recovery
phase are getting to disk without updating the CRC. That implies
buffers without verifiers being written....

More debug to come...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Thu, Jun 26, 2014 at 10:28:59AM +1000, Dave Chinner wrote:
> On Wed, Jun 25, 2014 at 11:21:44AM +1000, Dave Chinner wrote:
> > On Tue, Jun 24, 2014 at 11:50:52PM +0200, Fanael Linithien wrote:
> > Ok, so the CRC corresponds to the version of the AGI that was logged
> > at lsn = 0x30000017e. That means the version on disk is a partial
> > update without a CRC recalculation. Ok, so how can that happen?
> > 
> > Given the lsn mismatch, I suspect log recovery has played a part as
> > it will not update the LSN when replaying changes in the log. It
> > should, however, always be attaching the appropriate verifier to
> > the buffers being recovered so the CRC should be recalculated
> > correctly.
> 
> Ok, I have confirmed that this is occurring and behaving correctly.
> 
> [   24.437878] XFS (vdb): Mounting V5 Filesystem
> [   24.554429] XFS (vdb): Starting recovery (logdev: internal)
> [   24.623466] XFS (vdb): xfs_agi_write_verify: lsn reset block 0x2
> [   24.625263] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x8
> [   24.627307] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x10
> [   24.628729] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x18
> [   24.630085] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20000
> [   24.631504] XFS (vdb): xfs_da3_node_write_verify: lsn reset block 0x20008
> [   24.632935] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20010
> [   24.634360] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20018
> [   24.635622] XFS (vdb): xfs_dir3_free_write_verify: lsn reset block 0x201e0
> [   24.636656] XFS (vdb): __write_verify: lsn reset block 0x201e8
> [   24.637510] XFS (vdb): __write_verify: lsn reset block 0x201f0
> [   24.638365] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x201f8
> [   24.639378] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202c0
> [   24.640397] XFS (vdb): __write_verify: lsn reset block 0x202c8
> [   24.641260] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202d0
> [   24.664330] XFS (vdb): Ending recovery (logdev: internal)
> 
> But that also confirms that log recovery is recalculating the CRC
> after replaying changes into that block:
> 
> # xfs_db -c "agi 0" -c "p lsn" -c "p crc" /dev/vdb
> lsn = 0xffffffffffffffff
> crc = 0x788c4f63 (correct)
> 
> So the common log recovery path for buffers is working as it is
> designed to do.
> 
> What I still don't understand yet is how changes after this recovery
> phase are getting to disk without updating the CRC. That implies
> buffers without verifiers being written....
> 
> More debug to come...

Can you apply this patch and run your tests? If should spew warnings
to dmesg if a metadata buffer is ever written without an ops
structure attached to it (i.e. won't have CRCs recalculated).

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

xfs: spew warnings on cached buffers without b_ops callbacks.

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: Metadata CRC error upon unclean unmount

[Mark Tinguely]

On 06/25/14 19:28, Dave Chinner wrote:
> On Wed, Jun 25, 2014 at 11:21:44AM +1000, Dave Chinner wrote:
>> On Tue, Jun 24, 2014 at 11:50:52PM +0200, Fanael Linithien wrote:
>> Ok, so the CRC corresponds to the version of the AGI that was logged
>> at lsn = 0x30000017e. That means the version on disk is a partial
>> update without a CRC recalculation. Ok, so how can that happen?
>>
>> Given the lsn mismatch, I suspect log recovery has played a part as
>> it will not update the LSN when replaying changes in the log. It
>> should, however, always be attaching the appropriate verifier to
>> the buffers being recovered so the CRC should be recalculated
>> correctly.
>
> Ok, I have confirmed that this is occurring and behaving correctly.
>
> [   24.437878] XFS (vdb): Mounting V5 Filesystem
> [   24.554429] XFS (vdb): Starting recovery (logdev: internal)
> [   24.623466] XFS (vdb): xfs_agi_write_verify: lsn reset block 0x2
> [   24.625263] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x8
> [   24.627307] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x10
> [   24.628729] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x18
> [   24.630085] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20000
> [   24.631504] XFS (vdb): xfs_da3_node_write_verify: lsn reset block 0x20008
> [   24.632935] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20010
> [   24.634360] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20018
> [   24.635622] XFS (vdb): xfs_dir3_free_write_verify: lsn reset block 0x201e0
> [   24.636656] XFS (vdb): __write_verify: lsn reset block 0x201e8
> [   24.637510] XFS (vdb): __write_verify: lsn reset block 0x201f0
> [   24.638365] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x201f8
> [   24.639378] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202c0
> [   24.640397] XFS (vdb): __write_verify: lsn reset block 0x202c8
> [   24.641260] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202d0
> [   24.664330] XFS (vdb): Ending recovery (logdev: internal)
>
> But that also confirms that log recovery is recalculating the CRC
> after replaying changes into that block:
>
> # xfs_db -c "agi 0" -c "p lsn" -c "p crc" /dev/vdb
> lsn = 0xffffffffffffffff
> crc = 0x788c4f63 (correct)
>
> So the common log recovery path for buffers is working as it is
> designed to do.
>
> What I still don't understand yet is how changes after this recovery
> phase are getting to disk without updating the CRC. That implies
> buffers without verifiers being written....
>
> More debug to come...
>
> Cheers,
>
> Dave.

Could an out of order CIL push cause this?

SGI saw sequence 2 (and sometimes 3/4) of the cil push get in front of 
cil push sequence 1. Looks like the setting of 
log->l_cilp->xc_ctx->commit_lsn in xlog_cil_init_post_recovery() lets 
this happen.

--Mark.

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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Thu, Jun 26, 2014 at 03:03:53PM -0500, Mark Tinguely wrote:
> On 06/25/14 19:28, Dave Chinner wrote:
> >On Wed, Jun 25, 2014 at 11:21:44AM +1000, Dave Chinner wrote:
> >>On Tue, Jun 24, 2014 at 11:50:52PM +0200, Fanael Linithien wrote:
> >>Ok, so the CRC corresponds to the version of the AGI that was logged
> >>at lsn = 0x30000017e. That means the version on disk is a partial
> >>update without a CRC recalculation. Ok, so how can that happen?
> >>
> >>Given the lsn mismatch, I suspect log recovery has played a part as
> >>it will not update the LSN when replaying changes in the log. It
> >>should, however, always be attaching the appropriate verifier to
> >>the buffers being recovered so the CRC should be recalculated
> >>correctly.
> >
> >Ok, I have confirmed that this is occurring and behaving correctly.
> >
> >[   24.437878] XFS (vdb): Mounting V5 Filesystem
> >[   24.554429] XFS (vdb): Starting recovery (logdev: internal)
> >[   24.623466] XFS (vdb): xfs_agi_write_verify: lsn reset block 0x2
> >[   24.625263] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x8
> >[   24.627307] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x10
> >[   24.628729] XFS (vdb): xfs_btree_sblock_calc_crc: lsn reset block 0x18
> >[   24.630085] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20000
> >[   24.631504] XFS (vdb): xfs_da3_node_write_verify: lsn reset block 0x20008
> >[   24.632935] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20010
> >[   24.634360] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x20018
> >[   24.635622] XFS (vdb): xfs_dir3_free_write_verify: lsn reset block 0x201e0
> >[   24.636656] XFS (vdb): __write_verify: lsn reset block 0x201e8
> >[   24.637510] XFS (vdb): __write_verify: lsn reset block 0x201f0
> >[   24.638365] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x201f8
> >[   24.639378] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202c0
> >[   24.640397] XFS (vdb): __write_verify: lsn reset block 0x202c8
> >[   24.641260] XFS (vdb): xfs_dir3_data_write_verify: lsn reset block 0x202d0
> >[   24.664330] XFS (vdb): Ending recovery (logdev: internal)
> >
> >But that also confirms that log recovery is recalculating the CRC
> >after replaying changes into that block:
> >
> ># xfs_db -c "agi 0" -c "p lsn" -c "p crc" /dev/vdb
> >lsn = 0xffffffffffffffff
> >crc = 0x788c4f63 (correct)
> >
> >So the common log recovery path for buffers is working as it is
> >designed to do.
> >
> >What I still don't understand yet is how changes after this recovery
> >phase are getting to disk without updating the CRC. That implies
> >buffers without verifiers being written....
> >
> >More debug to come...
> >
> >Cheers,
> >
> >Dave.
> 
> Could an out of order CIL push cause this?

I don't think so - the issue appears to be that a CRC is not being
recalculated on a buffer before IO has been issued to disk, not that
there is incorrect metadata in the buffer. Regardless of how we
modify the buffer, the CRC should always match the contents of the
block on disk because we calculate it with the buffer locked and
just prior to it being written.

> SGI saw sequence 2 (and sometimes 3/4) of the cil push get in front
> of cil push sequence 1. Looks like the setting of
> log->l_cilp->xc_ctx->commit_lsn in xlog_cil_init_post_recovery()
> lets this happen.

I don't think can actually happen - the CIL is not used until after
xlog_cil_init_post_recovery() is completed and transactions start
during EFI recovery. Any attempt to use it prior to that call will
oops on the null ctx_ticket.

As for the ordering issue, I'm pretty sure that was fixed in
commit f876e44 ("xfs: always do log forces via the workqueue").

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Mark Tinguely]

On 06/26/14 17:47, Dave Chinner wrote:
> On Thu, Jun 26, 2014 at 03:03:53PM -0500, Mark Tinguely wrote:

>> Could an out of order CIL push cause this?
>
> I don't think so - the issue appears to be that a CRC is not being
> recalculated on a buffer before IO has been issued to disk, not that
> there is incorrect metadata in the buffer. Regardless of how we
> modify the buffer, the CRC should always match the contents of the
> block on disk because we calculate it with the buffer locked and
> just prior to it being written.
>
>> SGI saw sequence 2 (and sometimes 3/4) of the cil push get in front
>> of cil push sequence 1. Looks like the setting of
>> log->l_cilp->xc_ctx->commit_lsn in xlog_cil_init_post_recovery()
>> lets this happen.
>
> I don't think can actually happen - the CIL is not used until after
> xlog_cil_init_post_recovery() is completed and transactions start
> during EFI recovery. Any attempt to use it prior to that call will
> oops on the null ctx_ticket.
>
> As for the ordering issue, I'm pretty sure that was fixed in
> commit f876e44 ("xfs: always do log forces via the workqueue").

The problem will be with the first CIL push *after* the 
xlog_cil_init_post_recovery() especially if the first ctx has a large 
vector list and the following ones have small ones.

Looks to me that the problem is still in the cil push worker.

--Mark.



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

Re: Metadata CRC error upon unclean unmount

[Dave Chinner]

On Fri, Jun 27, 2014 at 09:26:35AM -0500, Mark Tinguely wrote:
> On 06/26/14 17:47, Dave Chinner wrote:
> >On Thu, Jun 26, 2014 at 03:03:53PM -0500, Mark Tinguely wrote:
> 
> >>Could an out of order CIL push cause this?
> >
> >I don't think so - the issue appears to be that a CRC is not being
> >recalculated on a buffer before IO has been issued to disk, not that
> >there is incorrect metadata in the buffer. Regardless of how we
> >modify the buffer, the CRC should always match the contents of the
> >block on disk because we calculate it with the buffer locked and
> >just prior to it being written.
> >
> >>SGI saw sequence 2 (and sometimes 3/4) of the cil push get in front
> >>of cil push sequence 1. Looks like the setting of
> >>log->l_cilp->xc_ctx->commit_lsn in xlog_cil_init_post_recovery()
> >>lets this happen.
> >
> >I don't think can actually happen - the CIL is not used until after
> >xlog_cil_init_post_recovery() is completed and transactions start
> >during EFI recovery. Any attempt to use it prior to that call will
> >oops on the null ctx_ticket.
> >
> >As for the ordering issue, I'm pretty sure that was fixed in
> >commit f876e44 ("xfs: always do log forces via the workqueue").
> 
> The problem will be with the first CIL push *after* the
> xlog_cil_init_post_recovery() especially if the first ctx has a
> large vector list and the following ones have small ones.

Sequence 2 cannot start until sequence 1 is on the committing list
and the xc_ctx_lock has been dropped. If seqeunce 2 is then pushed,
while sequence 1 is still writing to the log, then sequence 2 can be
interleaved with sequence 1.

However, the sequences on the commit list are then strictly ordered
while the commit record is written. i.e. seqeunce 2 will sleep
waiting for seqeunce 1 to write it's commit record, which then wakes
sequence 2 so it can write it's commit record, whcih then wakes
seqeunce 3... and so on.

Log recovered once cares that the commit records for each checkpoint
are written in the correct order. You can see the checkpoint
transactions be written to the log out of order, but the order of
commit records determines the order in which checkpoints are
replayed during recovery.

> Looks to me that the problem is still in the cil push worker.

I can't see how the commit records (which are written in
xfs_log_done()) would be incorrectly ordered given the way that
the commit list code serialises and orders calls to xfs_log_done()
based on sequence number.

Keep in mind that I might just be being stupid and missing
something so obvious I need a brown paper bag to hide in, so you'll
need to spell it out for me.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: Metadata CRC error upon unclean unmount

[Mark Tinguely]

On 06/27/14 19:49, Dave Chinner wrote:
> On Fri, Jun 27, 2014 at 09:26:35AM -0500, Mark Tinguely wrote:
>> On 06/26/14 17:47, Dave Chinner wrote:
>>> On Thu, Jun 26, 2014 at 03:03:53PM -0500, Mark Tinguely wrote:
>>
>>>> Could an out of order CIL push cause this?
>>>
>>> I don't think so - the issue appears to be that a CRC is not being
>>> recalculated on a buffer before IO has been issued to disk, not that
>>> there is incorrect metadata in the buffer. Regardless of how we
>>> modify the buffer, the CRC should always match the contents of the
>>> block on disk because we calculate it with the buffer locked and
>>> just prior to it being written.
>>>
>>>> SGI saw sequence 2 (and sometimes 3/4) of the cil push get in front
>>>> of cil push sequence 1. Looks like the setting of
>>>> log->l_cilp->xc_ctx->commit_lsn in xlog_cil_init_post_recovery()
>>>> lets this happen.
>>>
>>> I don't think can actually happen - the CIL is not used until after
>>> xlog_cil_init_post_recovery() is completed and transactions start
>>> during EFI recovery. Any attempt to use it prior to that call will
>>> oops on the null ctx_ticket.
>>>
>>> As for the ordering issue, I'm pretty sure that was fixed in
>>> commit f876e44 ("xfs: always do log forces via the workqueue").
>>
>> The problem will be with the first CIL push *after* the
>> xlog_cil_init_post_recovery() especially if the first ctx has a
>> large vector list and the following ones have small ones.
>
> Sequence 2 cannot start until sequence 1 is on the committing list
> and the xc_ctx_lock has been dropped. If seqeunce 2 is then pushed,
> while sequence 1 is still writing to the log, then sequence 2 can be
> interleaved with sequence 1.
>
> However, the sequences on the commit list are then strictly ordered
> while the commit record is written. i.e. seqeunce 2 will sleep
> waiting for seqeunce 1 to write it's commit record, which then wakes
> sequence 2 so it can write it's commit record, whcih then wakes
> seqeunce 3... and so on.
>
> Log recovered once cares that the commit records for each checkpoint
> are written in the correct order. You can see the checkpoint
> transactions be written to the log out of order, but the order of
> commit records determines the order in which checkpoints are
> replayed during recovery.
>
>> Looks to me that the problem is still in the cil push worker.
>
> I can't see how the commit records (which are written in
> xfs_log_done()) would be incorrectly ordered given the way that
> the commit list code serialises and orders calls to xfs_log_done()
> based on sequence number.
>
> Keep in mind that I might just be being stupid and missing
> something so obvious I need a brown paper bag to hide in, so you'll
> need to spell it out for me.
>
> Cheers,
>
> Dave.


It took me a long time to find the needle in the hay stack:

  427 STATIC int
  428 xlog_cil
...
  568         /*
  569          * now that we've written the checkpoint into the log, 
strictly
  570          * order the commit records so replay will get them in the 
right order.
  571          */
  572 restart:
  573         spin_lock(&cil->xc_push_lock);
  574         list_for_each_entry(new_ctx, &cil->xc_committing, 
committing) {
  575                 /*
  576                  * Avoid getting stuck in this loop because we 
were woken by the
  577                  * shutdown, but then went back to sleep once 
already in the
  578                  * shutdown state.
  579                  */
  580                 if (XLOG_FORCED_SHUTDOWN(log)) {
  581                         spin_unlock(&cil->xc_push_lock);
  582                         goto out_abort_free_ticket;
  583                 }
  584
  585                 /*
  586                  * Higher sequences will wait for this one so skip 
them.
  587                  * Don't wait for our own sequence, either.
  588                  */
  589                 if (new_ctx->sequence >= ctx->sequence)
  590                         continue;
  591                 if (!new_ctx->commit_lsn) {
		         ^^^^^^^^^^^^^^^^^^^^^          here ...
  592                         /*
  593                          * It is still being pushed! Wait for the 
push to
  594                          * complete, then start again from the 
beginning.
  595                          */
  596                         xlog_wait(&cil->xc_commit_wait, 
&cil->xc_push_lock);
  597                         goto restart;
  598                 }
  599         }
  600         spin_unlock(&cil->xc_push_lock);_push(
  429         struct xlog             *log)
  430 {
...and ...

   65 /*
   66  * After the first stage of log recovery is done, we know where 
the head and
   67  * tail of the log are. We need this log initialisation done 
before we can
   68  * initialise the first CIL checkpoint context.
   69  *
   70  * Here we allocate a log ticket to track space usage during a CIL 
push.  This
   71  * ticket is passed to xlog_write() directly so that we don't 
slowly leak log
   72  * space by failing to account for space used by log headers and 
additional
   73  * region headers for split regions.
   74  */
   75 void
   76 xlog_cil_init_post_recovery(
   77         struct xlog     *log)
   78 {
   79         log->l_cilp->xc_ctx->ticket = xlog_cil_ticket_alloc(log);
   80         log->l_cilp->xc_ctx->sequence = 1;
   81         log->l_cilp->xc_ctx->commit_lsn = 
xlog_assign_lsn(log->l_curr_cycle,
   82 
log->l_curr_block);
		^^^^^^^^^^ this setting is the problem.
   83 }


We need:
   1) More than one cil push after recovery. It appears that the cil push
      worker still does the pushes in separate threads and they write
      their log vector list in parallel.
   2) first push after the recovery is much larger than the following
      push(es).
     a) the following push's log writes beat the first.
     b) when they enter the above loop to check to see who is the lowest
        cil push sequence, since the commit_lsn was set in
        xlog_cil_init_post_recovery, so the later push sequences think
        that push 1 is complete writing the log item list and commit
        ticket, so they proceed and write their commit tickets.

--Mark.

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