Re: INFO: trying to register non-static key in is_dynamic_key

[Andrey Konovalov]

On Fri, Jun 19, 2020 at 12:03 PM Dmitry Vyukov <dvyukov@xxxxxxxxxx> wrote:
>
> On Fri, Jun 19, 2020 at 11:53 AM Peter Zijlstra <peterz@xxxxxxxxxxxxx> wrote:
> >
> > On Thu, Jun 18, 2020 at 02:17:15PM -0700, syzbot wrote:
> >
> > > INFO: trying to register non-static key.
> > > the code is fine but needs lockdep annotation.
> > > turning off the locking correctness validator.
> > > CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.7.0-syzkaller #0
> > > Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> > > Call Trace:
> > >  <IRQ>
> > >  __dump_stack lib/dump_stack.c:77 [inline]
> > >  dump_stack+0xf6/0x16e lib/dump_stack.c:118
> > >  assign_lock_key kernel/locking/lockdep.c:894 [inline]
> > >  register_lock_class+0x1442/0x17e0 kernel/locking/lockdep.c:1206
> > >  arch_stack_walk+0x81/0xf0 arch/x86/kernel/stacktrace.c:25
> > >  lock_downgrade+0x720/0x720 kernel/locking/lockdep.c:4624
> > >  is_dynamic_key+0x1b0/0x1b0 kernel/locking/lockdep.c:1176
> > >  trace_hardirqs_off+0x50/0x1f0 kernel/trace/trace_preemptirq.c:83
> > >  __lock_acquire+0x101/0x6270 kernel/locking/lockdep.c:4259
> > >  save_stack+0x32/0x40 mm/kasan/common.c:50
> >
> > So I'm thinking this is in fact:
> >
> >         spin_lock_irqsave(&depot_lock, flags);
> >
> > from lib/stackdepot.c:stack_depot_save(), which has gone missing from
> > the stack due to tail-call optimizations.
> >
> > Now depot_lock is declared thusly:
> >
> >   static DEFINE_SPINLOCK(depot_lock);
> >
> > and I'm trying to figure out how lockdep manages to conclude that isn't
> > static storage.... most odd.
>
> Note there also was something wrong with the unwinder:
> https://syzkaller.appspot.com/x/log.txt?x=13f305a9100000
> (or with something else in the kernel), so potentially it did not
> happen save_stack.
>
> In fact, Andrey just reverted this parsing of questionable frames in syzkaller:
> https://github.com/google/syzkaller/commit/4d2d1ebee3b65c404576d1c8573a0ec48b03b883
> (was done because of what turned out to be ORC unwinder bug, which was fixed).
>
> So potentially we just need to close this is invalid now.

Rerunning the repro shows a different stack:

INFO: trying to register non-static key.
the code is fine but needs lockdep annotation.
turning off the locking correctness validator.
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.8.0-rc1+ #2
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1 04/01/2014
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77
 dump_stack+0xf6/0x16e lib/dump_stack.c:118
 assign_lock_key kernel/locking/lockdep.c:894
 register_lock_class+0x1228/0x16d0 kernel/locking/lockdep.c:1206
 __lock_acquire+0x100/0x6950 kernel/locking/lockdep.c:4259
 lock_acquire+0x18b/0x7c0 kernel/locking/lockdep.c:4959
 __raw_spin_lock_irqsave ./include/linux/spinlock_api_smp.h:110
 _raw_spin_lock_irqsave+0x32/0x50 kernel/locking/spinlock.c:159
 ath9k_htc_rxep+0x31/0x210 drivers/net/wireless/ath/ath9k/htc_drv_txrx.c:1128
 ath9k_htc_rx_msg+0x2d9/0xb10 drivers/net/wireless/ath/ath9k/htc_hst.c:459
 ath9k_hif_usb_rx_stream drivers/net/wireless/ath/ath9k/hif_usb.c:638
 ath9k_hif_usb_rx_cb+0xc76/0x1050 drivers/net/wireless/ath/ath9k/hif_usb.c:671
 __usb_hcd_giveback_urb+0x29a/0x550 drivers/usb/core/hcd.c:1650
 usb_hcd_giveback_urb+0x367/0x410 drivers/usb/core/hcd.c:1716
 dummy_timer+0x125d/0x333b drivers/usb/gadget/udc/dummy_hcd.c:1967
 call_timer_fn+0x1ac/0x6e0 kernel/time/timer.c:1404
 expire_timers kernel/time/timer.c:1449
 __run_timers kernel/time/timer.c:1773
 __run_timers kernel/time/timer.c:1740
 run_timer_softirq+0x5e5/0x14c0 kernel/time/timer.c:1786
 __do_softirq+0x21e/0x98b kernel/softirq.c:292
 asm_call_on_stack+0xf/0x20 arch/x86/entry/entry_64.S:711
 </IRQ>
 __run_on_irqstack ./arch/x86/include/asm/irq_stack.h:22
 run_on_irqstack_cond ./arch/x86/include/asm/irq_stack.h:48
 do_softirq_own_stack+0x109/0x140 arch/x86/kernel/irq_64.c:77
 invoke_softirq kernel/softirq.c:387
 __irq_exit_rcu kernel/softirq.c:417
 irq_exit_rcu+0x16f/0x1a0 kernel/softirq.c:429
 sysvec_apic_timer_interrupt+0xd3/0x1b0 arch/x86/kernel/apic/apic.c:1091
 asm_sysvec_apic_timer_interrupt+0x12/0x20 ./arch/x86/include/asm/idtentry.h:596
RIP: 0010:native_safe_halt ./arch/x86/include/asm/irqflags.h:60
RIP: 0010:arch_safe_halt ./arch/x86/include/asm/irqflags.h:103
RIP: 0010:default_idle+0x28/0x2f0 arch/x86/kernel/process.c:700
Code: cc cc 41 56 41 55 65 44 8b 2d 44 77 66 7a 41 54 55 53 0f 1f 44
00 00 e8 f6 d7 a9 fb e9 07 00 00 00 0f 00 2d 2a 34 47 00 fb f4 <65> 44
8b 2d 20 77 66 7a 0f 1f 44 00 00 5b 5d 41 3
RSP: 0018:ffffffff87007da0 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffffffff8702f840 RCX: 1ffffffff0fd45ea
RDX: 1ffffffff0e0600f RSI: 0000000000000000 RDI: ffffffff87030078
RBP: fffffbfff0e05f08 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000000 R14: ffffffff87ea1fc8 R15: 0000000000000000
 cpuidle_idle_call kernel/sched/idle.c:154
 do_idle+0x3ec/0x510 kernel/sched/idle.c:269
 cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:365
 start_kernel+0x9fc/0xa39 init/main.c:1043
 secondary_startup_64+0xb6/0xc0 arch/x86/kernel/head_64.S:243

So this is a dup of:

#syz dup: INFO: trying to register non-static key in ath9k_htc_rxep

Not sure why lockdep triggered on save_stack() in this run.