EFSCORRUPTED on mount?

EFSCORRUPTED on mount?

[Gregory Farnum]

While working with a Ceph node running XFS we somehow managed to
corrupt our filesystem. I don't think there were any hard powercycles
on this node, but while starting up after a kernel upgrade (it's
running 3.1) the daemon was performing its usual startup sequence (a
lot of file truncates, mostly) when it got an error out of the
filesystem:

2011-11-17 16:00:37.294876 7f83f3eef720 filestore(/mnt/osd.17)
truncate meta/pginfo_12.7c8/0 size 0
2011-11-17 16:00:37.483407 7f83f3eef720 filestore(/mnt/osd.17)
truncate meta/pginfo_12.7c8/0 size 0 = -117
2011-11-17 16:00:37.483476 7f83f3eef720 filestore(/mnt/osd.17)  error
error 117: Structure needs cleaning not handled

When I tried to look at the filesystem, it failed with EIO. When I
tried to mount the filesystem after a remount, it gave me an internal
error:

root@cephstore6358:~# mount /dev/sdg1 /mnt/osd.17
2011 Nov 18 14:52:47 cephstore6358 [82374.729383] XFS: Internal error
XFS_WANT_CORRUPTED_GOTO at line 1664 of file fs/xfs/xfs_alloc.c.
Caller 0xffffffff811d6b71
2011 Nov 18 14:52:47 cephstore6358 [82374.729386]
2011 Nov 18 14:52:47 cephstore6358 [82374.758262] XFS (sdg1): Internal
error xfs_trans_cancel at line 1928 of file fs/xfs/xfs_trans.c.
Caller 0xffffffff811fa463
2011 Nov 18 14:52:47 cephstore6358 [82374.758265]
2011 Nov 18 14:52:47 cephstore6358 [82374.758352] XFS (sdg1):
Corruption of in-memory data detected.  Shutting down filesystem
2011 Nov 18 14:52:47 cephstore6358 [82374.758356] XFS (sdg1): Please
umount the filesystem and rectify the problem(s)
2011 Nov 18 14:52:47 cephstore6358 [82374.758364] XFS (sdg1): Failed
to recover EFIs
mount: Structure needs cleaning

dmesg had a little more output:

dmesg says:
[82373.779312] XFS (sdg1): Mounting Filesystem
[82373.930531] XFS (sdg1): Starting recovery (logdev: internal)
[82374.729383] XFS: Internal error XFS_WANT_CORRUPTED_GOTO at line
1664 of file fs/xfs/xfs_alloc.c.  Caller 0xffffffff811d6b71
[82374.729386]
[82374.741959] Pid: 30648, comm: mount Not tainted
3.1.0-dho-00004-g1ffcb5c-dirty #1
[82374.749543] Call Trace:
[82374.751994]  [<ffffffff811d606e>] ? xfs_free_ag_extent+0x4e3/0x698
[82374.758157]  [<ffffffff811ce1f8>] ? xfs_setup_devices+0x84/0x84
[82374.758163]  [<ffffffff811ce1f8>] ? xfs_setup_devices+0x84/0x84
[82374.758167]  [<ffffffff811d6b71>] ? xfs_free_extent+0xb6/0xf9
[82374.758171]  [<ffffffff811d3034>] ? kmem_zone_alloc+0x58/0x9e
[82374.758179]  [<ffffffff812095f9>] ? xfs_trans_get_efd+0x21/0x2a
[82374.758185]  [<ffffffff811fa413>] ? xlog_recover_process_efi+0x113/0x172
[82374.758190]  [<ffffffff811fa54b>] ? xlog_recover_process_efis+0x4e/0x8e
[82374.758194]  [<ffffffff811faa53>] ? xlog_recover_finish+0x14/0x88
[82374.758199]  [<ffffffff8120088e>] ? xfs_mountfs+0x46c/0x56a
[82374.758204]  [<ffffffff811ce365>] ? xfs_fs_fill_super+0x16d/0x244
[82374.758213]  [<ffffffff810d5dcf>] ? mount_bdev+0x13d/0x198
[82374.758218]  [<ffffffff810d4a42>] ? mount_fs+0xc/0xa6
[82374.758225]  [<ffffffff810eb274>] ? vfs_kern_mount+0x61/0x97
[82374.758230]  [<ffffffff810eb316>] ? do_kern_mount+0x49/0xd6
[82374.758234]  [<ffffffff810eba99>] ? do_mount+0x6f6/0x75d
[82374.758241]  [<ffffffff810b4429>] ? memdup_user+0x3a/0x56
[82374.758246]  [<ffffffff810ebb88>] ? sys_mount+0x88/0xc4
[82374.758254]  [<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
[82374.758262] XFS (sdg1): Internal error xfs_trans_cancel at line
1928 of file fs/xfs/xfs_trans.c.  Caller 0xffffffff811fa463

[82374.758265]
[82374.758268] Pid: 30648, comm: mount Not tainted
3.1.0-dho-00004-g1ffcb5c-dirty #1
[82374.758270] Call Trace:
[82374.758275]  [<ffffffff81201ecd>] ? xfs_trans_cancel+0x56/0xcf
[82374.758279]  [<ffffffff811fa463>] ? xlog_recover_process_efi+0x163/0x172
[82374.758284]  [<ffffffff811fa54b>] ? xlog_recover_process_efis+0x4e/0x8e
[82374.758288]  [<ffffffff811faa53>] ? xlog_recover_finish+0x14/0x88
[82374.758293]  [<ffffffff8120088e>] ? xfs_mountfs+0x46c/0x56a
[82374.758298]  [<ffffffff811ce365>] ? xfs_fs_fill_super+0x16d/0x244
[82374.758303]  [<ffffffff810d5dcf>] ? mount_bdev+0x13d/0x198
[82374.758307]  [<ffffffff810d4a42>] ? mount_fs+0xc/0xa6
[82374.758312]  [<ffffffff810eb274>] ? vfs_kern_mount+0x61/0x97
[82374.758317]  [<ffffffff810eb316>] ? do_kern_mount+0x49/0xd6
[82374.758321]  [<ffffffff810eba99>] ? do_mount+0x6f6/0x75d
[82374.758325]  [<ffffffff810b4429>] ? memdup_user+0x3a/0x56
[82374.758330]  [<ffffffff810ebb88>] ? sys_mount+0x88/0xc4
[82374.758335]  [<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
[82374.758341] XFS (sdg1): xfs_do_force_shutdown(0x8) called from line
1929 of file fs/xfs/xfs_trans.c.  Return address = 0xffffffff81201ee6
[82374.758352] XFS (sdg1): Corruption of in-memory data detected.
Shutting down filesystem
[82374.758356] XFS (sdg1): Please umount the filesystem and rectify
the problem(s)
[82374.758364] XFS (sdg1): Failed to recover EFIs
[82374.758367] XFS (sdg1): log mount finish failed

xfs_check doesn't give me much either, since I assume the errors above
are involved in log replay:
root@cephstore6358:~# xfs_check -v /dev/sdg1
ERROR: The filesystem has valuable metadata changes in a log which needs to
be replayed.  Mount the filesystem to replay the log, and unmount it before
re-running xfs_check.  If you are unable to mount the filesystem, then use
the xfs_repair -L option to destroy the log and attempt a repair.
Note that destroying the log may cause corruption -- please attempt a mount
of the filesystem before doing this.

Is there something useful I can do about this? Data I can provide to
help track down what broke?
-Greg

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

Re: EFSCORRUPTED on mount?

[Emmanuel Florac]

Le Mon, 21 Nov 2011 10:06:20 -0800 vous écriviez:

> Is there something useful I can do about this? Data I can provide to
> help track down what broke?

xfs_check is mostly useless nowadays, use "xfs_repair -n" instead. At
this stage, there's probably not much you can do but an "xfs_repair -L"
to zero the log. Hope for the better.

In my opinion some service using the filesystem (ceph?) got stuck at
reboot and prevented proper unmounting of the fs. Or maybe was tehre
some IO error; you could check your logs for this too.

-- 
------------------------------------------------------------------------
Emmanuel Florac     |   Direction technique
                    |   Intellique
                    |	<eflorac@intellique.com>
                    |   +33 1 78 94 84 02
------------------------------------------------------------------------

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

Re: EFSCORRUPTED on mount?

[Ben Myers]

Hey Greg,

On Mon, Nov 21, 2011 at 10:06:20AM -0800, Gregory Farnum wrote:
> Is there something useful I can do about this? Data I can provide to
> help track down what broke?

It might be useful if you can provide an xfs_metadump of the filesystem.

xfs_metadump /dev/foo - | bzip2 > /tmp/foo.bz2

Thanks,
	Ben

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

Re: EFSCORRUPTED on mount?

[Gregory Farnum]

I lied a little bit — turns out an admin restarted the node with
reboot -fn. But I've been assured this shouldn't have been able to
corrupt the filesystem, so troubleshooting continues.

On Mon, Nov 21, 2011 at 2:13 PM, Ben Myers <bpm@sgi.com> wrote:
> Hey Greg,
>
> It might be useful if you can provide an xfs_metadump of the filesystem.
>
> xfs_metadump /dev/foo - | bzip2 > /tmp/foo.bz2
Sure. I posted it at ceph.newdream.net/sdg1.bz2
Thanks!

On Mon, Nov 21, 2011 at 1:52 PM, Emmanuel Florac <eflorac@intellique.com> wrote:
> xfs_check is mostly useless nowadays, use "xfs_repair -n" instead. At
> this stage, there's probably not much you can do but an "xfs_repair -L"
> to zero the log. Hope for the better.

oot@cephstore6358:~# xfs_repair -n /dev/sdg1
Phase 1 - find and verify superblock...
Phase 2 - using internal log
        - scan filesystem freespace and inode maps...
block (1,7800040-7800040) multiply claimed by cnt space tree, state - 2
agf_freeblks 80672443, counted 80672410 in ag 1
sb_icount 64, counted 251840
sb_ifree 61, counted 66
sb_fdblocks 462898325, counted 358494731
        - found root inode chunk
Phase 3 - for each AG...
        - scan (but don't clear) agi unlinked lists...
        - process known inodes and perform inode discovery...
        - agno = 0
data fork in ino 9434 claims free block 141395214
data fork in ino 9770 claims free block 142474809
data fork in ino 10212 claims free block 142638961
data fork in ino 11173 claims free block 142644317
data fork in ino 14117 claims free block 142411949
        - agno = 1
data fork in ino 2147485225 claims free block 142644284
data fork in ino 2147485241 claims free block 142465951
data fork in ino 2147486073 claims free block 142459130
data fork in ino 2147496267 claims free block 142411931
data fork in ino 2147497106 claims free block 142426585
data fork in ino 2147497824 claims free block 141402019
data fork in ino 2147502462 claims free block 142638996
data fork in ino 2150562849 claims free block 141404091
data fork in ino 2150562852 claims free block 141397795
data fork in ino 2150564343 claims free block 142644220
        - agno = 2
        - agno = 3
        - process newly discovered inodes...
Phase 4 - check for duplicate blocks...
        - setting up duplicate extent list...
        - check for inodes claiming duplicate blocks...
        - agno = 0
        - agno = 2
        - agno = 1
        - agno = 3
entry "inc\uosdmap.8818__0_A69FF397" at block 2 offset 2376 in
directory inode 2147484449 references free inode 2262318364
        would clear inode number in entry at offset 2376...
entry "inc\uosdmap.8817__0_A69FF2C7" at block 2 offset 2216 in
directory inode 377265 references free inode 2685370
        would clear inode number in entry at offset 2216...
entry "osdmap.8818__0_0A3E6C28" at block 2 offset 2056 in directory
inode 621643 references free inode 2685371
        would clear inode number in entry at offset 2056...
No modify flag set, skipping phase 5
Phase 6 - check inode connectivity...
        - traversing filesystem ...
entry "inc\uosdmap.8817__0_A69FF2C7" in directory inode 377265 points
to free inode 2685370, would junk entry
bad hash table for directory inode 377265 (no data entry): would rebuild
entry "osdmap.8818__0_0A3E6C28" in directory inode 621643 points to
free inode 2685371, would junk entry
bad hash table for directory inode 621643 (no data entry): would rebuild
bad hash table for directory inode 2147484441 (no leaf entry): would rebuild
entry "inc\uosdmap.8818__0_A69FF397" in directory inode 2147484449
points to free inode 2262318364, would junk entry
leaf block 8388608 for directory inode 2147484449 bad tail
        - traversal finished ...
        - moving disconnected inodes to lost+found ...
Phase 7 - verify link counts...
would have reset inode 2685369 nlinks from 1 to 2
would have reset inode 2262318317 nlinks from 1 to 2
No modify flag set, skipping filesystem flush and exiting.

root@cephstore6358:~# xfs_repair /dev/sdg1
Phase 1 - find and verify superblock...
Phase 2 - using internal log
        - zero log...
ERROR: The filesystem has valuable metadata changes in a log which needs to
be replayed.  Mount the filesystem to replay the log, and unmount it before
re-running xfs_repair.  If you are unable to mount the filesystem, then use
the -L option to destroy the log and attempt a repair.
Note that destroying the log may cause corruption -- please attempt a mount
of the filesystem before doing this.

root@cephstore6358:~# mount /dev/sdg1 /mnt/osd.17
2011 Nov 21 16:18:19 cephstore6358 [ 9989.033072] XFS: Internal error
XFS_WANT_CORRUPTED_GOTO at line 1664 of file fs/xfs/xfs_alloc.c.
Caller 0xffffffff811d6b71
2011 Nov 21 16:18:19 cephstore6358 [ 9989.033075]
2011 Nov 21 16:18:19 cephstore6358 [ 9989.053128] XFS (sdg1): Internal
error xfs_trans_cancel at line 1928 of file fs/xfs/xfs_trans.c.
Caller 0xffffffff811fa463
2011 Nov 21 16:18:19 cephstore6358 [ 9989.053130]
2011 Nov 21 16:18:19 cephstore6358 [ 9989.053215] XFS (sdg1):
Corruption of in-memory data detected.  Shutting down filesystem
2011 Nov 21 16:18:19 cephstore6358 [ 9989.053218] XFS (sdg1): Please
umount the filesystem and rectify the problem(s)
2011 Nov 21 16:18:19 cephstore6358 [ 9989.053226] XFS (sdg1): Failed
to recover EFIs
mount: Structure needs cleaning

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

Re: EFSCORRUPTED on mount?

[Dave Chinner]

On Mon, Nov 21, 2011 at 04:21:30PM -0800, Gregory Farnum wrote:
> I lied a little bit — turns out an admin restarted the node with
> reboot -fn.
FWIW, that reboot command does this:

-n     Don't sync before reboot or halt. Note that the kernel and
storage drivers may still sync.

-f     Force halt or reboot, don't call shutdown(8).

In other words, your admin basically told the system to shutdown
without syncing the data or running shutdown scripts that sync data.
i.e. it forces an immediate reboot while the system is still active,
causing an unclean shutdown and guaranteed data loss.

> But I've been assured this shouldn't have been able to
> corrupt the filesystem, so troubleshooting continues.

That depends entirely on your hardware. Are you running with
barriers enabled?  If you don't have barriers active, then metadata
corruption is entirely possible in this scenarion, especially if the
hardware does a drive reset or power cycle during the reboot
procedure. Even with barriers, there are RAID controllers that
enable back end drive caches and they fail to get flushed and hence
can cause corruption on unclean shutdowns.

IOWs, I'd be looking at how your storage is configured and
ruling that out as a cause before even trying to look at the
filesystem...

> On Mon, Nov 21, 2011 at 2:13 PM, Ben Myers <bpm@sgi.com> wrote:
> > Hey Greg,
> >
> > It might be useful if you can provide an xfs_metadump of the filesystem.
> >
> > xfs_metadump /dev/foo - | bzip2 > /tmp/foo.bz2
> Sure. I posted it at ceph.newdream.net/sdg1.bz2
> Thanks!
> 
> On Mon, Nov 21, 2011 at 1:52 PM, Emmanuel Florac <eflorac@intellique.com> wrote:
> > xfs_check is mostly useless nowadays, use "xfs_repair -n" instead. At
> > this stage, there's probably not much you can do but an "xfs_repair -L"
> > to zero the log. Hope for the better.
> 
> oot@cephstore6358:~# xfs_repair -n /dev/sdg1
> Phase 1 - find and verify superblock...
> Phase 2 - using internal log
>         - scan filesystem freespace and inode maps...
> block (1,7800040-7800040) multiply claimed by cnt space tree, state - 2
> agf_freeblks 80672443, counted 80672410 in ag 1
> sb_icount 64, counted 251840
> sb_ifree 61, counted 66
> sb_fdblocks 462898325, counted 358494731
.....

All these errors are likely to be caused by the fact log replay has
not completed. The only one that is suspect is the first one:

> block (1,7800040-7800040) multiply claimed by cnt space tree, state - 2

But there's no way the cause of that can be determined after the
fact from a metadump....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: EFSCORRUPTED on mount?

[Emmanuel Florac]

Le Mon, 21 Nov 2011 16:21:30 -0800 vous écriviez:

> I lied a little bit — turns out an admin restarted the node with
> reboot -fn. But I've been assured this shouldn't have been able to
> corrupt the filesystem, so troubleshooting continues.
> 

You need to use "xfs_repair -L" to zero the log.

-- 
------------------------------------------------------------------------
Emmanuel Florac     |   Direction technique
                    |   Intellique
                    |	<eflorac@intellique.com>
                    |   +33 1 78 94 84 02
------------------------------------------------------------------------

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

Re: EFSCORRUPTED on mount?

[Eric Sandeen]

On 11/21/11 12:06 PM, Gregory Farnum wrote:
> While working with a Ceph node running XFS we somehow managed to
> corrupt our filesystem. I don't think there were any hard powercycles
> on this node, but while starting up after a kernel upgrade (it's
> running 3.1) the daemon was performing its usual startup sequence (a
> lot of file truncates, mostly) when it got an error out of the
> filesystem:

Others have had good comments but also:

> 2011-11-17 16:00:37.294876 7f83f3eef720 filestore(/mnt/osd.17)
> truncate meta/pginfo_12.7c8/0 size 0
> 2011-11-17 16:00:37.483407 7f83f3eef720 filestore(/mnt/osd.17)
> truncate meta/pginfo_12.7c8/0 size 0 = -117
> 2011-11-17 16:00:37.483476 7f83f3eef720 filestore(/mnt/osd.17)  error
> error 117: Structure needs cleaning not handled

was there anything in dmesg/system logs right at this point?  XFS should
have said something about this original error.

-Eric

> When I tried to look at the filesystem, it failed with EIO. When I
> tried to mount the filesystem after a remount, it gave me an internal
> error:
> 
> root@cephstore6358:~# mount /dev/sdg1 /mnt/osd.17
> 2011 Nov 18 14:52:47 cephstore6358 [82374.729383] XFS: Internal error
> XFS_WANT_CORRUPTED_GOTO at line 1664 of file fs/xfs/xfs_alloc.c.
> Caller 0xffffffff811d6b71
> 2011 Nov 18 14:52:47 cephstore6358 [82374.729386]
> 2011 Nov 18 14:52:47 cephstore6358 [82374.758262] XFS (sdg1): Internal
> error xfs_trans_cancel at line 1928 of file fs/xfs/xfs_trans.c.
> Caller 0xffffffff811fa463
> 2011 Nov 18 14:52:47 cephstore6358 [82374.758265]
> 2011 Nov 18 14:52:47 cephstore6358 [82374.758352] XFS (sdg1):
> Corruption of in-memory data detected.  Shutting down filesystem
> 2011 Nov 18 14:52:47 cephstore6358 [82374.758356] XFS (sdg1): Please
> umount the filesystem and rectify the problem(s)
> 2011 Nov 18 14:52:47 cephstore6358 [82374.758364] XFS (sdg1): Failed
> to recover EFIs
> mount: Structure needs cleaning
> 
> dmesg had a little more output:
> 
> dmesg says:
> [82373.779312] XFS (sdg1): Mounting Filesystem
> [82373.930531] XFS (sdg1): Starting recovery (logdev: internal)
> [82374.729383] XFS: Internal error XFS_WANT_CORRUPTED_GOTO at line
> 1664 of file fs/xfs/xfs_alloc.c.  Caller 0xffffffff811d6b71
> [82374.729386]
> [82374.741959] Pid: 30648, comm: mount Not tainted
> 3.1.0-dho-00004-g1ffcb5c-dirty #1
> [82374.749543] Call Trace:
> [82374.751994]  [<ffffffff811d606e>] ? xfs_free_ag_extent+0x4e3/0x698
> [82374.758157]  [<ffffffff811ce1f8>] ? xfs_setup_devices+0x84/0x84
> [82374.758163]  [<ffffffff811ce1f8>] ? xfs_setup_devices+0x84/0x84
> [82374.758167]  [<ffffffff811d6b71>] ? xfs_free_extent+0xb6/0xf9
> [82374.758171]  [<ffffffff811d3034>] ? kmem_zone_alloc+0x58/0x9e
> [82374.758179]  [<ffffffff812095f9>] ? xfs_trans_get_efd+0x21/0x2a
> [82374.758185]  [<ffffffff811fa413>] ? xlog_recover_process_efi+0x113/0x172
> [82374.758190]  [<ffffffff811fa54b>] ? xlog_recover_process_efis+0x4e/0x8e
> [82374.758194]  [<ffffffff811faa53>] ? xlog_recover_finish+0x14/0x88
> [82374.758199]  [<ffffffff8120088e>] ? xfs_mountfs+0x46c/0x56a
> [82374.758204]  [<ffffffff811ce365>] ? xfs_fs_fill_super+0x16d/0x244
> [82374.758213]  [<ffffffff810d5dcf>] ? mount_bdev+0x13d/0x198
> [82374.758218]  [<ffffffff810d4a42>] ? mount_fs+0xc/0xa6
> [82374.758225]  [<ffffffff810eb274>] ? vfs_kern_mount+0x61/0x97
> [82374.758230]  [<ffffffff810eb316>] ? do_kern_mount+0x49/0xd6
> [82374.758234]  [<ffffffff810eba99>] ? do_mount+0x6f6/0x75d
> [82374.758241]  [<ffffffff810b4429>] ? memdup_user+0x3a/0x56
> [82374.758246]  [<ffffffff810ebb88>] ? sys_mount+0x88/0xc4
> [82374.758254]  [<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
> [82374.758262] XFS (sdg1): Internal error xfs_trans_cancel at line
> 1928 of file fs/xfs/xfs_trans.c.  Caller 0xffffffff811fa463
> 
> [82374.758265]
> [82374.758268] Pid: 30648, comm: mount Not tainted
> 3.1.0-dho-00004-g1ffcb5c-dirty #1
> [82374.758270] Call Trace:
> [82374.758275]  [<ffffffff81201ecd>] ? xfs_trans_cancel+0x56/0xcf
> [82374.758279]  [<ffffffff811fa463>] ? xlog_recover_process_efi+0x163/0x172
> [82374.758284]  [<ffffffff811fa54b>] ? xlog_recover_process_efis+0x4e/0x8e
> [82374.758288]  [<ffffffff811faa53>] ? xlog_recover_finish+0x14/0x88
> [82374.758293]  [<ffffffff8120088e>] ? xfs_mountfs+0x46c/0x56a
> [82374.758298]  [<ffffffff811ce365>] ? xfs_fs_fill_super+0x16d/0x244
> [82374.758303]  [<ffffffff810d5dcf>] ? mount_bdev+0x13d/0x198
> [82374.758307]  [<ffffffff810d4a42>] ? mount_fs+0xc/0xa6
> [82374.758312]  [<ffffffff810eb274>] ? vfs_kern_mount+0x61/0x97
> [82374.758317]  [<ffffffff810eb316>] ? do_kern_mount+0x49/0xd6
> [82374.758321]  [<ffffffff810eba99>] ? do_mount+0x6f6/0x75d
> [82374.758325]  [<ffffffff810b4429>] ? memdup_user+0x3a/0x56
> [82374.758330]  [<ffffffff810ebb88>] ? sys_mount+0x88/0xc4
> [82374.758335]  [<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
> [82374.758341] XFS (sdg1): xfs_do_force_shutdown(0x8) called from line
> 1929 of file fs/xfs/xfs_trans.c.  Return address = 0xffffffff81201ee6
> [82374.758352] XFS (sdg1): Corruption of in-memory data detected.
> Shutting down filesystem
> [82374.758356] XFS (sdg1): Please umount the filesystem and rectify
> the problem(s)
> [82374.758364] XFS (sdg1): Failed to recover EFIs
> [82374.758367] XFS (sdg1): log mount finish failed
> 
> xfs_check doesn't give me much either, since I assume the errors above
> are involved in log replay:
> root@cephstore6358:~# xfs_check -v /dev/sdg1
> ERROR: The filesystem has valuable metadata changes in a log which needs to
> be replayed.  Mount the filesystem to replay the log, and unmount it before
> re-running xfs_check.  If you are unable to mount the filesystem, then use
> the xfs_repair -L option to destroy the log and attempt a repair.
> Note that destroying the log may cause corruption -- please attempt a mount
> of the filesystem before doing this.
> 
> Is there something useful I can do about this? Data I can provide to
> help track down what broke?
> -Greg
> 
> _______________________________________________
> 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: EFSCORRUPTED on mount?

[Gregory Farnum]

On Mon, Nov 21, 2011 at 5:41 PM, Dave Chinner <david@fromorbit.com> wrote:
> In other words, your admin basically told the system to shutdown
> without syncing the data or running shutdown scripts that sync data.
> i.e. it forces an immediate reboot while the system is still active,
> causing an unclean shutdown and guaranteed data loss.
And he's been yelled at appropriately. ;) But the data loss actually
isn't a problem for us here as long as the filesystem isn't corrupted.

>> But I've been assured this shouldn't have been able to
>> corrupt the filesystem, so troubleshooting continues.
>
> That depends entirely on your hardware. Are you running with
> barriers enabled?  If you don't have barriers active, then metadata
> corruption is entirely possible in this scenarion, especially if the
> hardware does a drive reset or power cycle during the reboot
> procedure. Even with barriers, there are RAID controllers that
> enable back end drive caches and they fail to get flushed and hence
> can cause corruption on unclean shutdowns.
Barriers on (at least, nobody turned them off); the RAID card is
battery-backed; here are megacli dumps:
http://pastebin.com/yTskgzWG
http://pastebin.com/ekhczycy

Sorry if I seem to eager to assume it's an xfs bug but Ceph is a magic
machine for taking stable filesystems and making them cry. :/


On Tue, Nov 22, 2011 at 7:06 AM, Eric Sandeen <sandeen@sandeen.net> wrote:
> Others have had good comments but also:
>
>> 2011-11-17 16:00:37.294876 7f83f3eef720 filestore(/mnt/osd.17)
>> truncate meta/pginfo_12.7c8/0 size 0
>> 2011-11-17 16:00:37.483407 7f83f3eef720 filestore(/mnt/osd.17)
>> truncate meta/pginfo_12.7c8/0 size 0 = -117
>> 2011-11-17 16:00:37.483476 7f83f3eef720 filestore(/mnt/osd.17)  error
>> error 117: Structure needs cleaning not handled
>
> was there anything in dmesg/system logs right at this point?  XFS should
> have said something about this original error.
Whoops. The following is a sample of what was in dmesg and kern.log
after that point but before I did anything else (it repeated a lot but
there weren't any other lines of output):
xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
[56459.526220] XFS (sdg1): xfs_log_force: error 5 returned.
[56489.544153] XFS (sdg1): xfs_log_force: error 5 returned.
[56519.562087] XFS (sdg1): xfs_log_force: error 5 returned.
[56549.580021] XFS (sdg1): xfs_log_force: error 5 returned.
[56579.597956] XFS (sdg1): xfs_log_force: error 5 returned.
[56609.615889] XFS (sdg1): xfs_log_force: error 5 returned.
[56613.036430] XFS (sdg1): xfs_log_force: error 5 returned.
[56613.041731] XFS (sdg1): xfs_do_force_shutdown(0x1) called from line
1037 of file fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
[56619.430497] XFS (sdg1): xfs_log_force: error 5 returned.
[56619.435796] XFS (sdg1): xfs_do_force_shutdown(0x1) called from line
1037 of file fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8

Thanks!
-Greg

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

Re: EFSCORRUPTED on mount?

[Eric Sandeen]

On 11/22/11 12:47 PM, Gregory Farnum wrote:
> On Tue, Nov 22, 2011 at 7:06 AM, Eric Sandeen <sandeen@sandeen.net> wrote:
>> > Others have had good comments but also:
>> >
>>> >> 2011-11-17 16:00:37.294876 7f83f3eef720 filestore(/mnt/osd.17)
>>> >> truncate meta/pginfo_12.7c8/0 size 0
>>> >> 2011-11-17 16:00:37.483407 7f83f3eef720 filestore(/mnt/osd.17)
>>> >> truncate meta/pginfo_12.7c8/0 size 0 = -117
>>> >> 2011-11-17 16:00:37.483476 7f83f3eef720 filestore(/mnt/osd.17)  error
>>> >> error 117: Structure needs cleaning not handled
>> >
>> > was there anything in dmesg/system logs right at this point?  XFS should
>> > have said something about this original error.
> Whoops. The following is a sample of what was in dmesg and kern.log
> after that point but before I did anything else (it repeated a lot but
> there weren't any other lines of output):
> xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
> [56459.526220] XFS (sdg1): xfs_log_force: error 5 returned.
> [56489.544153] XFS (sdg1): xfs_log_force: error 5 returned.
> [56519.562087] XFS (sdg1): xfs_log_force: error 5 returned.
> [56549.580021] XFS (sdg1): xfs_log_force: error 5 returned.
> [56579.597956] XFS (sdg1): xfs_log_force: error 5 returned.
> [56609.615889] XFS (sdg1): xfs_log_force: error 5 returned.
> [56613.036430] XFS (sdg1): xfs_log_force: error 5 returned.

Ok, error 5 is EIO:

8 include/asm-generic/errno-base.h        8 #define EIO 5

So the very first error you saw was "xfs_do_force_shutdown(0x1) called from line..." ?
Or the "xfs_log_force error 5 returned?"  I'm wondering if there was more
before this.

It's worth looking carefully to see the very first problem reported by xfs,
and posibly from storage before that. (i.e. did your storage go wonky?)

-Eric

> [56613.041731] XFS (sdg1): xfs_do_force_shutdown(0x1) called from line
> 1037 of file fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
> [56619.430497] XFS (sdg1): xfs_log_force: error 5 returned.
> [56619.435796] XFS (sdg1): xfs_do_force_shutdown(0x1) called from line
> 1037 of file fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
> 
> Thanks!
> -Greg
> 

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

Re: EFSCORRUPTED on mount?

[Gregory Farnum]

On Tue, Nov 22, 2011 at 10:52 AM, Eric Sandeen <sandeen@sandeen.net> wrote:
> Ok, error 5 is EIO:
>
> 8 include/asm-generic/errno-base.h        8 #define EIO 5
>
> So the very first error you saw was "xfs_do_force_shutdown(0x1) called from line..." ?
> Or the "xfs_log_force error 5 returned?"  I'm wondering if there was more
> before this.
>
> It's worth looking carefully to see the very first problem reported by xfs,
> and posibly from storage before that. (i.e. did your storage go wonky?)
Oh, we have a few more logs than I'd thought to look for. The xfs
related messages from bootup after the kernel upgrade:
Nov 17 16:01:01 cephstore6358 kernel: [    1.924668] SGI XFS with
security attributes, large block/inode numbers, no debug enabled
...
Nov 17 16:01:01 cephstore6358 kernel: [  190.047204] XFS (sdc1):
Mounting Filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  190.198126] XFS (sdc1):
Starting recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  190.281929] XFS (sdc1):
Ending recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  190.296303] XFS (sde1):
Mounting Filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  190.430809] XFS (sde1):
Starting recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  197.486417] XFS (sde1):
Ending recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  197.492596] XFS (sdg1):
Mounting Filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  197.652085] XFS (sdg1):
Starting recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  197.724493] XFS (sdg1):
Ending recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  197.730526] XFS (sdi1):
Mounting Filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  197.871074] XFS (sdi1):
Starting recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  206.570177] XFS (sdi1):
Ending recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  206.576329] XFS (sdk1):
Mounting Filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  206.738760] XFS (sdk1):
Starting recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  206.823346] XFS (sdk1):
Ending recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  206.837938] XFS (sdm1):
Mounting Filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  206.962455] XFS (sdm1):
Starting recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  207.062120] XFS (sdm1):
Ending recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  207.078134] XFS (sdo1):
Mounting Filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  207.240052] XFS (sdo1):
Starting recovery (logdev: internal)
Nov 17 16:01:01 cephstore6358 kernel: [  207.321602] XFS (sdo1):
Ending recovery (logdev: internal)
...
Nov 17 16:01:01 cephstore6358 kernel: [  214.214688] XFS: Internal
error XFS_WANT_CORRUPTED_GOTO at line 1664 of file fs/xfs/xfs_alloc.c.
 Caller 0xffffffff811d6b71
Nov 17 16:01:01 cephstore6358 kernel: [  214.214692]
Nov 17 16:01:01 cephstore6358 kernel: [  214.227313] Pid: 11196, comm:
ceph-osd Not tainted 3.1.0-dho-00004-g1ffcb5c-dirty #1
Nov 17 16:01:01 cephstore6358 kernel: [  214.235056] Call Trace:
Nov 17 16:01:01 cephstore6358 kernel: [  214.237530]
[<ffffffff811d606e>] ? xfs_free_ag_extent+0x4e3/0x698
Nov 17 16:01:01 cephstore6358 kernel: [  214.243717]
[<ffffffff811d6b71>] ? xfs_free_extent+0xb6/0xf9
Nov 17 16:01:01 cephstore6358 kernel: [  214.249468]
[<ffffffff811d3034>] ? kmem_zone_alloc+0x58/0x9e
Nov 17 16:01:01 cephstore6358 kernel: [  214.255220]
[<ffffffff812095f9>] ? xfs_trans_get_efd+0x21/0x2a
Nov 17 16:01:01 cephstore6358 kernel: [  214.261159]
[<ffffffff811e2011>] ? xfs_bmap_finish+0xeb/0x160
Nov 17 16:01:01 cephstore6358 kernel: [  214.266993]
[<ffffffff811f8634>] ? xfs_itruncate_extents+0xe8/0x1d0
Nov 17 16:01:01 cephstore6358 kernel: [  214.273361]
[<ffffffff811f879f>] ? xfs_itruncate_data+0x83/0xee
Nov 17 16:01:01 cephstore6358 kernel: [  214.279362]
[<ffffffff811cb0a2>] ? xfs_setattr_size+0x246/0x36c
Nov 17 16:01:01 cephstore6358 kernel: [  214.285363]
[<ffffffff811cb1e3>] ? xfs_vn_setattr+0x1b/0x2f
Nov 17 16:01:01 cephstore6358 kernel: [  214.291031]
[<ffffffff810e7875>] ? notify_change+0x16d/0x23e
Nov 17 16:01:01 cephstore6358 kernel: [  214.296776]
[<ffffffff810d2982>] ? do_truncate+0x68/0x86
Nov 17 16:01:01 cephstore6358 kernel: [  214.302172]
[<ffffffff810d2b11>] ? sys_truncate+0x171/0x173
Nov 17 16:01:01 cephstore6358 kernel: [  214.307846]
[<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
Nov 17 16:01:01 cephstore6358 kernel: [  214.314031] XFS (sdg1):
xfs_do_force_shutdown(0x8) called from line 3864 of file
fs/xfs/xfs_bmap.c.  Return address = 0xffffffff811e2046
Nov 17 16:01:01 cephstore6358 kernel: [  214.340451] XFS (sdg1):
Corruption of in-memory data detected.  Shutting down filesystem
Nov 17 16:01:01 cephstore6358 kernel: [  214.348518] XFS (sdg1):
Please umount the filesystem and rectify the problem(s)
Nov 17 16:01:01 cephstore6358 kernel: [  227.789285] XFS (sdg1):
xfs_log_force: error 5 returned.
Nov 17 16:01:01 cephstore6358 kernel: [  229.820255] XFS (sdg1):
xfs_log_force: error 5 returned.
Nov 17 16:01:01 cephstore6358 kernel: [  229.825550] XFS (sdg1):
xfs_do_force_shutdown(0x1) called from line 1037 of file
fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
Nov 17 16:01:01 cephstore6358 kernel: [  229.845089] XFS (sdg1):
xfs_log_force: error 5 returned.
Nov 17 16:01:01 cephstore6358 kernel: [  229.850388] XFS (sdg1):
xfs_do_force_shutdown(0x1) called from line 1037 of file
fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
(etc)

I don't know the xfs code at all, but that looks like a bug to me —
either the system got itself into a broken state from valid on-disk
structures, or else the (best I can tell properly-ordered, barriered,
etc) journal didn't properly protect against brokenness elsewhere.
Also note that the initial post-reboot mount succeeded (it didn't
break until after doing a series of truncates), and the subsequent
ones are failing.
-Greg

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

Re: EFSCORRUPTED on mount?

[Eric Sandeen]

On 11/22/11 1:29 PM, Gregory Farnum wrote:
> On Tue, Nov 22, 2011 at 10:52 AM, Eric Sandeen <sandeen@sandeen.net> wrote:
>> Ok, error 5 is EIO:
>>
>> 8 include/asm-generic/errno-base.h        8 #define EIO 5
>>
>> So the very first error you saw was "xfs_do_force_shutdown(0x1) called from line..." ?
>> Or the "xfs_log_force error 5 returned?"  I'm wondering if there was more
>> before this.
>>
>> It's worth looking carefully to see the very first problem reported by xfs,
>> and posibly from storage before that. (i.e. did your storage go wonky?)
> Oh, we have a few more logs than I'd thought to look for. The xfs
> related messages from bootup after the kernel upgrade:
> Nov 17 16:01:01 cephstore6358 kernel: [    1.924668] SGI XFS with
> security attributes, large block/inode numbers, no debug enabled
> ...
> Nov 17 16:01:01 cephstore6358 kernel: [  190.047204] XFS (sdc1):
> Mounting Filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  190.198126] XFS (sdc1):
> Starting recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  190.281929] XFS (sdc1):
> Ending recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  190.296303] XFS (sde1):
> Mounting Filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  190.430809] XFS (sde1):
> Starting recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  197.486417] XFS (sde1):
> Ending recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  197.492596] XFS (sdg1):
> Mounting Filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  197.652085] XFS (sdg1):
> Starting recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  197.724493] XFS (sdg1):
> Ending recovery (logdev: internal)

so by here sdg1 had to go through recovery, but was otherwise happy.

> Nov 17 16:01:01 cephstore6358 kernel: [  197.730526] XFS (sdi1):
> Mounting Filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  197.871074] XFS (sdi1):
> Starting recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  206.570177] XFS (sdi1):
> Ending recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  206.576329] XFS (sdk1):
> Mounting Filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  206.738760] XFS (sdk1):
> Starting recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  206.823346] XFS (sdk1):
> Ending recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  206.837938] XFS (sdm1):
> Mounting Filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  206.962455] XFS (sdm1):
> Starting recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  207.062120] XFS (sdm1):
> Ending recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  207.078134] XFS (sdo1):
> Mounting Filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  207.240052] XFS (sdo1):
> Starting recovery (logdev: internal)
> Nov 17 16:01:01 cephstore6358 kernel: [  207.321602] XFS (sdo1):
> Ending recovery (logdev: internal)
> ...

All that recovery a result of the icky shutdown procedure I guess....

> Nov 17 16:01:01 cephstore6358 kernel: [  214.214688] XFS: Internal
> error XFS_WANT_CORRUPTED_GOTO at line 1664 of file fs/xfs/xfs_alloc.c.
>  Caller 0xffffffff811d6b71

And this was the first indication of trouble.

> Nov 17 16:01:01 cephstore6358 kernel: [  214.214692]
> Nov 17 16:01:01 cephstore6358 kernel: [  214.227313] Pid: 11196, comm:
> ceph-osd Not tainted 3.1.0-dho-00004-g1ffcb5c-dirty #1
> Nov 17 16:01:01 cephstore6358 kernel: [  214.235056] Call Trace:
> Nov 17 16:01:01 cephstore6358 kernel: [  214.237530]
> [<ffffffff811d606e>] ? xfs_free_ag_extent+0x4e3/0x698
> Nov 17 16:01:01 cephstore6358 kernel: [  214.243717]
> [<ffffffff811d6b71>] ? xfs_free_extent+0xb6/0xf9
> Nov 17 16:01:01 cephstore6358 kernel: [  214.249468]
> [<ffffffff811d3034>] ? kmem_zone_alloc+0x58/0x9e
> Nov 17 16:01:01 cephstore6358 kernel: [  214.255220]
> [<ffffffff812095f9>] ? xfs_trans_get_efd+0x21/0x2a
> Nov 17 16:01:01 cephstore6358 kernel: [  214.261159]
> [<ffffffff811e2011>] ? xfs_bmap_finish+0xeb/0x160
> Nov 17 16:01:01 cephstore6358 kernel: [  214.266993]
> [<ffffffff811f8634>] ? xfs_itruncate_extents+0xe8/0x1d0
> Nov 17 16:01:01 cephstore6358 kernel: [  214.273361]
> [<ffffffff811f879f>] ? xfs_itruncate_data+0x83/0xee
> Nov 17 16:01:01 cephstore6358 kernel: [  214.279362]
> [<ffffffff811cb0a2>] ? xfs_setattr_size+0x246/0x36c
> Nov 17 16:01:01 cephstore6358 kernel: [  214.285363]
> [<ffffffff811cb1e3>] ? xfs_vn_setattr+0x1b/0x2f
> Nov 17 16:01:01 cephstore6358 kernel: [  214.291031]
> [<ffffffff810e7875>] ? notify_change+0x16d/0x23e
> Nov 17 16:01:01 cephstore6358 kernel: [  214.296776]
> [<ffffffff810d2982>] ? do_truncate+0x68/0x86
> Nov 17 16:01:01 cephstore6358 kernel: [  214.302172]
> [<ffffffff810d2b11>] ? sys_truncate+0x171/0x173
> Nov 17 16:01:01 cephstore6358 kernel: [  214.307846]
> [<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
> Nov 17 16:01:01 cephstore6358 kernel: [  214.314031] XFS (sdg1):
> xfs_do_force_shutdown(0x8) called from line 3864 of file
> fs/xfs/xfs_bmap.c.  Return address = 0xffffffff811e2046

by here it had shut down, and you were just riding along when
it went kablooey.  Any non-xfs error just before this point?

> Nov 17 16:01:01 cephstore6358 kernel: [  214.340451] XFS (sdg1):
> Corruption of in-memory data detected.  Shutting down filesystem
> Nov 17 16:01:01 cephstore6358 kernel: [  214.348518] XFS (sdg1):
> Please umount the filesystem and rectify the problem(s)
> Nov 17 16:01:01 cephstore6358 kernel: [  227.789285] XFS (sdg1):
> xfs_log_force: error 5 returned.
> Nov 17 16:01:01 cephstore6358 kernel: [  229.820255] XFS (sdg1):
> xfs_log_force: error 5 returned.

To be honest I'm not sure offhand if this error 5 (EIO) is a
result of the shutdown, or the cause of it.

-Eric

> Nov 17 16:01:01 cephstore6358 kernel: [  229.825550] XFS (sdg1):
> xfs_do_force_shutdown(0x1) called from line 1037 of file
> fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
> Nov 17 16:01:01 cephstore6358 kernel: [  229.845089] XFS (sdg1):
> xfs_log_force: error 5 returned.
> Nov 17 16:01:01 cephstore6358 kernel: [  229.850388] XFS (sdg1):
> xfs_do_force_shutdown(0x1) called from line 1037 of file
> fs/xfs/xfs_buf.c.  Return address = 0xffffffff811c2aa8
> (etc)
> 
> I don't know the xfs code at all, but that looks like a bug to me —
> either the system got itself into a broken state from valid on-disk
> structures, or else the (best I can tell properly-ordered, barriered,
> etc) journal didn't properly protect against brokenness elsewhere.
> Also note that the initial post-reboot mount succeeded (it didn't
> break until after doing a series of truncates), and the subsequent
> ones are failing.
> -Greg
> 

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

Re: EFSCORRUPTED on mount?

[Christoph Hellwig]

On Tue, Nov 22, 2011 at 10:47:24AM -0800, Gregory Farnum wrote:
> Barriers on (at least, nobody turned them off); the RAID card is
> battery-backed; here are megacli dumps:
> http://pastebin.com/yTskgzWG
> http://pastebin.com/ekhczycy

I had a lot of of issues with megaraid cards and their unsafe caching
settings, up to the point that I'd recommend staying away from them
now.  Can you check in the megacli config if the _disk_ write caches
are enabled?  megaraid adapters used to do that a lot, and given that
the disk cache isn't batter backed it's fairly fatal.

I think in your dump this one might be the culprit given that SATA
disks outside of a few niches come with a writeback cache policy:

Disk Cache Policy: Disk's Default

try changing that to an explicit writethrough mode - and maybe try
running a crash data integrity test like

	http://www.complang.tuwien.ac.at/anton/hdtest/

on this controller.

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

Re: EFSCORRUPTED on mount?

[Christoph Hellwig]

On Tue, Nov 22, 2011 at 03:53:07PM -0600, Eric Sandeen wrote:
> > Ending recovery (logdev: internal)
> > ...
> 
> All that recovery a result of the icky shutdown procedure I guess....
> 
> > Nov 17 16:01:01 cephstore6358 kernel: [  214.214688] XFS: Internal
> > error XFS_WANT_CORRUPTED_GOTO at line 1664 of file fs/xfs/xfs_alloc.c.
> >  Caller 0xffffffff811d6b71
> 
> And this was the first indication of trouble.

allocation btree corruption - we try to free a block, which had already
been inserted into the by-size allocation btree.  This very much looks
like a cache failure to me.

> > Nov 17 16:01:01 cephstore6358 kernel: [  214.302172]
> > [<ffffffff810d2b11>] ? sys_truncate+0x171/0x173
> > Nov 17 16:01:01 cephstore6358 kernel: [  214.307846]
> > [<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
> > Nov 17 16:01:01 cephstore6358 kernel: [  214.314031] XFS (sdg1):
> > xfs_do_force_shutdown(0x8) called from line 3864 of file
> > fs/xfs/xfs_bmap.c.  Return address = 0xffffffff811e2046
> 
> by here it had shut down, and you were just riding along when
> it went kablooey.  Any non-xfs error just before this point?

And this was the caller of xfs_free_extent, now shuting the fs down
because of the above error.

> > Nov 17 16:01:01 cephstore6358 kernel: [  214.340451] XFS (sdg1):
> > Corruption of in-memory data detected.  Shutting down filesystem
> > Nov 17 16:01:01 cephstore6358 kernel: [  214.348518] XFS (sdg1):
> > Please umount the filesystem and rectify the problem(s)
> > Nov 17 16:01:01 cephstore6358 kernel: [  227.789285] XFS (sdg1):
> > xfs_log_force: error 5 returned.
> > Nov 17 16:01:01 cephstore6358 kernel: [  229.820255] XFS (sdg1):
> > xfs_log_force: error 5 returned.
> 
> To be honest I'm not sure offhand if this error 5 (EIO) is a
> result of the shutdown, or the cause of it.

It is.  One the filesystem has been shut down xfs_log_force will
always return EIO.  The printk for is rather useless, though.

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

Re: EFSCORRUPTED on mount?

[Gregory Farnum]

On Tue, Nov 22, 2011 at 1:53 PM, Eric Sandeen <sandeen@sandeen.net> wrote:
> And this was the first indication of trouble.
>
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.214692]
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.227313] Pid: 11196, comm:
>> ceph-osd Not tainted 3.1.0-dho-00004-g1ffcb5c-dirty #1
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.235056] Call Trace:
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.237530]
>> [<ffffffff811d606e>] ? xfs_free_ag_extent+0x4e3/0x698
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.243717]
>> [<ffffffff811d6b71>] ? xfs_free_extent+0xb6/0xf9
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.249468]
>> [<ffffffff811d3034>] ? kmem_zone_alloc+0x58/0x9e
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.255220]
>> [<ffffffff812095f9>] ? xfs_trans_get_efd+0x21/0x2a
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.261159]
>> [<ffffffff811e2011>] ? xfs_bmap_finish+0xeb/0x160
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.266993]
>> [<ffffffff811f8634>] ? xfs_itruncate_extents+0xe8/0x1d0
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.273361]
>> [<ffffffff811f879f>] ? xfs_itruncate_data+0x83/0xee
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.279362]
>> [<ffffffff811cb0a2>] ? xfs_setattr_size+0x246/0x36c
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.285363]
>> [<ffffffff811cb1e3>] ? xfs_vn_setattr+0x1b/0x2f
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.291031]
>> [<ffffffff810e7875>] ? notify_change+0x16d/0x23e
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.296776]
>> [<ffffffff810d2982>] ? do_truncate+0x68/0x86
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.302172]
>> [<ffffffff810d2b11>] ? sys_truncate+0x171/0x173
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.307846]
>> [<ffffffff8166c07b>] ? system_call_fastpath+0x16/0x1b
>> Nov 17 16:01:01 cephstore6358 kernel: [  214.314031] XFS (sdg1):
>> xfs_do_force_shutdown(0x8) called from line 3864 of file
>> fs/xfs/xfs_bmap.c.  Return address = 0xffffffff811e2046
>
> by here it had shut down, and you were just riding along when
> it went kablooey.  Any non-xfs error just before this point?

Nope, nothing from anybody else.


On Tue, Nov 22, 2011 at 2:11 PM, Christoph Hellwig <hch@infradead.org> wrote:
> On Tue, Nov 22, 2011 at 10:47:24AM -0800, Gregory Farnum wrote:
>> Barriers on (at least, nobody turned them off); the RAID card is
>> battery-backed; here are megacli dumps:
>> http://pastebin.com/yTskgzWG
>> http://pastebin.com/ekhczycy
>
> I had a lot of of issues with megaraid cards and their unsafe caching
> settings, up to the point that I'd recommend staying away from them
> now.  Can you check in the megacli config if the _disk_ write caches
> are enabled?  megaraid adapters used to do that a lot, and given that
> the disk cache isn't batter backed it's fairly fatal.
>
> I think in your dump this one might be the culprit given that SATA
> disks outside of a few niches come with a writeback cache policy:
>
> Disk Cache Policy: Disk's Default
>
> try changing that to an explicit writethrough mode - and maybe try
> running a crash data integrity test like
>
>        http://www.complang.tuwien.ac.at/anton/hdtest/
>
> on this controller.
We're going to look into this in more detail very shortly. Right now
all I can tell you is that none of the drives ever actually lost
power, so unless something is explicitly telling them to clear their
caches I don't know how the drives could have lost their cache to
cause a problem like this.
But for now I'll just see what I can get by zeroing out the log, and
we'll get back to you again if we manage to reproduce this in a
situation where we can tell you more definitively about the caching
and barriers.
Thanks guys,
-Greg

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

Re: EFSCORRUPTED on mount?

[Christoph Hellwig]

On Tue, Nov 22, 2011 at 04:03:15PM -0800, Gregory Farnum wrote:
> We're going to look into this in more detail very shortly. Right now
> all I can tell you is that none of the drives ever actually lost
> power, so unless something is explicitly telling them to clear their
> caches I don't know how the drives could have lost their cache to
> cause a problem like this.
> But for now I'll just see what I can get by zeroing out the log, and
> we'll get back to you again if we manage to reproduce this in a
> situation where we can tell you more definitively about the caching
> and barriers.

I would be very interested in that.  The situation you have is fairly
easy to pinpoint down - we do log recovery and find and EFI record
in the log - that is one that logs the intent to free extents.

We haven't found the corresponing EFD record, which cancels it out
as part of the transaction doing the actual freeing.  I'd love to
see a log dump of a fs iff this can be reproduced as that would
shows us if we had some sort of bug in recovery.

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