INFO: trying to register non-static key in is_dynamic_key

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit: b791d1bd Merge tag 'locking-kcsan-2020-06-11' of git://git..
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=13f305a9100000
kernel config: https://syzkaller.appspot.com/x/.config?x=16c2467d4b6dbee2
dashboard link: https://syzkaller.appspot.com/bug?extid=42bc0d31b9a21faebdf8
compiler: gcc (GCC) 9.0.0 20181231 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=136ad566100000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=10138f7a100000

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

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
save_stack+0x1b/0x40 mm/kasan/common.c:48
set_track mm/kasan/common.c:56 [inline]
__kasan_kmalloc mm/kasan/common.c:494 [inline]
__kasan_kmalloc.constprop.0+0xbf/0xd0 mm/kasan/common.c:467
slab_post_alloc_hook mm/slab.h:586 [inline]
slab_alloc_node mm/slub.c:2824 [inline]
slab_alloc mm/slub.c:2832 [inline]
kmem_cache_alloc+0xd8/0x300 mm/slub.c:2837
__build_skb+0x21/0x60 net/core/skbuff.c:311
__netdev_alloc_skb+0x1e2/0x360 net/core/skbuff.c:464
__dev_alloc_skb include/linux/skbuff.h:2813 [inline]
ath9k_hif_usb_rx_stream drivers/net/wireless/ath/ath9k/hif_usb.c:620 [inline]
ath9k_hif_usb_rx_cb+0x64f/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+0x368/0x420 drivers/usb/core/hcd.c:1716
dummy_timer+0x125e/0x32b4 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 [inline]
__run_timers kernel/time/timer.c:1773 [inline]
__run_timers kernel/time/timer.c:1740 [inline]
run_timer_softirq+0x5e5/0x14c0 kernel/time/timer.c:1786
__do_softirq+0x21e/0x996 kernel/softirq.c:292
lockdep_hardirqs_on_prepare+0x550/0x550 kernel/locking/lockdep.c:3667
native_safe_halt arch/x86/include/asm/irqflags.h:60 [inline]
arch_safe_halt arch/x86/include/asm/irqflags.h:103 [inline]
acpi_safe_halt drivers/acpi/processor_idle.c:111 [inline]
acpi_safe_halt+0x72/0x90 drivers/acpi/processor_idle.c:108


---
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.
syzbot can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches

[Greg KH]

On Thu, Jun 18, 2020 at 02:17:15PM -0700, syzbot wrote:
> Hello,
>
> syzbot found the following crash on:
>
> HEAD commit: b791d1bd Merge tag 'locking-kcsan-2020-06-11' of git://git..
> 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=13f305a9100000
> kernel config: https://syzkaller.appspot.com/x/.config?x=16c2467d4b6dbee2
> dashboard link: https://syzkaller.appspot.com/bug?extid=42bc0d31b9a21faebdf8
> compiler: gcc (GCC) 9.0.0 20181231 (experimental)
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=136ad566100000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=10138f7a100000
>
> IMPORTANT: if you fix the bug, please add the following tag to the commit:
> Reported-by: syzbot+42bc0d...@syzkaller.appspotmail.com
>
> INFO: trying to register non-static key.
> the code is fine but needs lockdep annotation.

Why is INFO: triggering syzbot?

[Dmitry Vyukov]

This is a kernel bug, no?

And there are lots of other kernel bug types that start with INFO:
https://github.com/google/syzkaller/blob/master/pkg/report/linux.go#L1302

The rules to understand when linux kernel has bugged are insanely
complex in syzkaller:
https://github.com/google/syzkaller/blob/master/pkg/report/linux.go#L914-L1685
(+hundreds of hardcoded function names and file names above).

[Greg KH]

I understand it's tough, but "the code is fine but needs lockdep
annotation" feels like it's a "here's an improvement that you can make"
type of report, not a "crash" like this message says.

thanks,

greg k-h

[Dmitry Vyukov]

Can you think of a single description that would be suitable for all
of these types of things?
I can change the wording in the static template right now. But finding
proper wording for all of these things, annotating them, updating 500
tests probably won't be high on anybody's priority list. Or do you
consider it important enough to contribute? ;)

[Peter Zijlstra]

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.

[Dmitry Vyukov]

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.

[Andrey Konovalov]

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.