syzbot


INFO: task hung in blk_trace_ioctl (3)

Status: closed as invalid on 2022/02/07 19:19
Reported-by: syzbot+@syzkaller.appspotmail.com
First crash: 433d, last: 367d
similar bugs (3):
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: task hung in blk_trace_ioctl 3 1457d 1537d 0/24 auto-closed as invalid on 2019/06/04 08:29
upstream INFO: task hung in blk_trace_ioctl (2) 4 1057d 1167d 0/24 auto-closed as invalid on 2020/04/09 23:38
linux-4.19 INFO: task hung in blk_trace_ioctl 1 121d 121d 0/1 auto-obsoleted due to no activity on 2022/12/01 07:14

Sample crash report:
INFO: task syz-executor.4:9485 blocked for more than 143 seconds.
      Not tainted 5.16.0-rc3-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.4  state:D stack:25904 pid: 9485 ppid: 20294 flags:0x00004004
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4972 [inline]
 __schedule+0xb72/0x1460 kernel/sched/core.c:6253
 schedule+0x12b/0x1f0 kernel/sched/core.c:6326
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6385
 __mutex_lock_common+0xd1f/0x2590 kernel/locking/mutex.c:680
 __mutex_lock kernel/locking/mutex.c:740 [inline]
 mutex_lock_nested+0x1a/0x20 kernel/locking/mutex.c:792
 blk_trace_ioctl+0xe7/0x8d0 kernel/trace/blktrace.c:725
 blkdev_common_ioctl+0xf1e/0x2000 block/ioctl.c:529
 blkdev_ioctl+0x2f8/0x790 block/ioctl.c:603
 vfs_ioctl fs/ioctl.c:51 [inline]
 __do_sys_ioctl fs/ioctl.c:874 [inline]
 __se_sys_ioctl+0xfb/0x170 fs/ioctl.c:860
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fb815477ae9
RSP: 002b:00007fb8129ed188 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007fb81558af60 RCX: 00007fb815477ae9
RDX: 0000000000001200 RSI: 0000000000001276 RDI: 0000000000000003
RBP: 00007fb8154d1f6d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007fffb4f0640f R14: 00007fb8129ed300 R15: 0000000000022000
 </TASK>
INFO: task syz-executor.4:9504 blocked for more than 143 seconds.
      Not tainted 5.16.0-rc3-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.4  state:D stack:27472 pid: 9504 ppid: 20294 flags:0x00004004
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4972 [inline]
 __schedule+0xb72/0x1460 kernel/sched/core.c:6253
 schedule+0x12b/0x1f0 kernel/sched/core.c:6326
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6385
 __mutex_lock_common+0xd1f/0x2590 kernel/locking/mutex.c:680
 __mutex_lock kernel/locking/mutex.c:740 [inline]
 mutex_lock_nested+0x1a/0x20 kernel/locking/mutex.c:792
 blk_trace_ioctl+0xe7/0x8d0 kernel/trace/blktrace.c:725
 blkdev_common_ioctl+0xf1e/0x2000 block/ioctl.c:529
 blkdev_ioctl+0x2f8/0x790 block/ioctl.c:603
 vfs_ioctl fs/ioctl.c:51 [inline]
 __do_sys_ioctl fs/ioctl.c:874 [inline]
 __se_sys_ioctl+0xfb/0x170 fs/ioctl.c:860
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fb815477ae9
RSP: 002b:00007fb8129ab188 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007fb81558b0e0 RCX: 00007fb815477ae9
RDX: 0000000000001200 RSI: 0000000000001276 RDI: 0000000000000003
RBP: 00007fb8154d1f6d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007fffb4f0640f R14: 00007fb8129ab300 R15: 0000000000022000
 </TASK>

Showing all locks held in the system:
1 lock held by khungtaskd/27:
 #0: ffffffff8cb1dd40 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
1 lock held by systemd-journal/2963:
 #0: ffff8881461c7338 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_invalidate_lock_shared include/linux/fs.h:838 [inline]
 #0: ffff8881461c7338 (mapping.invalidate_lock){++++}-{3:3}, at: page_cache_ra_unbounded+0x1b8/0x9f0 mm/readahead.c:194
1 lock held by systemd-timesyn/3057:
 #0: ffff88801aeb4b58 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_invalidate_lock_shared include/linux/fs.h:838 [inline]
 #0: ffff88801aeb4b58 (mapping.invalidate_lock){++++}-{3:3}, at: page_cache_ra_unbounded+0x1b8/0x9f0 mm/readahead.c:194
2 locks held by in:imklog/6193:
 #0: ffff888075d2cb58 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_invalidate_lock_shared include/linux/fs.h:838 [inline]
 #0: ffff888075d2cb58 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_fault+0x47d/0x1630 mm/filemap.c:3096
 #1: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __perform_reclaim mm/page_alloc.c:4585 [inline]
 #1: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __alloc_pages_direct_reclaim mm/page_alloc.c:4609 [inline]
 #1: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __alloc_pages_slowpath+0x10fe/0x2530 mm/page_alloc.c:5007
1 lock held by cron/6184:
 #0: ffff888075d33768 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_invalidate_lock_shared include/linux/fs.h:838 [inline]
 #0: ffff888075d33768 (mapping.invalidate_lock){++++}-{3:3}, at: page_cache_ra_unbounded+0x1b8/0x9f0 mm/readahead.c:194
1 lock held by syz-fuzzer/6502:
 #0: ffff88806fe35550 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_invalidate_lock_shared include/linux/fs.h:838 [inline]
 #0: ffff88806fe35550 (mapping.invalidate_lock){++++}-{3:3}, at: page_cache_ra_unbounded+0x1b8/0x9f0 mm/readahead.c:194
1 lock held by syz-fuzzer/6508:
 #0: ffff88806fe35550 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_invalidate_lock_shared include/linux/fs.h:838 [inline]
 #0: ffff88806fe35550 (mapping.invalidate_lock){++++}-{3:3}, at: page_cache_ra_unbounded+0x1b8/0x9f0 mm/readahead.c:194
2 locks held by syz-fuzzer/19015:
 #0: ffff88806fe35550 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_invalidate_lock_shared include/linux/fs.h:838 [inline]
 #0: ffff88806fe35550 (mapping.invalidate_lock){++++}-{3:3}, at: filemap_fault+0x47d/0x1630 mm/filemap.c:3096
 #1: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __perform_reclaim mm/page_alloc.c:4585 [inline]
 #1: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __alloc_pages_direct_reclaim mm/page_alloc.c:4609 [inline]
 #1: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __alloc_pages_slowpath+0x10fe/0x2530 mm/page_alloc.c:5007
3 locks held by syz-executor.3/9483:
 #0: ffff88801a5074a0 (&q->debugfs_mutex){+.+.}-{3:3}, at: blk_trace_ioctl+0xe7/0x8d0 kernel/trace/blktrace.c:725
 #1: ffffffff8cb5d2c8 (relay_channels_mutex){+.+.}-{3:3}, at: relay_open+0x36c/0x990 kernel/relay.c:518
 #2: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __perform_reclaim mm/page_alloc.c:4585 [inline]
 #2: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __alloc_pages_direct_reclaim mm/page_alloc.c:4609 [inline]
 #2: ffffffff8cbe1640 (fs_reclaim){+.+.}-{0:0}, at: __alloc_pages_slowpath+0x10fe/0x2530 mm/page_alloc.c:5007
1 lock held by syz-executor.4/9485:
 #0: ffff88801a5074a0 (&q->debugfs_mutex){+.+.}-{3:3}, at: blk_trace_ioctl+0xe7/0x8d0 kernel/trace/blktrace.c:725
1 lock held by syz-executor.4/9504:
 #0: ffff88801a5074a0 (&q->debugfs_mutex){+.+.}-{3:3}, at: blk_trace_ioctl+0xe7/0x8d0 kernel/trace/blktrace.c:725

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

NMI backtrace for cpu 0
CPU: 0 PID: 27 Comm: khungtaskd Not tainted 5.16.0-rc3-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1dc/0x2d8 lib/dump_stack.c:106
 nmi_cpu_backtrace+0x45f/0x490 lib/nmi_backtrace.c:111
 nmi_trigger_cpumask_backtrace+0x16a/0x280 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:210 [inline]
 watchdog+0xc82/0xcd0 kernel/hung_task.c:295
 kthread+0x468/0x490 kernel/kthread.c:327
 ret_from_fork+0x1f/0x30
 </TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 44 Comm: kworker/u4:2 Not tainted 5.16.0-rc3-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: bat_events batadv_purge_orig
RIP: 0010:visit_lock_entry kernel/locking/lockdep.c:1491 [inline]
RIP: 0010:__bfs kernel/locking/lockdep.c:1771 [inline]
RIP: 0010:__bfs_backwards kernel/locking/lockdep.c:1815 [inline]
RIP: 0010:check_irq_usage kernel/locking/lockdep.c:2755 [inline]
RIP: 0010:check_prev_add kernel/locking/lockdep.c:3067 [inline]
RIP: 0010:check_prevs_add kernel/locking/lockdep.c:3186 [inline]
RIP: 0010:validate_chain+0x24c7/0x8240 kernel/locking/lockdep.c:3801
Code: 41 b5 01 eb 0c 4d 8b 3f 4d 39 f7 0f 84 e6 fb ff ff 49 8d 5f 30 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 8f 6a 69 00 4c 89 23 41 f6 c5 01 0f 84 82 00 00
RSP: 0000:ffffc90000dc0340 EFLAGS: 00000046
RAX: 1ffffffff20fe211 RBX: ffffffff907f1088 RCX: dffffc0000000000
RDX: 0000000000000000 RSI: 0000000000000008 RDI: ffffffff8f8e3d10
RBP: ffffc90000dc0650 R08: dffffc0000000000 R09: fffffbfff1ff35de
R10: fffffbfff1ff35de R11: 0000000000000000 R12: ffffffff907ed4d8
R13: 0000000000000000 R14: ffffffff8f8e3cf0 R15: ffffffff907f1058
FS:  0000000000000000(0000) GS:ffff8880b9b00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000454740 CR3: 000000001e753000 CR4: 00000000003526e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 __lock_acquire+0x1382/0x2b00 kernel/locking/lockdep.c:5027
 lock_acquire+0x19f/0x4d0 kernel/locking/lockdep.c:5637
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
 debug_object_activate+0x97/0x6a0 lib/debugobjects.c:661
 debug_timer_activate kernel/time/timer.c:729 [inline]
 __mod_timer+0x824/0xd20 kernel/time/timer.c:1050
 sk_reset_timer+0x1f/0xb0 net/core/sock.c:3180
 tcp_delack_timer_handler+0x4d9/0x990 net/ipv4/tcp_timer.c:317
 tcp_delack_timer+0x1c8/0x2e0 net/ipv4/tcp_timer.c:344
 call_timer_fn+0xf6/0x210 kernel/time/timer.c:1421
 expire_timers kernel/time/timer.c:1466 [inline]
 __run_timers+0x71a/0x910 kernel/time/timer.c:1734
 run_timer_softirq+0x63/0xf0 kernel/time/timer.c:1747
 __do_softirq+0x392/0x7a3 kernel/softirq.c:558
 do_softirq+0x161/0x240 kernel/softirq.c:459
 </IRQ>
 <TASK>
 __local_bh_enable_ip+0x1b0/0x1f0 kernel/softirq.c:383
 spin_unlock_bh include/linux/spinlock.h:394 [inline]
 batadv_purge_orig_ref+0x33c2/0x34b0 net/batman-adv/originator.c:1259
 batadv_purge_orig+0x15/0x60 net/batman-adv/originator.c:1272
 process_one_work+0x853/0x1140 kernel/workqueue.c:2298
 worker_thread+0xac1/0x1320 kernel/workqueue.c:2445
 kthread+0x468/0x490 kernel/kthread.c:327
 ret_from_fork+0x1f/0x30
 </TASK>
----------------
Code disassembly (best guess):
   0:	41 b5 01             	mov    $0x1,%r13b
   3:	eb 0c                	jmp    0x11
   5:	4d 8b 3f             	mov    (%r15),%r15
   8:	4d 39 f7             	cmp    %r14,%r15
   b:	0f 84 e6 fb ff ff    	je     0xfffffbf7
  11:	49 8d 5f 30          	lea    0x30(%r15),%rbx
  15:	48 89 d8             	mov    %rbx,%rax
  18:	48 c1 e8 03          	shr    $0x3,%rax
  1c:	48 b9 00 00 00 00 00 	movabs $0xdffffc0000000000,%rcx
  23:	fc ff df
  26:	80 3c 08 00          	cmpb   $0x0,(%rax,%rcx,1)
* 2a:	74 08                	je     0x34 <-- trapping instruction
  2c:	48 89 df             	mov    %rbx,%rdi
  2f:	e8 8f 6a 69 00       	callq  0x696ac3
  34:	4c 89 23             	mov    %r12,(%rbx)
  37:	41 f6 c5 01          	test   $0x1,%r13b
  3b:	0f                   	.byte 0xf
  3c:	84                   	.byte 0x84
  3d:	82                   	(bad)

Crashes (2):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci-upstream-kasan-gce-smack-root 2021/11/30 08:17 upstream d58071a8a76d d0830353 .config log report info INFO: task hung in blk_trace_ioctl
ci-upstream-kasan-gce-386 2021/09/26 06:26 upstream a5e0aceabef6 8cac236e .config log report info INFO: task hung in blk_trace_ioctl
* Struck through repros no longer work on HEAD.