[syzbot] [reiserfs?] INFO: task hung in flush_old_commits

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: f1fcbaa18b28 Linux 6.4-rc2
git tree: git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci
console output: https://syzkaller.appspot.com/x/log.txt?x=16a6382e280000
kernel config: https://syzkaller.appspot.com/x/.config?x=3dc1cdd68141cdc3
dashboard link: https://syzkaller.appspot.com/bug?extid=0a684c061589dcc30e51
compiler: Debian clang version 15.0.7, GNU ld (GNU Binutils for Debian) 2.35.2
userspace arch: arm64
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=163079f9280000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1239f37e280000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/f9e1748cceea/disk-f1fcbaa1.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/6dea99343621/vmlinux-f1fcbaa1.xz
kernel image: https://storage.googleapis.com/syzbot-assets/f5a93f86012d/Image-f1fcbaa1.gz.xz
mounted in repro: https://storage.googleapis.com/syzbot-assets/f87acf2fade6/mount_1.gz

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

INFO: task kworker/0:2:1599 blocked for more than 143 seconds.
Not tainted 6.4.0-rc2-syzkaller-gf1fcbaa18b28 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:2 state:D stack:0 pid:1599 ppid:2 flags:0x00000008
Workqueue: events_long flush_old_commits
Call trace:
__switch_to+0x320/0x754 arch/arm64/kernel/process.c:556
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0x1368/0x23b8 kernel/sched/core.c:6669
schedule+0xc4/0x170 kernel/sched/core.c:6745
schedule_preempt_disabled+0x18/0x2c kernel/sched/core.c:6804
__mutex_lock_common+0xbd8/0x21a0 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x2c/0x38 kernel/locking/mutex.c:799
reiserfs_write_lock+0x7c/0xe8 fs/reiserfs/lock.c:27
reiserfs_sync_fs fs/reiserfs/super.c:76 [inline]
flush_old_commits+0x1b0/0x2b8 fs/reiserfs/super.c:111
process_one_work+0x788/0x12d4 kernel/workqueue.c:2405
worker_thread+0x8e0/0xfe8 kernel/workqueue.c:2552
kthread+0x288/0x310 kernel/kthread.c:379
ret_from_fork+0x10/0x20 arch/arm64/kernel/entry.S:870

Showing all locks held in the system:
1 lock held by rcu_tasks_kthre/13:
#0:
ffff8000160810d0
(
rcu_tasks.tasks_gp_mutex
){+.+.}-{3:3}
, at: rcu_tasks_one_gp+0x44/0xcf4 kernel/rcu/tasks.h:518
1 lock held by rcu_tasks_trace/14:
#0:
ffff800016081490
(
rcu_tasks_trace.tasks_gp_mutex
){+.+.}-{3:3}
, at: rcu_tasks_one_gp+0x44/0xcf4 kernel/rcu/tasks.h:518
1 lock held by khungtaskd/28:
#0:
ffff800016080f00
(
rcu_read_lock
){....}-{1:2}
, at: rcu_lock_acquire+0xc/0x44 include/linux/rcupdate.h:326
4 locks held by kworker/0:2/1599:
#0:
ffff0000c0021538
(
(wq_completion)events_long
){+.+.}-{0:0}
, at: process_one_work+0x664/0x12d4 kernel/workqueue.c:2378
#1:
ffff800022d77c20
(
(work_completion)(&(&sbi->old_work)->work)
){+.+.}-{0:0}
, at: process_one_work+0x6a8/0x12d4 kernel/workqueue.c:2380
#2:
ffff0000df14e0e0
(
&type->s_umount_key
#40
){++++}-{3:3}
, at: flush_old_commits+0xcc/0x2b8 fs/reiserfs/super.c:97
#3:
ffff0000c5d07090
(
&sbi->lock
){+.+.}-{3:3}
, at: reiserfs_write_lock+0x7c/0xe8 fs/reiserfs/lock.c:27
2 locks held by getty/5732:
#0:
ffff0000d4c6f098
(
&tty->ldisc_sem
){++++}-{0:0}
, at: ldsem_down_read+0x3c/0x4c drivers/tty/tty_ldsem.c:340
#1:
ffff80001ae302f0
(
&ldata->atomic_read_lock
){+.+.}-{3:3}
, at: n_tty_read+0x414/0x1210 drivers/tty/n_tty.c:2176
7 locks held by syz-executor247/6003:

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



---
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 bug is already fixed, 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 change bug's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

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

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

[syzbot]

syzbot has bisected this issue to:

commit d82dcd9e21b77d338dc4875f3d4111f0db314a7c
Author: Roberto Sassu <robert...@huawei.com>
Date: Fri Mar 31 12:32:18 2023 +0000

reiserfs: Add security prefix to xattr name in reiserfs_security_write()

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=11c39639280000
start commit: 421ca22e3138 Merge tag 'nfs-for-6.4-2' of git://git.linux-..
git tree: upstream
final oops: https://syzkaller.appspot.com/x/report.txt?x=13c39639280000
console output: https://syzkaller.appspot.com/x/log.txt?x=15c39639280000
kernel config: https://syzkaller.appspot.com/x/.config?x=7d8067683055e3f5
dashboard link: https://syzkaller.appspot.com/bug?extid=0a684c061589dcc30e51
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14312791280000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=12da8605280000

Reported-by: syzbot+0a684c...@syzkaller.appspotmail.com
Fixes: d82dcd9e21b7 ("reiserfs: Add security prefix to xattr name in reiserfs_security_write()")

For information about bisection process see: https://goo.gl/tpsmEJ#bisection

[Paul Moore]

Roberto, I think we need to resolve this somehow. As I mentioned
earlier, I don't believe this to be a fault in your patch, rather that
patch simply triggered a situation that had not been present before,
likely because the reiserfs code always failed when writing LSM
xattrs. Regardless, we still need to fix the deadlocks that sysbot
has been reporting.

Has anyone dug into the reiserfs code to try and resolve the deadlock?
Considering the state of reiserfs, I'm guessing no one has, and I
can't blame them; I personally would have a hard time justifying
significant time spent on reiserfs at this point. Unless someone has
any better ideas, I'm wondering if we shouldn't just admit defeat with
reiserfs and LSM xattrs and disable/remove the reiserfs LSM xattr
support? Given the bug that Roberto was fixing with the patch in
question, it's unlikely this was working anyway.

--
paul-moore.com

[Roberto Sassu]

Hi Paul

ok, I will try.

Roberto

[Paul Moore]

Thanks Roberto. If it gets to be too challenging, let us know and we
can look into safely disabling the LSM xattrs for reiserfs, I'll be
shocked if anyone is successfully using LSM xattrs on reiserfs.

[Roberto Sassu]

Ok, at least I know what happens...

+ Jan, Jeff

I'm focusing on this reproducer, which works 100% of the times:

https://syzkaller.appspot.com/text?tag=ReproSyz&x=163079f9280000

This is the last lock, before things go wrong:

Thread 5 hit Breakpoint 2, reiserfs_write_lock (s=s@entry=0xffff888066e28000) at fs/reiserfs/lock.c:24
24 {
(gdb) bt
#0 reiserfs_write_lock (s=s@entry=0xffff888066e28000) at fs/reiserfs/lock.c:24
#1 0xffffffff821a559a in reiserfs_get_block (inode=inode@entry=0xffff888069fd0190, block=block@entry=15, bh_result=bh_result@entry=0xffff888075940000, create=create@entry=1) at fs/reiserfs/inode.c:680
#2 0xffffffff81f50254 in __block_write_begin_int (folio=0xffffea00019a9180, pos=pos@entry=61440, len=len@entry=1, get_block=get_block@entry=0xffffffff821a5390 <reiserfs_get_block>, iomap=iomap@entry=0x0 <fixed_percpu_data>) at fs/buffer.c:2064
#3 0xffffffff81f5165a in __block_write_begin (page=page@entry=0xffffea00019a9180, pos=pos@entry=61440, len=len@entry=1, get_block=get_block@entry=0xffffffff821a5390 <reiserfs_get_block>) at ./arch/x86/include/asm/jump_label.h:27
#4 0xffffffff821a3e3d in reiserfs_write_begin (file=<optimized out>, mapping=<optimized out>, pos=61440, len=1, pagep=<optimized out>, fsdata=<optimized out>) at fs/reiserfs/inode.c:2779
#5 0xffffffff81aec252 in generic_perform_write (iocb=iocb@entry=0xffffc9002130fb60, i=i@entry=0xffffc9002130fd00) at mm/filemap.c:3923
#6 0xffffffff81b0604e in __generic_file_write_iter (iocb=iocb@entry=0xffffc9002130fb60, from=from@entry=0xffffc9002130fd00) at mm/filemap.c:4051
#7 0xffffffff81b06383 in generic_file_write_iter (iocb=0xffffc9002130fb60, from=0xffffc9002130fd00) at mm/filemap.c:4083
#8 0xffffffff81e3240b in call_write_iter (file=0xffff888012692d00, iter=0xffffc9002130fd00, kio=0xffffc9002130fb60) at ./include/linux/fs.h:1868
#9 do_iter_readv_writev (filp=filp@entry=0xffff888012692d00, iter=iter@entry=0xffffc9002130fd00, ppos=ppos@entry=0xffffc9002130fe90, type=type@entry=1, flags=flags@entry=0) at fs/read_write.c:735
#10 0xffffffff81e33da4 in do_iter_write (flags=0, pos=0xffffc9002130fe90, iter=0xffffc9002130fd00, file=0xffff888012692d00) at fs/read_write.c:860
#11 do_iter_write (file=0xffff888012692d00, iter=0xffffc9002130fd00, pos=0xffffc9002130fe90, flags=0) at fs/read_write.c:841
#12 0xffffffff81e34611 in vfs_writev (file=file@entry=0xffff888012692d00, vec=vec@entry=0x20000480, vlen=vlen@entry=1, pos=pos@entry=0xffffc9002130fe90, flags=flags@entry=0) at fs/read_write.c:933
#13 0xffffffff81e34fd6 in do_pwritev (fd=fd@entry=5, vec=vec@entry=0x20000480, vlen=vlen@entry=1, pos=pos@entry=61440, flags=flags@entry=0) at fs/read_write.c:1030
#14 0xffffffff81e3b61f in __do_sys_pwritev2 (pos_h=<optimized out>, flags=0, pos_l=61440, vlen=1, vec=0x20000480, fd=5) at fs/read_write.c:1089
#15 __se_sys_pwritev2 (pos_h=<optimized out>, flags=0, pos_l=61440, vlen=1, vec=536872064, fd=5) at fs/read_write.c:1080
#16 __x64_sys_pwritev2 (regs=0xffffc9002130ff58) at fs/read_write.c:1080
#17 0xffffffff880dd279 in do_syscall_x64 (nr=<optimized out>, regs=0xffffc9002130ff58) at arch/x86/entry/common.c:50
#18 do_syscall_64 (regs=0xffffc9002130ff58, nr=<optimized out>) at arch/x86/entry/common.c:80
#19 0xffffffff8820008b in entry_SYSCALL_64 () at arch/x86/entry/entry_64.S:120
#20 0x0000000000406e00 in ?? ()
#21 0x00007f99e21b5000 in ?? ()
#22 0x0000000000000000 in ?? ()

After that, there is a very long loop doing:

Thread 5 hit Breakpoint 3, reiserfs_read_bitmap_block (sb=sb@entry=0xffff888066e28000, bitmap=bitmap@entry=1) at fs/reiserfs/bitmap.c:1417
1417 {
(gdb) c
Continuing.

Thread 5 hit Breakpoint 3, reiserfs_read_bitmap_block (sb=sb@entry=0xffff888066e28000, bitmap=bitmap@entry=2) at fs/reiserfs/bitmap.c:1417
1417 {
(gdb)
Continuing.

and so on...

[ 628.589974][ T6003] REISERFS warning (device loop0): sh-2029: %s: bitmap block (#%u) reading failed reiserfs_read_bitmap_block: reiserfs_read_bitmap_block

This message appears because we are here:

struct buffer_head *reiserfs_read_bitmap_block(struct super_block *sb,
unsigned int bitmap)
{

[...]

bh = sb_bread(sb, block);
if (bh == NULL)
reiserfs_warning(sb, "sh-2029: %s: bitmap block (#%u) "
"reading failed", __func__, block);

The hanging task (kthread) is trying to hold the same lock, which
unfortunately is not going to be released soon:

static int reiserfs_sync_fs(struct super_block *s, int wait)
{

[...]

reiserfs_write_lock(s);

I didn't get yet if the reason of this long loop is because we cannot
flush at this point, or just because of the test. I tried to
synchronously flush, but didn't make any difference.

I did a very simple change, which can be totally wrong:

@@ -94,7 +96,7 @@ static void flush_old_commits(struct work_struct *work)
* trylock as reiserfs_cancel_old_flush() may be waiting for this work
* to complete with s_umount held.
*/
- if (!down_read_trylock(&s->s_umount)) {
+ if (sbi->lock_owner || !down_read_trylock(&s->s_umount)) {
/* Requeue work if we are not cancelling it */
spin_lock(&sbi->old_work_lock);
if (sbi->work_queued == 1)


If the lock is held, instead of waiting, reschedule the flush.

Anyway, at least this report does not seem to be related to fixing
security xattrs.

Roberto

[Jan Kara]

Well, the commit d82dcd9e21b ("reiserfs: Add security prefix to xattr name
in reiserfs_security_write()") looks obviously broken to me. It does:

char xattr_name[XATTR_NAME_MAX + 1] = XATTR_SECURITY_PREFIX;

Which is not how we can initialize strings in C... ;)

Honza

--
Jan Kara <ja...@suse.com>
SUSE Labs, CR

[Roberto Sassu]

Thanks for having a look!

Sorry for the silly question, do I need to patch it? It is already in
stable kernels... (next time I document myself better)

Thanks

Roberto

[Jan Kara]

I'm growing old or what but indeed string assignment in initializers in C
works fine. It is only the assignment in code that would be problematic.
I'm sorry for the noise.

Honza

[Roberto Sassu]

Cool, thanks!

It seems the difference with just doing memcpy() is that the compiler
fully initializes the array (256 bytes), instead of copying the
required amount.

Roberto

[syzbot]

syzbot suspects this issue was fixed by commit:

commit 6f861765464f43a71462d52026fbddfc858239a5
Author: Jan Kara <ja...@suse.cz>
Date: Wed Nov 1 17:43:10 2023 +0000

fs: Block writes to mounted block devices

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=152ff3f2180000

start commit: 421ca22e3138 Merge tag 'nfs-for-6.4-2' of git://git.linux-..
git tree: upstream

kernel config: https://syzkaller.appspot.com/x/.config?x=7d8067683055e3f5
dashboard link: https://syzkaller.appspot.com/bug?extid=0a684c061589dcc30e51
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14312791280000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=12da8605280000

If the result looks correct, please mark the issue as fixed by replying with:

#syz fix: fs: Block writes to mounted block devices

[syzbot]

Auto-closing this bug as obsolete.
No recent activity, existing reproducers are no longer triggering the issue.