[syzbot] [sound?] BUG: sleeping function called from invalid context in snd_card_locked

[syzbot <syzbot+4cb9fad083898f54c517@syzkaller.appspotmail.com>]

Hello,

syzbot found the following issue on:

HEAD commit:    d082ecbc71e9 Linux 6.14-rc4
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=14e3d7a4580000
kernel config:  https://syzkaller.appspot.com/x/.config?x=8f2f8fb6ad08b539
dashboard link: https://syzkaller.appspot.com/bug?extid=4cb9fad083898f54c517
compiler:       gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40

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

Downloadable assets:
disk image (non-bootable): https://storage.googleapis.com/syzbot-assets/7feb34a89c2a/non_bootable_disk-d082ecbc.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/f7cfa9bd3468/vmlinux-d082ecbc.xz
kernel image: https://storage.googleapis.com/syzbot-assets/d47dd7c3fc5d/bzImage-d082ecbc.xz

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

BUG: sleeping function called from invalid context at kernel/locking/mutex.c:562
in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 1167, name: kworker/0:1H
preempt_count: 0, expected: 0
RCU nest depth: 0, expected: 0
2 locks held by kworker/0:1H/1167:
 #0: ffff88801b089148 ((wq_completion)events_highpri){+.+.}-{0:0}, at: process_one_work+0x1293/0x1ba0 kernel/workqueue.c:3211
 #1: ffffc900061f7d18 ((work_completion)(&timer->task_work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3212
irq event stamp: 1044
hardirqs last  enabled at (1043): [<ffffffff8b59c523>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:159 [inline]
hardirqs last  enabled at (1043): [<ffffffff8b59c523>] _raw_spin_unlock_irq+0x23/0x50 kernel/locking/spinlock.c:202
hardirqs last disabled at (1044): [<ffffffff8b59c2c2>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (1044): [<ffffffff8b59c2c2>] _raw_spin_lock_irqsave+0x52/0x60 kernel/locking/spinlock.c:162
softirqs last  enabled at (204): [<ffffffff817c131b>] softirq_handle_end kernel/softirq.c:407 [inline]
softirqs last  enabled at (204): [<ffffffff817c131b>] handle_softirqs+0x5bb/0x8f0 kernel/softirq.c:589
softirqs last disabled at (183): [<ffffffff817c17e9>] __do_softirq kernel/softirq.c:595 [inline]
softirqs last disabled at (183): [<ffffffff817c17e9>] invoke_softirq kernel/softirq.c:435 [inline]
softirqs last disabled at (183): [<ffffffff817c17e9>] __irq_exit_rcu+0x109/0x170 kernel/softirq.c:662
CPU: 0 UID: 0 PID: 1167 Comm: kworker/0:1H Not tainted 6.14.0-rc4-syzkaller #0
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.3-debian-1.16.3-2~bpo12+1 04/01/2014
Workqueue: events_highpri snd_timer_work
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:94 [inline]
 dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:120
 __might_resched+0x3c0/0x5e0 kernel/sched/core.c:8767
 __mutex_lock_common kernel/locking/mutex.c:562 [inline]
 __mutex_lock+0x108/0xb10 kernel/locking/mutex.c:730
 class_mutex_constructor include/linux/mutex.h:201 [inline]
 snd_card_locked+0x1b/0x60 sound/core/init.c:399
 snd_request_card+0x14/0x70 sound/core/sound.c:62
 snd_seq_client_use_ptr+0x375/0x3c0 sound/core/seq/seq_clientmgr.c:152
 get_event_dest_client sound/core/seq/seq_clientmgr.c:533 [inline]
 snd_seq_deliver_single_event+0xdb/0x6e0 sound/core/seq/seq_clientmgr.c:663
 snd_seq_deliver_event+0x291/0x4b0 sound/core/seq/seq_clientmgr.c:822
 snd_seq_dispatch_event+0x117/0x580 sound/core/seq/seq_clientmgr.c:897
 snd_seq_check_queue+0x248/0x510 sound/core/seq/seq_queue.c:256
 snd_seq_timer_interrupt+0x2e3/0x390 sound/core/seq/seq_timer.c:153
 snd_timer_process_callbacks+0x217/0x2e0 sound/core/timer.c:785
 snd_timer_work+0xa9/0x100 sound/core/timer.c:815
 process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3236
 process_scheduled_works kernel/workqueue.c:3317 [inline]
 worker_thread+0x6c8/0xf00 kernel/workqueue.c:3398
 kthread+0x3af/0x750 kernel/kthread.c:464
 ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:148
 ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
 </TASK>

================================
WARNING: inconsistent lock state
6.14.0-rc4-syzkaller #0 Tainted: G        W         
--------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
kworker/0:1H/1167 [HC0[0]:SC0[0]:HE1:SE1] takes:
ffff8880236dc148 (&timer->lock){?.-.}-{3:3}, at: spin_lock include/linux/spinlock.h:351 [inline]
ffff8880236dc148 (&timer->lock){?.-.}-{3:3}, at: snd_timer_process_callbacks+0x227/0x2e0 sound/core/timer.c:786
{IN-HARDIRQ-W} state was registered at:
  lock_acquire.part.0+0x11b/0x380 kernel/locking/lockdep.c:5851
  __raw_spin_lock include/linux/spinlock_api_smp.h:133 [inline]
  _raw_spin_lock+0x2e/0x40 kernel/locking/spinlock.c:154
  spin_lock include/linux/spinlock.h:351 [inline]
  class_spinlock_constructor include/linux/spinlock.h:559 [inline]
  snd_hrtimer_callback+0x53/0x400 sound/core/hrtimer.c:38
  __run_hrtimer kernel/time/hrtimer.c:1801 [inline]
  __hrtimer_run_queues+0x20a/0xae0 kernel/time/hrtimer.c:1865
  hrtimer_interrupt+0x392/0x8e0 kernel/time/hrtimer.c:1927
  local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1038 [inline]
  __sysvec_apic_timer_interrupt+0x10f/0x400 arch/x86/kernel/apic/apic.c:1055
  instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1049 [inline]
  sysvec_apic_timer_interrupt+0x9f/0xc0 arch/x86/kernel/apic/apic.c:1049
  asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
  __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:151 [inline]
  _raw_spin_unlock_irqrestore+0x31/0x80 kernel/locking/spinlock.c:194
  class_raw_spinlock_irqsave_destructor include/linux/spinlock.h:551 [inline]
  try_to_wake_up+0x949/0x1490 kernel/sched/core.c:4214
  wake_up_process kernel/sched/core.c:4463 [inline]
  wake_up_q+0x9c/0x160 kernel/sched/core.c:1075
  raw_spin_unlock_irqrestore_wake include/linux/sched/wake_q.h:96 [inline]
  __mutex_unlock_slowpath+0x231/0x6a0 kernel/locking/mutex.c:933
  device_unlock include/linux/device.h:1045 [inline]
  hub_event+0xc5f/0x4e10 drivers/usb/core/hub.c:5954
  process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3236
  process_scheduled_works kernel/workqueue.c:3317 [inline]
  worker_thread+0x6c8/0xf00 kernel/workqueue.c:3398
  kthread+0x3af/0x750 kernel/kthread.c:464
  ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:148
  ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
irq event stamp: 1197
hardirqs last  enabled at (1197): [<ffffffff8b59c5b2>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:151 [inline]
hardirqs last  enabled at (1197): [<ffffffff8b59c5b2>] _raw_spin_unlock_irqrestore+0x52/0x80 kernel/locking/spinlock.c:194
hardirqs last disabled at (1196): [<ffffffff8b59c2c2>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (1196): [<ffffffff8b59c2c2>] _raw_spin_lock_irqsave+0x52/0x60 kernel/locking/spinlock.c:162
softirqs last  enabled at (1156): [<ffffffff817c131b>] softirq_handle_end kernel/softirq.c:407 [inline]
softirqs last  enabled at (1156): [<ffffffff817c131b>] handle_softirqs+0x5bb/0x8f0 kernel/softirq.c:589
softirqs last disabled at (1047): [<ffffffff817c17e9>] __do_softirq kernel/softirq.c:595 [inline]
softirqs last disabled at (1047): [<ffffffff817c17e9>] invoke_softirq kernel/softirq.c:435 [inline]
softirqs last disabled at (1047): [<ffffffff817c17e9>] __irq_exit_rcu+0x109/0x170 kernel/softirq.c:662

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(&timer->lock);
  <Interrupt>
    lock(&timer->lock);

 *** DEADLOCK ***

2 locks held by kworker/0:1H/1167:
 #0: ffff88801b089148 ((wq_completion)events_highpri){+.+.}-{0:0}, at: process_one_work+0x1293/0x1ba0 kernel/workqueue.c:3211
 #1: ffffc900061f7d18 ((work_completion)(&timer->task_work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3212

stack backtrace:
CPU: 0 UID: 0 PID: 1167 Comm: kworker/0:1H Tainted: G        W          6.14.0-rc4-syzkaller #0
Tainted: [W]=WARN
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.3-debian-1.16.3-2~bpo12+1 04/01/2014
Workqueue: events_highpri snd_timer_work
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:94 [inline]
 dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:120
 print_usage_bug.part.0+0x3fb/0x680 kernel/locking/lockdep.c:4040
 print_usage_bug kernel/locking/lockdep.c:4008 [inline]
 valid_state kernel/locking/lockdep.c:4054 [inline]
 mark_lock_irq kernel/locking/lockdep.c:4265 [inline]
 mark_lock+0x92d/0xc60 kernel/locking/lockdep.c:4751
 mark_usage kernel/locking/lockdep.c:4660 [inline]
 __lock_acquire+0x98e/0x3c40 kernel/locking/lockdep.c:5182
 lock_acquire.part.0+0x11b/0x380 kernel/locking/lockdep.c:5851
 __raw_spin_lock include/linux/spinlock_api_smp.h:133 [inline]
 _raw_spin_lock+0x2e/0x40 kernel/locking/spinlock.c:154
 spin_lock include/linux/spinlock.h:351 [inline]
 snd_timer_process_callbacks+0x227/0x2e0 sound/core/timer.c:786
 snd_timer_work+0xa9/0x100 sound/core/timer.c:815
 process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3236
 process_scheduled_works kernel/workqueue.c:3317 [inline]
 worker_thread+0x6c8/0xf00 kernel/workqueue.c:3398
 kthread+0x3af/0x750 kernel/kthread.c:464
 ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:148
 ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
 </TASK>
------------[ cut here ]------------
raw_local_irq_restore() called with IRQs enabled
WARNING: CPU: 0 PID: 1167 at kernel/locking/irqflag-debug.c:10 warn_bogus_irq_restore+0x29/0x30 kernel/locking/irqflag-debug.c:10
Modules linked in:
CPU: 0 UID: 0 PID: 1167 Comm: kworker/0:1H Tainted: G        W          6.14.0-rc4-syzkaller #0
Tainted: [W]=WARN
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.3-debian-1.16.3-2~bpo12+1 04/01/2014
Workqueue: events_highpri snd_timer_work
RIP: 0010:warn_bogus_irq_restore+0x29/0x30 kernel/locking/irqflag-debug.c:10
Code: 90 f3 0f 1e fa 90 80 3d f9 a7 f3 04 00 74 06 90 c3 cc cc cc cc c6 05 ea a7 f3 04 01 90 48 c7 c7 c0 e6 6c 8b e8 58 df 22 f6 90 <0f> 0b 90 90 eb df 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90
RSP: 0018:ffffc900061f7c18 EFLAGS: 00010282
RAX: 0000000000000000 RBX: ffff8880236dc130 RCX: ffffffff817a1229
RDX: ffff888028238000 RSI: ffffffff817a1236 RDI: 0000000000000001
RBP: 0000000000000286 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000000 R11: 61636f6c5f776172 R12: ffff8880236dc000
R13: ffff8880236dc1b0 R14: 0000000000000000 R15: ffff88801b09d800
FS:  0000000000000000(0000) GS:ffff88806a600000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fecdd000218 CR3: 0000000031f9c000 CR4: 0000000000352ef0
DR0: 0000000000000002 DR1: fffffffffffffffb DR2: 0000000000010001
DR3: 0000000000000004 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <TASK>
 __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:151 [inline]
 _raw_spin_unlock_irqrestore+0x74/0x80 kernel/locking/spinlock.c:194
 spin_unlock_irqrestore include/linux/spinlock.h:406 [inline]
 class_spinlock_irqsave_destructor include/linux/spinlock.h:572 [inline]
 snd_timer_work+0xbe/0x100 sound/core/timer.c:814
 process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3236
 process_scheduled_works kernel/workqueue.c:3317 [inline]
 worker_thread+0x6c8/0xf00 kernel/workqueue.c:3398
 kthread+0x3af/0x750 kernel/kthread.c:464
 ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:148
 ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
 </TASK>


---
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 syzkaller@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

If the report is already addressed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want to overwrite report's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the report is a duplicate of another one, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup