INFO: task hung in ath6kl_usb_power_off

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit: c8d141ce USB: Fix up terminology in include files
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git usb-testing
console output: https://syzkaller.appspot.com/x/log.txt?x=15d1a9a7100000
kernel config: https://syzkaller.appspot.com/x/.config?x=999be4eb2478ffa5
dashboard link: https://syzkaller.appspot.com/bug?extid=2d6ac90723742279e101
compiler: gcc (GCC) 10.1.0-syz 20200507

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

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+2d6ac9...@syzkaller.appspotmail.com

INFO: task kworker/0:6:3087 blocked for more than 143 seconds.
Not tainted 5.8.0-rc3-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:6 D24216 3087 2 0x80004000
Workqueue: usb_hub_wq hub_event
Call Trace:
context_switch kernel/sched/core.c:3453 [inline]
__schedule+0x88a/0x1cb0 kernel/sched/core.c:4178
schedule+0xcd/0x2b0 kernel/sched/core.c:4253
schedule_timeout+0x1d8/0x250 kernel/time/timer.c:1873
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
flush_workqueue+0x3ff/0x13e0 kernel/workqueue.c:2832
flush_scheduled_work include/linux/workqueue.h:597 [inline]
ath6kl_usb_flush_all drivers/net/wireless/ath/ath6kl/usb.c:476 [inline]
hif_detach_htc drivers/net/wireless/ath/ath6kl/usb.c:856 [inline]
ath6kl_usb_power_off+0xbe/0xf0 drivers/net/wireless/ath/ath6kl/usb.c:1055
ath6kl_hif_power_off drivers/net/wireless/ath/ath6kl/hif-ops.h:143 [inline]
ath6kl_core_init drivers/net/wireless/ath/ath6kl/core.c:255 [inline]
ath6kl_core_init+0x236/0x10d0 drivers/net/wireless/ath/ath6kl/core.c:66
ath6kl_usb_probe+0xc30/0x11d0 drivers/net/wireless/ath/ath6kl/usb.c:1155
usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:374
really_probe+0x291/0xc90 drivers/base/dd.c:525
driver_probe_device+0x26b/0x3d0 drivers/base/dd.c:701
__device_attach_driver+0x1d1/0x290 drivers/base/dd.c:807
bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
__device_attach+0x28d/0x430 drivers/base/dd.c:873
bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
device_add+0xb09/0x1b40 drivers/base/core.c:2680
usb_set_configuration+0xf05/0x18a0 drivers/usb/core/message.c:2032
usb_generic_driver_probe+0xba/0xf2 drivers/usb/core/generic.c:241
usb_probe_device+0xd9/0x250 drivers/usb/core/driver.c:272
really_probe+0x291/0xc90 drivers/base/dd.c:525
driver_probe_device+0x26b/0x3d0 drivers/base/dd.c:701
__device_attach_driver+0x1d1/0x290 drivers/base/dd.c:807
bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
__device_attach+0x28d/0x430 drivers/base/dd.c:873
bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
device_add+0xb09/0x1b40 drivers/base/core.c:2680
usb_new_device.cold+0x71d/0xfd4 drivers/usb/core/hub.c:2554
hub_port_connect drivers/usb/core/hub.c:5208 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5348 [inline]
port_event drivers/usb/core/hub.c:5494 [inline]
hub_event+0x2361/0x4390 drivers/usb/core/hub.c:5576
process_one_work+0x94c/0x15f0 kernel/workqueue.c:2269
worker_thread+0x64c/0x1120 kernel/workqueue.c:2415
kthread+0x392/0x470 kernel/kthread.c:291
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:293
INFO: task kworker/0:7:3122 blocked for more than 143 seconds.
Not tainted 5.8.0-rc3-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:7 D24656 3122 2 0x80004000
Workqueue: events request_firmware_work_func
Call Trace:
context_switch kernel/sched/core.c:3453 [inline]
__schedule+0x88a/0x1cb0 kernel/sched/core.c:4178
schedule+0xcd/0x2b0 kernel/sched/core.c:4253
schedule_preempt_disabled+0xc/0x20 kernel/sched/core.c:4312
__mutex_lock_common kernel/locking/mutex.c:1033 [inline]
__mutex_lock+0x3e2/0x10a0 kernel/locking/mutex.c:1103
device_lock include/linux/device.h:768 [inline]
ath9k_hif_usb_firmware_fail drivers/net/wireless/ath/ath9k/hif_usb.c:1108 [inline]
ath9k_hif_usb_firmware_cb+0x3ac/0x530 drivers/net/wireless/ath/ath9k/hif_usb.c:1241
request_firmware_work_func+0x126/0x250 drivers/base/firmware_loader/main.c:1001
process_one_work+0x94c/0x15f0 kernel/workqueue.c:2269
worker_thread+0x64c/0x1120 kernel/workqueue.c:2415
kthread+0x392/0x470 kernel/kthread.c:291
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:293

Showing all locks held in the system:
3 locks held by kworker/1:1/21:
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x82b/0x15f0 kernel/workqueue.c:2240
#1: ffff8881da317da8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x85f/0x15f0 kernel/workqueue.c:2244
#2: ffff8881d4439218 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#2: ffff8881d4439218 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c5/0x4390 drivers/usb/core/hub.c:5522
1 lock held by khungtaskd/23:
#0: ffffffff873124a0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x264 kernel/locking/lockdep.c:5779
3 locks held by kworker/1:2/68:
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x82b/0x15f0 kernel/workqueue.c:2240
#1: ffff8881d5b3fda8 ((work_completion)(&fw_work->work)){+.+.}-{0:0}, at: process_one_work+0x85f/0x15f0 kernel/workqueue.c:2244
#2: ffff8881d4531218 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#2: ffff8881d4531218 (&dev->mutex){....}-{3:3}, at: ath9k_hif_usb_firmware_fail drivers/net/wireless/ath/ath9k/hif_usb.c:1108 [inline]
#2: ffff8881d4531218 (&dev->mutex){....}-{3:3}, at: ath9k_hif_usb_firmware_cb+0x3ac/0x530 drivers/net/wireless/ath/ath9k/hif_usb.c:1241
1 lock held by in:imklog/244:
#0: ffff8881c8675270 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100 fs/file.c:826
2 locks held by agetty/252:
#0: ffff8881cfef0098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:267
#1: ffffc900009f62e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x223/0x1a30 drivers/tty/n_tty.c:2156
5 locks held by kworker/0:6/3087:
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x82b/0x15f0 kernel/workqueue.c:2240
#1: ffff8881c6627da8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x85f/0x15f0 kernel/workqueue.c:2244
#2: ffff8881d4471218 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#2: ffff8881d4471218 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c5/0x4390 drivers/usb/core/hub.c:5522
#3: ffff8881cd548218 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#3: ffff8881cd548218 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x430 drivers/base/dd.c:850
#4: ffff8881d22c31a8 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#4: ffff8881d22c31a8 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x430 drivers/base/dd.c:850
5 locks held by kworker/1:3/3121:
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x82b/0x15f0 kernel/workqueue.c:2240
#1: ffff8881cd83fda8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x85f/0x15f0 kernel/workqueue.c:2244
#2: ffff8881d44d1218 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#2: ffff8881d44d1218 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c5/0x4390 drivers/usb/core/hub.c:5522
#3: ffff8881d44d4588 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3012 [inline]
#3: ffff8881d44d4588 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5139 [inline]
#3: ffff8881d44d4588 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5348 [inline]
#3: ffff8881d44d4588 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5494 [inline]
#3: ffff8881d44d4588 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x217c/0x4390 drivers/usb/core/hub.c:5576
#4: ffff8881d4f69b68 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_init+0x1b6/0x2e80 drivers/usb/core/hub.c:4563
3 locks held by kworker/0:7/3122:
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff8881da028d38 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x82b/0x15f0 kernel/workqueue.c:2240
#1: ffff8881cd477da8 ((work_completion)(&fw_work->work)){+.+.}-{0:0}, at: process_one_work+0x85f/0x15f0 kernel/workqueue.c:2244
#2: ffff8881d4471218 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#2: ffff8881d4471218 (&dev->mutex){....}-{3:3}, at: ath9k_hif_usb_firmware_fail drivers/net/wireless/ath/ath9k/hif_usb.c:1108 [inline]
#2: ffff8881d4471218 (&dev->mutex){....}-{3:3}, at: ath9k_hif_usb_firmware_cb+0x3ac/0x530 drivers/net/wireless/ath/ath9k/hif_usb.c:1241
3 locks held by kworker/0:8/3125:
6 locks held by kworker/1:5/3225:
5 locks held by kworker/1:6/3235:
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff8881d88a6138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x82b/0x15f0 kernel/workqueue.c:2240
#1: ffff8881c90c7da8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x85f/0x15f0 kernel/workqueue.c:2244
#2: ffff8881d4491218 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:768 [inline]
#2: ffff8881d4491218 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c5/0x4390 drivers/usb/core/hub.c:5522
#3: ffff8881d4494588 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3012 [inline]
#3: ffff8881d4494588 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5139 [inline]
#3: ffff8881d4494588 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5348 [inline]
#3: ffff8881d4494588 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5494 [inline]
#3: ffff8881d4494588 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x217c/0x4390 drivers/usb/core/hub.c:5576
#4: ffff8881d4f54b68 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_init+0x1b6/0x2e80 drivers/usb/core/hub.c:4563
2 locks held by agetty/6439:
#0: ffff8881ce39d098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:267
#1: ffffc9000fc9d2e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x223/0x1a30 drivers/tty/n_tty.c:2156

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

NMI backtrace for cpu 0
CPU: 0 PID: 23 Comm: khungtaskd Not tainted 5.8.0-rc3-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+0xf6/0x16e lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x74/0xb6 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1da/0x1f4 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:209 [inline]
watchdog+0xd6a/0xfd0 kernel/hung_task.c:295
kthread+0x392/0x470 kernel/kthread.c:291
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:293
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 3235 Comm: kworker/1:6 Not tainted 5.8.0-rc3-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: usb_hub_wq hub_event
RIP: 0010:io_serial_in+0x60/0x80 drivers/tty/serial/8250/8250_port.c:447
Code: 0f b6 8d f1 00 00 00 48 8d 7d 40 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1 ea 03 d3 e3 80 3c 02 00 75 13 03 5d 40 89 da ec <5b> 0f b6 c0 5d c3 e8 c5 6a 42 ff eb c9 e8 ee 6a 42 ff eb e6 66 90
RSP: 0018:ffff8881c90c7418 EFLAGS: 00000002
RAX: dffffc0000000060 RBX: 00000000000003fd RCX: 0000000000000000
RDX: 00000000000003fd RSI: ffffffff8226e15c RDI: ffffffff8a2a3be0
RBP: ffffffff8a2a3ba0 R08: 0000000000000001 R09: 0000000000000003
R10: 000000000000000a R11: 0000000000000007 R12: 0000000000000020
R13: fffffbfff14547c6 R14: fffffbfff145477e R15: dffffc0000000000
FS: 0000000000000000(0000) GS:ffff8881db300000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f7a9b574000 CR3: 00000001c7596000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
serial_in drivers/tty/serial/8250/8250.h:113 [inline]
wait_for_xmitr+0x9a/0x210 drivers/tty/serial/8250/8250_port.c:2060
serial8250_console_putchar+0x1b/0x50 drivers/tty/serial/8250/8250_port.c:3197
uart_console_write+0x59/0x100 drivers/tty/serial/serial_core.c:1949
serial8250_console_write+0x8c5/0xa90 drivers/tty/serial/8250/8250_port.c:3269
call_console_drivers kernel/printk/printk.c:1816 [inline]
console_unlock+0x87a/0xcd0 kernel/printk/printk.c:2493
vprintk_emit+0x1b2/0x460 kernel/printk/printk.c:2021
dev_vprintk_emit+0x3eb/0x436 drivers/base/core.c:3883
dev_printk_emit+0xba/0xf1 drivers/base/core.c:3894
__dev_printk+0xcf/0xf5 drivers/base/core.c:3906
_dev_info+0xd7/0x109 drivers/base/core.c:3952
hub_port_init.cold+0x264/0x32f drivers/usb/core/hub.c:4628
hub_port_connect drivers/usb/core/hub.c:5140 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5348 [inline]
port_event drivers/usb/core/hub.c:5494 [inline]
hub_event+0x2191/0x4390 drivers/usb/core/hub.c:5576
process_one_work+0x94c/0x15f0 kernel/workqueue.c:2269
worker_thread+0x64c/0x1120 kernel/workqueue.c:2415
kthread+0x392/0x470 kernel/kthread.c:291
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:293


---
This bug 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 bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

[Tetsuo Handa]

Patch "ath6kl: avoid flush_scheduled_work() usage" at
https://git.kernel.org/pub/scm/linux/kernel/git/kvalo/ath.git/commit/?h=ath-next&id=62ebaf2f9261cd2367ae928a39343fcdbfe9f877
might be able to mitigate this problem, by reducing works to flush.
If this patch does not help, this problem might be nothing but overstressing...

[Tetsuo Handa]

I finally found why lockdep was not able to report this deadlock.
device_initialize() was hiding dev->mutex from lockdep tests.
I hope we can get rid of this lockdep_set_novalidate_class()...

Below is a reproducer kernel module. If request_firmware_nowait() called

INIT_WORK(&fw_work->work, request_firmware_work_func);
schedule_work(&fw_work->work);

before hub_event() calls

usb_lock_device(hdev);

, flush_scheduled_work() from hub_event() becomes responsible for flushing
fw_work->work. But flush_scheduled_work() can't flush fw_work->work because
dev->mutex is held by hub_event().

----------------------------------------
#include <linux/module.h>
#include <linux/sched.h>

static DEFINE_MUTEX(mutex);

static void request_firmware_work_func(struct work_struct *work)
{
schedule_timeout_uninterruptible(HZ); // inject race window for allowing hub_event() to find this work
mutex_lock(&mutex); // device_lock(parent) from ath9k_hif_usb_firmware_fail() waits for ath6kl_hif_power_off() to release dev->mutex
mutex_unlock(&mutex); // device_unlock(parent) from ath9k_hif_usb_firmware_fail()
}
static void hub_event(struct work_struct *work)
{
mutex_lock(&mutex); // usb_lock_device(hdev)
flush_scheduled_work(); // ath6kl_usb_flush_all() from ath6kl_hif_power_off() waits for request_firmware_work_func() while holding dev->mutex
mutex_unlock(&mutex); // usb_unlock_device(hdev)
}

static DECLARE_WORK(fw_work, request_firmware_work_func);
static DECLARE_WORK(hub_events, hub_event);

static int __init test_init(void)
{
lockdep_set_novalidate_class(&mutex); // device_initialize() suppresses lockdep warning
schedule_work(&fw_work); // request_firmware_nowait() from ath9k driver queues into system_wq
queue_work(system_freezable_wq, &hub_events); // kick_hub_wq() from usb code queues into hub_wq
return 0;
}

static void test_exit(void)
{
}

module_init(test_init);
module_exit(test_exit);
MODULE_LICENSE("GPL");
----------------------------------------

----------------------------------------
[ 38.832553][ T2786] test: loading out-of-tree module taints kernel.
[ 187.116969][ T35] INFO: task kworker/0:2:33 blocked for more than 143 seconds.
[ 187.121366][ T35] Tainted: G O 5.19.0-rc4-next-20220701 #43
[ 187.124830][ T35] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 187.128724][ T35] task:kworker/0:2 state:D stack: 0 pid: 33 ppid: 2 flags:0x00004000
[ 187.133235][ T35] Workqueue: events_freezable hub_event [test]
[ 187.136000][ T35] Call Trace:
[ 187.137512][ T35] <TASK>
[ 187.138863][ T35] __schedule+0x304/0x8f0
[ 187.140923][ T35] schedule+0x40/0xa0
[ 187.142940][ T35] schedule_timeout+0x300/0x3a0
[ 187.145341][ T35] ? mark_held_locks+0x55/0x80
[ 187.147518][ T35] ? wait_for_completion+0x6b/0x130
[ 187.149257][ T35] ? _raw_spin_unlock_irq+0x22/0x30
[ 187.151187][ T35] ? wait_for_completion+0x6b/0x130
[ 187.152915][ T35] ? trace_hardirqs_on+0x3b/0xd0
[ 187.154388][ T35] wait_for_completion+0x73/0x130
[ 187.155547][ T35] __flush_workqueue+0x17b/0x480
[ 187.156710][ T35] ? __mutex_lock+0x12b/0xe10
[ 187.157703][ T35] ? wait_for_completion+0x2d/0x130
[ 187.158837][ T35] hub_event+0x1e/0x30 [test]
[ 187.160286][ T35] ? hub_event+0x1e/0x30 [test]
[ 187.161352][ T35] process_one_work+0x292/0x570
[ 187.162565][ T35] worker_thread+0x2f/0x3d0
[ 187.163590][ T35] ? process_one_work+0x570/0x570
[ 187.164779][ T35] kthread+0xd6/0x100
[ 187.165940][ T35] ? kthread_complete_and_exit+0x20/0x20
[ 187.167077][ T35] ret_from_fork+0x1f/0x30
[ 187.168319][ T35] </TASK>
[ 187.169190][ T35] INFO: task kworker/0:3:54 blocked for more than 143 seconds.
[ 187.171458][ T35] Tainted: G O 5.19.0-rc4-next-20220701 #43
[ 187.173380][ T35] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 187.175359][ T35] task:kworker/0:3 state:D stack: 0 pid: 54 ppid: 2 flags:0x00004000
[ 187.177660][ T35] Workqueue: events request_firmware_work_func [test]
[ 187.179221][ T35] Call Trace:
[ 187.180381][ T35] <TASK>
[ 187.181170][ T35] __schedule+0x304/0x8f0
[ 187.182618][ T35] schedule+0x40/0xa0
[ 187.184207][ T35] schedule_preempt_disabled+0x10/0x20
[ 187.186318][ T35] __mutex_lock+0x650/0xe10
[ 187.188527][ T35] ? request_firmware_work_func+0x1c/0x30 [test]
[ 187.190094][ T35] mutex_lock_nested+0x16/0x20
[ 187.191905][ T35] ? mutex_lock_nested+0x16/0x20
[ 187.193159][ T35] request_firmware_work_func+0x1c/0x30 [test]
[ 187.194643][ T35] process_one_work+0x292/0x570
[ 187.195899][ T35] worker_thread+0x2f/0x3d0
[ 187.197031][ T35] ? process_one_work+0x570/0x570
[ 187.198489][ T35] kthread+0xd6/0x100
[ 187.199756][ T35] ? kthread_complete_and_exit+0x20/0x20
[ 187.201224][ T35] ret_from_fork+0x1f/0x30
[ 187.202374][ T35] </TASK>
[ 187.203293][ T35]
[ 187.203293][ T35] Showing all locks held in the system:
[ 187.205200][ T35] 1 lock held by rcu_tasks_trace/10:
[ 187.206489][ T35] #0: ffffffffb25bdea0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x28/0x3b0
[ 187.209383][ T35] 3 locks held by kworker/0:2/33:
[ 187.210930][ T35] #0: ffff9e2bc004d148 ((wq_completion)events_freezable){+.+.}-{0:0}, at: process_one_work+0x215/0x570
[ 187.214012][ T35] #1: ffffac448032fe68 (hub_events){+.+.}-{0:0}, at: process_one_work+0x215/0x570
[ 187.217162][ T35] #2: ffffffffc067b130 (&dev->mutex){....}-{3:3}, at: hub_event+0x12/0x30 [test]
[ 187.220277][ T35] 1 lock held by khungtaskd/35:
[ 187.221592][ T35] #0: ffffffffb25be5c0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire.constprop.56+0x0/0x30
[ 187.224310][ T35] 3 locks held by kworker/0:3/54:
[ 187.225596][ T35] #0: ffff9e2bc004cb48 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x215/0x570
[ 187.228147][ T35] #1: ffffac4480cebe68 (fw_work){+.+.}-{0:0}, at: process_one_work+0x215/0x570
[ 187.230646][ T35] #2: ffffffffc067b130 (&dev->mutex){....}-{3:3}, at: request_firmware_work_func+0x1c/0x30 [test]
[ 187.234203][ T35] 2 locks held by agetty/2729:
[ 187.235463][ T35] #0: ffff9e2bc71740a0 (&tty->ldisc_sem){++++}-{0:0}, at: ldsem_down_read+0xe/0x10
[ 187.237864][ T35] #1: ffffac448229f2f8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x168/0x5f0
[ 187.240571][ T35] 2 locks held by agetty/2731:
[ 187.241876][ T35] #0: ffff9e2bc907b8a0 (&tty->ldisc_sem){++++}-{0:0}, at: ldsem_down_read+0xe/0x10
[ 187.244312][ T35] #1: ffffac44822a72f8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x168/0x5f0
[ 187.246938][ T35]
[ 187.247756][ T35] =============================================
[ 187.247756][ T35]
----------------------------------------

#syz fix: ath6kl: avoid flush_scheduled_work() usage