Re: [Bug report][fstests generic/047] 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]

[Dave Chinner <david@fromorbit.com>]

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?

-Dave.
-- 
Dave Chinner
david@fromorbit.com