syzbot


inconsistent lock state in snd_timer_interrupt (2)

Status: fixed on 2024/04/11 14:16
Subsystems: sound
[Documentation on labels]
Fix commit: 587d67fd929a ALSA: timer: Fix missing irq-disable at closing
First crash: 20d, last: 18d
Cause bisection: introduced by (bisect log) :
commit beb45974dd49068b24788bbfc2abe20d50503761
Author: Takashi Iwai <tiwai@suse.de>
Date: Tue Feb 27 08:52:45 2024 +0000

  ALSA: timer: Use guard() for locking

Crash: inconsistent lock state in snd_timer_interrupt (log)
Repro: C syz .config
  
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream inconsistent lock state in snd_timer_interrupt (3) sound C 710 14d 18d 26/26 fixed on 2024/04/22 10:23
upstream inconsistent lock state in snd_timer_interrupt sound C 1927 20d 42d 26/26 fixed on 2024/04/10 03:59

Sample crash report:
================================
WARNING: inconsistent lock state
6.8.0-syzkaller-08951-gfe46a7dd189e #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
syz-executor350/5081 [HC0[0]:SC1[1]:HE0:SE0] takes:
ffff888029a37948 (&timer->lock){+.?.}-{2:2}, at: class_spinlock_irqsave_constructor include/linux/spinlock.h:574 [inline]
ffff888029a37948 (&timer->lock){+.?.}-{2:2}, at: snd_timer_interrupt.part.0+0x31/0xd80 sound/core/timer.c:818
{SOFTIRQ-ON-W} state was registered at:
  lock_acquire kernel/locking/lockdep.c:5754 [inline]
  lock_acquire+0x1b1/0x540 kernel/locking/lockdep.c:5719
  __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:561 [inline]
  snd_timer_close_locked+0x65/0xbd0 sound/core/timer.c:412
  snd_timer_close+0x8b/0xf0 sound/core/timer.c:464
  snd_timer_user_release+0x91/0x260 sound/core/timer.c:1468
  __fput+0x273/0xb80 fs/file_table.c:422
  task_work_run+0x151/0x250 kernel/task_work.c:180
  exit_task_work include/linux/task_work.h:38 [inline]
  do_exit+0xa7d/0x2be0 kernel/exit.c:878
  do_group_exit+0xd3/0x2a0 kernel/exit.c:1027
  __do_sys_exit_group kernel/exit.c:1038 [inline]
  __se_sys_exit_group kernel/exit.c:1036 [inline]
  __x64_sys_exit_group+0x3e/0x50 kernel/exit.c:1036
  do_syscall_x64 arch/x86/entry/common.c:52 [inline]
  do_syscall_64+0xd5/0x260 arch/x86/entry/common.c:83
  entry_SYSCALL_64_after_hwframe+0x6d/0x75
irq event stamp: 1029
hardirqs last  enabled at (1028): [<ffffffff8ad6ef43>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:159 [inline]
hardirqs last  enabled at (1028): [<ffffffff8ad6ef43>] _raw_spin_unlock_irq+0x23/0x50 kernel/locking/spinlock.c:202
hardirqs last disabled at (1029): [<ffffffff8ad6ece2>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (1029): [<ffffffff8ad6ece2>] _raw_spin_lock_irqsave+0x52/0x60 kernel/locking/spinlock.c:162
softirqs last  enabled at (428): [<ffffffff8132e1d3>] local_bh_enable include/linux/bottom_half.h:33 [inline]
softirqs last  enabled at (428): [<ffffffff8132e1d3>] fpregs_unlock arch/x86/include/asm/fpu/api.h:80 [inline]
softirqs last  enabled at (428): [<ffffffff8132e1d3>] fpu_clone+0x393/0xb60 arch/x86/kernel/fpu/core.c:634
softirqs last disabled at (1025): [<ffffffff8152e549>] invoke_softirq kernel/softirq.c:428 [inline]
softirqs last disabled at (1025): [<ffffffff8152e549>] __irq_exit_rcu kernel/softirq.c:633 [inline]
softirqs last disabled at (1025): [<ffffffff8152e549>] irq_exit_rcu+0xb9/0x120 kernel/softirq.c:645

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

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

 *** DEADLOCK ***

3 locks held by syz-executor350/5081:
 #0: ffffffff8d40a098 (tasklist_lock){.+.+}-{2:2}, at: __do_wait+0x105/0x890 kernel/exit.c:1587
 #1: ffffffff8d7b49e0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:298 [inline]
 #1: ffffffff8d7b49e0 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:750 [inline]
 #1: ffffffff8d7b49e0 (rcu_read_lock){....}-{1:2}, at: __task_pid_nr_ns+0x39/0x500 kernel/pid.c:510
 #2: ffffc90000a08cb0 ((&priv->tlist)){+.-.}-{0:0}, at: call_timer_fn+0x11a/0x5b0 kernel/time/timer.c:1789

stack backtrace:
CPU: 1 PID: 5081 Comm: syz-executor350 Not tainted 6.8.0-syzkaller-08951-gfe46a7dd189e #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/27/2024
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:114
 print_usage_bug kernel/locking/lockdep.c:3971 [inline]
 valid_state kernel/locking/lockdep.c:4013 [inline]
 mark_lock_irq kernel/locking/lockdep.c:4216 [inline]
 mark_lock+0x923/0xc60 kernel/locking/lockdep.c:4678
 mark_usage kernel/locking/lockdep.c:4567 [inline]
 __lock_acquire+0x13d4/0x3b30 kernel/locking/lockdep.c:5091
 lock_acquire kernel/locking/lockdep.c:5754 [inline]
 lock_acquire+0x1b1/0x540 kernel/locking/lockdep.c:5719
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0x3a/0x60 kernel/locking/spinlock.c:162
 class_spinlock_irqsave_constructor include/linux/spinlock.h:574 [inline]
 snd_timer_interrupt.part.0+0x31/0xd80 sound/core/timer.c:818
 snd_timer_interrupt sound/core/timer.c:1107 [inline]
 snd_timer_s_function+0x14f/0x200 sound/core/timer.c:1107
 call_timer_fn+0x1a3/0x5b0 kernel/time/timer.c:1792
 expire_timers kernel/time/timer.c:1843 [inline]
 __run_timers+0x74b/0xab0 kernel/time/timer.c:2408
 __run_timer_base kernel/time/timer.c:2419 [inline]
 __run_timer_base kernel/time/timer.c:2412 [inline]
 run_timer_base+0x111/0x190 kernel/time/timer.c:2428
 run_timer_softirq+0x1a/0x40 kernel/time/timer.c:2438
 __do_softirq+0x21b/0x8de kernel/softirq.c:554
 invoke_softirq kernel/softirq.c:428 [inline]
 __irq_exit_rcu kernel/softirq.c:633 [inline]
 irq_exit_rcu+0xb9/0x120 kernel/softirq.c:645
 instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
 sysvec_apic_timer_interrupt+0x95/0xb0 arch/x86/kernel/apic/apic.c:1043
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
RIP: 0010:lock_is_held_type+0x107/0x150 kernel/locking/lockdep.c:5830
Code: 00 00 b8 ff ff ff ff 65 0f c1 05 4c 56 2f 75 83 f8 01 75 2d 9c 58 f6 c4 02 75 43 48 f7 04 24 00 02 00 00 74 01 fb 48 83 c4 08 <44> 89 e8 5b 5d 41 5c 41 5d 41 5e 41 5f e9 b7 f2 03 00 45 31 ed eb
RSP: 0018:ffffc900087efaa0 EFLAGS: 00000296
RAX: 0000000000000046 RBX: ffff888022564700 RCX: 0000000000000001
RDX: 0000000000000000 RSI: ffffffff8b0ccb80 RDI: ffffffff8b6eb4e0
RBP: ffffffff8d7b49e0 R08: 0000000000000005 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000001 R12: ffff888022563c00
R13: 0000000000000001 R14: 00000000ffffffff R15: 0000000000000001
 __task_pid_nr_ns+0x2e7/0x500 kernel/pid.c:513
 task_pid_vnr include/linux/pid.h:242 [inline]
 wait_task_zombie kernel/exit.c:1085 [inline]
 wait_consider_task+0x12ce/0x4150 kernel/exit.c:1416
 do_wait_thread kernel/exit.c:1479 [inline]
 __do_wait+0x1e2/0x890 kernel/exit.c:1597
 do_wait+0x219/0x540 kernel/exit.c:1631
 kernel_wait4+0x16c/0x280 kernel/exit.c:1790
 __do_sys_wait4+0x15f/0x170 kernel/exit.c:1818
 do_syscall_x64 arch/x86/entry/common.c:52 [inline]
 do_syscall_64+0xd5/0x260 arch/x86/entry/common.c:83
 entry_SYSCALL_64_after_hwframe+0x6d/0x75
RIP: 0033:0x7ffa8af9f5b3
Code: fe ff e9 41 ff ff ff 31 c9 e9 09 00 00 00 66 0f 1f 84 00 00 00 00 00 80 3d b1 9a 07 00 00 49 89 ca 74 14 b8 3d 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 5d c3 0f 1f 40 00 48 83 ec 28 89 54 24 14 48
RSP: 002b:00007ffcd221f748 EFLAGS: 00000202 ORIG_RAX: 000000000000003d
RAX: ffffffffffffffda RBX: 00000000000013dc RCX: 00007ffa8af9f5b3
RDX: 0000000040000001 RSI: 00007ffcd221f75c RDI: 00000000ffffffff
RBP: 00000000000f4240 R08: 0000000000000070 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000202 R12: 000000000001b601
R13: 00007ffcd221f75c R14: 00007ffcd221f770 R15: 00007ffcd221f760
 </TASK>
----------------
Code disassembly (best guess):
   0:	00 00                	add    %al,(%rax)
   2:	b8 ff ff ff ff       	mov    $0xffffffff,%eax
   7:	65 0f c1 05 4c 56 2f 	xadd   %eax,%gs:0x752f564c(%rip)        # 0x752f565b
   e:	75
   f:	83 f8 01             	cmp    $0x1,%eax
  12:	75 2d                	jne    0x41
  14:	9c                   	pushf
  15:	58                   	pop    %rax
  16:	f6 c4 02             	test   $0x2,%ah
  19:	75 43                	jne    0x5e
  1b:	48 f7 04 24 00 02 00 	testq  $0x200,(%rsp)
  22:	00
  23:	74 01                	je     0x26
  25:	fb                   	sti
  26:	48 83 c4 08          	add    $0x8,%rsp
* 2a:	44 89 e8             	mov    %r13d,%eax <-- trapping instruction
  2d:	5b                   	pop    %rbx
  2e:	5d                   	pop    %rbp
  2f:	41 5c                	pop    %r12
  31:	41 5d                	pop    %r13
  33:	41 5e                	pop    %r14
  35:	41 5f                	pop    %r15
  37:	e9 b7 f2 03 00       	jmp    0x3f2f3
  3c:	45 31 ed             	xor    %r13d,%r13d
  3f:	eb                   	.byte 0xeb

Crashes (208):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2024/04/10 07:37 upstream fe46a7dd189e 56086b24 .config strace log report syz C [disk image] [vmlinux] [kernel image] ci-upstream-kasan-badwrites-root inconsistent lock state in snd_timer_interrupt
2024/04/10 07:06 upstream fe46a7dd189e 56086b24 .config strace log report syz C [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 14:04 upstream fe46a7dd189e 478efa7f .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 13:57 upstream fe46a7dd189e 478efa7f .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 07:53 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 06:52 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 06:13 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 05:01 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 04:44 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 03:43 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-badwrites-root inconsistent lock state in snd_timer_interrupt
2024/04/11 02:59 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 01:47 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/11 00:49 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 23:45 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 23:31 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 22:30 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 21:24 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 21:01 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 19:47 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 16:03 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 15:01 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 14:07 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:55 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:48 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-badwrites-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:41 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-badwrites-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:26 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:18 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:07 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:07 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 12:07 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:56 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:46 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-badwrites-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:36 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:30 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:30 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:29 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:12 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:12 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 11:12 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 10:48 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 10:47 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 10:29 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 10:29 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 10:22 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
2024/04/10 10:15 upstream fe46a7dd189e 56086b24 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-selinux-root inconsistent lock state in snd_timer_interrupt
* Struck through repros no longer work on HEAD.