syzbot


INFO: task hung in blk_trace_ioctl

Status: auto-closed as invalid on 2019/06/04 08:29
Subsystems: trace block
[Documentation on labels]
Reported-by: syzbot+e2ed26ec4d1d80c8a2d9@syzkaller.appspotmail.com
First crash: 2048d, last: 1966d
Similar bugs (4)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: task hung in blk_trace_ioctl (2) block trace 4 1565d 1675d 0/26 auto-closed as invalid on 2020/04/09 23:38
upstream INFO: task hung in blk_trace_ioctl (3) trace block 2 876d 941d 0/26 closed as invalid on 2022/02/07 19:19
upstream INFO: task hung in blk_trace_ioctl (4) block trace C done 26 1d12h 145d 0/26 upstream: reported C repro on 2023/11/30 21:17
linux-4.19 INFO: task hung in blk_trace_ioctl 1 630d 630d 0/1 auto-obsoleted due to no activity on 2022/12/01 07:14

Sample crash report:
342856 pages reserved
0 pages cma reserved
Out of memory: Kill process 9305 (syz-executor5) score 1005 or sacrifice child
Killed process 9305 (syz-executor5) total-vm:70340kB, anon-rss:6296kB, file-rss:32768kB, shmem-rss:0kB
oom_reaper: reaped process 9305 (syz-executor5), now anon-rss:0kB, file-rss:32768kB, shmem-rss:0kB
INFO: task syz-executor1:9683 blocked for more than 140 seconds.
      Not tainted 4.20.0-rc2+ #333
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D25208  9683   6022 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2831 [inline]
 __schedule+0x8cf/0x21d0 kernel/sched/core.c:3472
 schedule+0xfe/0x460 kernel/sched/core.c:3516
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3574
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xaff/0x16f0 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
 blkdev_ioctl+0x9e9/0x21b0 block/ioctl.c:591
 block_ioctl+0xee/0x130 fs/block_dev.c:1883
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:509 [inline]
 do_vfs_ioctl+0x1de/0x1790 fs/ioctl.c:696
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:713
 __do_sys_ioctl fs/ioctl.c:720 [inline]
 __se_sys_ioctl fs/ioctl.c:718 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:718
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457569
Code: Bad RIP value.
RSP: 002b:00007f38a1f65c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457569
RDX: 0000000000000000 RSI: 0000000000001276 RDI: 0000000000000004
RBP: 000000000072bfa0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f38a1f666d4
R13: 00000000004bea0a R14: 00000000004cea88 R15: 00000000ffffffff
INFO: task syz-executor1:9684 blocked for more than 140 seconds.
      Not tainted 4.20.0-rc2+ #333
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D25208  9684   6022 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2831 [inline]
 __schedule+0x8cf/0x21d0 kernel/sched/core.c:3472
 schedule+0xfe/0x460 kernel/sched/core.c:3516
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3574
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xaff/0x16f0 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
 blkdev_ioctl+0x9e9/0x21b0 block/ioctl.c:591
 block_ioctl+0xee/0x130 fs/block_dev.c:1883
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:509 [inline]
 do_vfs_ioctl+0x1de/0x1790 fs/ioctl.c:696
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:713
 __do_sys_ioctl fs/ioctl.c:720 [inline]
 __se_sys_ioctl fs/ioctl.c:718 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:718
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457569
Code: Bad RIP value.
RSP: 002b:00007f38a1f44c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457569
RDX: 0000000020000500 RSI: 00000000c0481273 RDI: 0000000000000004
RBP: 000000000072c040 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f38a1f456d4
R13: 00000000004be9cf R14: 00000000004cea40 R15: 00000000ffffffff
INFO: task syz-executor1:9685 blocked for more than 140 seconds.
      Not tainted 4.20.0-rc2+ #333
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D21992  9685   6022 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2831 [inline]
 __schedule+0x8cf/0x21d0 kernel/sched/core.c:3472
 schedule+0xfe/0x460 kernel/sched/core.c:3516
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3574
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xaff/0x16f0 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
 blkdev_ioctl+0x9e9/0x21b0 block/ioctl.c:591
 block_ioctl+0xee/0x130 fs/block_dev.c:1883
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:509 [inline]
 do_vfs_ioctl+0x1de/0x1790 fs/ioctl.c:696
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:713
 __do_sys_ioctl fs/ioctl.c:720 [inline]
 __se_sys_ioctl fs/ioctl.c:718 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:718
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457569
Code: Bad RIP value.
RSP: 002b:00007f38a1f23c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457569
RDX: 0000000020000140 RSI: 00000000c0481273 RDI: 0000000000000004
RBP: 000000000072c0e0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f38a1f246d4
R13: 00000000004be9cf R14: 00000000004cea40 R15: 00000000ffffffff
INFO: task syz-executor1:9690 blocked for more than 140 seconds.
      Not tainted 4.20.0-rc2+ #333
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D23328  9690   6022 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2831 [inline]
 __schedule+0x8cf/0x21d0 kernel/sched/core.c:3472
 schedule+0xfe/0x460 kernel/sched/core.c:3516
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3574
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xaff/0x16f0 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
 blkdev_ioctl+0x9e9/0x21b0 block/ioctl.c:591
 block_ioctl+0xee/0x130 fs/block_dev.c:1883
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:509 [inline]
 do_vfs_ioctl+0x1de/0x1790 fs/ioctl.c:696
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:713
 __do_sys_ioctl fs/ioctl.c:720 [inline]
 __se_sys_ioctl fs/ioctl.c:718 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:718
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457569
Code: Bad RIP value.
RSP: 002b:00007f38a1f02c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457569
RDX: 0000000000000000 RSI: 0000000000001276 RDI: 0000000000000004
RBP: 000000000072c180 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f38a1f036d4
R13: 00000000004bea0a R14: 00000000004cea88 R15: 00000000ffffffff
INFO: task syz-executor1:9692 blocked for more than 140 seconds.
      Not tainted 4.20.0-rc2+ #333
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D25304  9692   6022 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2831 [inline]
 __schedule+0x8cf/0x21d0 kernel/sched/core.c:3472
 schedule+0xfe/0x460 kernel/sched/core.c:3516
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3574
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xaff/0x16f0 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
 blkdev_ioctl+0x9e9/0x21b0 block/ioctl.c:591
 block_ioctl+0xee/0x130 fs/block_dev.c:1883
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:509 [inline]
 do_vfs_ioctl+0x1de/0x1790 fs/ioctl.c:696
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:713
 __do_sys_ioctl fs/ioctl.c:720 [inline]
 __se_sys_ioctl fs/ioctl.c:718 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:718
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457569
Code: Bad RIP value.
RSP: 002b:00007f38a1ec0c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457569
RDX: 0000000020000500 RSI: 00000000c0481273 RDI: 0000000000000004
RBP: 000000000072c2c0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f38a1ec16d4
R13: 00000000004be9cf R14: 00000000004cea40 R15: 00000000ffffffff

Showing all locks held in the system:
1 lock held by khungtaskd/995:
 #0: 00000000ceae1bb2 (rcu_read_lock){....}, at: debug_show_all_locks+0xd0/0x424 kernel/locking/lockdep.c:4379
1 lock held by rsyslogd/5882:
 #0: 000000001d6970be (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x1bb/0x200 fs/file.c:766
2 locks held by getty/5973:
 #0: 000000001fb1b888 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 000000005f6231e5 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1e80 drivers/tty/n_tty.c:2154
2 locks held by getty/5974:
 #0: 00000000908acf1c (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 00000000f186abee (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1e80 drivers/tty/n_tty.c:2154
2 locks held by getty/5975:
 #0: 000000000c00b327 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 000000009c9f770a (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1e80 drivers/tty/n_tty.c:2154
2 locks held by getty/5976:
 #0: 0000000036d357b5 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 00000000c99c90b7 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1e80 drivers/tty/n_tty.c:2154
2 locks held by getty/5977:
 #0: 0000000017b03b21 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 000000005ff8389e (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1e80 drivers/tty/n_tty.c:2154
2 locks held by getty/5978:
 #0: 00000000c48da5e7 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 0000000003703577 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1e80 drivers/tty/n_tty.c:2154
2 locks held by getty/5979:
 #0: 00000000fa3a978d (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 0000000061a55729 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1e80 drivers/tty/n_tty.c:2154
2 locks held by syz-executor1/9679:
1 lock held by syz-executor1/9683:
 #0: 000000004ec3e646 (&q->blk_trace_mutex){+.+.}, at: blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
1 lock held by syz-executor1/9684:
 #0: 000000004ec3e646 (&q->blk_trace_mutex){+.+.}, at: blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
1 lock held by syz-executor1/9685:
 #0: 000000004ec3e646 (&q->blk_trace_mutex){+.+.}, at: blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
1 lock held by syz-executor1/9690:
 #0: 000000004ec3e646 (&q->blk_trace_mutex){+.+.}, at: blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711
1 lock held by syz-executor1/9692:
 #0: 000000004ec3e646 (&q->blk_trace_mutex){+.+.}, at: blk_trace_ioctl+0xeb/0x2f0 kernel/trace/blktrace.c:711

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

NMI backtrace for cpu 0
CPU: 0 PID: 995 Comm: khungtaskd Not tainted 4.20.0-rc2+ #333
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x244/0x39d lib/dump_stack.c:113
 nmi_cpu_backtrace.cold.2+0x5c/0xa1 lib/nmi_backtrace.c:101
 nmi_trigger_cpumask_backtrace+0x1e8/0x22a lib/nmi_backtrace.c:62
 arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
 trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:205 [inline]
 watchdog+0xb51/0x1060 kernel/hung_task.c:289
 kthread+0x35a/0x440 kernel/kthread.c:246
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Sending NMI from CPU 0 to CPUs 1:
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.356 msecs
NMI backtrace for cpu 1
CPU: 1 PID: 9679 Comm: syz-executor1 Not tainted 4.20.0-rc2+ #333
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:__lock_acquire+0x8f3/0x4c20 kernel/locking/lockdep.c:3345
Code: 00 00 48 b8 00 00 00 00 00 fc ff df 48 c1 ea 03 0f b6 04 02 84 c0 74 08 3c 03 0f 8e d2 30 00 00 41 8b 83 78 08 00 00 83 c0 01 <83> f8 2f 41 89 83 78 08 00 00 77 1f 3b 05 2b c0 1b 09 c7 84 24 98
RSP: 0018:ffff8881821a6f30 EFLAGS: 00000006
RAX: 0000000000000003 RBX: ffffffff8a672328 RCX: 0000000000000001
RDX: 1ffff110305c4117 RSI: 0000000000000000 RDI: ffffffff8a672338
RBP: ffff8881821a72b8 R08: ffff888182e20930 R09: 0000000000000008
R10: 0000000000001f38 R11: ffff888182e20040 R12: 1ffff11030434e2a
R13: 0000000076a307dc R14: 5553193973839bda R15: ffff888182e20910
FS:  00007f38a1f87700(0000) GS:ffff8881daf00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffffff600400 CR3: 00000001d7619000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 lock_acquire+0x1ed/0x520 kernel/locking/lockdep.c:3844
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0x99/0xd0 kernel/locking/spinlock.c:152
 __debug_check_no_obj_freed lib/debugobjects.c:777 [inline]
 debug_check_no_obj_freed+0x17a/0x58d lib/debugobjects.c:818
 __vunmap+0x1a3/0x460 mm/vmalloc.c:1516
 vunmap+0x55/0x70 mm/vmalloc.c:1615
 relay_destroy_buf+0x77/0x360 kernel/relay.c:213
 relay_remove_buf kernel/relay.c:235 [inline]
 kref_put include/linux/kref.h:70 [inline]
 relay_close_buf+0x110/0x150 kernel/relay.c:496
 relay_open+0x6e2/0xac0 kernel/relay.c:610
 do_blk_trace_setup+0x4fe/0xdb0 kernel/trace/blktrace.c:532
 __blk_trace_setup+0xd5/0x180 kernel/trace/blktrace.c:577
 blk_trace_ioctl+0x17a/0x2f0 kernel/trace/blktrace.c:716
 blkdev_ioctl+0x9e9/0x21b0 block/ioctl.c:591
 block_ioctl+0xee/0x130 fs/block_dev.c:1883
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:509 [inline]
 do_vfs_ioctl+0x1de/0x1790 fs/ioctl.c:696
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:713
 __do_sys_ioctl fs/ioctl.c:720 [inline]
 __se_sys_ioctl fs/ioctl.c:718 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:718
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457569
Code: Bad RIP value.
RSP: 002b:00007f38a1f86c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457569
RDX: 0000000020000140 RSI: 00000000c0481273 RDI: 0000000000000004
RBP: 000000000072bf00 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f38a1f876d4
R13: 00000000004be9cf R14: 00000000004cea40 R15: 00000000ffffffff

Crashes (3):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2018/11/13 08:06 upstream ccda4af0f4b9 74dbb806 .config console log report ci-upstream-kasan-gce
2018/12/06 08:28 upstream d08970904582 764b42c4 .config console log report ci-upstream-kasan-gce-386
2018/09/15 12:59 upstream 090b75bcba62 a343a400 .config console log report ci-upstream-kasan-gce-386
* Struck through repros no longer work on HEAD.