syzbot


INFO: task hung in usbdev_open

Status: auto-closed as invalid on 2021/07/05 05:59
Reported-by: syzbot+39a89b844efa121ef4b7@syzkaller.appspotmail.com
First crash: 613d, last: 474d
similar bugs (5):
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: task hung in usbdev_open (2) 154 5h10m 542d 0/22 upstream: reported on 2020/12/29 11:48
linux-4.19 INFO: task hung in usbdev_open (2) 2 215d 223d 0/1 auto-closed as invalid on 2022/03/21 09:54
linux-4.19 INFO: task hung in usbdev_open 6 515d 602d 0/1 auto-closed as invalid on 2021/05/25 14:21
upstream INFO: task hung in usbdev_open 2 1004d 1004d 0/22 auto-closed as invalid on 2019/12/23 20:14
upstream INFO: task can't die in usbdev_open 4 508d 621d 0/22 auto-closed as invalid on 2021/04/02 18:49

Sample crash report:
ieee802154 phy1 wpan1: encryption failed: -22
Bluetooth: hci3 command 0x0406 tx timeout
ieee802154 phy1 wpan1: encryption failed: -22
Bluetooth: hci5 command 0x0406 tx timeout
ieee802154 phy1 wpan1: encryption failed: -22
INFO: task syz-executor.5:31217 blocked for more than 140 seconds.
      Not tainted 4.14.223-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.5  D29144 31217   7985 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2808 [inline]
 __schedule+0x88b/0x1de0 kernel/sched/core.c:3384
 schedule+0x8d/0x1b0 kernel/sched/core.c:3428
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3486
 __mutex_lock_common kernel/locking/mutex.c:833 [inline]
 __mutex_lock+0x669/0x1310 kernel/locking/mutex.c:893
 device_lock include/linux/device.h:1081 [inline]
 usbdev_open+0x142/0x780 drivers/usb/core/devio.c:1023
 chrdev_open+0x23c/0x6d0 fs/char_dev.c:423
 do_dentry_open+0x44b/0xec0 fs/open.c:777
 vfs_open+0x105/0x220 fs/open.c:888
 do_last fs/namei.c:3428 [inline]
 path_openat+0x628/0x2970 fs/namei.c:3569
 do_filp_open+0x179/0x3c0 fs/namei.c:3603
 do_sys_open+0x296/0x410 fs/open.c:1081
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x419554
RSP: 002b:00007ffb1fc0ecc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 0000000000419554
RDX: 0000000000000001 RSI: 00007ffb1fc0ed60 RDI: 00000000ffffff9c
RBP: 00007ffb1fc0ed60 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000001
R13: 00007ffdbaff1b3f R14: 00007ffb1fc0f300 R15: 0000000000022000
INFO: task syz-executor.5:31226 blocked for more than 140 seconds.
      Not tainted 4.14.223-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.5  D29240 31226   7985 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2808 [inline]
 __schedule+0x88b/0x1de0 kernel/sched/core.c:3384
 schedule+0x8d/0x1b0 kernel/sched/core.c:3428
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3486
 __mutex_lock_common kernel/locking/mutex.c:833 [inline]
 __mutex_lock+0x669/0x1310 kernel/locking/mutex.c:893
 device_lock include/linux/device.h:1081 [inline]
 usbdev_open+0x142/0x780 drivers/usb/core/devio.c:1023
 chrdev_open+0x23c/0x6d0 fs/char_dev.c:423
 do_dentry_open+0x44b/0xec0 fs/open.c:777
 vfs_open+0x105/0x220 fs/open.c:888
 do_last fs/namei.c:3428 [inline]
 path_openat+0x628/0x2970 fs/namei.c:3569
 do_filp_open+0x179/0x3c0 fs/namei.c:3603
 do_sys_open+0x296/0x410 fs/open.c:1081
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x419554
RSP: 002b:00007ffb1fbedcc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 0000000000419554
RDX: 0000000000000001 RSI: 00007ffb1fbedd60 RDI: 00000000ffffff9c
RBP: 00007ffb1fbedd60 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000001
R13: 00007ffdbaff1b3f R14: 00007ffb1fbee300 R15: 0000000000022000

Showing all locks held in the system:
1 lock held by khungtaskd/1531:
 #0:  (tasklist_lock){.+.+}, at: [<ffffffff86ff2257>] debug_show_all_locks+0x7c/0x21a kernel/locking/lockdep.c:4548
2 locks held by agetty/24750:
 #0:  (&tty->ldisc_sem){++++}, at: [<ffffffff835370e2>] tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:284
 #1:  (&ldata->atomic_read_lock){+.+.}, at: [<ffffffff8352c463>] n_tty_read+0x1e3/0x1680 drivers/tty/n_tty.c:2156
5 locks held by kworker/0:4/31155:
 #0:  ("usb_hub_wq"){+.+.}, at: [<ffffffff81363810>] process_one_work+0x6b0/0x14a0 kernel/workqueue.c:2087
 #1:  ((&hub->events)){+.+.}, at: [<ffffffff81363846>] process_one_work+0x6e6/0x14a0 kernel/workqueue.c:2091
 #2:  (&dev->mutex){....}, at: [<ffffffff8443bdb8>] device_lock include/linux/device.h:1081 [inline]
 #2:  (&dev->mutex){....}, at: [<ffffffff8443bdb8>] hub_event+0x108/0x3d70 drivers/usb/core/hub.c:5220
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8443d598>] usb_lock_port drivers/usb/core/hub.c:2934 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8443d598>] hub_port_connect drivers/usb/core/hub.c:4904 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8443d598>] hub_port_connect_change drivers/usb/core/hub.c:5088 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8443d598>] port_event drivers/usb/core/hub.c:5194 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8443d598>] hub_event+0x18e8/0x3d70 drivers/usb/core/hub.c:5274
 #4:  (hcd->address0_mutex){+.+.}, at: [<ffffffff844318bb>] hub_port_init+0x15b/0x2970 drivers/usb/core/hub.c:4429
1 lock held by syz-executor.5/31217:
 #0:  (&dev->mutex){....}, at: [<ffffffff8446e972>] device_lock include/linux/device.h:1081 [inline]
 #0:  (&dev->mutex){....}, at: [<ffffffff8446e972>] usbdev_open+0x142/0x780 drivers/usb/core/devio.c:1023
1 lock held by syz-executor.5/31226:
 #0:  (&dev->mutex){....}, at: [<ffffffff8446e972>] device_lock include/linux/device.h:1081 [inline]
 #0:  (&dev->mutex){....}, at: [<ffffffff8446e972>] usbdev_open+0x142/0x780 drivers/usb/core/devio.c:1023

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

NMI backtrace for cpu 0
CPU: 0 PID: 1531 Comm: khungtaskd Not tainted 4.14.223-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0x1b2/0x281 lib/dump_stack.c:58
 nmi_cpu_backtrace.cold+0x57/0x93 lib/nmi_backtrace.c:101
 nmi_trigger_cpumask_backtrace+0x13a/0x180 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:140 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:195 [inline]
 watchdog+0x5b9/0xb40 kernel/hung_task.c:274
 kthread+0x30d/0x420 kernel/kthread.c:232
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 8 Comm: rcu_preempt Not tainted 4.14.223-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
task: ffff8880b5414200 task.stack: ffff8880b5418000
RIP: 0010:lookup_chain_cache kernel/locking/lockdep.c:2361 [inline]
RIP: 0010:lookup_chain_cache_add kernel/locking/lockdep.c:2381 [inline]
RIP: 0010:validate_chain kernel/locking/lockdep.c:2435 [inline]
RIP: 0010:__lock_acquire+0xa86/0x3f20 kernel/locking/lockdep.c:3491
RSP: 0018:ffff8880b541f8c0 EFLAGS: 00000082
RAX: 1ffffffff167f931 RBX: ffffffff8b3843c8 RCX: 000000000000472e
RDX: 1ffffffff1735a86 RSI: 00000000877bb9f2 RDI: ffffffff8b3fc988
RBP: dffffc0000000000 R08: ffffffff8b9ad430 R09: 00000000000c0001
R10: ffff8880b5414ab0 R11: ffff8880b5414200 R12: ffff8880b5414ac8
R13: 0000000000000000 R14: f3e1ddd958bce766 R15: ffffffff8beb5d40
FS:  0000000000000000(0000) GS:ffff8880ba500000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f7993c2c000 CR3: 00000000a1b3d000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0x8c/0xc0 kernel/locking/spinlock.c:160
 debug_object_deactivate lib/debugobjects.c:502 [inline]
 debug_object_deactivate+0xdf/0x2e0 lib/debugobjects.c:491
 debug_timer_deactivate kernel/time/timer.c:698 [inline]
 debug_deactivate kernel/time/timer.c:750 [inline]
 detach_timer kernel/time/timer.c:790 [inline]
 detach_if_pending+0x82/0x430 kernel/time/timer.c:809
 try_to_del_timer_sync+0x9a/0xe0 kernel/time/timer.c:1181
 del_timer_sync+0x17c/0x240 kernel/time/timer.c:1246
 schedule_timeout+0x4b7/0xe90 kernel/time/timer.c:1748
 rcu_gp_kthread+0xc0a/0x1e60 kernel/rcu/tree.c:2255
 kthread+0x30d/0x420 kernel/kthread.c:232
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
Code: ea 03 80 3c 02 00 0f 85 17 2d 00 00 48 8b 1c cd c0 9a 98 8b 48 85 db 74 55 48 83 eb 08 74 4f 48 bd 00 00 00 00 00 fc ff df eb 06 <48> 83 eb 08 74 3d 48 8d 7b 18 48 89 f8 48 c1 e8 03 80 3c 28 00 

Crashes (7):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci2-linux-4-14 2021/03/07 05:58 linux-4.14.y 397a88b2cc86 e4b4d570 .config log report info INFO: task hung in usbdev_open
ci2-linux-4-14 2021/02/28 20:30 linux-4.14.y 3242aa3a635c 4c37c133 .config log report info INFO: task hung in usbdev_open
ci2-linux-4-14 2021/02/24 05:12 linux-4.14.y 3242aa3a635c fcc6d71b .config log report info INFO: task hung in usbdev_open
ci2-linux-4-14 2021/02/10 15:43 linux-4.14.y 2c8a3fceddf0 9c8b8541 .config log report info INFO: task hung in usbdev_open
ci2-linux-4-14 2020/12/24 15:22 linux-4.14.y 3f2ecb86cb90 c2c1d1dd .config log report info
ci2-linux-4-14 2020/11/20 10:06 linux-4.14.y 8961076ed318 0767f13f .config log report info
ci2-linux-4-14 2020/10/19 16:39 linux-4.14.y cbfa1702aaf6 ff4a3345 .config log report info