Message-ID: <000000000000fd12c10603522cc4@google.com>
Date:   Sat, 19 Aug 2023 20:15:37 -0700
From:   syzbot <syzbot+fb337a5ea8454f5f1e3f@...kaller.appspotmail.com>
To:     hdanton@...a.com, linux-kernel@...r.kernel.org,
        syzkaller-bugs@...glegroups.com
Subject: Re: [syzbot] [jfs?] INFO: task hung in path_mount (2)

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in iterate_supers

INFO: task syz-executor.2:5688 blocked for more than 143 seconds.
      Not tainted 6.5.0-rc6-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.2  state:D stack:24584 pid:5688  ppid:5393   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0x1873/0x48f0 kernel/sched/core.c:6710
 schedule+0xc3/0x180 kernel/sched/core.c:6786
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6845
 rwsem_down_read_slowpath+0x5f4/0x950 kernel/locking/rwsem.c:1086
 __down_read_common kernel/locking/rwsem.c:1250 [inline]
 __down_read kernel/locking/rwsem.c:1263 [inline]
 down_read+0x9c/0x2f0 kernel/locking/rwsem.c:1522
 iterate_supers+0xb0/0x1e0 fs/super.c:742
 quota_sync_all fs/quota/quota.c:69 [inline]
 __do_sys_quotactl fs/quota/quota.c:938 [inline]
 __se_sys_quotactl+0x391/0xa30 fs/quota/quota.c:917
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fb3b1a7cae9
RSP: 002b:00007fb3b28b80c8 EFLAGS: 00000246 ORIG_RAX: 00000000000000b3
RAX: ffffffffffffffda RBX: 00007fb3b1b9bf80 RCX: 00007fb3b1a7cae9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff80000101
RBP: 00007fb3b1ac847a R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000000b R14: 00007fb3b1b9bf80 R15: 00007fff6eac0208
 </TASK>
INFO: task syz-executor.4:5709 blocked for more than 143 seconds.
      Not tainted 6.5.0-rc6-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.4  state:D stack:25840 pid:5709  ppid:5390   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0x1873/0x48f0 kernel/sched/core.c:6710
 schedule+0xc3/0x180 kernel/sched/core.c:6786
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6845
 rwsem_down_write_slowpath+0xedd/0x13a0 kernel/locking/rwsem.c:1178
 __down_write_common+0x1aa/0x200 kernel/locking/rwsem.c:1306
 do_remount fs/namespace.c:2879 [inline]
 path_mount+0xbdd/0xfa0 fs/namespace.c:3654
 do_mount fs/namespace.c:3675 [inline]
 __do_sys_mount fs/namespace.c:3884 [inline]
 __se_sys_mount+0x2d9/0x3c0 fs/namespace.c:3861
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7efee2a7e1ea
RSP: 002b:00007efee3842ee8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
RAX: ffffffffffffffda RBX: 00007efee3842f80 RCX: 00007efee2a7e1ea
RDX: 0000000020000180 RSI: 0000000020000100 RDI: 0000000000000000
RBP: 0000000020000180 R08: 00007efee3842f80 R09: 0000000001a404ac
R10: 0000000001a404ac R11: 0000000000000246 R12: 0000000020000100
R13: 00007efee3842f40 R14: 0000000000000000 R15: 0000000020003600
 </TASK>
INFO: task syz-executor.0:5687 blocked for more than 143 seconds.
      Not tainted 6.5.0-rc6-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.0  state:D stack:24584 pid:5687  ppid:5386   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0x1873/0x48f0 kernel/sched/core.c:6710
 schedule+0xc3/0x180 kernel/sched/core.c:6786
 jfs_flush_journal+0x733/0xec0 fs/jfs/jfs_logmgr.c:1564
 jfs_sync_fs+0x80/0xa0 fs/jfs/super.c:684
 dquot_quota_sync+0xdb/0x490 fs/quota/dquot.c:704
 iterate_supers+0x12b/0x1e0 fs/super.c:744
 quota_sync_all fs/quota/quota.c:69 [inline]
 __do_sys_quotactl fs/quota/quota.c:938 [inline]
 __se_sys_quotactl+0x391/0xa30 fs/quota/quota.c:917
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fd84a27cae9
RSP: 002b:00007fd84afa50c8 EFLAGS: 00000246 ORIG_RAX: 00000000000000b3
RAX: ffffffffffffffda RBX: 00007fd84a39bf80 RCX: 00007fd84a27cae9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff80000101
RBP: 00007fd84a2c847a R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000000b R14: 00007fd84a39bf80 R15: 00007ffd56f86288
 </TASK>
INFO: task syz-executor.5:5689 blocked for more than 144 seconds.
      Not tainted 6.5.0-rc6-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.5  state:D stack:24584 pid:5689  ppid:5387   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0x1873/0x48f0 kernel/sched/core.c:6710
 schedule+0xc3/0x180 kernel/sched/core.c:6786
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6845
 rwsem_down_read_slowpath+0x5f4/0x950 kernel/locking/rwsem.c:1086
 __down_read_common kernel/locking/rwsem.c:1250 [inline]
 __down_read kernel/locking/rwsem.c:1263 [inline]
 down_read+0x9c/0x2f0 kernel/locking/rwsem.c:1522
 iterate_supers+0xb0/0x1e0 fs/super.c:742
 quota_sync_all fs/quota/quota.c:69 [inline]
 __do_sys_quotactl fs/quota/quota.c:938 [inline]
 __se_sys_quotactl+0x391/0xa30 fs/quota/quota.c:917
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f05ae27cae9
RSP: 002b:00007f05aef3a0c8 EFLAGS: 00000246 ORIG_RAX: 00000000000000b3
RAX: ffffffffffffffda RBX: 00007f05ae39bf80 RCX: 00007f05ae27cae9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff80000101
RBP: 00007f05ae2c847a R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000000b R14: 00007f05ae39bf80 R15: 00007ffed97249c8
 </TASK>
INFO: task syz-executor.1:5702 blocked for more than 144 seconds.
      Not tainted 6.5.0-rc6-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.1  state:D stack:24584 pid:5702  ppid:5378   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0x1873/0x48f0 kernel/sched/core.c:6710
 schedule+0xc3/0x180 kernel/sched/core.c:6786
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6845
 rwsem_down_read_slowpath+0x5f4/0x950 kernel/locking/rwsem.c:1086
 __down_read_common kernel/locking/rwsem.c:1250 [inline]
 __down_read kernel/locking/rwsem.c:1263 [inline]
 down_read+0x9c/0x2f0 kernel/locking/rwsem.c:1522
 iterate_supers+0xb0/0x1e0 fs/super.c:742
 quota_sync_all fs/quota/quota.c:69 [inline]
 __do_sys_quotactl fs/quota/quota.c:938 [inline]
 __se_sys_quotactl+0x391/0xa30 fs/quota/quota.c:917
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f862b87cae9
RSP: 002b:00007f862c6030c8 EFLAGS: 00000246 ORIG_RAX: 00000000000000b3
RAX: ffffffffffffffda RBX: 00007f862b99bf80 RCX: 00007f862b87cae9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff80000101
RBP: 00007f862b8c847a R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000000b R14: 00007f862b99bf80 R15: 00007ffe1c3a7d68
 </TASK>
INFO: task syz-executor.3:5710 blocked for more than 144 seconds.
      Not tainted 6.5.0-rc6-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.3  state:D stack:24584 pid:5710  ppid:5382   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0x1873/0x48f0 kernel/sched/core.c:6710
 schedule+0xc3/0x180 kernel/sched/core.c:6786
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6845
 rwsem_down_read_slowpath+0x5f4/0x950 kernel/locking/rwsem.c:1086
 __down_read_common kernel/locking/rwsem.c:1250 [inline]
 __down_read kernel/locking/rwsem.c:1263 [inline]
 down_read+0x9c/0x2f0 kernel/locking/rwsem.c:1522
 iterate_supers+0xb0/0x1e0 fs/super.c:742
 quota_sync_all fs/quota/quota.c:69 [inline]
 __do_sys_quotactl fs/quota/quota.c:938 [inline]
 __se_sys_quotactl+0x391/0xa30 fs/quota/quota.c:917
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f626d07cae9
RSP: 002b:00007f626de8d0c8 EFLAGS: 00000246 ORIG_RAX: 00000000000000b3
RAX: ffffffffffffffda RBX: 00007f626d19bf80 RCX: 00007f626d07cae9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff80000101
RBP: 00007f626d0c847a R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000000b R14: 00007f626d19bf80 R15: 00007ffe891110e8
 </TASK>

Showing all locks held in the system:
1 lock held by rcu_tasks_kthre/13:
 #0: ffffffff8d3295b0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:522
1 lock held by rcu_tasks_trace/14:
 #0: ffffffff8d329970 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:522
1 lock held by khungtaskd/28:
 #0: ffffffff8d3293e0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
2 locks held by kworker/u4:2/41:
2 locks held by getty/4770:
 #0: ffff88814bd10098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x25/0x70 drivers/tty/tty_ldisc.c:243
 #1: ffffc900015c02f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6b1/0x1dc0 drivers/tty/n_tty.c:2187
1 lock held by syz-executor.2/5688:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.4/5709:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: do_remount fs/namespace.c:2879 [inline]
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: path_mount+0xbdd/0xfa0 fs/namespace.c:3654
1 lock held by syz-executor.0/5687:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.5/5689:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.1/5702:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.3/5710:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.0/5982:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.2/6002:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.5/6005:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.1/6010:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.4/6012:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.3/6014:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.0/6048:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.2/6104:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.5/6108:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.3/6129:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.1/6131:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742
1 lock held by syz-executor.4/6135:
 #0: ffff8880694560e0 (&type->s_umount_key#64){++++}-{3:3}, at: iterate_supers+0xb0/0x1e0 fs/super.c:742

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

NMI backtrace for cpu 0
CPU: 0 PID: 28 Comm: khungtaskd Not tainted 6.5.0-rc6-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/26/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e7/0x2d0 lib/dump_stack.c:106
 nmi_cpu_backtrace+0x498/0x4d0 lib/nmi_backtrace.c:113
 nmi_trigger_cpumask_backtrace+0x187/0x300 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:160 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
 watchdog+0xec2/0xf00 kernel/hung_task.c:379
 kthread+0x2b8/0x350 kernel/kthread.c:389
 ret_from_fork+0x2e/0x60 arch/x86/kernel/process.c:145
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:304
 </TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 5445 Comm: kworker/1:5 Not tainted 6.5.0-rc6-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/26/2023
Workqueue: events nsim_dev_trap_report_work
RIP: 0010:on_stack arch/x86/include/asm/stacktrace.h:56 [inline]
RIP: 0010:unwind_next_frame+0x1932/0x2390 arch/x86/kernel/unwind_orc.c:665
Code: 89 f8 48 c1 e8 03 80 3c 18 00 74 05 e8 17 e6 a7 00 4c 8b 75 08 48 8d 5d 10 48 89 d8 48 c1 e8 03 48 b9 00 00 00 00 00 fc ff df <80> 3c 08 00 74 08 48 89 df e8 f0 e5 a7 00 4d 39 fe 0f 87 ba 00 00
RSP: 0018:ffffc90005ae7610 EFLAGS: 00000a06
RAX: 1ffff92000b5cede RBX: ffffc90005ae76f0 RCX: dffffc0000000000
RDX: dffffc0000000000 RSI: ffffc90005ae0000 RDI: ffffc90005ae76e8
RBP: ffffc90005ae76e0 R08: ffffc90005ae7850 R09: 0000000000000000
R10: ffffc90005ae7730 R11: fffff52000b5cee8 R12: 1ffffffff1e31b57
R13: 1ffff92000b5cedd R14: ffffc90005ae0000 R15: ffffc90005ae7860
FS:  0000000000000000(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000555d7f21b030 CR3: 000000002c0f7000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <NMI>
 </NMI>
 <TASK>
 arch_stack_walk+0x111/0x140 arch/x86/kernel/stacktrace.c:25
 stack_trace_save+0x117/0x1c0 kernel/stacktrace.c:122
 kasan_save_stack mm/kasan/common.c:45 [inline]
 kasan_set_track+0x4f/0x70 mm/kasan/common.c:52
 kasan_save_free_info+0x28/0x40 mm/kasan/generic.c:522
 ____kasan_slab_free+0xd6/0x120 mm/kasan/common.c:236
 kasan_slab_free include/linux/kasan.h:162 [inline]
 slab_free_hook mm/slub.c:1792 [inline]
 slab_free_freelist_hook mm/slub.c:1818 [inline]
 slab_free mm/slub.c:3801 [inline]
 kmem_cache_free+0x292/0x500 mm/slub.c:3823
 nsim_dev_trap_report drivers/net/netdevsim/dev.c:821 [inline]
 nsim_dev_trap_report_work+0x761/0xa90 drivers/net/netdevsim/dev.c:850
 process_one_work+0x92c/0x12c0 kernel/workqueue.c:2600
 worker_thread+0xa63/0x1210 kernel/workqueue.c:2751
 kthread+0x2b8/0x350 kernel/kthread.c:389
 ret_from_fork+0x2e/0x60 arch/x86/kernel/process.c:145
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:304
 </TASK>


Tested on:

commit:         2ccdd1b1 Linux 6.5-rc6
git tree:       https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
console output: https://syzkaller.appspot.com/x/log.txt?x=10ba0ebba80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=9c37cc0e4fcc5f8d
dashboard link: https://syzkaller.appspot.com/bug?extid=fb337a5ea8454f5f1e3f
compiler:       Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
patch:          https://syzkaller.appspot.com/x/patch.diff?x=16856a4ba80000

Powered by blists - more mailing lists