INFO: task hung in blk_trace_startstop

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 3f8a27f9e27b Linux 4.19.211
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=107059a4f00000
kernel config: https://syzkaller.appspot.com/x/.config?x=9b9277b418617afe
dashboard link: https://syzkaller.appspot.com/bug?extid=3915d101c947d310ffde
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)

Unfortunately, I don't have any reproducer for this issue yet.

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

kvm: pic: level sensitive irq not supported
ieee802154 phy0 wpan0: encryption failed: -22
ieee802154 phy1 wpan1: encryption failed: -22
ieee802154 phy0 wpan0: encryption failed: -22
ieee802154 phy1 wpan1: encryption failed: -22
INFO: task syz-executor.0:29000 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.0 D28776 29000 15904 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3619
__mutex_lock_common kernel/locking/mutex.c:1016 [inline]
__mutex_lock+0x5f0/0x1190 kernel/locking/mutex.c:1078
blk_trace_startstop+0x21/0x40 kernel/trace/blktrace.c:714
sg_ioctl+0x201d/0x2720 drivers/scsi/sg.c:1126
vfs_ioctl fs/ioctl.c:46 [inline]
file_ioctl fs/ioctl.c:501 [inline]
do_vfs_ioctl+0xcdb/0x12e0 fs/ioctl.c:688
ksys_ioctl+0x9b/0xc0 fs/ioctl.c:705
__do_sys_ioctl fs/ioctl.c:712 [inline]
__se_sys_ioctl fs/ioctl.c:710 [inline]
__x64_sys_ioctl+0x6f/0xb0 fs/ioctl.c:710
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f032237c0e9
Code: Bad RIP value.
RSP: 002b:00007f0320cd0168 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f032248f030 RCX: 00007f032237c0e9
RDX: 0000000000000000 RSI: 0000000000001274 RDI: 0000000000000004
RBP: 00007f03223d608d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffd8cffd43f R14: 00007f0320cd0300 R15: 0000000000022000
INFO: task syz-executor.0:29002 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.0 D29704 29002 15904 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3619
__mutex_lock_common kernel/locking/mutex.c:1016 [inline]
__mutex_lock+0x5f0/0x1190 kernel/locking/mutex.c:1078
blk_trace_setup+0x2f/0x60 kernel/trace/blktrace.c:626
sg_ioctl+0x270/0x2720 drivers/scsi/sg.c:1121
vfs_ioctl fs/ioctl.c:46 [inline]
file_ioctl fs/ioctl.c:501 [inline]
do_vfs_ioctl+0xcdb/0x12e0 fs/ioctl.c:688
ksys_ioctl+0x9b/0xc0 fs/ioctl.c:705
__do_sys_ioctl fs/ioctl.c:712 [inline]
__se_sys_ioctl fs/ioctl.c:710 [inline]
__x64_sys_ioctl+0x6f/0xb0 fs/ioctl.c:710
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f032237c0e9
Code: Bad RIP value.
RSP: 002b:00007f0320caf168 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f032248f100 RCX: 00007f032237c0e9
RDX: 0000000020000300 RSI: 00000000c0481273 RDI: 0000000000000004
RBP: 00007f03223d608d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffd8cffd43f R14: 00007f0320caf300 R15: 0000000000022000

Showing all locks held in the system:
1 lock held by khungtaskd/1570:
#0: 00000000dd23b9ab (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4441
1 lock held by in:imklog/7798:
#0: 0000000001b1494a (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
2 locks held by kworker/u4:8/9534:
1 lock held by syz-executor.2/28926:
#0: 0000000016eacf22 (&type->s_umount_key#89/1){+.+.}, at: alloc_super fs/super.c:226 [inline]
#0: 0000000016eacf22 (&type->s_umount_key#89/1){+.+.}, at: sget_userns+0x20b/0xcd0 fs/super.c:519
3 locks held by syz-executor.0/28977:
1 lock held by syz-executor.0/29000:
#0: 00000000eaaff6a9 (&q->blk_trace_mutex){+.+.}, at: blk_trace_startstop+0x21/0x40 kernel/trace/blktrace.c:714
1 lock held by syz-executor.0/29002:
#0: 00000000eaaff6a9 (&q->blk_trace_mutex){+.+.}, at: blk_trace_setup+0x2f/0x60 kernel/trace/blktrace.c:626

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

NMI backtrace for cpu 1
CPU: 1 PID: 1570 Comm: khungtaskd Not tainted 4.19.211-syzkaller #0
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+0x1fc/0x2ef lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1a6/0x1f0 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
watchdog+0x991/0xe60 kernel/hung_task.c:287
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 4690 Comm: systemd-journal Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:__rcu_read_unlock+0x15/0x160 kernel/rcu/tree_plugin.h:421
Code: ff 48 89 ef e8 0c f7 46 00 e9 9b fb ff ff 0f 1f 80 00 00 00 00 48 b8 00 00 00 00 00 fc ff df 55 53 65 48 8b 1c 25 c0 df 01 00 <48> 8d ab 70 03 00 00 48 89 ea 48 c1 ea 03 0f b6 04 02 84 c0 74 08
RSP: 0018:ffff8880a0d9f870 EFLAGS: 00000093
RAX: dffffc0000000000 RBX: ffff8880a0d94500 RCX: ffffffff816a27ca
RDX: 0000000000000000 RSI: ffffffff816a27ed RDI: 0000000000000005
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000005 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: ffff88813bff1918
FS: 00007f7a7a3a98c0(0000) GS:ffff8880ba000000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f7a776a2000 CR3: 00000000a2e52000 CR4: 00000000003406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
rcu_read_unlock include/linux/rcupdate.h:680 [inline]
__bpf_trace_run kernel/trace/bpf_trace.c:1165 [inline]
bpf_trace_run7+0x1b2/0x2c0 kernel/trace/bpf_trace.c:1206
__bpf_trace_lock_acquire+0x1bc/0x200 include/trace/events/lock.h:13
trace_lock_acquire include/trace/events/lock.h:13 [inline]
lock_acquire+0x298/0x3c0 kernel/locking/lockdep.c:3907
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
spin_lock include/linux/spinlock.h:329 [inline]
cache_flusharray mm/slab.c:3460 [inline]
___cache_free+0x241/0x3a0 mm/slab.c:3532
qlink_free mm/kasan/quarantine.c:147 [inline]
qlist_free_all+0x79/0x140 mm/kasan/quarantine.c:166
quarantine_reduce+0x1a9/0x230 mm/kasan/quarantine.c:259
kasan_kmalloc+0xa2/0x160 mm/kasan/kasan.c:538
slab_post_alloc_hook mm/slab.h:445 [inline]
slab_alloc mm/slab.c:3397 [inline]
kmem_cache_alloc+0x110/0x370 mm/slab.c:3557
prepare_creds+0x39/0x510 kernel/cred.c:255
do_faccessat+0x94/0x7a0 fs/open.c:359
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f7a796649c7
Code: 83 c4 08 48 3d 01 f0 ff ff 73 01 c3 48 8b 0d c8 d4 2b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 b8 15 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a1 d4 2b 00 f7 d8 64 89 01 48
RSP: 002b:00007ffe2ff43ec8 EFLAGS: 00000246 ORIG_RAX: 0000000000000015
RAX: ffffffffffffffda RBX: 00007ffe2ff46ef0 RCX: 00007f7a796649c7
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00005585d8d109a3
RBP: 00007ffe2ff44010 R08: 00005585d8d063e5 R09: 0000000000000018
R10: 0000000000000069 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: 00005585d91398a0 R15: 00007ffe2ff44500
----------------
Code disassembly (best guess):
0: ff 48 89 decl -0x77(%rax)
3: ef out %eax,(%dx)
4: e8 0c f7 46 00 callq 0x46f715
9: e9 9b fb ff ff jmpq 0xfffffba9
e: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
15: 48 b8 00 00 00 00 00 movabs $0xdffffc0000000000,%rax
1c: fc ff df
1f: 55 push %rbp
20: 53 push %rbx
21: 65 48 8b 1c 25 c0 df mov %gs:0x1dfc0,%rbx
28: 01 00
* 2a: 48 8d ab 70 03 00 00 lea 0x370(%rbx),%rbp <-- trapping instruction
31: 48 89 ea mov %rbp,%rdx
34: 48 c1 ea 03 shr $0x3,%rdx
38: 0f b6 04 02 movzbl (%rdx,%rax,1),%eax
3c: 84 c0 test %al,%al
3e: 74 08 je 0x48


---
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.

[syzbot]

Auto-closing this bug as obsolete.
Crashes did not happen for a while, no reproducer and no activity.