Hello,
We observed an issue "INFO: task hung in blk_trace_remove" during
fuzzing.
Unfortunately, we have not found a reproducer for the crash yet. We
will inform you if we have any update on this crash.
The crash information is attached at the end of this email.
Best regards,
Dae R. Jeong
------
- Kernel commit:
92f20ff72066d
- Crash report:
INFO: task syz-executor.0:13658 blocked for more than 143 seconds.
Not tainted 5.19.0-rc3-32288-g0f3b08299494 #3
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.0 state:D stack:27824 pid:13658 ppid: 6759 flags:0x00004004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5146 [inline]
__schedule+0x96c/0x10f0 kernel/sched/core.c:6458
schedule+0xea/0x1b0 kernel/sched/core.c:6530
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6589
__mutex_lock_common+0xe0f/0x25e0 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x17/0x20 kernel/locking/mutex.c:799
blk_trace_remove+0x1c/0x40 kernel/trace/blktrace.c:374
sg_ioctl_common drivers/scsi/sg.c:1130 [inline]
sg_ioctl+0x712/0x4be0 drivers/scsi/sg.c:1164
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:870 [inline]
__se_sys_ioctl+0x152/0x1f0 fs/ioctl.c:856
do_syscall_x64 arch/x86/entry/common.c:51 [inline]
do_syscall_64+0x4e/0xa0 arch/x86/entry/common.c:82
entry_SYSCALL_64_after_hwframe+0x46/0xb0
RIP: 0033:0x47268d
RSP: 002b:00007fab57574be8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 000000000057d4a0 RCX: 000000000047268d
RDX: 0000000000000000 RSI: 0000000000001276 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000057d4a8
R13: 000000000057d4ac R14: 00007ffe9afe72f0 R15: 00007fab57574d80
</TASK>
Showing all locks held in the system:
1 lock held by khungtaskd/40:
#0: ffffffff92f1a3e0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
1 lock held by in:imklog/6420:
#0: ffff88807d844368 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x3bf/0x530 fs/file.c:1036
4 locks held by syz-executor.0/13657:
1 lock held by syz-executor.0/13658:
#0: ffff888022c78378 (&q->debugfs_mutex){+.+.}-{3:3}, at: blk_trace_remove+0x1c/0x40 kernel/trace/blktrace.c:374
On Sun, Jul 03, 2022 at 01:57:25PM +0900, Dae R. Jeong wrote:
> Hello,
>
> We observed an issue "INFO: task hung in blk_trace_remove" during
> fuzzing.
We also observed a similar issue "INFO: task hung in
blk_trace_setup". At this point, we don't know whether these two
issues are caused by the same reason.
Unfortunately, we have not found a reproducer for this crash. We will
inform you if we have any update.
The crash information is attached at the end of this email.
Best regards,
Dae R. Jeong
------
- Kernel commit:
92f20ff72066d
- Crash report:
INFO: task syz-executor.0:13708 blocked for more than 143 seconds.
Not tainted 5.19.0-rc3-32288-g0f3b08299494 #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.0 state:D stack:26560 pid:13708 ppid: 6772 flags:0x00004004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5146 [inline]
__schedule+0x96c/0x10f0 kernel/sched/core.c:6458
schedule+0xea/0x1b0 kernel/sched/core.c:6530
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6589
__mutex_lock_common+0xe0f/0x25e0 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x17/0x20 kernel/locking/mutex.c:799
blk_trace_setup+0xa9/0x1b0 kernel/trace/blktrace.c:616
sg_ioctl_common drivers/scsi/sg.c:1122 [inline]
sg_ioctl+0x1b61/0x4000 drivers/scsi/sg.c:1164
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:870 [inline]
__se_sys_ioctl+0x129/0x1c0 fs/ioctl.c:856
do_syscall_x64 arch/x86/entry/common.c:51 [inline]
do_syscall_64+0x4e/0xa0 arch/x86/entry/common.c:82
entry_SYSCALL_64_after_hwframe+0x46/0xb0
RIP: 0033:0x478dc9
RSP: 002b:00007f5dde784be8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 000000000077d4a0 RCX: 0000000000478dc9
RDX: 0000000020000340 RSI: 00000000c0481273 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000077d4a8
R13: 000000000077d4ac R14: 000000000077d4a0 R15: 00007ffdfb78c900
</TASK>
INFO: task syz-executor.0:13709 blocked for more than 143 seconds.
Not tainted 5.19.0-rc3-32288-g0f3b08299494 #15
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.0 state:D stack:26608 pid:13709 ppid: 6772 flags:0x00004004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5146 [inline]
__schedule+0x96c/0x10f0 kernel/sched/core.c:6458
schedule+0xea/0x1b0 kernel/sched/core.c:6530
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6589
__mutex_lock_common+0xe0f/0x25e0 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x17/0x20 kernel/locking/mutex.c:799
blk_trace_setup+0xa9/0x1b0 kernel/trace/blktrace.c:616
sg_ioctl_common drivers/scsi/sg.c:1122 [inline]
sg_ioctl+0x1b61/0x4000 drivers/scsi/sg.c:1164
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:870 [inline]
__se_sys_ioctl+0x129/0x1c0 fs/ioctl.c:856
do_syscall_x64 arch/x86/entry/common.c:51 [inline]
do_syscall_64+0x4e/0xa0 arch/x86/entry/common.c:82
entry_SYSCALL_64_after_hwframe+0x46/0xb0
RIP: 0033:0x478dc9
RSP: 002b:00007f5dde763be8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 000000000077e9c0 RCX: 0000000000478dc9
RDX: 00000000200003c0 RSI: 00000000c0481273 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000077e9c8
R13: 000000000077e9cc R14: 000000000077e9c0 R15: 00007ffdfb78c900
</TASK>
Showing all locks held in the system:
1 lock held by khungtaskd/40:
#0: ffffffff9071a3e0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
1 lock held by systemd-journal/3025:
#0: ffff8880b933bb58 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x25/0x110 kernel/sched/core.c:544
1 lock held by in:imklog/6630:
#0: ffff88801c6e40e8 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x2f3/0x430 fs/file.c:1036
2 locks held by syz-executor.0/13707:
1 lock held by syz-executor.0/13708:
#0: ffff88814c195ff8 (&q->debugfs_mutex){+.+.}-{3:3}, at: blk_trace_setup+0xa9/0x1b0 kernel/trace/blktrace.c:616
1 lock held by syz-executor.0/13709:
#0: ffff88814c195ff8 (&q->debugfs_mutex){+.+.}-{3:3}, at: blk_trace_setup+0xa9/0x1b0 kernel/trace/blktrace.c:616
On Sun, Jul 03, 2022 at 01:57:20PM +0900, Dae R. Jeong wrote:
> Hello,
>
> We observed an issue "INFO: task hung in blk_trace_remove" during
> fuzzing.
>
> Unfortunately, we have not found a reproducer for the crash yet. We
> will inform you if we have any update on this crash.
>
> The crash information is attached at the end of this email.
This looks like it is due to locking an on the /dev/sg node instead
of the more usual (and more tested) block device node.
It might make sense to run with lockdep enabled to get a better
grip on potential locking issues here.