Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

On (11/30/17 16:07), Andrey Ryabinin wrote:
[..]
> >> You can try dirty patch from here:
> >> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
> >> It should make KASAN print the exact variable name and frame where it
> >> was allocated.
> > 
> > would be good if Fengguang can try this out. I can't reproduce the
> > problem on my x86 box (linux-next and Linus's trees both work fine
> > for me with KASAN + lockdep + TRACE_IRQ).
> 
> I suspect you don't have gcc 7. That's is requirement for use-after-scope.

I do have it.

gcc --version
gcc (GCC) 7.2.1 20171123

tested with

$ grep GCC .config
CONFIG_HAVE_GCC_PLUGINS=y
CONFIG_GCC_PLUGINS=y
# CONFIG_GCC_PLUGIN_CYC_COMPLEXITY is not set
# CONFIG_GCC_PLUGIN_LATENT_ENTROPY is not set
CONFIG_GCC_PLUGIN_STRUCTLEAK=y
CONFIG_GCC_PLUGIN_STRUCTLEAK_BYREF_ALL=y
CONFIG_GCC_PLUGIN_STRUCTLEAK_VERBOSE=y
# CONFIG_GCC_PLUGIN_RANDSTRUCT is not set

got the following use-after-scope:

 ==
 BUG: KASAN: use-after-scope in pcpu_setup_first_chunk+0x902/0xa21
 Write of size 8 at addr 81e07d78 by task swapper/0
 
 CPU: 0 PID: 0 Comm: swapper Not tainted 
4.15.0-rc1-dbg-00261-g716b8dd05fd3-dirty #927
 Call Trace:
  dump_stack+0xca/0x146
  ? _atomic_dec_and_lock+0xdd/0xdd
  ? show_regs_print_info+0x39/0x39
  ? pcpu_setup_first_chunk+0x902/0xa21
  print_address_description+0x6e/0x207
  ? pcpu_setup_first_chunk+0x902/0xa21
  kasan_report+0x21e/0x244
  pcpu_setup_first_chunk+0x902/0xa21
  ? pcpu_free_alloc_info+0x27/0x27
  ? memblock_remove+0x12/0x12
  pcpu_embed_first_chunk+0x3fa/0x4a6
  ? pcpup_populate_pte+0xa/0xa
  ? pcpu_fc_free+0x40/0x40
  setup_per_cpu_areas+0x7c/0x2df
  start_kernel+0x174/0x489
  ? mem_encrypt_init+0x6/0x6
  ? load_ucode_bsp+0x7f/0xe0
  secondary_startup_64+0xa5/0xb0
 
 
 Memory state around the buggy address:
  81e07c00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  81e07c80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 >81e07d00: 00 00 00 00 00 00 00 00 00 00 00 f1 f1 f1 f1 f8
 ^
  81e07d80: f2 f2 f2 f3 f3 f3 f3 00 00 00 00 00 00 00 00 00
  81e07e00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 ==

no printk() related reports.

-ss

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

On (11/30/17 16:07), Andrey Ryabinin wrote:
[..]
> >> You can try dirty patch from here:
> >> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
> >> It should make KASAN print the exact variable name and frame where it
> >> was allocated.
> > 
> > would be good if Fengguang can try this out. I can't reproduce the
> > problem on my x86 box (linux-next and Linus's trees both work fine
> > for me with KASAN + lockdep + TRACE_IRQ).
> 
> I suspect you don't have gcc 7. That's is requirement for use-after-scope.

I do have it.

gcc --version
gcc (GCC) 7.2.1 20171123

tested with

$ grep GCC .config
CONFIG_HAVE_GCC_PLUGINS=y
CONFIG_GCC_PLUGINS=y
# CONFIG_GCC_PLUGIN_CYC_COMPLEXITY is not set
# CONFIG_GCC_PLUGIN_LATENT_ENTROPY is not set
CONFIG_GCC_PLUGIN_STRUCTLEAK=y
CONFIG_GCC_PLUGIN_STRUCTLEAK_BYREF_ALL=y
CONFIG_GCC_PLUGIN_STRUCTLEAK_VERBOSE=y
# CONFIG_GCC_PLUGIN_RANDSTRUCT is not set

got the following use-after-scope:

 ==
 BUG: KASAN: use-after-scope in pcpu_setup_first_chunk+0x902/0xa21
 Write of size 8 at addr 81e07d78 by task swapper/0
 
 CPU: 0 PID: 0 Comm: swapper Not tainted 
4.15.0-rc1-dbg-00261-g716b8dd05fd3-dirty #927
 Call Trace:
  dump_stack+0xca/0x146
  ? _atomic_dec_and_lock+0xdd/0xdd
  ? show_regs_print_info+0x39/0x39
  ? pcpu_setup_first_chunk+0x902/0xa21
  print_address_description+0x6e/0x207
  ? pcpu_setup_first_chunk+0x902/0xa21
  kasan_report+0x21e/0x244
  pcpu_setup_first_chunk+0x902/0xa21
  ? pcpu_free_alloc_info+0x27/0x27
  ? memblock_remove+0x12/0x12
  pcpu_embed_first_chunk+0x3fa/0x4a6
  ? pcpup_populate_pte+0xa/0xa
  ? pcpu_fc_free+0x40/0x40
  setup_per_cpu_areas+0x7c/0x2df
  start_kernel+0x174/0x489
  ? mem_encrypt_init+0x6/0x6
  ? load_ucode_bsp+0x7f/0xe0
  secondary_startup_64+0xa5/0xb0
 
 
 Memory state around the buggy address:
  81e07c00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  81e07c80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 >81e07d00: 00 00 00 00 00 00 00 00 00 00 00 f1 f1 f1 f1 f8
 ^
  81e07d80: f2 f2 f2 f3 f3 f3 f3 00 00 00 00 00 00 00 00 00
  81e07e00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 ==

no printk() related reports.

-ss

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

On (11/30/17 22:30), Fengguang Wu wrote:
> On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:
> > On (11/30/17 09:16), Dmitry Vyukov wrote:
> > [..]
> > > > to be honest, this backtrace hardly makes any sense to me.
> > > >
> > > > vprintk_emit()
> > > >  reserve_standard_io_resources()
> > > >   __flush_tlb_all()
> > > >vprintk_emit()
> > > > __down_trylock_console_sem()
> > > >  wake_up_klogd()
> > > >   console_unlock()
> > > >
> > > > I need some help here.
> > > 
> > > 
> > > You can try dirty patch from here:
> > > https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
> > > It should make KASAN print the exact variable name and frame where it
> > > was allocated.
> > 
> > would be good if Fengguang can try this out. I can't reproduce the
> > problem on my x86 box (linux-next and Linus's trees both work fine
> > for me with KASAN + lockdep + TRACE_IRQ).
> 
> Attached is the dmesg with Dmitry's patch. The new output is:
> 
> [0.00] frame offset: 32
> [0.00] desc: '2 32 4 3 __u 96 8 3 __u '
> [0.00] func: console_unlock+0x0/0xcc0

thanks!

-ss

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

On (11/30/17 22:30), Fengguang Wu wrote:
> On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:
> > On (11/30/17 09:16), Dmitry Vyukov wrote:
> > [..]
> > > > to be honest, this backtrace hardly makes any sense to me.
> > > >
> > > > vprintk_emit()
> > > >  reserve_standard_io_resources()
> > > >   __flush_tlb_all()
> > > >vprintk_emit()
> > > > __down_trylock_console_sem()
> > > >  wake_up_klogd()
> > > >   console_unlock()
> > > >
> > > > I need some help here.
> > > 
> > > 
> > > You can try dirty patch from here:
> > > https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
> > > It should make KASAN print the exact variable name and frame where it
> > > was allocated.
> > 
> > would be good if Fengguang can try this out. I can't reproduce the
> > problem on my x86 box (linux-next and Linus's trees both work fine
> > for me with KASAN + lockdep + TRACE_IRQ).
> 
> Attached is the dmesg with Dmitry's patch. The new output is:
> 
> [0.00] frame offset: 32
> [0.00] desc: '2 32 4 3 __u 96 8 3 __u '
> [0.00] func: console_unlock+0x0/0xcc0

thanks!

-ss

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Dmitry Vyukov]

On Thu, Nov 30, 2017 at 3:30 PM, Fengguang Wu  wrote:
> On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:
>>
>> On (11/30/17 09:16), Dmitry Vyukov wrote:
>> [..]
>>>
>>> > to be honest, this backtrace hardly makes any sense to me.
>>> >
>>> > vprintk_emit()
>>> >  reserve_standard_io_resources()
>>> >   __flush_tlb_all()
>>> >vprintk_emit()
>>> > __down_trylock_console_sem()
>>> >  wake_up_klogd()
>>> >   console_unlock()
>>> >
>>> > I need some help here.
>>>
>>>
>>> You can try dirty patch from here:
>>> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
>>> It should make KASAN print the exact variable name and frame where it
>>> was allocated.
>>
>>
>> would be good if Fengguang can try this out. I can't reproduce the
>> problem on my x86 box (linux-next and Linus's trees both work fine
>> for me with KASAN + lockdep + TRACE_IRQ).
>
>
> Attached is the dmesg with Dmitry's patch. The new output is:
>
> [0.00] frame offset: 32
> [0.00] desc: '2 32 4 3 __u 96 8 3 __u '
> [0.00] func: console_unlock+0x0/0xcc0


Thanks for testing.
The output looks broken. There are more than 2 variables in
console_unlock. Probably it has found a wrong stack frame descriptor
on stack...
But Andrey says that use-after-scope has known false positives with
CONFIG_GCC_PLUGIN_STRUCTLEAK_BYREF_ALL=y, so probably this does not
matter.

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Dmitry Vyukov]

On Thu, Nov 30, 2017 at 3:30 PM, Fengguang Wu  wrote:
> On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:
>>
>> On (11/30/17 09:16), Dmitry Vyukov wrote:
>> [..]
>>>
>>> > to be honest, this backtrace hardly makes any sense to me.
>>> >
>>> > vprintk_emit()
>>> >  reserve_standard_io_resources()
>>> >   __flush_tlb_all()
>>> >vprintk_emit()
>>> > __down_trylock_console_sem()
>>> >  wake_up_klogd()
>>> >   console_unlock()
>>> >
>>> > I need some help here.
>>>
>>>
>>> You can try dirty patch from here:
>>> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
>>> It should make KASAN print the exact variable name and frame where it
>>> was allocated.
>>
>>
>> would be good if Fengguang can try this out. I can't reproduce the
>> problem on my x86 box (linux-next and Linus's trees both work fine
>> for me with KASAN + lockdep + TRACE_IRQ).
>
>
> Attached is the dmesg with Dmitry's patch. The new output is:
>
> [0.00] frame offset: 32
> [0.00] desc: '2 32 4 3 __u 96 8 3 __u '
> [0.00] func: console_unlock+0x0/0xcc0


Thanks for testing.
The output looks broken. There are more than 2 variables in
console_unlock. Probably it has found a wrong stack frame descriptor
on stack...
But Andrey says that use-after-scope has known false positives with
CONFIG_GCC_PLUGIN_STRUCTLEAK_BYREF_ALL=y, so probably this does not
matter.

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Fengguang Wu]

On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:

On (11/30/17 09:16), Dmitry Vyukov wrote:
[..]

> to be honest, this backtrace hardly makes any sense to me.
>
> vprintk_emit()
>  reserve_standard_io_resources()
>   __flush_tlb_all()
>vprintk_emit()
> __down_trylock_console_sem()
>  wake_up_klogd()
>   console_unlock()
>
> I need some help here.


You can try dirty patch from here:
https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
It should make KASAN print the exact variable name and frame where it
was allocated.


would be good if Fengguang can try this out. I can't reproduce the
problem on my x86 box (linux-next and Linus's trees both work fine
for me with KASAN + lockdep + TRACE_IRQ).


Attached is the dmesg with Dmitry's patch. The new output is:

[0.00] frame offset: 32
[0.00] desc: '2 32 4 3 __u 96 8 3 __u '
[0.00] func: console_unlock+0x0/0xcc0

Thanks,
Fengguang


dmesg.xz
Description: application/xz

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Fengguang Wu]

On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:

On (11/30/17 09:16), Dmitry Vyukov wrote:
[..]

> to be honest, this backtrace hardly makes any sense to me.
>
> vprintk_emit()
>  reserve_standard_io_resources()
>   __flush_tlb_all()
>vprintk_emit()
> __down_trylock_console_sem()
>  wake_up_klogd()
>   console_unlock()
>
> I need some help here.


You can try dirty patch from here:
https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
It should make KASAN print the exact variable name and frame where it
was allocated.


would be good if Fengguang can try this out. I can't reproduce the
problem on my x86 box (linux-next and Linus's trees both work fine
for me with KASAN + lockdep + TRACE_IRQ).


Attached is the dmesg with Dmitry's patch. The new output is:

[0.00] frame offset: 32
[0.00] desc: '2 32 4 3 __u 96 8 3 __u '
[0.00] func: console_unlock+0x0/0xcc0

Thanks,
Fengguang


dmesg.xz
Description: application/xz

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Andrey Ryabinin]

On 11/30/2017 11:29 AM, Sergey Senozhatsky wrote:
> On (11/30/17 09:16), Dmitry Vyukov wrote:
> [..]
>>> to be honest, this backtrace hardly makes any sense to me.
>>>
>>> vprintk_emit()
>>>  reserve_standard_io_resources()
>>>   __flush_tlb_all()
>>>vprintk_emit()
>>> __down_trylock_console_sem()
>>>  wake_up_klogd()
>>>   console_unlock()
>>>
>>> I need some help here.

.config has CONFIG_GCC_PLUGIN_STRUCTLEAK_BYREF_ALL=y
It's known to cause use-after-scope problems, so printk/console code is likely
has nothing to do with the bug.



>>
>> You can try dirty patch from here:
>> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
>> It should make KASAN print the exact variable name and frame where it
>> was allocated.
> 
> would be good if Fengguang can try this out. I can't reproduce the
> problem on my x86 box (linux-next and Linus's trees both work fine
> for me with KASAN + lockdep + TRACE_IRQ).

I suspect you don't have gcc 7. That's is requirement for use-after-scope.

>   -ss
> 

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Andrey Ryabinin]

On 11/30/2017 11:29 AM, Sergey Senozhatsky wrote:
> On (11/30/17 09:16), Dmitry Vyukov wrote:
> [..]
>>> to be honest, this backtrace hardly makes any sense to me.
>>>
>>> vprintk_emit()
>>>  reserve_standard_io_resources()
>>>   __flush_tlb_all()
>>>vprintk_emit()
>>> __down_trylock_console_sem()
>>>  wake_up_klogd()
>>>   console_unlock()
>>>
>>> I need some help here.

.config has CONFIG_GCC_PLUGIN_STRUCTLEAK_BYREF_ALL=y
It's known to cause use-after-scope problems, so printk/console code is likely
has nothing to do with the bug.



>>
>> You can try dirty patch from here:
>> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
>> It should make KASAN print the exact variable name and frame where it
>> was allocated.
> 
> would be good if Fengguang can try this out. I can't reproduce the
> problem on my x86 box (linux-next and Linus's trees both work fine
> for me with KASAN + lockdep + TRACE_IRQ).

I suspect you don't have gcc 7. That's is requirement for use-after-scope.

>   -ss
> 

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Fengguang Wu]

On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:

On (11/30/17 09:16), Dmitry Vyukov wrote:
[..]

> to be honest, this backtrace hardly makes any sense to me.
>
> vprintk_emit()
>  reserve_standard_io_resources()
>   __flush_tlb_all()
>vprintk_emit()
> __down_trylock_console_sem()
>  wake_up_klogd()
>   console_unlock()
>
> I need some help here.


You can try dirty patch from here:
https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
It should make KASAN print the exact variable name and frame where it
was allocated.


would be good if Fengguang can try this out. I can't reproduce the
problem on my x86 box (linux-next and Linus's trees both work fine
for me with KASAN + lockdep + TRACE_IRQ).


OK I'll try Dmitry's patch out.

Thanks,
Fengguang

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Fengguang Wu]

On Thu, Nov 30, 2017 at 05:29:09PM +0900, Sergey Senozhatsky wrote:

On (11/30/17 09:16), Dmitry Vyukov wrote:
[..]

> to be honest, this backtrace hardly makes any sense to me.
>
> vprintk_emit()
>  reserve_standard_io_resources()
>   __flush_tlb_all()
>vprintk_emit()
> __down_trylock_console_sem()
>  wake_up_klogd()
>   console_unlock()
>
> I need some help here.


You can try dirty patch from here:
https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
It should make KASAN print the exact variable name and frame where it
was allocated.


would be good if Fengguang can try this out. I can't reproduce the
problem on my x86 box (linux-next and Linus's trees both work fine
for me with KASAN + lockdep + TRACE_IRQ).


OK I'll try Dmitry's patch out.

Thanks,
Fengguang

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

On (11/30/17 09:16), Dmitry Vyukov wrote:
[..]
> > to be honest, this backtrace hardly makes any sense to me.
> >
> > vprintk_emit()
> >  reserve_standard_io_resources()
> >   __flush_tlb_all()
> >vprintk_emit()
> > __down_trylock_console_sem()
> >  wake_up_klogd()
> >   console_unlock()
> >
> > I need some help here.
> 
> 
> You can try dirty patch from here:
> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
> It should make KASAN print the exact variable name and frame where it
> was allocated.

would be good if Fengguang can try this out. I can't reproduce the
problem on my x86 box (linux-next and Linus's trees both work fine
for me with KASAN + lockdep + TRACE_IRQ).

-ss

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

On (11/30/17 09:16), Dmitry Vyukov wrote:
[..]
> > to be honest, this backtrace hardly makes any sense to me.
> >
> > vprintk_emit()
> >  reserve_standard_io_resources()
> >   __flush_tlb_all()
> >vprintk_emit()
> > __down_trylock_console_sem()
> >  wake_up_klogd()
> >   console_unlock()
> >
> > I need some help here.
> 
> 
> You can try dirty patch from here:
> https://groups.google.com/d/msg/kasan-dev/iDb5bhcMBT0/55QzwWaHAwAJ
> It should make KASAN print the exact variable name and frame where it
> was allocated.

would be good if Fengguang can try this out. I can't reproduce the
problem on my x86 box (linux-next and Linus's trees both work fine
for me with KASAN + lockdep + TRACE_IRQ).

-ss

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Dmitry Vyukov]

On Thu, Nov 30, 2017 at 7:47 AM, Sergey Senozhatsky
<sergey.senozhatsky.w...@gmail.com> wrote:
> Hi,
>
> On (11/30/17 10:26), Fengguang Wu wrote:
>> FYI this happens in mainline kernel v4.15-rc1 .
>> It shows up after v4.14 . Bisect is on the way.
>
> hm, printk saw no changes between 4.14 and 4.15
>
>
>> It occurs in 4 out of 4 boots.
>>
>> [0.00]RCU callback double-/use-after-free debug enabled.
>> [0.00]RCU CPU stall warnings timeout set to 100 
>> (rcu_cpu_stall_timeout).
>> [0.00]Tasks RCU enabled.
>> [0.00] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
>> [0.00] 
>> ==================
>> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0:
>>   atomic_read at 
>> arch/x86/include/asm/atomic.h:27
>>(inlined by) static_key_count 
>> at include/linux/jump_label.h:191
>>(inlined by) static_key_false 
>> at include/linux/jump_label.h:201
>>(inlined by) 
>> trace_console_rcuidle at include/trace/events/printk.h:10
>>(inlined by) 
>> call_console_drivers at kernel/printk/printk.c:1556
>>(inlined by) console_unlock 
>> at kernel/printk/printk.c:2233
>> [0.00] Write of size 4 at addr 83607aa0 by task swapper/0
>> [0.00]
>> [0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.15.0-rc1 #1
>> [0.00] Call Trace:
>> [0.00]  ? print_address_description+0x4f/0x3c0:
>>   print_address_description at 
>> mm/kasan/report.c:253
>> [0.00]  ? console_unlock+0x605/0xcc0:
>>   atomic_read at 
>> arch/x86/include/asm/atomic.h:27
>>(inlined by) static_key_count 
>> at include/linux/jump_label.h:191
>>(inlined by) static_key_false 
>> at include/linux/jump_label.h:201
>>(inlined by) 
>> trace_console_rcuidle at include/trace/events/printk.h:10
>>(inlined by) 
>> call_console_drivers at kernel/printk/printk.c:1556
>>(inlined by) console_unlock 
>> at kernel/printk/printk.c:2233
>
> so KASAN didn't like atomic_read(>enabled) from static_key_count()?
> "Write of size 4"...
>
>
>> [0.00]  ? kasan_report+0x304/0x390:
>>   kasan_report_error at 
>> mm/kasan/report.c:352
>>(inlined by) kasan_report at 
>> mm/kasan/report.c:409
>> [0.00]  ? console_unlock+0x605/0xcc0:
>>   atomic_read at 
>> arch/x86/include/asm/atomic.h:27
>>(inlined by) static_key_count 
>> at include/linux/jump_label.h:191
>>(inlined by) static_key_false 
>> at include/linux/jump_label.h:201
>>(inlined by) 
>> trace_console_rcuidle at include/trace/events/printk.h:10
>>(inlined by) 
>> call_console_drivers at kernel/printk/printk.c:1556
>>(inlined by) console_unlock 
>> at kernel/printk/printk.c:2233
>> [0.00]  ? wake_up_klogd+0x180/0x180:
>>   console_unlock at 
>> kernel/printk/printk.c:2138
>> [0.00]  ? _raw_spin_unlock_irqrestore+0xcf/0xf0:
>>   __raw_spin_unlock_irqrestore 
>> at include/linux/spinlock_api_smp.h:161
>>(inlined by) 
>> _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
>> [0.00]  ? __down_trylock_console_sem+0xf8/0x120:
>>   __down_trylock_console_sem at 
>> kernel/printk/printk.c:234
>> [0.00]  ? __down_trylock_console_sem+0x106/0x120:
>>   __down_trylock_console_sem at

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Dmitry Vyukov]

On Thu, Nov 30, 2017 at 7:47 AM, Sergey Senozhatsky
 wrote:
> Hi,
>
> On (11/30/17 10:26), Fengguang Wu wrote:
>> FYI this happens in mainline kernel v4.15-rc1 .
>> It shows up after v4.14 . Bisect is on the way.
>
> hm, printk saw no changes between 4.14 and 4.15
>
>
>> It occurs in 4 out of 4 boots.
>>
>> [0.00]RCU callback double-/use-after-free debug enabled.
>> [0.00]RCU CPU stall warnings timeout set to 100 
>> (rcu_cpu_stall_timeout).
>> [0.00]Tasks RCU enabled.
>> [0.00] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
>> [0.00] 
>> ======================
>> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0:
>>   atomic_read at 
>> arch/x86/include/asm/atomic.h:27
>>(inlined by) static_key_count 
>> at include/linux/jump_label.h:191
>>(inlined by) static_key_false 
>> at include/linux/jump_label.h:201
>>(inlined by) 
>> trace_console_rcuidle at include/trace/events/printk.h:10
>>(inlined by) 
>> call_console_drivers at kernel/printk/printk.c:1556
>>(inlined by) console_unlock 
>> at kernel/printk/printk.c:2233
>> [0.00] Write of size 4 at addr 83607aa0 by task swapper/0
>> [0.00]
>> [0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.15.0-rc1 #1
>> [0.00] Call Trace:
>> [0.00]  ? print_address_description+0x4f/0x3c0:
>>   print_address_description at 
>> mm/kasan/report.c:253
>> [0.00]  ? console_unlock+0x605/0xcc0:
>>   atomic_read at 
>> arch/x86/include/asm/atomic.h:27
>>(inlined by) static_key_count 
>> at include/linux/jump_label.h:191
>>(inlined by) static_key_false 
>> at include/linux/jump_label.h:201
>>(inlined by) 
>> trace_console_rcuidle at include/trace/events/printk.h:10
>>(inlined by) 
>> call_console_drivers at kernel/printk/printk.c:1556
>>(inlined by) console_unlock 
>> at kernel/printk/printk.c:2233
>
> so KASAN didn't like atomic_read(>enabled) from static_key_count()?
> "Write of size 4"...
>
>
>> [0.00]  ? kasan_report+0x304/0x390:
>>   kasan_report_error at 
>> mm/kasan/report.c:352
>>(inlined by) kasan_report at 
>> mm/kasan/report.c:409
>> [0.00]  ? console_unlock+0x605/0xcc0:
>>   atomic_read at 
>> arch/x86/include/asm/atomic.h:27
>>(inlined by) static_key_count 
>> at include/linux/jump_label.h:191
>>(inlined by) static_key_false 
>> at include/linux/jump_label.h:201
>>(inlined by) 
>> trace_console_rcuidle at include/trace/events/printk.h:10
>>(inlined by) 
>> call_console_drivers at kernel/printk/printk.c:1556
>>(inlined by) console_unlock 
>> at kernel/printk/printk.c:2233
>> [0.00]  ? wake_up_klogd+0x180/0x180:
>>   console_unlock at 
>> kernel/printk/printk.c:2138
>> [0.00]  ? _raw_spin_unlock_irqrestore+0xcf/0xf0:
>>   __raw_spin_unlock_irqrestore 
>> at include/linux/spinlock_api_smp.h:161
>>(inlined by) 
>> _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
>> [0.00]  ? __down_trylock_console_sem+0xf8/0x120:
>>   __down_trylock_console_sem at 
>> kernel/printk/printk.c:234
>> [0.00]  ? __down_trylock_console_sem+0x106/0x120:
>>   __down_trylock_console_sem at 
>> kernel/printk/printk.c:235
>> [0.00]  ? vprintk_emit+0x63e/

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

Hi,

On (11/30/17 10:26), Fengguang Wu wrote:
> FYI this happens in mainline kernel v4.15-rc1 .
> It shows up after v4.14 . Bisect is on the way.

hm, printk saw no changes between 4.14 and 4.15


> It occurs in 4 out of 4 boots.
> 
> [0.00]RCU callback double-/use-after-free debug enabled.
> [0.00]RCU CPU stall warnings timeout set to 100 
> (rcu_cpu_stall_timeout).
> [0.00]Tasks RCU enabled.
> [0.00] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
> [0.00] 
> ==============
> [0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0:
>   atomic_read at 
> arch/x86/include/asm/atomic.h:27
>(inlined by) static_key_count 
> at include/linux/jump_label.h:191
>(inlined by) static_key_false 
> at include/linux/jump_label.h:201
>(inlined by) 
> trace_console_rcuidle at include/trace/events/printk.h:10
>(inlined by) 
> call_console_drivers at kernel/printk/printk.c:1556
>(inlined by) console_unlock at 
> kernel/printk/printk.c:2233
> [0.00] Write of size 4 at addr 83607aa0 by task swapper/0
> [0.00]
> [0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.15.0-rc1 #1
> [0.00] Call Trace:
> [0.00]  ? print_address_description+0x4f/0x3c0:
>   print_address_description at 
> mm/kasan/report.c:253
> [0.00]  ? console_unlock+0x605/0xcc0:
>   atomic_read at 
> arch/x86/include/asm/atomic.h:27
>(inlined by) static_key_count 
> at include/linux/jump_label.h:191
>(inlined by) static_key_false 
> at include/linux/jump_label.h:201
>(inlined by) 
> trace_console_rcuidle at include/trace/events/printk.h:10
>(inlined by) 
> call_console_drivers at kernel/printk/printk.c:1556
>(inlined by) console_unlock at 
> kernel/printk/printk.c:2233

so KASAN didn't like atomic_read(>enabled) from static_key_count()?
"Write of size 4"...


> [0.00]  ? kasan_report+0x304/0x390:
>   kasan_report_error at 
> mm/kasan/report.c:352
>(inlined by) kasan_report at 
> mm/kasan/report.c:409
> [0.00]  ? console_unlock+0x605/0xcc0:
>   atomic_read at 
> arch/x86/include/asm/atomic.h:27
>(inlined by) static_key_count 
> at include/linux/jump_label.h:191
>(inlined by) static_key_false 
> at include/linux/jump_label.h:201
>(inlined by) 
> trace_console_rcuidle at include/trace/events/printk.h:10
>(inlined by) 
> call_console_drivers at kernel/printk/printk.c:1556
>(inlined by) console_unlock at 
> kernel/printk/printk.c:2233
> [0.00]  ? wake_up_klogd+0x180/0x180:
>   console_unlock at 
> kernel/printk/printk.c:2138
> [0.00]  ? _raw_spin_unlock_irqrestore+0xcf/0xf0:
>   __raw_spin_unlock_irqrestore at 
> include/linux/spinlock_api_smp.h:161
>(inlined by) 
> _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
> [0.00]  ? __down_trylock_console_sem+0xf8/0x120:
>   __down_trylock_console_sem at 
> kernel/printk/printk.c:234
> [0.00]  ? __down_trylock_console_sem+0x106/0x120:
>   __down_trylock_console_sem at 
> kernel/printk/printk.c:235
> [0.00]  ? vprintk_emit+0x63e/0x6f0:
>   vprintk_emit at 
> kernel/printk/printk.c:1757
> [0.00]  ? vprintk_func+0x11e/0x130:
>   vprintk_func at 
> kernel/printk/printk_safe.c:379
> [0.00]  ? printk+0xaf/0xcf:
>   printk at 
> kernel/printk/printk.c:1824
> [0.00]  ? s

Re: [ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Sergey Senozhatsky]

Hi,

On (11/30/17 10:26), Fengguang Wu wrote:
> FYI this happens in mainline kernel v4.15-rc1 .
> It shows up after v4.14 . Bisect is on the way.

hm, printk saw no changes between 4.14 and 4.15


> It occurs in 4 out of 4 boots.
> 
> [0.00]RCU callback double-/use-after-free debug enabled.
> [0.00]RCU CPU stall warnings timeout set to 100 
> (rcu_cpu_stall_timeout).
> [0.00]Tasks RCU enabled.
> [0.00] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
> [0.00] 
> ==============
> [0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0:
>   atomic_read at 
> arch/x86/include/asm/atomic.h:27
>(inlined by) static_key_count 
> at include/linux/jump_label.h:191
>(inlined by) static_key_false 
> at include/linux/jump_label.h:201
>(inlined by) 
> trace_console_rcuidle at include/trace/events/printk.h:10
>(inlined by) 
> call_console_drivers at kernel/printk/printk.c:1556
>(inlined by) console_unlock at 
> kernel/printk/printk.c:2233
> [0.00] Write of size 4 at addr 83607aa0 by task swapper/0
> [0.00]
> [0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.15.0-rc1 #1
> [0.00] Call Trace:
> [0.00]  ? print_address_description+0x4f/0x3c0:
>   print_address_description at 
> mm/kasan/report.c:253
> [0.00]  ? console_unlock+0x605/0xcc0:
>   atomic_read at 
> arch/x86/include/asm/atomic.h:27
>(inlined by) static_key_count 
> at include/linux/jump_label.h:191
>(inlined by) static_key_false 
> at include/linux/jump_label.h:201
>(inlined by) 
> trace_console_rcuidle at include/trace/events/printk.h:10
>(inlined by) 
> call_console_drivers at kernel/printk/printk.c:1556
>(inlined by) console_unlock at 
> kernel/printk/printk.c:2233

so KASAN didn't like atomic_read(>enabled) from static_key_count()?
"Write of size 4"...


> [0.00]  ? kasan_report+0x304/0x390:
>   kasan_report_error at 
> mm/kasan/report.c:352
>(inlined by) kasan_report at 
> mm/kasan/report.c:409
> [0.00]  ? console_unlock+0x605/0xcc0:
>   atomic_read at 
> arch/x86/include/asm/atomic.h:27
>(inlined by) static_key_count 
> at include/linux/jump_label.h:191
>(inlined by) static_key_false 
> at include/linux/jump_label.h:201
>(inlined by) 
> trace_console_rcuidle at include/trace/events/printk.h:10
>(inlined by) 
> call_console_drivers at kernel/printk/printk.c:1556
>(inlined by) console_unlock at 
> kernel/printk/printk.c:2233
> [0.00]  ? wake_up_klogd+0x180/0x180:
>   console_unlock at 
> kernel/printk/printk.c:2138
> [0.00]  ? _raw_spin_unlock_irqrestore+0xcf/0xf0:
>   __raw_spin_unlock_irqrestore at 
> include/linux/spinlock_api_smp.h:161
>(inlined by) 
> _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
> [0.00]  ? __down_trylock_console_sem+0xf8/0x120:
>   __down_trylock_console_sem at 
> kernel/printk/printk.c:234
> [0.00]  ? __down_trylock_console_sem+0x106/0x120:
>   __down_trylock_console_sem at 
> kernel/printk/printk.c:235
> [0.00]  ? vprintk_emit+0x63e/0x6f0:
>   vprintk_emit at 
> kernel/printk/printk.c:1757
> [0.00]  ? vprintk_func+0x11e/0x130:
>   vprintk_func at 
> kernel/printk/printk_safe.c:379
> [0.00]  ? printk+0xaf/0xcf:
>   printk at 
> kernel/printk/printk.c:1824
> [0.00]  ? s

[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Fengguang Wu]

Hello,

FYI this happens in mainline kernel v4.15-rc1 .
It shows up after v4.14 . Bisect is on the way.

It occurs in 4 out of 4 boots.

[0.00]  RCU callback double-/use-after-free debug enabled.
[0.00]  RCU CPU stall warnings timeout set to 100 
(rcu_cpu_stall_timeout).
[0.00]  Tasks RCU enabled.
[0.00] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
[0.00] 
==
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0:
atomic_read at 
arch/x86/include/asm/atomic.h:27
 (inlined by) static_key_count 
at include/linux/jump_label.h:191
 (inlined by) static_key_false 
at include/linux/jump_label.h:201
 (inlined by) 
trace_console_rcuidle at include/trace/events/printk.h:10
 (inlined by) 
call_console_drivers at kernel/printk/printk.c:1556
 (inlined by) console_unlock at 
kernel/printk/printk.c:2233
[0.00] Write of size 4 at addr 83607aa0 by task swapper/0
[0.00]
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.15.0-rc1 #1
[0.00] Call Trace:
[0.00]  ? print_address_description+0x4f/0x3c0:
print_address_description at 
mm/kasan/report.c:253
[0.00]  ? console_unlock+0x605/0xcc0:
atomic_read at 
arch/x86/include/asm/atomic.h:27
 (inlined by) static_key_count 
at include/linux/jump_label.h:191
 (inlined by) static_key_false 
at include/linux/jump_label.h:201
 (inlined by) 
trace_console_rcuidle at include/trace/events/printk.h:10
 (inlined by) 
call_console_drivers at kernel/printk/printk.c:1556
 (inlined by) console_unlock at 
kernel/printk/printk.c:2233
[0.00]  ? kasan_report+0x304/0x390:
kasan_report_error at 
mm/kasan/report.c:352
 (inlined by) kasan_report at 
mm/kasan/report.c:409
[0.00]  ? console_unlock+0x605/0xcc0:
atomic_read at 
arch/x86/include/asm/atomic.h:27
 (inlined by) static_key_count 
at include/linux/jump_label.h:191
 (inlined by) static_key_false 
at include/linux/jump_label.h:201
 (inlined by) 
trace_console_rcuidle at include/trace/events/printk.h:10
 (inlined by) 
call_console_drivers at kernel/printk/printk.c:1556
 (inlined by) console_unlock at 
kernel/printk/printk.c:2233
[0.00]  ? wake_up_klogd+0x180/0x180:
console_unlock at 
kernel/printk/printk.c:2138
[0.00]  ? _raw_spin_unlock_irqrestore+0xcf/0xf0:
__raw_spin_unlock_irqrestore at 
include/linux/spinlock_api_smp.h:161
 (inlined by) 
_raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
[0.00]  ? __down_trylock_console_sem+0xf8/0x120:
__down_trylock_console_sem at 
kernel/printk/printk.c:234
[0.00]  ? __down_trylock_console_sem+0x106/0x120:
__down_trylock_console_sem at 
kernel/printk/printk.c:235
[0.00]  ? vprintk_emit+0x63e/0x6f0:
vprintk_emit at 
kernel/printk/printk.c:1757
[0.00]  ? vprintk_func+0x11e/0x130:
vprintk_func at 
kernel/printk/printk_safe.c:379
[0.00]  ? printk+0xaf/0xcf:
printk at 
kernel/printk/printk.c:1824
[0.00]  ? show_regs_print_info+0x40/0x40:
printk at 
kernel/printk/printk.c:1824
[0.00]  ? __flush_tlb_all+0x1e/0x31:
__flush_tlb_global at 
arch/x86/include/asm/paravirt.h:298
 (inlined by) __flush_tlb_all 
at arch/x86/include/asm/tlbflush.h:293
[0.00]  ? native_flush_tlb_global+0x5/0xa0:
native_flush_tlb_global at 
arch/x86/kernel/paravirt.c:199
[0.00]  ? kasan_init+0x276

[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0

[Fengguang Wu]

Hello,

FYI this happens in mainline kernel v4.15-rc1 .
It shows up after v4.14 . Bisect is on the way.

It occurs in 4 out of 4 boots.

[0.00]  RCU callback double-/use-after-free debug enabled.
[0.00]  RCU CPU stall warnings timeout set to 100 
(rcu_cpu_stall_timeout).
[0.00]  Tasks RCU enabled.
[0.00] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
[0.00] 
==
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0:
atomic_read at 
arch/x86/include/asm/atomic.h:27
 (inlined by) static_key_count 
at include/linux/jump_label.h:191
 (inlined by) static_key_false 
at include/linux/jump_label.h:201
 (inlined by) 
trace_console_rcuidle at include/trace/events/printk.h:10
 (inlined by) 
call_console_drivers at kernel/printk/printk.c:1556
 (inlined by) console_unlock at 
kernel/printk/printk.c:2233
[0.00] Write of size 4 at addr 83607aa0 by task swapper/0
[0.00]
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.15.0-rc1 #1
[0.00] Call Trace:
[0.00]  ? print_address_description+0x4f/0x3c0:
print_address_description at 
mm/kasan/report.c:253
[0.00]  ? console_unlock+0x605/0xcc0:
atomic_read at 
arch/x86/include/asm/atomic.h:27
 (inlined by) static_key_count 
at include/linux/jump_label.h:191
 (inlined by) static_key_false 
at include/linux/jump_label.h:201
 (inlined by) 
trace_console_rcuidle at include/trace/events/printk.h:10
 (inlined by) 
call_console_drivers at kernel/printk/printk.c:1556
 (inlined by) console_unlock at 
kernel/printk/printk.c:2233
[0.00]  ? kasan_report+0x304/0x390:
kasan_report_error at 
mm/kasan/report.c:352
 (inlined by) kasan_report at 
mm/kasan/report.c:409
[0.00]  ? console_unlock+0x605/0xcc0:
atomic_read at 
arch/x86/include/asm/atomic.h:27
 (inlined by) static_key_count 
at include/linux/jump_label.h:191
 (inlined by) static_key_false 
at include/linux/jump_label.h:201
 (inlined by) 
trace_console_rcuidle at include/trace/events/printk.h:10
 (inlined by) 
call_console_drivers at kernel/printk/printk.c:1556
 (inlined by) console_unlock at 
kernel/printk/printk.c:2233
[0.00]  ? wake_up_klogd+0x180/0x180:
console_unlock at 
kernel/printk/printk.c:2138
[0.00]  ? _raw_spin_unlock_irqrestore+0xcf/0xf0:
__raw_spin_unlock_irqrestore at 
include/linux/spinlock_api_smp.h:161
 (inlined by) 
_raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
[0.00]  ? __down_trylock_console_sem+0xf8/0x120:
__down_trylock_console_sem at 
kernel/printk/printk.c:234
[0.00]  ? __down_trylock_console_sem+0x106/0x120:
__down_trylock_console_sem at 
kernel/printk/printk.c:235
[0.00]  ? vprintk_emit+0x63e/0x6f0:
vprintk_emit at 
kernel/printk/printk.c:1757
[0.00]  ? vprintk_func+0x11e/0x130:
vprintk_func at 
kernel/printk/printk_safe.c:379
[0.00]  ? printk+0xaf/0xcf:
printk at 
kernel/printk/printk.c:1824
[0.00]  ? show_regs_print_info+0x40/0x40:
printk at 
kernel/printk/printk.c:1824
[0.00]  ? __flush_tlb_all+0x1e/0x31:
__flush_tlb_global at 
arch/x86/include/asm/paravirt.h:298
 (inlined by) __flush_tlb_all 
at arch/x86/include/asm/tlbflush.h:293
[0.00]  ? native_flush_tlb_global+0x5/0xa0:
native_flush_tlb_global at 
arch/x86/kernel/paravirt.c:199
[0.00]  ? kasan_init+0x276