syzbot


possible deadlock in lock_timer_base

Status: upstream: reported C repro on 2023/05/25 21:57
Reported-by: syzbot+557afc3253b6c451257a@syzkaller.appspotmail.com
First crash: 308d, last: 12h06m
Fix bisection: failed (error log, bisect log)
  
Bug presence (1)
Date Name Commit Repro Result
2024/03/19 upstream (ToT) b3603fcb79b1 C Failed due to an error; will retry later
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
linux-6.1 possible deadlock in lock_timer_base C inconclusive 15 2d16h 285d 0/3 upstream: reported C repro on 2023/06/17 18:14
upstream possible deadlock in lock_timer_base batman bpf C 40 2h03m 1181d 1/26 upstream: reported C repro on 2021/01/03 06:59
Fix bisection attempts (4)
Created Duration User Patch Repo Result
2024/03/19 04:08 1m fix candidate upstream error job log (0)
2024/01/05 05:45 0m fix candidate upstream error job log (0)
2023/10/30 17:37 0m fix candidate upstream error job log (0)
2023/10/14 07:00 0m bisect fix linux-5.15.y error job log (0)

Sample crash report:
=====================================================
WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
5.15.152-syzkaller #0 Not tainted
-----------------------------------------------------
kworker/1:0/21 [HC0[0]:SC0[2]:HE0:SE0] is trying to acquire:
ffff8880764928d8 (&htab->buckets[i].lock){+...}-{2:2}, at: sock_hash_delete_elem+0xac/0x2f0 net/core/sock_map.c:937

and this task is already holding:
ffff8880b9b28098
 (&base->lock){-.-.}-{2:2}, at: lock_timer_base+0x120/0x260 kernel/time/timer.c:946
which would create a new lock dependency:
 (
&base->lock){-.-.}-{2:2} -> (&htab->buckets[i].lock){+...}-{2:2}

but this new dependency connects a HARDIRQ-irq-safe lock:
 (&base->lock){-.-.}-{2:2}

... which became HARDIRQ-irq-safe at:
  lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
  __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
  _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
  lock_timer_base+0x120/0x260 kernel/time/timer.c:946
  add_timer_on+0x1eb/0x580 kernel/time/timer.c:1169
  handle_irq_event_percpu kernel/irq/handle.c:198 [inline]
  handle_irq_event+0x124/0x2b0 kernel/irq/handle.c:213
  handle_edge_irq+0x245/0xbf0 kernel/irq/chip.c:822
  generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
  handle_irq arch/x86/kernel/irq.c:231 [inline]
  __common_interrupt+0xd7/0x1f0 arch/x86/kernel/irq.c:250
  common_interrupt+0x9f/0xc0 arch/x86/kernel/irq.c:240
  asm_common_interrupt+0x22/0x40 arch/x86/include/asm/idtentry.h:629
  console_unlock+0xe53/0x12b0 kernel/printk/printk.c:2743
  vprintk_emit+0xbf/0x150 kernel/printk/printk.c:2268
  _printk+0xd1/0x111 kernel/printk/printk.c:2293
  spectre_v2_select_mitigation+0x4b9/0x748 arch/x86/kernel/cpu/bugs.c:1626
  cpu_select_mitigations+0x3d/0x8f arch/x86/kernel/cpu/bugs.c:151
  arch_cpu_finalize_init+0xf/0x81 arch/x86/kernel/cpu/common.c:2253
  start_kernel+0x419/0x535 init/main.c:1104
  secondary_startup_64_no_verify+0xb1/0xbb

to a HARDIRQ-irq-unsafe lock:
 (&htab->buckets[i].lock){+...}-{2:2}

... which became HARDIRQ-irq-unsafe at:
...
  lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
  __raw_spin_lock_bh include/linux/spinlock_api_smp.h:135 [inline]
  _raw_spin_lock_bh+0x31/0x40 kernel/locking/spinlock.c:178
  sock_hash_free+0x14c/0x780 net/core/sock_map.c:1154
  process_one_work+0x8a1/0x10c0 kernel/workqueue.c:2310
  worker_thread+0xaca/0x1280 kernel/workqueue.c:2457
  kthread+0x3f6/0x4f0 kernel/kthread.c:319
  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:298

other info that might help us debug this:

 Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&htab->buckets[i].lock
);
                               local_irq_disable();
                               lock(&base->lock);
                               lock(
&htab->buckets[i].lock);
  <Interrupt>
    lock(&base->lock);

 *** DEADLOCK ***

4 locks held by kworker/1:0/21:
 #0: ffff888011c72138
 ((wq_completion)rcu_gp
){+.+.}-{0:0}
, at: process_one_work+0x78a/0x10c0 kernel/workqueue.c:2283
 #1: ffffc90000db7d20 ((work_completion)(&rew.rew_work)){+.+.}-{0:0}
, at: process_one_work+0x7d0/0x10c0 kernel/workqueue.c:2285
 #2: ffff8880b9b28098
 (&base->lock){-.-.}-{2:2}, at: lock_timer_base+0x120/0x260 kernel/time/timer.c:946
 #3: ffffffff8c91f720 (rcu_read_lock){....}-{1:2}
, at: rcu_lock_acquire+0x5/0x30 include/linux/rcupdate.h:268

the dependencies between HARDIRQ-irq-safe lock and the holding lock:
-> (&base->lock){-.-.}-{2:2} {
   IN-HARDIRQ-W at:
                    lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
                    __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
                    _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
                    lock_timer_base+0x120/0x260 kernel/time/timer.c:946
                    add_timer_on+0x1eb/0x580 kernel/time/timer.c:1169
                    handle_irq_event_percpu kernel/irq/handle.c:198 [inline]
                    handle_irq_event+0x124/0x2b0 kernel/irq/handle.c:213
                    handle_edge_irq+0x245/0xbf0 kernel/irq/chip.c:822
                    generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
                    handle_irq arch/x86/kernel/irq.c:231 [inline]
                    __common_interrupt+0xd7/0x1f0 arch/x86/kernel/irq.c:250
                    common_interrupt+0x9f/0xc0 arch/x86/kernel/irq.c:240
                    asm_common_interrupt+0x22/0x40 arch/x86/include/asm/idtentry.h:629
                    console_unlock+0xe53/0x12b0 kernel/printk/printk.c:2743
                    vprintk_emit+0xbf/0x150 kernel/printk/printk.c:2268
                    _printk+0xd1/0x111 kernel/printk/printk.c:2293
                    spectre_v2_select_mitigation+0x4b9/0x748 arch/x86/kernel/cpu/bugs.c:1626
                    cpu_select_mitigations+0x3d/0x8f arch/x86/kernel/cpu/bugs.c:151
                    arch_cpu_finalize_init+0xf/0x81 arch/x86/kernel/cpu/common.c:2253
                    start_kernel+0x419/0x535 init/main.c:1104
                    secondary_startup_64_no_verify+0xb1/0xbb
   IN-SOFTIRQ-W at:
                    lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
                    __raw_spin_lock_irq include/linux/spinlock_api_smp.h:128 [inline]
                    _raw_spin_lock_irq+0xcf/0x110 kernel/locking/spinlock.c:170
                    __run_timers+0x111/0x890 kernel/time/timer.c:1719
                    run_timer_softirq+0x63/0xf0 kernel/time/timer.c:1750
                    __do_softirq+0x3b3/0x93a kernel/softirq.c:558
                    invoke_softirq kernel/softirq.c:432 [inline]
                    __irq_exit_rcu+0x155/0x240 kernel/softirq.c:637
                    irq_exit_rcu+0x5/0x20 kernel/softirq.c:649
                    common_interrupt+0xa4/0xc0 arch/x86/kernel/irq.c:240
                    asm_common_interrupt+0x22/0x40 arch/x86/include/asm/idtentry.h:629
                    console_unlock+0xe53/0x12b0 kernel/printk/printk.c:2743
                    vprintk_emit+0xbf/0x150 kernel/printk/printk.c:2268
                    _printk+0xd1/0x111 kernel/printk/printk.c:2293
                    cpu_select_mitigations+0x56/0x8f arch/x86/kernel/cpu/bugs.c:166
                    arch_cpu_finalize_init+0xf/0x81 arch/x86/kernel/cpu/common.c:2253
                    start_kernel+0x419/0x535 init/main.c:1104
                    secondary_startup_64_no_verify+0xb1/0xbb
   INITIAL USE at:
                   lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
                   __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
                   _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
                   lock_timer_base+0x120/0x260 kernel/time/timer.c:946
                   add_timer_on+0x1eb/0x580 kernel/time/timer.c:1169
                   handle_irq_event_percpu kernel/irq/handle.c:198 [inline]
                   handle_irq_event+0x124/0x2b0 kernel/irq/handle.c:213
                   handle_edge_irq+0x245/0xbf0 kernel/irq/chip.c:822
                   generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
                   handle_irq arch/x86/kernel/irq.c:231 [inline]
                   __common_interrupt+0xd7/0x1f0 arch/x86/kernel/irq.c:250
                   common_interrupt+0x9f/0xc0 arch/x86/kernel/irq.c:240
                   asm_common_interrupt+0x22/0x40 arch/x86/include/asm/idtentry.h:629
                   console_unlock+0xe53/0x12b0 kernel/printk/printk.c:2743
                   vprintk_emit+0xbf/0x150 kernel/printk/printk.c:2268
                   _printk+0xd1/0x111 kernel/printk/printk.c:2293
                   spectre_v2_select_mitigation+0x4b9/0x748 arch/x86/kernel/cpu/bugs.c:1626
                   cpu_select_mitigations+0x3d/0x8f arch/x86/kernel/cpu/bugs.c:151
                   arch_cpu_finalize_init+0xf/0x81 arch/x86/kernel/cpu/common.c:2253
                   start_kernel+0x419/0x535 init/main.c:1104
                   secondary_startup_64_no_verify+0xb1/0xbb
 }
 ... key      at: [<ffffffff9140bfc0>] init_timer_cpu.__key+0x0/0x20

the dependencies between the lock to be acquired
 and HARDIRQ-irq-unsafe lock:
-> (&htab->buckets[i].lock
){+...}-{2:2} {
   HARDIRQ-ON-W at:
                    lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
                    __raw_spin_lock_bh include/linux/spinlock_api_smp.h:135 [inline]
                    _raw_spin_lock_bh+0x31/0x40 kernel/locking/spinlock.c:178
                    sock_hash_free+0x14c/0x780 net/core/sock_map.c:1154
                    process_one_work+0x8a1/0x10c0 kernel/workqueue.c:2310
                    worker_thread+0xaca/0x1280 kernel/workqueue.c:2457
                    kthread+0x3f6/0x4f0 kernel/kthread.c:319
                    ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:298
   INITIAL USE at:
                   lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
                   __raw_spin_lock_bh include/linux/spinlock_api_smp.h:135 [inline]
                   _raw_spin_lock_bh+0x31/0x40 kernel/locking/spinlock.c:178
                   sock_hash_free+0x14c/0x780 net/core/sock_map.c:1154
                   process_one_work+0x8a1/0x10c0 kernel/workqueue.c:2310
                   worker_thread+0xaca/0x1280 kernel/workqueue.c:2457
                   kthread+0x3f6/0x4f0 kernel/kthread.c:319
                   ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:298
 }
 ... key      at: [<ffffffff91789700>] sock_hash_alloc.__key+0x0/0x20
 ... acquired at:
   lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
   __raw_spin_lock_bh include/linux/spinlock_api_smp.h:135 [inline]
   _raw_spin_lock_bh+0x31/0x40 kernel/locking/spinlock.c:178
   sock_hash_delete_elem+0xac/0x2f0 net/core/sock_map.c:937
   bpf_prog_2c29ac5cdc6b1842+0x3a/0x678
   bpf_dispatcher_nop_func include/linux/bpf.h:780 [inline]
   __bpf_prog_run include/linux/filter.h:625 [inline]
   bpf_prog_run include/linux/filter.h:632 [inline]
   __bpf_trace_run kernel/trace/bpf_trace.c:1880 [inline]
   bpf_trace_run3+0x1d1/0x380 kernel/trace/bpf_trace.c:1918
   trace_timer_start include/trace/events/timer.h:52 [inline]
   enqueue_timer+0x3ae/0x540 kernel/time/timer.c:586
   internal_add_timer kernel/time/timer.c:611 [inline]
   __mod_timer+0xa60/0xeb0 kernel/time/timer.c:1062
   schedule_timeout+0x1b4/0x300 kernel/time/timer.c:1883
   synchronize_rcu_expedited_wait_once kernel/rcu/tree_exp.h:472 [inline]
   synchronize_rcu_expedited_wait kernel/rcu/tree_exp.h:523 [inline]
   rcu_exp_wait_wake kernel/rcu/tree_exp.h:590 [inline]
   rcu_exp_sel_wait_wake+0x7cb/0x1c00 kernel/rcu/tree_exp.h:624
   process_one_work+0x8a1/0x10c0 kernel/workqueue.c:2310
   worker_thread+0xaca/0x1280 kernel/workqueue.c:2457
   kthread+0x3f6/0x4f0 kernel/kthread.c:319
   ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:298


stack backtrace:
CPU: 1 PID: 21 Comm: kworker/1:0 Not tainted 5.15.152-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 02/29/2024
Workqueue: rcu_gp wait_rcu_exp_gp

Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2cb lib/dump_stack.c:106
 print_bad_irq_dependency kernel/locking/lockdep.c:2567 [inline]
 check_irq_usage kernel/locking/lockdep.c:2806 [inline]
 check_prev_add kernel/locking/lockdep.c:3057 [inline]
 check_prevs_add kernel/locking/lockdep.c:3172 [inline]
 validate_chain+0x4d01/0x5930 kernel/locking/lockdep.c:3788
 __lock_acquire+0x1295/0x1ff0 kernel/locking/lockdep.c:5012
 lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
 __raw_spin_lock_bh include/linux/spinlock_api_smp.h:135 [inline]
 _raw_spin_lock_bh+0x31/0x40 kernel/locking/spinlock.c:178
 sock_hash_delete_elem+0xac/0x2f0 net/core/sock_map.c:937
 bpf_prog_2c29ac5cdc6b1842+0x3a/0x678
 bpf_dispatcher_nop_func include/linux/bpf.h:780 [inline]
 __bpf_prog_run include/linux/filter.h:625 [inline]
 bpf_prog_run include/linux/filter.h:632 [inline]
 __bpf_trace_run kernel/trace/bpf_trace.c:1880 [inline]
 bpf_trace_run3+0x1d1/0x380 kernel/trace/bpf_trace.c:1918
 trace_timer_start include/trace/events/timer.h:52 [inline]
 enqueue_timer+0x3ae/0x540 kernel/time/timer.c:586
 internal_add_timer kernel/time/timer.c:611 [inline]
 __mod_timer+0xa60/0xeb0 kernel/time/timer.c:1062
 schedule_timeout+0x1b4/0x300 kernel/time/timer.c:1883
 synchronize_rcu_expedited_wait_once kernel/rcu/tree_exp.h:472 [inline]
 synchronize_rcu_expedited_wait kernel/rcu/tree_exp.h:523 [inline]
 rcu_exp_wait_wake kernel/rcu/tree_exp.h:590 [inline]
 rcu_exp_sel_wait_wake+0x7cb/0x1c00 kernel/rcu/tree_exp.h:624
 process_one_work+0x8a1/0x10c0 kernel/workqueue.c:2310
 worker_thread+0xaca/0x1280 kernel/workqueue.c:2457
 kthread+0x3f6/0x4f0 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:298
 </TASK>

Crashes (26):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2024/03/26 08:06 linux-5.15.y b95c01af2113 bcd9b39f .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in lock_timer_base
2024/03/26 06:46 linux-5.15.y b95c01af2113 bcd9b39f .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in lock_timer_base
2024/03/26 06:15 linux-5.15.y b95c01af2113 bcd9b39f .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in lock_timer_base
2024/03/26 05:44 linux-5.15.y b95c01af2113 bcd9b39f .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in lock_timer_base
2024/03/26 04:23 linux-5.15.y b95c01af2113 bcd9b39f .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in lock_timer_base
2024/03/26 04:16 linux-5.15.y b95c01af2113 bcd9b39f .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/24 00:11 linux-5.15.y b95c01af2113 0ea90952 .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in lock_timer_base
2024/03/19 10:32 linux-5.15.y b95c01af2113 baa80228 .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in lock_timer_base
2023/05/25 23:12 linux-5.15.y 1fe619a7d252 0513b3e6 .config console log report syz [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-arm64 possible deadlock in lock_timer_base
2024/03/28 21:16 linux-5.15.y 9465fef4ae35 e91187ee .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/28 16:28 linux-5.15.y 9465fef4ae35 e91187ee .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/27 01:52 linux-5.15.y 9465fef4ae35 454571b6 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/26 09:15 linux-5.15.y b95c01af2113 bcd9b39f .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/24 01:52 linux-5.15.y b95c01af2113 0ea90952 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/23 21:31 linux-5.15.y b95c01af2113 0ea90952 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/23 21:09 linux-5.15.y b95c01af2113 0ea90952 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/23 20:11 linux-5.15.y b95c01af2113 0ea90952 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/23 01:47 linux-5.15.y b95c01af2113 4b6cdce6 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/18 18:30 linux-5.15.y b95c01af2113 baa80228 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/18 08:23 linux-5.15.y b95c01af2113 d615901c .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/17 15:05 linux-5.15.y b95c01af2113 d615901c .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/17 15:05 linux-5.15.y b95c01af2113 d615901c .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/15 22:42 linux-5.15.y b95c01af2113 d615901c .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2024/03/13 13:43 linux-5.15.y 574362648507 db5b7ff0 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in lock_timer_base
2023/06/04 05:43 linux-5.15.y 0ab06468cbd1 a4ae4f42 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-arm64 possible deadlock in lock_timer_base
2023/05/25 21:57 linux-5.15.y 1fe619a7d252 0513b3e6 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-arm64 possible deadlock in lock_timer_base
* Struck through repros no longer work on HEAD.