On Mon, Nov 06, 2023 at 05:13:30PM +1100, Dave Chinner wrote:
> On Sun, Oct 29, 2023 at 12:11:22PM +0800, Zorro Lang wrote:
> > Hi xfs list,
> >
> > Recently I always hit xfs corruption by running fstests generic/047 [1], and
> > it show more failures in dmesg[2], e.g:
>
> OK, g/047 is an fsync test.
>
> >
> > XFS (loop1): Internal error !(flags & XFS_DABUF_MAP_HOLE_OK) at line 2572 of file fs/xfs/libxfs/xfs_da_btree.c. Caller xfs_dabuf_map.constprop.0+0x26c/0x368 [xfs]
>
> Ok, a directory block index translated to a hole in the file
> mapping. That's bad...
>
> > [2]
> > [ 376.468885] run fstests generic/047 at 2023-10-27 09:08:07
> > [ 376.675751] XFS (loop1): Mounting V5 Filesystem 716c9687-ee74-4c12-b6ad-a0b513194f2b
> > [ 376.677088] XFS (loop1): Ending clean mount
> > [ 376.678189] XFS (loop1): User initiated shutdown received.
> > [ 376.678194] XFS (loop1): Metadata I/O Error (0x4) detected at xfs_fs_goingdown+0x5a/0xf8 [xfs] (fs/xfs/xfs_fsops.c:492). Shutting down filesystem.
> > [ 376.678409] XFS (loop1): Please unmount the filesystem and rectify the problem(s)
> > [ 376.679423] XFS (loop1): Unmounting Filesystem 716c9687-ee74-4c12-b6ad-a0b513194f2b
> > [ 376.714910] XFS (loop1): Mounting V5 Filesystem 40196bb2-39f4-4c32-83ef-567f42216699
> > [ 376.716353] XFS (loop1): Ending clean mount
>
> Files are created and fsync'd here.
>
> > [ 380.375878] XFS (loop1): User initiated shutdown received.
> > [ 380.375888] XFS (loop1): Log I/O Error (0x6) detected at xfs_fs_goingdown+0xb4/0xf8 [xfs] (fs/xfs/xfs_fsops.c:495). Shutting down filesystem.
>
> Then the fs is shut down.
>
> > [ 380.376101] XFS (loop1): Please unmount the filesystem and rectify the problem(s)
> > [ 380.380373] XFS (loop1): Unmounting Filesystem 40196bb2-39f4-4c32-83ef-567f42216699
> > [ 380.383835] XFS (loop1): Mounting V5 Filesystem 40196bb2-39f4-4c32-83ef-567f42216699
> > [ 380.397086] XFS (loop1): Starting recovery (logdev: internal)
> > [ 380.465934] XFS (loop1): Ending recovery (logdev: internal)
>
> Then it is recovered....
> > [ 380.467409] XFS (loop1): Unmounting Filesystem 40196bb2-39f4-4c32-83ef-567f42216699
> > [ 380.475431] XFS (loop1): Mounting V5 Filesystem 40196bb2-39f4-4c32-83ef-567f42216699
> > [ 380.477235] XFS (loop1): Ending clean mount
> > [ 380.477500] XFS (loop1): Internal error !(flags & XFS_DABUF_MAP_HOLE_OK) at line 2572 of file fs/xfs/libxfs/xfs_da_btree.c. Caller xfs_dabuf_map.constprop.0+0x26c/0x368 [xfs]
>
> .... and now the directory is bad.
>
> > [ 380.477636] CPU: 0 PID: 337362 Comm: 047 Kdump: loaded Tainted: G W 6.6.0-rc7+ #1
> > [ 380.477639] Hardware name: IBM 3931 LA1 400 (KVM/Linux)
> > [ 380.477641] Call Trace:
> > [ 380.477642] [<0000000032d71372>] dump_stack_lvl+0x62/0x80
> > [ 380.477648] [<000003ff7ff96c00>] xfs_corruption_error+0x70/0xa0 [xfs]
> > [ 380.477762] [<000003ff7ff551ce>] xfs_dabuf_map.constprop.0+0x2a6/0x368 [xfs]
> > [ 380.477871] [<000003ff7ff5773e>] xfs_da_read_buf+0x6e/0x128 [xfs]
> > [ 380.477977] [<000003ff7ff57838>] xfs_da3_node_read+0x40/0x78 [xfs]
> > [ 380.478085] [<000003ff7ff58c7a>] xfs_da3_node_lookup_int+0x82/0x558 [xfs]
> > [ 380.478193] [<000003ff7ff68d6e>] xfs_dir2_node_lookup+0x3e/0x140 [xfs]
>
> So it's supposed to be in node format, which means enough blocks to
> have an external free list. I guess a thousand dirents is enough to
> do that.
>
> Yet fsync is run after every file is created and written, so the
> dirents and directory blocks should all be there....
>
> .....
>
> > _check_xfs_filesystem: filesystem on /dev/loop1 is inconsistent (r)
> > *** xfs_repair -n output ***
> > Phase 1 - find and verify superblock...
> > Phase 2 - using internal log
> > - zero log...
> > - scan filesystem freespace and inode maps...
> > - 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
> > bad nblocks 9 for inode 128, would reset to 0
> > no . entry for directory 128
> > no .. entry for root directory 128
> > problem with directory contents in inode 128
> > would clear root inode 128
> > bad nblocks 8 for inode 131, would reset to 0
> > bad nblocks 8 for inode 132, would reset to 0
> > bad nblocks 8 for inode 133, would reset to 0
> > ...
> > bad nblocks 8 for inode 62438, would reset to 0
> > bad nblocks 8 for inode 62439, would reset to 0
> > bad nblocks 8 for inode 62440, would reset to 0
> > bad nblocks 8 for inode 62441, would reset to 0
>
> Yet all the files - including the data files that were fsync'd - are
> all bad.
>
> Aparently the journal has been recovered, but lots of metadata
> updates that should have been in the journal are missing after
> recovery has completed? That doesn't make a whole lot of sense -
> when did these tests start failing? Can you run a bisect?
Hi Dave,
Thanks for your reply :) I tried to do a kernel bisect long time, but
find nothing ... Then suddently, I found it's failed from a xfsprogs
change [1].
Although that's not the root cause of this bug (on s390x), it just
enabled "nrext64" by default, which I never tested on s390x before.
For now, we know this's an issue about this feature, and only on
s390x for now.
Thanks,
Zorro
[1]
commit e5b18d7d1d962e942ce3b0a9ccdb5872074e24df
Author: Darrick J. Wong <djwong@xxxxxxxxxx>
Date: Mon Sep 25 14:59:25 2023 -0700
mkfs: enable large extent counts by default
>
> -Dave.
> --
> Dave Chinner
> david@xxxxxxxxxxxxx
>
