INFO: trying to register non-static key in is_dynamic_key

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+42bc0d31b9a21faebdf8@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 syzkaller@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

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

[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+42bc0d31b9a21faebdf8@syzkaller.appspotmail.com
> 
> INFO: trying to register non-static key.
> the code is fine but needs lockdep annotation.

Why is INFO: triggering syzbot?

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

[Dmitry Vyukov]

On Fri, Jun 19, 2020 at 9:07 AM Greg KH <greg@kroah.com> wrote:
>
> 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+42bc0d31b9a21faebdf8@syzkaller.appspotmail.com
> >
> > INFO: trying to register non-static key.
> > the code is fine but needs lockdep annotation.
>
> Why is INFO: triggering syzbot?

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).

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

[Greg KH]

On Fri, Jun 19, 2020 at 09:35:30AM +0200, Dmitry Vyukov wrote:
> On Fri, Jun 19, 2020 at 9:07 AM Greg KH <greg@kroah.com> wrote:
> >
> > 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+42bc0d31b9a21faebdf8@syzkaller.appspotmail.com
> > >
> > > INFO: trying to register non-static key.
> > > the code is fine but needs lockdep annotation.
> >
> > Why is INFO: triggering syzbot?
> 
> 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).

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

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

[Dmitry Vyukov]

On Fri, Jun 19, 2020 at 10:31 AM Greg KH <greg@kroah.com> wrote:
>
> On Fri, Jun 19, 2020 at 09:35:30AM +0200, Dmitry Vyukov wrote:
> > On Fri, Jun 19, 2020 at 9:07 AM Greg KH <greg@kroah.com> wrote:
> > >
> > > 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+42bc0d31b9a21faebdf8@syzkaller.appspotmail.com
> > > >
> > > > INFO: trying to register non-static key.
> > > > the code is fine but needs lockdep annotation.
> > >
> > > Why is INFO: triggering syzbot?
> >
> > 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).
>
> 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.

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? ;)

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

[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.

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

[Dmitry Vyukov]

On Fri, Jun 19, 2020 at 11:53 AM Peter Zijlstra <peterz@infradead.org> 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.

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@google.com> wrote:
>
> On Fri, Jun 19, 2020 at 11:53 AM Peter Zijlstra <peterz@infradead.org> 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.