syzbot


INFO: task hung in usbdev_release (2)

Status: upstream: reported C repro on 2023/09/16 19:39
Bug presence: origin:upstream
[Documentation on labels]
Reported-by: syzbot+943820c86ea757c17a1d@syzkaller.appspotmail.com
First crash: 384d, last: 163d
Fix bisection: failed (error log, bisect log)
  
Bug presence (1)
Date Name Commit Repro Result
2023/09/16 upstream (ToT) ad8a69f361b9 C [report] INFO: task hung in hub_port_init
Similar bugs (7)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: task hung in usbdev_release (2) usb C error 85 4d12h 422d 0/28 upstream: reported C repro on 2023/08/09 15:47
upstream INFO: task hung in usbdev_release usb 20 1021d 1428d 0/28 closed as invalid on 2022/02/07 19:19
linux-5.15 INFO: task hung in usbdev_release 1 221d 221d 0/3 auto-obsoleted due to no activity on 2024/06/05 22:03
linux-4.19 INFO: task hung in usbdev_release 1 1441d 1441d 0/1 auto-closed as invalid on 2021/02/21 22:17
linux-6.1 INFO: task hung in usbdev_release 1 569d 569d 0/3 auto-obsoleted due to no activity on 2023/07/13 23:24
linux-4.19 INFO: task hung in usbdev_release (2) 10 697d 1162d 0/1 auto-obsoleted due to no activity on 2023/03/08 04:55
linux-4.14 INFO: task hung in usbdev_release 2 1377d 1440d 0/1 auto-closed as invalid on 2021/04/27 06:36
Fix bisection attempts (6)
Created Duration User Patch Repo Result
2024/05/30 16:36 10m bisect fix linux-6.1.y error job log
2024/03/04 13:12 1h38m bisect fix linux-6.1.y OK (0) job log log
2024/01/26 05:21 1h47m bisect fix linux-6.1.y OK (0) job log log
2023/12/25 22:44 1h30m bisect fix linux-6.1.y OK (0) job log log
2023/11/25 04:47 1h28m bisect fix linux-6.1.y OK (0) job log log
2023/10/22 02:11 1h55m bisect fix linux-6.1.y OK (0) job log log

Sample crash report:
INFO: task syz-executor584:3574 blocked for more than 143 seconds.
      Not tainted 6.1.53-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor584 state:D stack:25248 pid:3574  ppid:3573   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5241 [inline]
 __schedule+0x132c/0x4330 kernel/sched/core.c:6554
 schedule+0xbf/0x180 kernel/sched/core.c:6630
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6689
 __mutex_lock_common+0xe2b/0x2520 kernel/locking/mutex.c:679
 __mutex_lock kernel/locking/mutex.c:747 [inline]
 mutex_lock_nested+0x17/0x20 kernel/locking/mutex.c:799
 device_lock include/linux/device.h:836 [inline]
 usbdev_release+0x76/0x7c0 drivers/usb/core/devio.c:1097
 __fput+0x3b7/0x890 fs/file_table.c:320
 task_work_run+0x246/0x300 kernel/task_work.c:179
 resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
 exit_to_user_mode_loop+0xd9/0x100 kernel/entry/common.c:171
 exit_to_user_mode_prepare+0xb1/0x140 kernel/entry/common.c:204
 __syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
 syscall_exit_to_user_mode+0x60/0x270 kernel/entry/common.c:297
 do_syscall_64+0x49/0xb0 arch/x86/entry/common.c:86
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f8bc42bf0e0
RSP: 002b:00007ffdd38cdf88 EFLAGS: 00000202 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 00007f8bc42bf0e0
RDX: 0000000000000007 RSI: 00007ffdd38cdac0 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000202 R12: 00000000000f4240
R13: 00007ffdd38ce238 R14: 0000000000000001 R15: 00007ffdd38cdfd0
 </TASK>

Showing all locks held in the system:
5 locks held by kworker/0:0/7:
 #0: ffff8880176fc538 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x77a/0x11f0
 #1: ffffc900000c7d20 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x7bd/0x11f0 kernel/workqueue.c:2267
 #2: ffff888022e21190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:836 [inline]
 #2: ffff888022e21190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1fe/0x5710 drivers/usb/core/hub.c:5739
 #3: ffff888022b6e4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3110 [inline]
 #3: ffff888022b6e4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5311 [inline]
 #3: ffff888022b6e4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5555 [inline]
 #3: ffff888022b6e4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
 #3: ffff888022b6e4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x2471/0x5710 drivers/usb/core/hub.c:5793
 #4: ffff888022d10868 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5312 [inline]
 #4: ffff888022d10868 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5555 [inline]
 #4: ffff888022d10868 (hcd->address0_mutex){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
 #4: ffff888022d10868 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_event+0x249e/0x5710 drivers/usb/core/hub.c:5793
2 locks held by kworker/u4:0/9:
 #0: ffff888012479138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x77a/0x11f0
 #1: ffffc900000e7d20 ((work_completion)(&(&kfence_timer)->work)){+.+.}-{0:0}, at: psi_task_switch+0x3a3/0x770 kernel/sched/psi.c:988
1 lock held by rcu_tasks_kthre/12:
 #0: ffffffff8d12a1b0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:516
1 lock held by rcu_tasks_trace/13:
 #0: ffffffff8d12a9b0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:516
1 lock held by khungtaskd/28:
 #0: ffffffff8d129fe0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
1 lock held by klogd/2993:
 #0: ffff8880b9839e18 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x26/0x140 kernel/sched/core.c:537
2 locks held by getty/3303:
 #0: ffff888028bea098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x21/0x70 drivers/tty/tty_ldisc.c:244
 #1: ffffc900031262f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6a7/0x1db0 drivers/tty/n_tty.c:2188
1 lock held by syz-executor584/3574:
 #0: ffff888022e21190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:836 [inline]
 #0: ffff888022e21190 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x76/0x7c0 drivers/usb/core/devio.c:1097

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

NMI backtrace for cpu 1
CPU: 1 PID: 28 Comm: khungtaskd Not tainted 6.1.53-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 08/04/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2cb lib/dump_stack.c:106
 nmi_cpu_backtrace+0x4e1/0x560 lib/nmi_backtrace.c:111
 nmi_trigger_cpumask_backtrace+0x1b0/0x3f0 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:220 [inline]
 watchdog+0xf18/0xf60 kernel/hung_task.c:377
 kthread+0x26e/0x300 kernel/kthread.c:376
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:306
 </TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 9 Comm: kworker/u4:0 Not tainted 6.1.53-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 08/04/2023
Workqueue: events_unbound toggle_allocation_gate
RIP: 0010:check_preemption_disabled+0x4b/0x110 lib/smp_processor_id.c:55
Code: 8b 05 91 54 7c 75 a9 ff ff ff 7f 74 22 65 48 8b 04 25 28 00 00 00 48 3b 44 24 08 0f 85 c7 00 00 00 89 d8 48 83 c4 10 5b 41 5c <41> 5e 41 5f c3 48 c7 04 24 00 00 00 00 9c 8f 04 24 f7 04 24 00 02
RSP: 0018:ffffc900000e7ae0 EFLAGS: 00000082
RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff88813fec0000
RDX: 0000000000000000 RSI: ffffffff8aebf420 RDI: ffffffff8b3ceb80
RBP: 0000000000000000 R08: ffffffff815a894a R09: fffffbfff1ce766e
R10: 0000000000000000 R11: dffffc0000000001 R12: 0000000000000246
R13: ffff88813fec0000 R14: 00000000ffffffff R15: ffffffff8d12a040
FS:  0000000000000000(0000) GS:ffff8880b9800000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ffe66ab2278 CR3: 000000000ce8e000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <NMI>
 </NMI>
 <TASK>
 lockdep_recursion_finish kernel/locking/lockdep.c:467 [inline]
 lock_is_held_type+0xfd/0x180 kernel/locking/lockdep.c:5705
 lock_is_held include/linux/lockdep.h:283 [inline]
 __might_resched+0xa1/0x780 kernel/sched/core.c:9898
 process_one_work+0xa71/0x11f0 kernel/workqueue.c:2318
 worker_thread+0xa5f/0x1210 kernel/workqueue.c:2439
 kthread+0x26e/0x300 kernel/kthread.c:376
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:306
 </TASK>

Crashes (6):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2023/09/16 19:38 linux-6.1.y 09045dae0d90 0b6a67ac .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan INFO: task hung in usbdev_release
2024/04/17 09:14 linux-6.1.y cd5d98c0556c 18f6e127 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan INFO: task hung in usbdev_release
2024/03/16 13:47 linux-6.1.y d7543167affd d615901c .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan INFO: task hung in usbdev_release
2024/04/25 08:57 linux-6.1.y 6741e066ec76 8bdc0f22 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan-arm64 INFO: task hung in usbdev_release
2024/04/22 18:44 linux-6.1.y 6741e066ec76 36c961ad .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan-arm64 INFO: task hung in usbdev_release
2024/03/16 11:01 linux-6.1.y d7543167affd d615901c .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-6-1-kasan-arm64 INFO: task hung in usbdev_release
* Struck through repros no longer work on HEAD.