[syzbot] [xfs?] INFO: task hung in xfs_ail_push_all_sync (2)

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 09f6b0c8904b Merge tag 'linux_kselftest-fixes-6.12-rc3' of..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=14af3fd0580000
kernel config: https://syzkaller.appspot.com/x/.config?x=7cd9e7e4a8a0a15b
dashboard link: https://syzkaller.appspot.com/bug?extid=611be8174be36ca5dbc9
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16c7705f980000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=14d2fb27980000

Downloadable assets:
disk image (non-bootable): https://storage.googleapis.com/syzbot-assets/7feb34a89c2a/non_bootable_disk-09f6b0c8.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/3844cfd6d6b9/vmlinux-09f6b0c8.xz
kernel image: https://storage.googleapis.com/syzbot-assets/8752e101c1ff/bzImage-09f6b0c8.xz
mounted in repro: https://storage.googleapis.com/syzbot-assets/5410decf46fa/mount_1.gz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+611be8...@syzkaller.appspotmail.com

INFO: task syz-executor279:5128 blocked for more than 143 seconds.
Not tainted 6.12.0-rc2-syzkaller-00291-g09f6b0c8904b #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor279 state:D stack:25488 pid:5128 tgid:5105 ppid:5102 flags:0x00004006
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x1895/0x4b30 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0x14b/0x320 kernel/sched/core.c:6774
xfs_ail_push_all_sync+0x236/0x310 fs/xfs/xfs_trans_ail.c:726
xfs_log_quiesce+0xdf/0x5b0 fs/xfs/xfs_log.c:1018
xfs_fs_freeze+0x8d/0x1a0 fs/xfs/xfs_super.c:936
freeze_super+0x81b/0xee0 fs/super.c:2107
fs_bdev_freeze+0x1ac/0x320 fs/super.c:1484
bdev_freeze+0xd6/0x220 block/bdev.c:257
xfs_fs_goingdown+0xa9/0x160 fs/xfs/xfs_fsops.c:446
xfs_file_ioctl+0x12e5/0x1a30 fs/xfs/xfs_ioctl.c:1343
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:907 [inline]
__se_sys_ioctl+0xf9/0x170 fs/ioctl.c:893
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xf3/0x230 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f70924b2539
RSP: 002b:00007f709243f168 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f709253c6d8 RCX: 00007f70924b2539
RDX: 0000000020000080 RSI: 000000008004587d RDI: 0000000000000005
RBP: 00007f709253c6d0 R08: 00007f709243f6c0 R09: 0000000000000000
R10: 00007f709243f6c0 R11: 0000000000000246 R12: 00007f709253c6dc
R13: 000000000000006e R14: 00007ffd410540a0 R15: 00007ffd41054188
</TASK>

Showing all locks held in the system:
1 lock held by khungtaskd/25:
#0: ffffffff8e937de0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
#0: ffffffff8e937de0 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
#0: ffffffff8e937de0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x55/0x2a0 kernel/locking/lockdep.c:6720
2 locks held by getty/4897:
#0: ffff88801e2510a0 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x25/0x70 drivers/tty/tty_ldisc.c:243
#1: ffffc9000039b2f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6a6/0x1e00 drivers/tty/n_tty.c:2211
5 locks held by syz-executor279/5128:
#0: ffff888031ccc6b0 (&bdev->bd_fsfreeze_mutex){+.+.}-{3:3}, at: bdev_freeze+0x2a/0x220 block/bdev.c:248
#1: ffff888011c84420 (sb_writers#10){++++}-{0:0}, at: sb_wait_write fs/super.c:1896 [inline]
#1: ffff888011c84420 (sb_writers#10){++++}-{0:0}, at: freeze_super+0x4e9/0xee0 fs/super.c:2085
#2: ffff888011c840e0 (&type->s_umount_key#44){+.+.}-{3:3}, at: __super_lock fs/super.c:56 [inline]
#2: ffff888011c840e0 (&type->s_umount_key#44){+.+.}-{3:3}, at: __super_lock_excl fs/super.c:71 [inline]
#2: ffff888011c840e0 (&type->s_umount_key#44){+.+.}-{3:3}, at: freeze_super+0x4f1/0xee0 fs/super.c:2086
#3: ffff888011c84518 (sb_pagefaults#2){+.+.}-{0:0}, at: sb_wait_write fs/super.c:1896 [inline]
#3: ffff888011c84518 (sb_pagefaults#2){+.+.}-{0:0}, at: freeze_super+0x519/0xee0 fs/super.c:2090
#4: ffff888011c84610 (sb_internal#2){++++}-{0:0}, at: sb_wait_write fs/super.c:1896 [inline]
#4: ffff888011c84610 (sb_internal#2){++++}-{0:0}, at: freeze_super+0x7cc/0xee0 fs/super.c:2104

=============================================

NMI backtrace for cpu 0
CPU: 0 UID: 0 PID: 25 Comm: khungtaskd Not tainted 6.12.0-rc2-syzkaller-00291-g09f6b0c8904b #0
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.3-debian-1.16.3-2~bpo12+1 04/01/2014
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:94 [inline]
dump_stack_lvl+0x241/0x360 lib/dump_stack.c:120
nmi_cpu_backtrace+0x49c/0x4d0 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x198/0x320 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:162 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:223 [inline]
watchdog+0xff4/0x1040 kernel/hung_task.c:379
kthread+0x2f0/0x390 kernel/kthread.c:389
ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

If the report is already addressed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.

If you want to overwrite report's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the report is a duplicate of another one, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup

[Dave Chinner]

On Wed, Oct 16, 2024 at 04:22:27PM -0700, syzbot wrote:
> Hello,
>
> syzbot found the following issue on:
>
> HEAD commit: 09f6b0c8904b Merge tag 'linux_kselftest-fixes-6.12-rc3' of..
> git tree: upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=14af3fd0580000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7cd9e7e4a8a0a15b
> dashboard link: https://syzkaller.appspot.com/bug?extid=611be8174be36ca5dbc9
> compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16c7705f980000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=14d2fb27980000

I explained this last time syzbot triggered this: this is a syzbot
configuration problem, not a filesystem bug.

[ 96.418071][ T5112] XFS (loop0): Mounting V5 Filesystem c496e05e-540d-4c72-b591-04d79d8b4eeb
[ 96.593743][ T5112] XFS (loop0): Ending clean mount
[ 96.791357][ T5112] loop0: detected capacity change from 32768 to 0
[ 96.814808][ T5127] xfsaild/loop0: attempt to access beyond end of device
[ 96.814808][ T5127] loop0: rw=4097, sector=2, nr_sectors = 1 limit=0
[ 96.851235][ T5127] xfsaild/loop0: attempt to access beyond end of device
[ 96.851235][ T5127] loop0: rw=4097, sector=24, nr_sectors = 8 limit=0
[ 96.860284][ T9] XFS (loop0): metadata I/O error in "xfs_buf_ioerror_alert_ratelimited+0x7b/0x1e0" at daddr 0x2 len 1 error 5
[ 96.886045][ T9] kworker/0:1: attempt to access beyond end of device
[ 96.886045][ T9] loop0: rw=4097, sector=2, nr_sectors = 1 limit=0
[ 96.900489][ T5127] xfsaild/loop0: attempt to access beyond end of device
[ 96.900489][ T5127] loop0: rw=4097, sector=32, nr_sectors = 8 limit=0
[ 96.932892][ T9] kworker/0:1: attempt to access beyond end of device
[ 96.932892][ T9] loop0: rw=4097, sector=24, nr_sectors = 8 limit=0
[ 96.940364][ T5127] xfsaild/loop0: attempt to access beyond end of device
[ 96.940364][ T5127] loop0: rw=4097, sector=8832, nr_sectors = 64 limit=0
.....

And so it goes until something tries to freeze the filesystem and
gets stuck waiting for writeback of metadata that is not making
progress because XFS defaults to -retry metadata write errors
forever- until the filesystem is shut down.

If the user expects an XFS filesystem to fail fast when they
accidentally shrink the block device under a mounted filesytem, then
they need to configure XFS to fail metadata IO fast. Otherwise
metadata will remain dirty and be retried until the filesystem is
shut down or the error behaviour is reconfigured.

Please fix your syzbot configurations and/or tests that screw with
the block device under filesystems to configure XFS filesystems to
fail fast so that these tests no longer generate unwanted noise.

#syz invalid

-Dave.
--
Dave Chinner
da...@fromorbit.com

[Aleksandr Nogikh]

Hi Dave,

On Thu, Oct 17, 2024 at 2:53 AM 'Dave Chinner' via syzkaller-bugs
<syzkall...@googlegroups.com> wrote:
>
> On Wed, Oct 16, 2024 at 04:22:27PM -0700, syzbot wrote:
> > Hello,
> >
> > syzbot found the following issue on:
> >
> > HEAD commit: 09f6b0c8904b Merge tag 'linux_kselftest-fixes-6.12-rc3' of..
> > git tree: upstream
> > console output: https://syzkaller.appspot.com/x/log.txt?x=14af3fd0580000
> > kernel config: https://syzkaller.appspot.com/x/.config?x=7cd9e7e4a8a0a15b
> > dashboard link: https://syzkaller.appspot.com/bug?extid=611be8174be36ca5dbc9
> > compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
> > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16c7705f980000
> > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=14d2fb27980000
>

It's better to just leave the issue open until syzbot actually stops
triggering it. Otherwise, after every "#syz invalid", the crash will
be eventually seen again and re-sent to the mailing lists.

In the other email you mentioned
"/sys/fs/xfs/<dev>/error/metadata/EIO/max_retries" as the only way to
prevent this hang. Must max_retries be set every time after xfs is
mounted? Or is it possible to somehow preconfigure it once at VM boot
and then no longer worry about it during fuzzing?

--
Aleksandr

[Dave Chinner]

On Fri, Oct 18, 2024 at 12:13:33PM +0200, Aleksandr Nogikh wrote:
> Hi Dave,
>
> On Thu, Oct 17, 2024 at 2:53 AM 'Dave Chinner' via syzkaller-bugs
> <syzkall...@googlegroups.com> wrote:
> >
> > On Wed, Oct 16, 2024 at 04:22:27PM -0700, syzbot wrote:
> > > Hello,
> > >
> > > syzbot found the following issue on:
> > >
> > > HEAD commit: 09f6b0c8904b Merge tag 'linux_kselftest-fixes-6.12-rc3' of..
> > > git tree: upstream
> > > console output: https://syzkaller.appspot.com/x/log.txt?x=14af3fd0580000
> > > kernel config: https://syzkaller.appspot.com/x/.config?x=7cd9e7e4a8a0a15b
> > > dashboard link: https://syzkaller.appspot.com/bug?extid=611be8174be36ca5dbc9
> > > compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
> > > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16c7705f980000
> > > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=14d2fb27980000
> >
>
> It's better to just leave the issue open until syzbot actually stops
> triggering it. Otherwise, after every "#syz invalid", the crash will
> be eventually seen again and re-sent to the mailing lists.
>
> In the other email you mentioned
> "/sys/fs/xfs/<dev>/error/metadata/EIO/max_retries" as the only way to
> prevent this hang. Must max_retries be set every time after xfs is
> mounted? Or is it possible to somehow preconfigure it once at VM boot
> and then no longer worry about it during fuzzing?

It's a post mount config because the filesystem has to be mounted
before the error config files show up in /sys/fs/xfs/<dev>/....

For example, in fstests we set "fail_at_unmount" specifically when
running a test that will error out all writes and then unmount.

The code that does this is in common/xfs:

# Prepare a mounted filesystem for an IO error shutdown test by disabling retry
# for metadata writes. This prevents a (rare) log livelock when:
#
# - The log has given out all available grant space, preventing any new
# writers from tripping over IO errors (and shutting down the fs/log),
# - All log buffers were written to disk, and
# - The log tail is pinned because the AIL keeps hitting EIO trying to write
# committed changes back into the filesystem.
#
# Real users might want the default behavior of the AIL retrying writes forever
# but for testing purposes we don't want to wait.
#
# The sole parameter should be the filesystem data device, e.g. $SCRATCH_DEV.
_xfs_prepare_for_eio_shutdown()
{
local dev="$1"
local ctlfile="error/fail_at_unmount"

# Once we enable IO errors, it's possible that a writer thread will
# trip over EIO, cancel the transaction, and shut down the system.
# This is expected behavior, so we need to remove the "Internal error"
# message from the list of things that can cause the test to be marked
# as failed.
_add_dmesg_filter "Internal error"

# Don't retry any writes during the (presumably) post-shutdown unmount
_has_fs_sysfs "$ctlfile" && _set_fs_sysfs_attr $dev "$ctlfile" 1

# Disable retry of metadata writes that fail with EIO
for ctl in max_retries retry_timeout_seconds; do
ctlfile="error/metadata/EIO/$ctl"

_has_fs_sysfs "$ctlfile" && _set_fs_sysfs_attr $dev "$ctlfile" 0
done
}

However, this does not address the same issue when a filesystem
freeze is run (because it has to bring the on-disk state down to the
same as a clean unmounted filesystem). Hence for syzbot, the only
way to avoid this sort of issue is to cap the maximum number of
retries so that metadata writes fail as soon as the device starts
rejecting them.

Realistically, we want syzbot to exercise both the retry logic and
the hard fail logic. Right now it is only exercising the retry
logic, so setting the max retries to, say, three retries would
exercise both the retry logic and the hard fail logic and still
avoid all the potential "livelock until user intervention" test
hangs...