INFO: task hung in usbdev_open

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: f5d8eef0 Linux 4.19.154
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=128e7b98500000
kernel config: https://syzkaller.appspot.com/x/.config?x=be9b9357b4680aa1
dashboard link: https://syzkaller.appspot.com/bug?extid=4ce33fc9c94c614851d1
compiler: gcc (GCC) 10.1.0-syz 20200507

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+4ce33f...@syzkaller.appspotmail.com

Bluetooth: hci1: command 0x0406 tx timeout
Bluetooth: hci3: command 0x0406 tx timeout
INFO: task syz-executor.1:15241 blocked for more than 140 seconds.
Not tainted 4.19.154-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.1 D28240 15241 12351 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:1002 [inline]
__mutex_lock+0x647/0x1260 kernel/locking/mutex.c:1072
device_lock include/linux/device.h:1173 [inline]
usbdev_open+0x152/0x7f0 drivers/usb/core/devio.c:1007
chrdev_open+0x266/0x770 fs/char_dev.c:423
do_dentry_open+0x4aa/0x1160 fs/open.c:796
do_last fs/namei.c:3421 [inline]
path_openat+0x793/0x2df0 fs/namei.c:3537
do_filp_open+0x18c/0x3f0 fs/namei.c:3567
do_sys_open+0x3b3/0x520 fs/open.c:1085
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4179b1
Code: Bad RIP value.
RSP: 002b:00007f273e54a820 EFLAGS: 00000293 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00000000004179b1
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 00007f273e54a850
RBP: 000000000118bf60 R08: 000000000000000f R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 000000000118bf2c
R13: 00007fffb2401eaf R14: 00007f273e54b9c0 R15: 000000000118bf2c

Showing all locks held in the system:
1 lock held by khungtaskd/1565:
#0: 00000000c3d2bdd9 (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4440
5 locks held by kworker/1:2/3507:
#0: 00000000028c1039 ((wq_completion)"usb_hub_wq"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2126
#1: 00000000c658c09c ((work_completion)(&hub->events)){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2130
#2: 000000009710be45 (&dev->mutex){....}, at: device_lock include/linux/device.h:1173 [inline]
#2: 000000009710be45 (&dev->mutex){....}, at: hub_event+0x11b/0x43f0 drivers/usb/core/hub.c:5337
#3: 00000000385c0130 (&port_dev->status_lock){+.+.}, at: usb_lock_port drivers/usb/core/hub.c:2977 [inline]
#3: 00000000385c0130 (&port_dev->status_lock){+.+.}, at: hub_port_connect drivers/usb/core/hub.c:5019 [inline]
#3: 00000000385c0130 (&port_dev->status_lock){+.+.}, at: hub_port_connect_change drivers/usb/core/hub.c:5203 [inline]
#3: 00000000385c0130 (&port_dev->status_lock){+.+.}, at: port_event drivers/usb/core/hub.c:5311 [inline]
#3: 00000000385c0130 (&port_dev->status_lock){+.+.}, at: hub_event+0x1ce3/0x43f0 drivers/usb/core/hub.c:5391
#4: 0000000001479b4c (hcd->address0_mutex){+.+.}, at: hub_port_init+0x1b6/0x2fa0 drivers/usb/core/hub.c:4528
1 lock held by in:imklog/7735:
#0: 000000009ef70d81 (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
3 locks held by kworker/u4:12/14835:
#0: 000000005356d61c (&rq->lock){-.-.}, at: idle_balance kernel/sched/fair.c:9701 [inline]
#0: 000000005356d61c (&rq->lock){-.-.}, at: pick_next_task_fair+0x556/0x1570 kernel/sched/fair.c:6840
#1: 00000000c3d2bdd9 (rcu_read_lock){....}, at: cpu_of kernel/sched/sched.h:927 [inline]
#1: 00000000c3d2bdd9 (rcu_read_lock){....}, at: __update_idle_core+0x39/0x3e0 kernel/sched/fair.c:6057
#2: 0000000061dc7206 (&(&bat_priv->mcast.mla_lock)->rlock){+.+.}, at: spin_lock include/linux/spinlock.h:329 [inline]
#2: 0000000061dc7206 (&(&bat_priv->mcast.mla_lock)->rlock){+.+.}, at: batadv_mcast_mla_update+0xad/0x1bf0 net/batman-adv/multicast.c:653
1 lock held by syz-executor.1/15241:
#0: 000000009710be45 (&dev->mutex){....}, at: device_lock include/linux/device.h:1173 [inline]
#0: 000000009710be45 (&dev->mutex){....}, at: usbdev_open+0x152/0x7f0 drivers/usb/core/devio.c:1007

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

NMI backtrace for cpu 0
CPU: 0 PID: 1565 Comm: khungtaskd Not tainted 4.19.154-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/0x2fe lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1a6/0x1eb 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 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 12225 Comm: kworker/u4:7 Not tainted 4.19.154-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: phy18 ieee80211_iface_work
RIP: 0010:__mutex_trylock_or_owner kernel/locking/mutex.c:99 [inline]
RIP: 0010:__mutex_trylock kernel/locking/mutex.c:125 [inline]
RIP: 0010:__mutex_lock_common kernel/locking/mutex.c:927 [inline]
RIP: 0010:__mutex_lock+0x109/0x1260 kernel/locking/mutex.c:1072
Code: e8 bc 3c 86 f9 4c 89 f8 5f 48 c1 e8 03 65 4c 8b 24 25 80 df 01 00 80 3c 18 00 0f 85 bf 0f 00 00 49 c7 c5 20 a7 23 8d 4d 8b 37 <48> b8 00 00 00 00 00 fc ff df 4c 89 ed 48 c1 ed 03 48 01 c5 4c 89
RSP: 0018:ffff8880552cf908 EFLAGS: 00000246
RAX: 1ffff1100aca7309 RBX: dffffc0000000000 RCX: ffffffff8814a7d4
RDX: ffffed100aca730a RSI: 0000000000000008 RDI: ffffffff87ba17a9
RBP: 0000000000000000 R08: 0000000000000000 R09: ffffed100aca7309
R10: ffff88805653984f R11: 0000000000000000 R12: ffff888061490500
R13: ffffffff8d23a720 R14: 0000000000000000 R15: ffff888056539848
FS: 0000000000000000(0000) GS:ffff8880ba100000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f9c77684020 CR3: 00000000aad7a000 CR4: 00000000001426e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
sdata_lock net/mac80211/ieee80211_i.h:990 [inline]
ieee80211_ibss_rx_queued_mgmt+0xe9/0x18b0 net/mac80211/ibss.c:1623
ieee80211_iface_work+0x5c4/0x8a0 net/mac80211/iface.c:1345
process_one_work+0x864/0x1570 kernel/workqueue.c:2155
worker_thread+0x64c/0x1130 kernel/workqueue.c:2298
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415


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