Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Sergey Senozhatsky]

On (03/01/18 16:53), Dmitry Vyukov wrote:
[..]
> > Hello Dmitry,
> >
> > I believe it's this one
> >
> > https://marc.info/?l=linux-kernel=151200883525299
> 
> 
> Thanks, but now that I debugged this one, I think that one is the same issue.
> Amusingly a write in READ_ONCE is actually legitimate because
> GCC_PLUGIN_STRUCTLEAK emits an initializing write for __u variable in
> READ_ONCE implementation.

Thanks. It's great to have you in Cc ;)

-ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Sergey Senozhatsky]

On (03/01/18 16:53), Dmitry Vyukov wrote:
[..]
> > Hello Dmitry,
> >
> > I believe it's this one
> >
> > https://marc.info/?l=linux-kernel=151200883525299
> 
> 
> Thanks, but now that I debugged this one, I think that one is the same issue.
> Amusingly a write in READ_ONCE is actually legitimate because
> GCC_PLUGIN_STRUCTLEAK emits an initializing write for __u variable in
> READ_ONCE implementation.

Thanks. It's great to have you in Cc ;)

-ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Hao, Shun]

sorry for missing the attached script in original mail, here to add it.

On Thu, 2018-03-01 at 08:47 +, Dmitry Vyukov wrote:
> On Thu, Mar 1, 2018 at 2:37 AM, Sergey Senozhatsky
>  wrote:
> > Hello,
> > 
> > Cc-ing Dmitry Vyukov and kasan-dev on this.
> > 
> > On (02/28/18 16:59), Petr Mladek wrote:
> > [..]
> > > > > 
> > > > > [0.00] BUG: KASAN: use-after-scope in
> > > > > console_unlock+0x185/0x960
> > > > > [0.00] BUG: KASAN: use-after-scope in
> > > > > console_unlock+0x185/0x960
> > > > 
> > > > Is there any change to get disassembly of console_unlock() from
> > > > the
> > > > problematic build?
> > > > 
> > > > I have troubles to reproduce this myself. Also I was not able
> > > > to find any
> > > > bug just by looking into the code yet. The disassembly might
> > > > help
> > > > a lot here.
> > > > 
> > > > 
> > > > Interesting symptoms (for myself and other debuggers):
> > > > 
> > > > The lines are duplicated. Therefore it happened when real
> > > > console was registered and before the early console was
> > > > unregistered.
> > > > See also the full dmesg for these actions. The related printk
> > > > messages
> > > > are right after the KASAN report.
> > > > 
> > > > I wonder if it is unsafe to pass the console_lock via
> > > > console_trylock_spinnning() from console_unlock() called
> > > > in register_console(). I do not see any problem but I might
> > > > be blind.
> > 
> > I'm not sure it we actually have concurrent printks at that state
> > yet,
> > might be too early for any printk offloading. The backtrace still
> > makes no sense to me at all, tho. We had this report twice,
> > probably,
> > already (even before the offloading patchset, if I'm not mistaken).
> > 
> > https://marc.info/?l=linux-kernel=151200883525299
> > 
> > [..]
> > > I feel lost a bit.
> > 
> > Yeah... can't understand what's going on there.
> > 
> > The last time kasan didn't like this part
> > 
> > [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
> > 
> > complaining that there was a write of size 4... at atomic_read().
> > 
> > Now it's reporting that the write of size 1 was out of scope.
> > 
> > > I am really curious what code is proceed on the line
> > > console_unlock+0x185/0x960.
> > 
> > Agreed.
> > 
> > On my system 0x185/0x960 is somewhere around
> > 
> > 
> >  191e:   89 d7   mov%edx,%edi
> >  1920:   e8 06 e7 ff ff  callq  2b 
> >  1925:   48 89 2d 00 00 00
> > 00mov%rbp,0x0(%rip)# 192c 
> >  192c:   89 05 00 00 00
> > 00   mov%eax,0x0(%rip)# 1932 
> > > >   1932:   eb a9   jmp18dd
> > > > 
> > 
> >  1934:   8b 35 00 00 00
> > 00   mov0x0(%rip),%esi# 193a 
> >  193a:   b9 00 04 00 00  mov$0x400,%ecx
> >  193f:   4c 89 efmov%r13,%rdi
> >  1942:   31 ed   xor%ebp,%ebp
> > 
> > 
> > That jmp 18dd after log_next() is a `goto skip' in
> > suppress_message_printing() branch
> > 
> > skip:
> > if (console_seq == log_next_seq)
> > break;
> > 
> > msg = log_from_idx(console_idx);
> > if (suppress_message_printing(msg->level)) {
> > /*
> >  * Skip record we have buffered and already
> > printed
> >  * directly to the console when we received
> > it, and
> >  * record that has level above the console
> > loglevel.
> >  */
> > console_idx = log_next(console_idx);
> > console_seq++;
> > > >  goto skip;
> > 
> > }
> > 
> > 
> > As far as I can tell.
> 
> 
> Hi Shun,
> 
> The report says "job-script is attached in this email", but I don't
> see it attached. Did you forget to attach it? How can I reproduce
> this
> exact build?
> Could you post a symbolized report with inlines frames?

job-script
Description: job-script

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Hao, Shun]

sorry for missing the attached script in original mail, here to add it.

On Thu, 2018-03-01 at 08:47 +, Dmitry Vyukov wrote:
> On Thu, Mar 1, 2018 at 2:37 AM, Sergey Senozhatsky
>  wrote:
> > Hello,
> > 
> > Cc-ing Dmitry Vyukov and kasan-dev on this.
> > 
> > On (02/28/18 16:59), Petr Mladek wrote:
> > [..]
> > > > > 
> > > > > [0.00] BUG: KASAN: use-after-scope in
> > > > > console_unlock+0x185/0x960
> > > > > [0.00] BUG: KASAN: use-after-scope in
> > > > > console_unlock+0x185/0x960
> > > > 
> > > > Is there any change to get disassembly of console_unlock() from
> > > > the
> > > > problematic build?
> > > > 
> > > > I have troubles to reproduce this myself. Also I was not able
> > > > to find any
> > > > bug just by looking into the code yet. The disassembly might
> > > > help
> > > > a lot here.
> > > > 
> > > > 
> > > > Interesting symptoms (for myself and other debuggers):
> > > > 
> > > > The lines are duplicated. Therefore it happened when real
> > > > console was registered and before the early console was
> > > > unregistered.
> > > > See also the full dmesg for these actions. The related printk
> > > > messages
> > > > are right after the KASAN report.
> > > > 
> > > > I wonder if it is unsafe to pass the console_lock via
> > > > console_trylock_spinnning() from console_unlock() called
> > > > in register_console(). I do not see any problem but I might
> > > > be blind.
> > 
> > I'm not sure it we actually have concurrent printks at that state
> > yet,
> > might be too early for any printk offloading. The backtrace still
> > makes no sense to me at all, tho. We had this report twice,
> > probably,
> > already (even before the offloading patchset, if I'm not mistaken).
> > 
> > https://marc.info/?l=linux-kernel=151200883525299
> > 
> > [..]
> > > I feel lost a bit.
> > 
> > Yeah... can't understand what's going on there.
> > 
> > The last time kasan didn't like this part
> > 
> > [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
> > 
> > complaining that there was a write of size 4... at atomic_read().
> > 
> > Now it's reporting that the write of size 1 was out of scope.
> > 
> > > I am really curious what code is proceed on the line
> > > console_unlock+0x185/0x960.
> > 
> > Agreed.
> > 
> > On my system 0x185/0x960 is somewhere around
> > 
> > 
> >  191e:   89 d7   mov%edx,%edi
> >  1920:   e8 06 e7 ff ff  callq  2b 
> >  1925:   48 89 2d 00 00 00
> > 00mov%rbp,0x0(%rip)# 192c 
> >  192c:   89 05 00 00 00
> > 00   mov%eax,0x0(%rip)# 1932 
> > > >   1932:   eb a9   jmp18dd
> > > > 
> > 
> >  1934:   8b 35 00 00 00
> > 00   mov0x0(%rip),%esi# 193a 
> >  193a:   b9 00 04 00 00  mov$0x400,%ecx
> >  193f:   4c 89 efmov%r13,%rdi
> >  1942:   31 ed   xor%ebp,%ebp
> > 
> > 
> > That jmp 18dd after log_next() is a `goto skip' in
> > suppress_message_printing() branch
> > 
> > skip:
> > if (console_seq == log_next_seq)
> > break;
> > 
> > msg = log_from_idx(console_idx);
> > if (suppress_message_printing(msg->level)) {
> > /*
> >  * Skip record we have buffered and already
> > printed
> >  * directly to the console when we received
> > it, and
> >  * record that has level above the console
> > loglevel.
> >  */
> > console_idx = log_next(console_idx);
> > console_seq++;
> > > >  goto skip;
> > 
> > }
> > 
> > 
> > As far as I can tell.
> 
> 
> Hi Shun,
> 
> The report says "job-script is attached in this email", but I don't
> see it attached. Did you forget to attach it? How can I reproduce
> this
> exact build?
> Could you post a symbolized report with inlines frames?

job-script
Description: job-script

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Kees Cook]

On Thu, Mar 1, 2018 at 6:14 AM, Ard Biesheuvel
 wrote:
> On 1 March 2018 at 14:09, Dmitry Vyukov  wrote:
> ..
>> +Ard, Kees
>>
>> This is a problem with GCC_PLUGIN_STRUCTLEAK_BYREF_ALL. It inserts an
>> initializing write for __u used in READ_ONCE outside of live scope of
>> the variable.
>> Below "movb   $0x1,0x0(%r13)" and "movb   $0xf8,0x0(%r13)" denote live
>> scope of the variable __u (the 0xf8 that appears in the KASAN report).
>> But the initializing store at 811a5f84 (and the corresponding
>> KASAN check) are outside of that scope, which causes the KASAN report.
>>
>>
>> 811a5f61: 49 8d 9f 40 ff ff ff lea-0xc0(%r15),%rbx
>> 811a5f68: 4d 8d 67 80  lea-0x80(%r15),%r12
>> kernel/printk/printk.c:1600
>> waiter = READ_ONCE(console_waiter);
>> 811a5f79: 49 89 dd  mov%rbx,%r13
>> 811a5f7c: e8 d3 4e 21 00callq  813bae54 
>> <__asan_store1>
>> 811a5f81: 4c 89 e7  mov%r12,%rdi
>> 811a5f84: 41 c6 87 40 ff ff ff movb   $0x0,-0xc0(%r15)
>> 811a5f8b: 00
>> 811a5f8c: 49 c1 ed 03  shr$0x3,%r13
>> 811a5f90: e8 bf 4e 21 00callq  813bae54 
>> <__asan_store1>
>> kernel/printk/printk.c:1599
>> raw_spin_lock(_owner_lock);
>> 811a5f95: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
>> 811a5f9c: 41 c6 47 80 00movb   $0x0,-0x80(%r15)
>> 811a5fa1: e8 92 a9 e7 00callq  82020938 
>> <_raw_spin_lock>
>> kernel/printk/printk.c:1600
>> waiter = READ_ONCE(console_waiter);
>> 811a5fa6: 4c 03 ad e8 fe ff ff add-0x118(%rbp),%r13
>> __read_once_size():
>> ./include/linux/compiler.h:178
>> })
>>
>> static __always_inline
>> void __read_once_size(const volatile void *p, void *res, int size)
>> {
>> __READ_ONCE_SIZE;
>> 811a5fad: 44 8a 35 2c 7b e6 02 mov0x2e67b2c(%rip),%r14b
>> # 8400dae0 
>> 811a5fb4: 48 89 df  mov%rbx,%rdi
>> console_lock_spinning_disable_and_check():
>> kernel/printk/printk.c:1600
>> 811a5fb7: 41 c6 45 00 01movb   $0x1,0x0(%r13)
>> __read_once_size():
>> ./include/linux/compiler.h:178
>> 811a5fbc: e8 93 4e 21 00callq  813bae54 
>> <__asan_store1>
>> console_lock_spinning_disable_and_check():
>> kernel/printk/printk.c:1600
>> 811a5fc1: 48 89 df  mov%rbx,%rdi
>> __read_once_size():
>> ./include/linux/compiler.h:178
>> 811a5fc4: 45 88 b7 40 ff ff ff mov%r14b,-0xc0(%r15)
>> console_lock_spinning_disable_and_check():
>> kernel/printk/printk.c:1600
>> 811a5fcb: e8 3d 4e 21 00callq  813bae0d 
>> <__asan_load1>
>> 811a5fd0: 45 8a b7 40 ff ff ff mov-0xc0(%r15),%r14b
>> kernel/printk/printk.c:1602
>> raw_spin_unlock(_owner_lock);
>> 811a5fd7: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
>> 811a5fde: 41 c6 45 00 f8movb   $0xf8,0x0(%r13)
>> kernel/printk/printk.c:1601
>> console_owner = NULL;
>> 811a5fe3: 48 c7 05 32 7b e6 02 movq   $0x0,0x2e67b32(%rip)
>># 8400db20 
>> 811a5fea: 00 00 00 00
>> kernel/printk/printk.c:1602
>> raw_spin_unlock(_owner_lock);
>> 811a5fee: e8 d1 ab e7 00callq  82020bc4
>> <_raw_spin_unlock>
>>
>>
>>
>> We either need to fix GCC_PLUGIN_STRUCTLEAK_BYREF_ALL (and probably
>> GCC_PLUGIN_STRUCTLEAK) to insert initialization at proper places or
>> run before KASAN instrumentation (though, since the initializing
>> stores are instrumented, it already runs partially before KASAN), or
>> declare GCC_PLUGIN_STRUCTLEAK incompatible with KASAN (it's not the
>> first time we debug this).
>
> I am pretty sure that this is a fundamental issue with the plugin, and
> not specific to BYREF_ALL. BYREF_ALL just increases the number of
> occurrences, making it easier to hit this issue.
>
> I'd be fine with making the plugin mutually exclusive with KASAN.

I'm fine making it mutally exclusive: it forces KASAN to run without
the protections the plugin provides, so really, that's better to test
(i.e. the plugin could cover up bugs that KASAN might otherwise find).

-Kees

-- 
Kees Cook
Pixel Security

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Kees Cook]

On Thu, Mar 1, 2018 at 6:14 AM, Ard Biesheuvel
 wrote:
> On 1 March 2018 at 14:09, Dmitry Vyukov  wrote:
> ..
>> +Ard, Kees
>>
>> This is a problem with GCC_PLUGIN_STRUCTLEAK_BYREF_ALL. It inserts an
>> initializing write for __u used in READ_ONCE outside of live scope of
>> the variable.
>> Below "movb   $0x1,0x0(%r13)" and "movb   $0xf8,0x0(%r13)" denote live
>> scope of the variable __u (the 0xf8 that appears in the KASAN report).
>> But the initializing store at 811a5f84 (and the corresponding
>> KASAN check) are outside of that scope, which causes the KASAN report.
>>
>>
>> 811a5f61: 49 8d 9f 40 ff ff ff lea-0xc0(%r15),%rbx
>> 811a5f68: 4d 8d 67 80  lea-0x80(%r15),%r12
>> kernel/printk/printk.c:1600
>> waiter = READ_ONCE(console_waiter);
>> 811a5f79: 49 89 dd  mov%rbx,%r13
>> 811a5f7c: e8 d3 4e 21 00callq  813bae54 
>> <__asan_store1>
>> 811a5f81: 4c 89 e7  mov%r12,%rdi
>> 811a5f84: 41 c6 87 40 ff ff ff movb   $0x0,-0xc0(%r15)
>> 811a5f8b: 00
>> 811a5f8c: 49 c1 ed 03  shr$0x3,%r13
>> 811a5f90: e8 bf 4e 21 00callq  813bae54 
>> <__asan_store1>
>> kernel/printk/printk.c:1599
>> raw_spin_lock(_owner_lock);
>> 811a5f95: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
>> 811a5f9c: 41 c6 47 80 00movb   $0x0,-0x80(%r15)
>> 811a5fa1: e8 92 a9 e7 00callq  82020938 
>> <_raw_spin_lock>
>> kernel/printk/printk.c:1600
>> waiter = READ_ONCE(console_waiter);
>> 811a5fa6: 4c 03 ad e8 fe ff ff add-0x118(%rbp),%r13
>> __read_once_size():
>> ./include/linux/compiler.h:178
>> })
>>
>> static __always_inline
>> void __read_once_size(const volatile void *p, void *res, int size)
>> {
>> __READ_ONCE_SIZE;
>> 811a5fad: 44 8a 35 2c 7b e6 02 mov0x2e67b2c(%rip),%r14b
>> # 8400dae0 
>> 811a5fb4: 48 89 df  mov%rbx,%rdi
>> console_lock_spinning_disable_and_check():
>> kernel/printk/printk.c:1600
>> 811a5fb7: 41 c6 45 00 01movb   $0x1,0x0(%r13)
>> __read_once_size():
>> ./include/linux/compiler.h:178
>> 811a5fbc: e8 93 4e 21 00callq  813bae54 
>> <__asan_store1>
>> console_lock_spinning_disable_and_check():
>> kernel/printk/printk.c:1600
>> 811a5fc1: 48 89 df  mov%rbx,%rdi
>> __read_once_size():
>> ./include/linux/compiler.h:178
>> 811a5fc4: 45 88 b7 40 ff ff ff mov%r14b,-0xc0(%r15)
>> console_lock_spinning_disable_and_check():
>> kernel/printk/printk.c:1600
>> 811a5fcb: e8 3d 4e 21 00callq  813bae0d 
>> <__asan_load1>
>> 811a5fd0: 45 8a b7 40 ff ff ff mov-0xc0(%r15),%r14b
>> kernel/printk/printk.c:1602
>> raw_spin_unlock(_owner_lock);
>> 811a5fd7: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
>> 811a5fde: 41 c6 45 00 f8movb   $0xf8,0x0(%r13)
>> kernel/printk/printk.c:1601
>> console_owner = NULL;
>> 811a5fe3: 48 c7 05 32 7b e6 02 movq   $0x0,0x2e67b32(%rip)
>># 8400db20 
>> 811a5fea: 00 00 00 00
>> kernel/printk/printk.c:1602
>> raw_spin_unlock(_owner_lock);
>> 811a5fee: e8 d1 ab e7 00callq  82020bc4
>> <_raw_spin_unlock>
>>
>>
>>
>> We either need to fix GCC_PLUGIN_STRUCTLEAK_BYREF_ALL (and probably
>> GCC_PLUGIN_STRUCTLEAK) to insert initialization at proper places or
>> run before KASAN instrumentation (though, since the initializing
>> stores are instrumented, it already runs partially before KASAN), or
>> declare GCC_PLUGIN_STRUCTLEAK incompatible with KASAN (it's not the
>> first time we debug this).
>
> I am pretty sure that this is a fundamental issue with the plugin, and
> not specific to BYREF_ALL. BYREF_ALL just increases the number of
> occurrences, making it easier to hit this issue.
>
> I'd be fine with making the plugin mutually exclusive with KASAN.

I'm fine making it mutally exclusive: it forces KASAN to run without
the protections the plugin provides, so really, that's better to test
(i.e. the plugin could cover up bugs that KASAN might otherwise find).

-Kees

-- 
Kees Cook
Pixel Security

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 4:19 PM, Sergey Senozhatsky
 wrote:
> On (03/01/18 09:51), Dmitry Vyukov wrote:
>> > https://marc.info/?l=linux-kernel=151200883525299
>> >
>> > [..]
>> >> I feel lost a bit.
>> >
>> > Yeah... can't understand what's going on there.
>> >
>> > The last time kasan didn't like this part
>> >
>> > [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
>> >
>> > complaining that there was a write of size 4... at atomic_read().
>>
>> Hi Sergey,
>>
>> Where is that report?
>> I doubt that KASAN has instrumented a read as a write (at least there
>> are no such known cases), so perhaps it's pointing to some other
>> memory access.
>
> Hello Dmitry,
>
> I believe it's this one
>
> https://marc.info/?l=linux-kernel=151200883525299


Thanks, but now that I debugged this one, I think that one is the same issue.
Amusingly a write in READ_ONCE is actually legitimate because
GCC_PLUGIN_STRUCTLEAK emits an initializing write for __u variable in
READ_ONCE implementation.

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 4:19 PM, Sergey Senozhatsky
 wrote:
> On (03/01/18 09:51), Dmitry Vyukov wrote:
>> > https://marc.info/?l=linux-kernel=151200883525299
>> >
>> > [..]
>> >> I feel lost a bit.
>> >
>> > Yeah... can't understand what's going on there.
>> >
>> > The last time kasan didn't like this part
>> >
>> > [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
>> >
>> > complaining that there was a write of size 4... at atomic_read().
>>
>> Hi Sergey,
>>
>> Where is that report?
>> I doubt that KASAN has instrumented a read as a write (at least there
>> are no such known cases), so perhaps it's pointing to some other
>> memory access.
>
> Hello Dmitry,
>
> I believe it's this one
>
> https://marc.info/?l=linux-kernel=151200883525299


Thanks, but now that I debugged this one, I think that one is the same issue.
Amusingly a write in READ_ONCE is actually legitimate because
GCC_PLUGIN_STRUCTLEAK emits an initializing write for __u variable in
READ_ONCE implementation.

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Sergey Senozhatsky]

On (03/01/18 09:51), Dmitry Vyukov wrote:
> > https://marc.info/?l=linux-kernel=151200883525299
> >
> > [..]
> >> I feel lost a bit.
> >
> > Yeah... can't understand what's going on there.
> >
> > The last time kasan didn't like this part
> >
> > [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
> >
> > complaining that there was a write of size 4... at atomic_read().
> 
> Hi Sergey,
> 
> Where is that report?
> I doubt that KASAN has instrumented a read as a write (at least there
> are no such known cases), so perhaps it's pointing to some other
> memory access.

Hello Dmitry,

I believe it's this one

https://marc.info/?l=linux-kernel=151200883525299


-ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Sergey Senozhatsky]

On (03/01/18 09:51), Dmitry Vyukov wrote:
> > https://marc.info/?l=linux-kernel=151200883525299
> >
> > [..]
> >> I feel lost a bit.
> >
> > Yeah... can't understand what's going on there.
> >
> > The last time kasan didn't like this part
> >
> > [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
> >
> > complaining that there was a write of size 4... at atomic_read().
> 
> Hi Sergey,
> 
> Where is that report?
> I doubt that KASAN has instrumented a read as a write (at least there
> are no such known cases), so perhaps it's pointing to some other
> memory access.

Hello Dmitry,

I believe it's this one

https://marc.info/?l=linux-kernel=151200883525299


-ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Ard Biesheuvel]

On 1 March 2018 at 14:09, Dmitry Vyukov  wrote:
..
> +Ard, Kees
>
> This is a problem with GCC_PLUGIN_STRUCTLEAK_BYREF_ALL. It inserts an
> initializing write for __u used in READ_ONCE outside of live scope of
> the variable.
> Below "movb   $0x1,0x0(%r13)" and "movb   $0xf8,0x0(%r13)" denote live
> scope of the variable __u (the 0xf8 that appears in the KASAN report).
> But the initializing store at 811a5f84 (and the corresponding
> KASAN check) are outside of that scope, which causes the KASAN report.
>
>
> 811a5f61: 49 8d 9f 40 ff ff ff lea-0xc0(%r15),%rbx
> 811a5f68: 4d 8d 67 80  lea-0x80(%r15),%r12
> kernel/printk/printk.c:1600
> waiter = READ_ONCE(console_waiter);
> 811a5f79: 49 89 dd  mov%rbx,%r13
> 811a5f7c: e8 d3 4e 21 00callq  813bae54 
> <__asan_store1>
> 811a5f81: 4c 89 e7  mov%r12,%rdi
> 811a5f84: 41 c6 87 40 ff ff ff movb   $0x0,-0xc0(%r15)
> 811a5f8b: 00
> 811a5f8c: 49 c1 ed 03  shr$0x3,%r13
> 811a5f90: e8 bf 4e 21 00callq  813bae54 
> <__asan_store1>
> kernel/printk/printk.c:1599
> raw_spin_lock(_owner_lock);
> 811a5f95: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
> 811a5f9c: 41 c6 47 80 00movb   $0x0,-0x80(%r15)
> 811a5fa1: e8 92 a9 e7 00callq  82020938 
> <_raw_spin_lock>
> kernel/printk/printk.c:1600
> waiter = READ_ONCE(console_waiter);
> 811a5fa6: 4c 03 ad e8 fe ff ff add-0x118(%rbp),%r13
> __read_once_size():
> ./include/linux/compiler.h:178
> })
>
> static __always_inline
> void __read_once_size(const volatile void *p, void *res, int size)
> {
> __READ_ONCE_SIZE;
> 811a5fad: 44 8a 35 2c 7b e6 02 mov0x2e67b2c(%rip),%r14b
> # 8400dae0 
> 811a5fb4: 48 89 df  mov%rbx,%rdi
> console_lock_spinning_disable_and_check():
> kernel/printk/printk.c:1600
> 811a5fb7: 41 c6 45 00 01movb   $0x1,0x0(%r13)
> __read_once_size():
> ./include/linux/compiler.h:178
> 811a5fbc: e8 93 4e 21 00callq  813bae54 
> <__asan_store1>
> console_lock_spinning_disable_and_check():
> kernel/printk/printk.c:1600
> 811a5fc1: 48 89 df  mov%rbx,%rdi
> __read_once_size():
> ./include/linux/compiler.h:178
> 811a5fc4: 45 88 b7 40 ff ff ff mov%r14b,-0xc0(%r15)
> console_lock_spinning_disable_and_check():
> kernel/printk/printk.c:1600
> 811a5fcb: e8 3d 4e 21 00callq  813bae0d <__asan_load1>
> 811a5fd0: 45 8a b7 40 ff ff ff mov-0xc0(%r15),%r14b
> kernel/printk/printk.c:1602
> raw_spin_unlock(_owner_lock);
> 811a5fd7: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
> 811a5fde: 41 c6 45 00 f8movb   $0xf8,0x0(%r13)
> kernel/printk/printk.c:1601
> console_owner = NULL;
> 811a5fe3: 48 c7 05 32 7b e6 02 movq   $0x0,0x2e67b32(%rip)
># 8400db20 
> 811a5fea: 00 00 00 00
> kernel/printk/printk.c:1602
> raw_spin_unlock(_owner_lock);
> 811a5fee: e8 d1 ab e7 00callq  82020bc4
> <_raw_spin_unlock>
>
>
>
> We either need to fix GCC_PLUGIN_STRUCTLEAK_BYREF_ALL (and probably
> GCC_PLUGIN_STRUCTLEAK) to insert initialization at proper places or
> run before KASAN instrumentation (though, since the initializing
> stores are instrumented, it already runs partially before KASAN), or
> declare GCC_PLUGIN_STRUCTLEAK incompatible with KASAN (it's not the
> first time we debug this).

I am pretty sure that this is a fundamental issue with the plugin, and
not specific to BYREF_ALL. BYREF_ALL just increases the number of
occurrences, making it easier to hit this issue.

I'd be fine with making the plugin mutually exclusive with KASAN.

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Ard Biesheuvel]

On 1 March 2018 at 14:09, Dmitry Vyukov  wrote:
..
> +Ard, Kees
>
> This is a problem with GCC_PLUGIN_STRUCTLEAK_BYREF_ALL. It inserts an
> initializing write for __u used in READ_ONCE outside of live scope of
> the variable.
> Below "movb   $0x1,0x0(%r13)" and "movb   $0xf8,0x0(%r13)" denote live
> scope of the variable __u (the 0xf8 that appears in the KASAN report).
> But the initializing store at 811a5f84 (and the corresponding
> KASAN check) are outside of that scope, which causes the KASAN report.
>
>
> 811a5f61: 49 8d 9f 40 ff ff ff lea-0xc0(%r15),%rbx
> 811a5f68: 4d 8d 67 80  lea-0x80(%r15),%r12
> kernel/printk/printk.c:1600
> waiter = READ_ONCE(console_waiter);
> 811a5f79: 49 89 dd  mov%rbx,%r13
> 811a5f7c: e8 d3 4e 21 00callq  813bae54 
> <__asan_store1>
> 811a5f81: 4c 89 e7  mov%r12,%rdi
> 811a5f84: 41 c6 87 40 ff ff ff movb   $0x0,-0xc0(%r15)
> 811a5f8b: 00
> 811a5f8c: 49 c1 ed 03  shr$0x3,%r13
> 811a5f90: e8 bf 4e 21 00callq  813bae54 
> <__asan_store1>
> kernel/printk/printk.c:1599
> raw_spin_lock(_owner_lock);
> 811a5f95: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
> 811a5f9c: 41 c6 47 80 00movb   $0x0,-0x80(%r15)
> 811a5fa1: e8 92 a9 e7 00callq  82020938 
> <_raw_spin_lock>
> kernel/printk/printk.c:1600
> waiter = READ_ONCE(console_waiter);
> 811a5fa6: 4c 03 ad e8 fe ff ff add-0x118(%rbp),%r13
> __read_once_size():
> ./include/linux/compiler.h:178
> })
>
> static __always_inline
> void __read_once_size(const volatile void *p, void *res, int size)
> {
> __READ_ONCE_SIZE;
> 811a5fad: 44 8a 35 2c 7b e6 02 mov0x2e67b2c(%rip),%r14b
> # 8400dae0 
> 811a5fb4: 48 89 df  mov%rbx,%rdi
> console_lock_spinning_disable_and_check():
> kernel/printk/printk.c:1600
> 811a5fb7: 41 c6 45 00 01movb   $0x1,0x0(%r13)
> __read_once_size():
> ./include/linux/compiler.h:178
> 811a5fbc: e8 93 4e 21 00callq  813bae54 
> <__asan_store1>
> console_lock_spinning_disable_and_check():
> kernel/printk/printk.c:1600
> 811a5fc1: 48 89 df  mov%rbx,%rdi
> __read_once_size():
> ./include/linux/compiler.h:178
> 811a5fc4: 45 88 b7 40 ff ff ff mov%r14b,-0xc0(%r15)
> console_lock_spinning_disable_and_check():
> kernel/printk/printk.c:1600
> 811a5fcb: e8 3d 4e 21 00callq  813bae0d <__asan_load1>
> 811a5fd0: 45 8a b7 40 ff ff ff mov-0xc0(%r15),%r14b
> kernel/printk/printk.c:1602
> raw_spin_unlock(_owner_lock);
> 811a5fd7: 48 c7 c7 e0 90 b5 82 mov$0x82b590e0,%rdi
> 811a5fde: 41 c6 45 00 f8movb   $0xf8,0x0(%r13)
> kernel/printk/printk.c:1601
> console_owner = NULL;
> 811a5fe3: 48 c7 05 32 7b e6 02 movq   $0x0,0x2e67b32(%rip)
># 8400db20 
> 811a5fea: 00 00 00 00
> kernel/printk/printk.c:1602
> raw_spin_unlock(_owner_lock);
> 811a5fee: e8 d1 ab e7 00callq  82020bc4
> <_raw_spin_unlock>
>
>
>
> We either need to fix GCC_PLUGIN_STRUCTLEAK_BYREF_ALL (and probably
> GCC_PLUGIN_STRUCTLEAK) to insert initialization at proper places or
> run before KASAN instrumentation (though, since the initializing
> stores are instrumented, it already runs partially before KASAN), or
> declare GCC_PLUGIN_STRUCTLEAK incompatible with KASAN (it's not the
> first time we debug this).

I am pretty sure that this is a fundamental issue with the plugin, and
not specific to BYREF_ALL. BYREF_ALL just increases the number of
occurrences, making it easier to hit this issue.

I'd be fine with making the plugin mutually exclusive with KASAN.

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 11:06 AM, Tetsuo Handa
<from-linux...@i-love.sakura.ne.jp> wrote:
> Dmitry Vyukov wrote:
>> Hi Shun,
>>
>> The report says "job-script is attached in this email", but I don't
>> see it attached. Did you forget to attach it? How can I reproduce this
>> exact build?
>> Could you post a symbolized report with inlines frames?
>>
>
> Forwarded by penguin-ker...@i-love.sakura.ne.jp
> --- Original Message ---
>  From:Tetsuo Handa <penguin-ker...@i-love.sakura.ne.jp>
>  To:  Petr Mladek <pmla...@suse.com>
>  Cc:  kernel test robot <shun@intel.com>, Cong Wang 
> <xiyou.wangc...@gmail.com>, Dave Hansen <dave.han...@intel.com>, Johannes 
> Weiner <han...@cmpxchg.org>, Mel Gorman <mgor...@suse.de>, Michal Hocko 
> <mho...@kernel.org>, Vlastimil Babka <vba...@suse.cz>, Peter Zijlstra 
> <pet...@infradead.org>, Linus Torvalds <torva...@linux-foundation.org>, Jan 
> Kara <j...@suse.cz>, Mathieu Desnoyers <mathieu.desnoy...@efficios.com>, 
> Byungchul Park <byungchul.p...@lge.com>, Tejun Heo <t...@kernel.org>, Pavel 
> Machek <pa...@ucw.cz>, Steven Rostedt <rost...@goodmis.org>, Sergey 
> Senozhatsky <sergey.senozhat...@gmail.com>, LKML 
> <linux-kernel@vger.kernel.org>, l...@01.org
>  Date:Thu, 01 Mar 2018 10:08:19 +0900
>  Subject: Re: [lkp-robot] [printk]  c162d5b433: BUG:KASAN:use-after-scope_in_c
> 
>
> Petr Mladek wrote:
>> I am really curious what code is proceed on the line
>> console_unlock+0x185/0x960.
>
> I can reproduce this warning with VMware environment.
> Something is happening inside __asan_store1() before calling 
> raw_spin_lock(_owner_lock) ?
>
>
>
> [0.00] Kernel command line: 
> BOOT_IMAGE=/boot/vmlinuz-4.14.0-12953-gc162d5b 
> root=UUID=98df1583-260a-423a-a193-182dade5d085 ro crashkernel=256M 
> security=none sysrq_always_enabled console=ttyS0,115200n8 console=tty0 
> LANG=en_US.UTF-8
> [0.00] sysrq: sysrq always enabled.
> [0.00] Dentry cache hash table entries: 524288 (order: 10, 4194304 
> bytes)
> [0.00] Inode-cache hash table entries: 262144 (order: 9, 2097152 
> bytes)
> [0.00] Memory: 3045216K/4193716K available (15633K kernel code, 6278K 
> rwdata, 6948K rodata, 3592K init, 24228K bss, 1148500K reserved, 0K 
> cma-reserved)
> [0.00] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=64, Nodes=1
> [0.00] ftrace: allocating 34522 entries in 135 pages
> [0.00] Running RCU self tests
> [0.00] Hierarchical RCU implementation.
> [0.00]  RCU event tracing is enabled.
> [0.00]  RCU dyntick-idle grace-period acceleration is enabled.
> [0.00]  RCU lockdep checking is enabled.
> [0.00]  Tasks RCU enabled.
> [0.00] NR_IRQS: 4352, nr_irqs: 936, preallocated irqs: 16
> [0.00]  Offload RCU callbacks from CPUs: .
> [0.00] 
> ==
> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> [0.00] Write of size 1 at addr 828079b8 by task swapper/0
> [0.00]
> [0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b 
> #414
> [0.00] Call Trace:
> [0.00]  ? dump_stack+0x11d/0x1c5
> [0.00]  ? printk+0xb5/0xd1
> [0.00]  ? arch_local_irq_restore+0x17/0x17
> [0.00]  ? do_raw_spin_unlock+0x137/0x169
> [0.00]  ? irq_trace+0x2e/0x32
> [0.00]  ? console_unlock+0x185/0x960
> [0.00]  ? print_address_description+0x6e/0x23b
> [0.00]  ? console_unlock+0x185/0x960
> [0.00]  ? kasan_report+0x223/0x249
> [0.00]  ? console_unlock+0x185/0x960
> [0.00]  ? wake_up_klogd+0xdf/0xdf
> [0.00]  ? do_raw_spin_unlock+0x145/0x169
> [0.00]  ? do_raw_spin_trylock+0xed/0xed
> [0.00]  ? irq_trace+0x2e/0x32
> [0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
> [0.00]  ? time_hardirqs_off+0x12/0x2d
> [0.00]  ? arch_local_save_flags+0x7/0x8
> [0.00]  ? trace_hardirqs_off_caller+0x127/0x139
> [0.00]  ? irq_trace+0x2e/0x32
> [0.00]  ? vprintk_emit+0x579/0x823
> [0.00]  ? __down_trylock_console_sem+0x90/0xa4
> [0.00]  ? __down_trylock_console_sem+0x9d/0xa4
> [0.00]  ? vprintk_emit+0x7ec/0x823
> [0.00]  ? console_unlock+0x960/0x960
> [0.00]  ? memblock_merge_regions+0x2d/0x154
> [0.00]  ? memblock_add_range+0x322/0x333
> [0.00]  ? memblock_reserve+0xbb/0xe1
> [0

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 11:06 AM, Tetsuo Handa
 wrote:
> Dmitry Vyukov wrote:
>> Hi Shun,
>>
>> The report says "job-script is attached in this email", but I don't
>> see it attached. Did you forget to attach it? How can I reproduce this
>> exact build?
>> Could you post a symbolized report with inlines frames?
>>
>
> Forwarded by penguin-ker...@i-love.sakura.ne.jp
> --- Original Message ---
>  From:Tetsuo Handa 
>  To:  Petr Mladek 
>  Cc:  kernel test robot , Cong Wang 
> , Dave Hansen , Johannes 
> Weiner , Mel Gorman , Michal Hocko 
> , Vlastimil Babka , Peter Zijlstra 
> , Linus Torvalds , Jan 
> Kara , Mathieu Desnoyers , 
> Byungchul Park , Tejun Heo , Pavel 
> Machek , Steven Rostedt , Sergey 
> Senozhatsky , LKML 
> , l...@01.org
>  Date:    Thu, 01 Mar 2018 10:08:19 +0900
>  Subject: Re: [lkp-robot] [printk]  c162d5b433: BUG:KASAN:use-after-scope_in_c
> 
>
> Petr Mladek wrote:
>> I am really curious what code is proceed on the line
>> console_unlock+0x185/0x960.
>
> I can reproduce this warning with VMware environment.
> Something is happening inside __asan_store1() before calling 
> raw_spin_lock(_owner_lock) ?
>
>
>
> [0.00] Kernel command line: 
> BOOT_IMAGE=/boot/vmlinuz-4.14.0-12953-gc162d5b 
> root=UUID=98df1583-260a-423a-a193-182dade5d085 ro crashkernel=256M 
> security=none sysrq_always_enabled console=ttyS0,115200n8 console=tty0 
> LANG=en_US.UTF-8
> [0.00] sysrq: sysrq always enabled.
> [0.00] Dentry cache hash table entries: 524288 (order: 10, 4194304 
> bytes)
> [0.00] Inode-cache hash table entries: 262144 (order: 9, 2097152 
> bytes)
> [0.00] Memory: 3045216K/4193716K available (15633K kernel code, 6278K 
> rwdata, 6948K rodata, 3592K init, 24228K bss, 1148500K reserved, 0K 
> cma-reserved)
> [0.00] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=64, Nodes=1
> [0.00] ftrace: allocating 34522 entries in 135 pages
> [0.00] Running RCU self tests
> [0.00] Hierarchical RCU implementation.
> [0.00]  RCU event tracing is enabled.
> [0.00]  RCU dyntick-idle grace-period acceleration is enabled.
> [0.00]  RCU lockdep checking is enabled.
> [0.00]  Tasks RCU enabled.
> [0.00] NR_IRQS: 4352, nr_irqs: 936, preallocated irqs: 16
> [0.00]  Offload RCU callbacks from CPUs: .
> [0.00] 
> ==
> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> [0.00] Write of size 1 at addr 828079b8 by task swapper/0
> [0.00]
> [0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b 
> #414
> [0.00] Call Trace:
> [0.00]  ? dump_stack+0x11d/0x1c5
> [0.00]  ? printk+0xb5/0xd1
> [0.00]  ? arch_local_irq_restore+0x17/0x17
> [0.00]  ? do_raw_spin_unlock+0x137/0x169
> [0.00]  ? irq_trace+0x2e/0x32
> [0.00]  ? console_unlock+0x185/0x960
> [0.00]  ? print_address_description+0x6e/0x23b
> [0.00]  ? console_unlock+0x185/0x960
> [0.00]  ? kasan_report+0x223/0x249
> [0.00]  ? console_unlock+0x185/0x960
> [0.00]  ? wake_up_klogd+0xdf/0xdf
> [0.00]  ? do_raw_spin_unlock+0x145/0x169
> [0.00]  ? do_raw_spin_trylock+0xed/0xed
> [0.00]  ? irq_trace+0x2e/0x32
> [0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
> [0.00]  ? time_hardirqs_off+0x12/0x2d
> [0.00]  ? arch_local_save_flags+0x7/0x8
> [0.00]  ? trace_hardirqs_off_caller+0x127/0x139
> [0.00]  ? irq_trace+0x2e/0x32
> [0.00]  ? vprintk_emit+0x579/0x823
> [0.00]  ? __down_trylock_console_sem+0x90/0xa4
> [0.00]  ? __down_trylock_console_sem+0x9d/0xa4
> [0.00]  ? vprintk_emit+0x7ec/0x823
> [0.00]  ? console_unlock+0x960/0x960
> [0.00]  ? memblock_merge_regions+0x2d/0x154
> [0.00]  ? memblock_add_range+0x322/0x333
> [0.00]  ? memblock_reserve+0xbb/0xe1
> [0.00]  ? memblock_add+0xe1/0xe1
> [0.00]  ? set_pte+0x24/0x27
> [0.00]  ? vprintk_func+0x94/0xa5
> [0.00]  ? printk+0xb5/0xd1
> [0.00]  ? show_regs_print_info+0x41/0x41
> [0.00]  ? kasan_populate_zero_shadow+0x37b/0x3f6
> [0.00]  ? native_flush_tlb_global+0x74/0x80
> [0.00]  ? kasan_init+0x211/0x22d
> [0.00]  ? setup_arch+0xdfa/0xf3c
> [0.00]  ? css_set_populated+0x79/0x79
> [0.00]  ? reserve_standard_io_resources+0x39/0x39
> [0.00]  ? vprintk_fun

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Tetsuo Handa]

Dmitry Vyukov wrote:
> Hi Shun,
> 
> The report says "job-script is attached in this email", but I don't
> see it attached. Did you forget to attach it? How can I reproduce this
> exact build?
> Could you post a symbolized report with inlines frames?
> 

Forwarded by penguin-ker...@i-love.sakura.ne.jp
--- Original Message ---
 From:Tetsuo Handa <penguin-ker...@i-love.sakura.ne.jp>
 To:  Petr Mladek <pmla...@suse.com>
 Cc:  kernel test robot <shun@intel.com>, Cong Wang 
<xiyou.wangc...@gmail.com>, Dave Hansen <dave.han...@intel.com>, Johannes 
Weiner <han...@cmpxchg.org>, Mel Gorman <mgor...@suse.de>, Michal Hocko 
<mho...@kernel.org>, Vlastimil Babka <vba...@suse.cz>, Peter Zijlstra 
<pet...@infradead.org>, Linus Torvalds <torva...@linux-foundation.org>, Jan 
Kara <j...@suse.cz>, Mathieu Desnoyers <mathieu.desnoy...@efficios.com>, 
Byungchul Park <byungchul.p...@lge.com>, Tejun Heo <t...@kernel.org>, Pavel 
Machek <pa...@ucw.cz>, Steven Rostedt <rost...@goodmis.org>, Sergey Senozhatsky 
<sergey.senozhat...@gmail.com>, LKML <linux-kernel@vger.kernel.org>, l...@01.org
 Date:Thu, 01 Mar 2018 10:08:19 +0900
 Subject: Re: [lkp-robot] [printk]  c162d5b433: BUG:KASAN:use-after-scope_in_c


Petr Mladek wrote:
> I am really curious what code is proceed on the line
> console_unlock+0x185/0x960.

I can reproduce this warning with VMware environment.
Something is happening inside __asan_store1() before calling 
raw_spin_lock(_owner_lock) ?



[0.00] Kernel command line: 
BOOT_IMAGE=/boot/vmlinuz-4.14.0-12953-gc162d5b 
root=UUID=98df1583-260a-423a-a193-182dade5d085 ro crashkernel=256M 
security=none sysrq_always_enabled console=ttyS0,115200n8 console=tty0 
LANG=en_US.UTF-8
[0.00] sysrq: sysrq always enabled.
[0.00] Dentry cache hash table entries: 524288 (order: 10, 4194304 
bytes)
[0.00] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[0.00] Memory: 3045216K/4193716K available (15633K kernel code, 6278K 
rwdata, 6948K rodata, 3592K init, 24228K bss, 1148500K reserved, 0K 
cma-reserved)
[0.00] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=64, Nodes=1
[0.00] ftrace: allocating 34522 entries in 135 pages
[0.00] Running RCU self tests
[0.00] Hierarchical RCU implementation.
[0.00]  RCU event tracing is enabled.
[0.00]  RCU dyntick-idle grace-period acceleration is enabled.
[0.00]  RCU lockdep checking is enabled.
[0.00]  Tasks RCU enabled.
[0.00] NR_IRQS: 4352, nr_irqs: 936, preallocated irqs: 16
[0.00]  Offload RCU callbacks from CPUs: .
[0.00] 
==
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] Write of size 1 at addr 828079b8 by task swapper/0
[0.00] 
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b 
#414
[0.00] Call Trace:
[0.00]  ? dump_stack+0x11d/0x1c5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? arch_local_irq_restore+0x17/0x17
[0.00]  ? do_raw_spin_unlock+0x137/0x169
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? print_address_description+0x6e/0x23b
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? kasan_report+0x223/0x249
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? wake_up_klogd+0xdf/0xdf
[0.00]  ? do_raw_spin_unlock+0x145/0x169
[0.00]  ? do_raw_spin_trylock+0xed/0xed
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
[0.00]  ? time_hardirqs_off+0x12/0x2d
[0.00]  ? arch_local_save_flags+0x7/0x8
[0.00]  ? trace_hardirqs_off_caller+0x127/0x139
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? vprintk_emit+0x579/0x823
[0.00]  ? __down_trylock_console_sem+0x90/0xa4
[0.00]  ? __down_trylock_console_sem+0x9d/0xa4
[0.00]  ? vprintk_emit+0x7ec/0x823
[0.00]  ? console_unlock+0x960/0x960
[0.00]  ? memblock_merge_regions+0x2d/0x154
[0.00]  ? memblock_add_range+0x322/0x333
[0.00]  ? memblock_reserve+0xbb/0xe1
[0.00]  ? memblock_add+0xe1/0xe1
[0.00]  ? set_pte+0x24/0x27
[0.00]  ? vprintk_func+0x94/0xa5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? show_regs_print_info+0x41/0x41
[0.00]  ? kasan_populate_zero_shadow+0x37b/0x3f6
[0.00]  ? native_flush_tlb_global+0x74/0x80
[0.00]  ? kasan_init+0x211/0x22d
[0.00]  ? setup_arch+0xdfa/0xf3c
[0.00]  ? css_set_populated+0x79/0x79
[0.00]  ? reserve_standard_io_resources+0x39/0x39
[0.00]  ? vprintk_func+0x9d/0xa5
[0.00]  ?

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Tetsuo Handa]

Dmitry Vyukov wrote:
> Hi Shun,
> 
> The report says "job-script is attached in this email", but I don't
> see it attached. Did you forget to attach it? How can I reproduce this
> exact build?
> Could you post a symbolized report with inlines frames?
> 

Forwarded by penguin-ker...@i-love.sakura.ne.jp
--- Original Message ---
 From:Tetsuo Handa 
 To:  Petr Mladek 
 Cc:  kernel test robot , Cong Wang 
, Dave Hansen , Johannes 
Weiner , Mel Gorman , Michal Hocko 
, Vlastimil Babka , Peter Zijlstra 
, Linus Torvalds , Jan 
Kara , Mathieu Desnoyers , 
Byungchul Park , Tejun Heo , Pavel 
Machek , Steven Rostedt , Sergey Senozhatsky 
, LKML , l...@01.org
 Date:Thu, 01 Mar 2018 10:08:19 +0900
 Subject: Re: [lkp-robot] [printk]  c162d5b433: BUG:KASAN:use-after-scope_in_c


Petr Mladek wrote:
> I am really curious what code is proceed on the line
> console_unlock+0x185/0x960.

I can reproduce this warning with VMware environment.
Something is happening inside __asan_store1() before calling 
raw_spin_lock(_owner_lock) ?



[0.00] Kernel command line: 
BOOT_IMAGE=/boot/vmlinuz-4.14.0-12953-gc162d5b 
root=UUID=98df1583-260a-423a-a193-182dade5d085 ro crashkernel=256M 
security=none sysrq_always_enabled console=ttyS0,115200n8 console=tty0 
LANG=en_US.UTF-8
[0.00] sysrq: sysrq always enabled.
[0.00] Dentry cache hash table entries: 524288 (order: 10, 4194304 
bytes)
[0.00] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[0.00] Memory: 3045216K/4193716K available (15633K kernel code, 6278K 
rwdata, 6948K rodata, 3592K init, 24228K bss, 1148500K reserved, 0K 
cma-reserved)
[0.00] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=64, Nodes=1
[0.00] ftrace: allocating 34522 entries in 135 pages
[0.00] Running RCU self tests
[0.00] Hierarchical RCU implementation.
[0.00]  RCU event tracing is enabled.
[0.00]  RCU dyntick-idle grace-period acceleration is enabled.
[0.00]  RCU lockdep checking is enabled.
[0.00]  Tasks RCU enabled.
[0.00] NR_IRQS: 4352, nr_irqs: 936, preallocated irqs: 16
[0.00]  Offload RCU callbacks from CPUs: .
[0.00] 
==
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] Write of size 1 at addr 828079b8 by task swapper/0
[0.00] 
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b 
#414
[0.00] Call Trace:
[0.00]  ? dump_stack+0x11d/0x1c5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? arch_local_irq_restore+0x17/0x17
[0.00]  ? do_raw_spin_unlock+0x137/0x169
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? print_address_description+0x6e/0x23b
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? kasan_report+0x223/0x249
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? wake_up_klogd+0xdf/0xdf
[0.00]  ? do_raw_spin_unlock+0x145/0x169
[0.00]  ? do_raw_spin_trylock+0xed/0xed
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
[0.00]  ? time_hardirqs_off+0x12/0x2d
[0.00]  ? arch_local_save_flags+0x7/0x8
[0.00]  ? trace_hardirqs_off_caller+0x127/0x139
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? vprintk_emit+0x579/0x823
[0.00]  ? __down_trylock_console_sem+0x90/0xa4
[0.00]  ? __down_trylock_console_sem+0x9d/0xa4
[0.00]  ? vprintk_emit+0x7ec/0x823
[0.00]  ? console_unlock+0x960/0x960
[0.00]  ? memblock_merge_regions+0x2d/0x154
[0.00]  ? memblock_add_range+0x322/0x333
[0.00]  ? memblock_reserve+0xbb/0xe1
[0.00]  ? memblock_add+0xe1/0xe1
[0.00]  ? set_pte+0x24/0x27
[0.00]  ? vprintk_func+0x94/0xa5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? show_regs_print_info+0x41/0x41
[0.00]  ? kasan_populate_zero_shadow+0x37b/0x3f6
[0.00]  ? native_flush_tlb_global+0x74/0x80
[0.00]  ? kasan_init+0x211/0x22d
[0.00]  ? setup_arch+0xdfa/0xf3c
[0.00]  ? css_set_populated+0x79/0x79
[0.00]  ? reserve_standard_io_resources+0x39/0x39
[0.00]  ? vprintk_func+0x9d/0xa5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? show_regs_print_info+0x41/0x41
[0.00]  ? start_kernel+0xa2/0x515
[0.00]  ? mem_encrypt_init+0xa/0xa
[0.00]  ? x86_family+0x2e/0x33
[0.00]  ? load_ucode_bsp+0x58/0xec
[0.00]  ? secondary_startup_64+0xa5/0xb0
[0.00] 
[0.00] 
[0.00] Memory state around the buggy address:
[0.00]  82807880: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
00
[0.00]  82807900: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
00
[0.00] >f

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 2:37 AM, Sergey Senozhatsky
 wrote:
> Hello,
>
> Cc-ing Dmitry Vyukov and kasan-dev on this.
>
> On (02/28/18 16:59), Petr Mladek wrote:
> [..]
>> > >
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> >
>> > Is there any change to get disassembly of console_unlock() from the
>> > problematic build?
>> >
>> > I have troubles to reproduce this myself. Also I was not able to find any
>> > bug just by looking into the code yet. The disassembly might help
>> > a lot here.
>> >
>> >
>> > Interesting symptoms (for myself and other debuggers):
>> >
>> > The lines are duplicated. Therefore it happened when real
>> > console was registered and before the early console was unregistered.
>> > See also the full dmesg for these actions. The related printk messages
>> > are right after the KASAN report.
>> >
>> > I wonder if it is unsafe to pass the console_lock via
>> > console_trylock_spinnning() from console_unlock() called
>> > in register_console(). I do not see any problem but I might
>> > be blind.
>
> I'm not sure it we actually have concurrent printks at that state yet,
> might be too early for any printk offloading. The backtrace still
> makes no sense to me at all, tho. We had this report twice, probably,
> already (even before the offloading patchset, if I'm not mistaken).
>
> https://marc.info/?l=linux-kernel=151200883525299
>
> [..]
>> I feel lost a bit.
>
> Yeah... can't understand what's going on there.
>
> The last time kasan didn't like this part
>
> [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
>
> complaining that there was a write of size 4... at atomic_read().

Hi Sergey,

Where is that report?
I doubt that KASAN has instrumented a read as a write (at least there
are no such known cases), so perhaps it's pointing to some other
memory access.


> Now it's reporting that the write of size 1 was out of scope.
>
>> I am really curious what code is proceed on the line
>> console_unlock+0x185/0x960.
>
> Agreed.
>
> On my system 0x185/0x960 is somewhere around
>
>
>  191e:   89 d7   mov%edx,%edi
>  1920:   e8 06 e7 ff ff  callq  2b 
>  1925:   48 89 2d 00 00 00 00mov%rbp,0x0(%rip)# 192c 
> 
>  192c:   89 05 00 00 00 00   mov%eax,0x0(%rip)# 1932 
> 
>>>   1932:   eb a9   jmp18dd 
>  1934:   8b 35 00 00 00 00   mov0x0(%rip),%esi# 193a 
> 
>  193a:   b9 00 04 00 00  mov$0x400,%ecx
>  193f:   4c 89 efmov%r13,%rdi
>  1942:   31 ed   xor%ebp,%ebp

For a KASAN report IP must point to one of __asan_[report_]load/store function.

> That jmp 18dd after log_next() is a `goto skip' in
> suppress_message_printing() branch
>
> skip:
> if (console_seq == log_next_seq)
> break;
>
> msg = log_from_idx(console_idx);
> if (suppress_message_printing(msg->level)) {
> /*
>  * Skip record we have buffered and already printed
>  * directly to the console when we received it, and
>  * record that has level above the console loglevel.
>  */
> console_idx = log_next(console_idx);
> console_seq++;
>>>  goto skip;
> }
>
>
> As far as I can tell.
>
> -ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 2:37 AM, Sergey Senozhatsky
 wrote:
> Hello,
>
> Cc-ing Dmitry Vyukov and kasan-dev on this.
>
> On (02/28/18 16:59), Petr Mladek wrote:
> [..]
>> > >
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> >
>> > Is there any change to get disassembly of console_unlock() from the
>> > problematic build?
>> >
>> > I have troubles to reproduce this myself. Also I was not able to find any
>> > bug just by looking into the code yet. The disassembly might help
>> > a lot here.
>> >
>> >
>> > Interesting symptoms (for myself and other debuggers):
>> >
>> > The lines are duplicated. Therefore it happened when real
>> > console was registered and before the early console was unregistered.
>> > See also the full dmesg for these actions. The related printk messages
>> > are right after the KASAN report.
>> >
>> > I wonder if it is unsafe to pass the console_lock via
>> > console_trylock_spinnning() from console_unlock() called
>> > in register_console(). I do not see any problem but I might
>> > be blind.
>
> I'm not sure it we actually have concurrent printks at that state yet,
> might be too early for any printk offloading. The backtrace still
> makes no sense to me at all, tho. We had this report twice, probably,
> already (even before the offloading patchset, if I'm not mistaken).
>
> https://marc.info/?l=linux-kernel=151200883525299
>
> [..]
>> I feel lost a bit.
>
> Yeah... can't understand what's going on there.
>
> The last time kasan didn't like this part
>
> [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
>
> complaining that there was a write of size 4... at atomic_read().

Hi Sergey,

Where is that report?
I doubt that KASAN has instrumented a read as a write (at least there
are no such known cases), so perhaps it's pointing to some other
memory access.


> Now it's reporting that the write of size 1 was out of scope.
>
>> I am really curious what code is proceed on the line
>> console_unlock+0x185/0x960.
>
> Agreed.
>
> On my system 0x185/0x960 is somewhere around
>
>
>  191e:   89 d7   mov%edx,%edi
>  1920:   e8 06 e7 ff ff  callq  2b 
>  1925:   48 89 2d 00 00 00 00mov%rbp,0x0(%rip)# 192c 
> 
>  192c:   89 05 00 00 00 00   mov%eax,0x0(%rip)# 1932 
> 
>>>   1932:   eb a9   jmp18dd 
>  1934:   8b 35 00 00 00 00   mov0x0(%rip),%esi# 193a 
> 
>  193a:   b9 00 04 00 00  mov$0x400,%ecx
>  193f:   4c 89 efmov%r13,%rdi
>  1942:   31 ed   xor%ebp,%ebp

For a KASAN report IP must point to one of __asan_[report_]load/store function.

> That jmp 18dd after log_next() is a `goto skip' in
> suppress_message_printing() branch
>
> skip:
> if (console_seq == log_next_seq)
> break;
>
> msg = log_from_idx(console_idx);
> if (suppress_message_printing(msg->level)) {
> /*
>  * Skip record we have buffered and already printed
>  * directly to the console when we received it, and
>  * record that has level above the console loglevel.
>  */
> console_idx = log_next(console_idx);
> console_seq++;
>>>  goto skip;
> }
>
>
> As far as I can tell.
>
> -ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 2:37 AM, Sergey Senozhatsky
 wrote:
> Hello,
>
> Cc-ing Dmitry Vyukov and kasan-dev on this.
>
> On (02/28/18 16:59), Petr Mladek wrote:
> [..]
>> > >
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> >
>> > Is there any change to get disassembly of console_unlock() from the
>> > problematic build?
>> >
>> > I have troubles to reproduce this myself. Also I was not able to find any
>> > bug just by looking into the code yet. The disassembly might help
>> > a lot here.
>> >
>> >
>> > Interesting symptoms (for myself and other debuggers):
>> >
>> > The lines are duplicated. Therefore it happened when real
>> > console was registered and before the early console was unregistered.
>> > See also the full dmesg for these actions. The related printk messages
>> > are right after the KASAN report.
>> >
>> > I wonder if it is unsafe to pass the console_lock via
>> > console_trylock_spinnning() from console_unlock() called
>> > in register_console(). I do not see any problem but I might
>> > be blind.
>
> I'm not sure it we actually have concurrent printks at that state yet,
> might be too early for any printk offloading. The backtrace still
> makes no sense to me at all, tho. We had this report twice, probably,
> already (even before the offloading patchset, if I'm not mistaken).
>
> https://marc.info/?l=linux-kernel=151200883525299
>
> [..]
>> I feel lost a bit.
>
> Yeah... can't understand what's going on there.
>
> The last time kasan didn't like this part
>
> [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
>
> complaining that there was a write of size 4... at atomic_read().
>
> Now it's reporting that the write of size 1 was out of scope.
>
>> I am really curious what code is proceed on the line
>> console_unlock+0x185/0x960.
>
> Agreed.
>
> On my system 0x185/0x960 is somewhere around
>
>
>  191e:   89 d7   mov%edx,%edi
>  1920:   e8 06 e7 ff ff  callq  2b 
>  1925:   48 89 2d 00 00 00 00mov%rbp,0x0(%rip)# 192c 
> 
>  192c:   89 05 00 00 00 00   mov%eax,0x0(%rip)# 1932 
> 
>>>   1932:   eb a9   jmp18dd 
>  1934:   8b 35 00 00 00 00   mov0x0(%rip),%esi# 193a 
> 
>  193a:   b9 00 04 00 00  mov$0x400,%ecx
>  193f:   4c 89 efmov%r13,%rdi
>  1942:   31 ed   xor%ebp,%ebp
>
>
> That jmp 18dd after log_next() is a `goto skip' in
> suppress_message_printing() branch
>
> skip:
> if (console_seq == log_next_seq)
> break;
>
> msg = log_from_idx(console_idx);
> if (suppress_message_printing(msg->level)) {
> /*
>  * Skip record we have buffered and already printed
>  * directly to the console when we received it, and
>  * record that has level above the console loglevel.
>  */
> console_idx = log_next(console_idx);
> console_seq++;
>>>  goto skip;
> }
>
>
> As far as I can tell.


Hi Shun,

The report says "job-script is attached in this email", but I don't
see it attached. Did you forget to attach it? How can I reproduce this
exact build?
Could you post a symbolized report with inlines frames?

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Dmitry Vyukov]

On Thu, Mar 1, 2018 at 2:37 AM, Sergey Senozhatsky
 wrote:
> Hello,
>
> Cc-ing Dmitry Vyukov and kasan-dev on this.
>
> On (02/28/18 16:59), Petr Mladek wrote:
> [..]
>> > >
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
>> >
>> > Is there any change to get disassembly of console_unlock() from the
>> > problematic build?
>> >
>> > I have troubles to reproduce this myself. Also I was not able to find any
>> > bug just by looking into the code yet. The disassembly might help
>> > a lot here.
>> >
>> >
>> > Interesting symptoms (for myself and other debuggers):
>> >
>> > The lines are duplicated. Therefore it happened when real
>> > console was registered and before the early console was unregistered.
>> > See also the full dmesg for these actions. The related printk messages
>> > are right after the KASAN report.
>> >
>> > I wonder if it is unsafe to pass the console_lock via
>> > console_trylock_spinnning() from console_unlock() called
>> > in register_console(). I do not see any problem but I might
>> > be blind.
>
> I'm not sure it we actually have concurrent printks at that state yet,
> might be too early for any printk offloading. The backtrace still
> makes no sense to me at all, tho. We had this report twice, probably,
> already (even before the offloading patchset, if I'm not mistaken).
>
> https://marc.info/?l=linux-kernel=151200883525299
>
> [..]
>> I feel lost a bit.
>
> Yeah... can't understand what's going on there.
>
> The last time kasan didn't like this part
>
> [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
>
> complaining that there was a write of size 4... at atomic_read().
>
> Now it's reporting that the write of size 1 was out of scope.
>
>> I am really curious what code is proceed on the line
>> console_unlock+0x185/0x960.
>
> Agreed.
>
> On my system 0x185/0x960 is somewhere around
>
>
>  191e:   89 d7   mov%edx,%edi
>  1920:   e8 06 e7 ff ff  callq  2b 
>  1925:   48 89 2d 00 00 00 00mov%rbp,0x0(%rip)# 192c 
> 
>  192c:   89 05 00 00 00 00   mov%eax,0x0(%rip)# 1932 
> 
>>>   1932:   eb a9   jmp18dd 
>  1934:   8b 35 00 00 00 00   mov0x0(%rip),%esi# 193a 
> 
>  193a:   b9 00 04 00 00  mov$0x400,%ecx
>  193f:   4c 89 efmov%r13,%rdi
>  1942:   31 ed   xor%ebp,%ebp
>
>
> That jmp 18dd after log_next() is a `goto skip' in
> suppress_message_printing() branch
>
> skip:
> if (console_seq == log_next_seq)
> break;
>
> msg = log_from_idx(console_idx);
> if (suppress_message_printing(msg->level)) {
> /*
>  * Skip record we have buffered and already printed
>  * directly to the console when we received it, and
>  * record that has level above the console loglevel.
>  */
> console_idx = log_next(console_idx);
> console_seq++;
>>>  goto skip;
> }
>
>
> As far as I can tell.


Hi Shun,

The report says "job-script is attached in this email", but I don't
see it attached. Did you forget to attach it? How can I reproduce this
exact build?
Could you post a symbolized report with inlines frames?

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Sergey Senozhatsky]

Hello,

Cc-ing Dmitry Vyukov and kasan-dev on this.

On (02/28/18 16:59), Petr Mladek wrote:
[..]
> > > 
> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> > 
> > Is there any change to get disassembly of console_unlock() from the
> > problematic build?
> > 
> > I have troubles to reproduce this myself. Also I was not able to find any
> > bug just by looking into the code yet. The disassembly might help
> > a lot here.
> > 
> > 
> > Interesting symptoms (for myself and other debuggers):
> > 
> > The lines are duplicated. Therefore it happened when real
> > console was registered and before the early console was unregistered.
> > See also the full dmesg for these actions. The related printk messages
> > are right after the KASAN report.
> > 
> > I wonder if it is unsafe to pass the console_lock via
> > console_trylock_spinnning() from console_unlock() called
> > in register_console(). I do not see any problem but I might
> > be blind.

I'm not sure it we actually have concurrent printks at that state yet,
might be too early for any printk offloading. The backtrace still
makes no sense to me at all, tho. We had this report twice, probably,
already (even before the offloading patchset, if I'm not mistaken).

https://marc.info/?l=linux-kernel=151200883525299

[..]
> I feel lost a bit.

Yeah... can't understand what's going on there.

The last time kasan didn't like this part

[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

complaining that there was a write of size 4... at atomic_read().

Now it's reporting that the write of size 1 was out of scope.

> I am really curious what code is proceed on the line
> console_unlock+0x185/0x960.

Agreed.

On my system 0x185/0x960 is somewhere around


 191e:   89 d7   mov%edx,%edi
 1920:   e8 06 e7 ff ff  callq  2b 
 1925:   48 89 2d 00 00 00 00mov%rbp,0x0(%rip)# 192c 

 192c:   89 05 00 00 00 00   mov%eax,0x0(%rip)# 1932 

>>   1932:   eb a9   jmp18dd 
 1934:   8b 35 00 00 00 00   mov0x0(%rip),%esi# 193a 

 193a:   b9 00 04 00 00  mov$0x400,%ecx
 193f:   4c 89 efmov%r13,%rdi
 1942:   31 ed   xor%ebp,%ebp


That jmp 18dd after log_next() is a `goto skip' in
suppress_message_printing() branch

skip:
if (console_seq == log_next_seq)
break;

msg = log_from_idx(console_idx);
if (suppress_message_printing(msg->level)) {
/*
 * Skip record we have buffered and already printed
 * directly to the console when we received it, and
 * record that has level above the console loglevel.
 */
console_idx = log_next(console_idx);
console_seq++;
>>  goto skip;
}


As far as I can tell.

-ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Sergey Senozhatsky]

Hello,

Cc-ing Dmitry Vyukov and kasan-dev on this.

On (02/28/18 16:59), Petr Mladek wrote:
[..]
> > > 
> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> > > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> > 
> > Is there any change to get disassembly of console_unlock() from the
> > problematic build?
> > 
> > I have troubles to reproduce this myself. Also I was not able to find any
> > bug just by looking into the code yet. The disassembly might help
> > a lot here.
> > 
> > 
> > Interesting symptoms (for myself and other debuggers):
> > 
> > The lines are duplicated. Therefore it happened when real
> > console was registered and before the early console was unregistered.
> > See also the full dmesg for these actions. The related printk messages
> > are right after the KASAN report.
> > 
> > I wonder if it is unsafe to pass the console_lock via
> > console_trylock_spinnning() from console_unlock() called
> > in register_console(). I do not see any problem but I might
> > be blind.

I'm not sure it we actually have concurrent printks at that state yet,
might be too early for any printk offloading. The backtrace still
makes no sense to me at all, tho. We had this report twice, probably,
already (even before the offloading patchset, if I'm not mistaken).

https://marc.info/?l=linux-kernel=151200883525299

[..]
> I feel lost a bit.

Yeah... can't understand what's going on there.

The last time kasan didn't like this part

[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

complaining that there was a write of size 4... at atomic_read().

Now it's reporting that the write of size 1 was out of scope.

> I am really curious what code is proceed on the line
> console_unlock+0x185/0x960.

Agreed.

On my system 0x185/0x960 is somewhere around


 191e:   89 d7   mov%edx,%edi
 1920:   e8 06 e7 ff ff  callq  2b 
 1925:   48 89 2d 00 00 00 00mov%rbp,0x0(%rip)# 192c 

 192c:   89 05 00 00 00 00   mov%eax,0x0(%rip)# 1932 

>>   1932:   eb a9   jmp18dd 
 1934:   8b 35 00 00 00 00   mov0x0(%rip),%esi# 193a 

 193a:   b9 00 04 00 00  mov$0x400,%ecx
 193f:   4c 89 efmov%r13,%rdi
 1942:   31 ed   xor%ebp,%ebp


That jmp 18dd after log_next() is a `goto skip' in
suppress_message_printing() branch

skip:
if (console_seq == log_next_seq)
break;

msg = log_from_idx(console_idx);
if (suppress_message_printing(msg->level)) {
/*
 * Skip record we have buffered and already printed
 * directly to the console when we received it, and
 * record that has level above the console loglevel.
 */
console_idx = log_next(console_idx);
console_seq++;
>>  goto skip;
}


As far as I can tell.

-ss

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Petr Mladek]

On Wed 2018-02-28 11:23:34, Petr Mladek wrote:
> On Sat 2018-02-24 13:34:05, kernel test robot wrote:
> > TO: Petr Mladek 
> > CC: Cong Wang , Dave Hansen 
> > , Johannes Weiner , Mel Gorman 
> > , Michal Hocko , Vlastimil Babka 
> > , Peter Zijlstra , Linus Torvalds 
> > , Jan Kara , Mathieu Desnoyers 
> > , Tetsuo Handa 
> > , Byungchul Park 
> > , Tejun Heo , Pavel Machek 
> > , Steven Rostedt (VMware) , Sergey 
> > Senozhatsky , LKML 
> > , linux-kernel@vger.kernel.org, l...@01.org
> > 
> > 
> > 
> > FYI, we noticed the following commit (built with gcc-7):
> > 
> > commit: c162d5b4338d72deed61aa65ed0f2f4ba2bbc8ab ("printk: Hide console 
> > waiter logic into helpers")
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> > 
> > in testcase: boot
> > 
> > on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G
> > 
> > caused below changes (please refer to attached dmesg/kmsg for entire 
> > log/backtrace):
> > 
> > 
> > ++++
> > || dbdda842fe | c162d5b433 |
> > ++++
> > | boot_successes | 0  | 0  |
> > | boot_failures  | 18 | 16 |
> > | BUG:KASAN:use-after-scope_in_p | 18 ||
> > | BUG:KASAN:use-after-scope_in_c | 0  | 16 |
> > ++++
> > 
> > 
> > 
> > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> 
> Is there any change to get disassembly of console_unlock() from the
> problematic build?
> 
> I have troubles to reproduce this myself. Also I was not able to find any
> bug just by looking into the code yet. The disassembly might help
> a lot here.
> 
> 
> Interesting symptoms (for myself and other debuggers):
> 
> The lines are duplicated. Therefore it happened when real
> console was registered and before the early console was unregistered.
> See also the full dmesg for these actions. The related printk messages
> are right after the KASAN report.
> 
> I wonder if it is unsafe to pass the console_lock via
> console_trylock_spinnning() from console_unlock() called
> in register_console(). I do not see any problem but I might
> be blind.

The KASAN report is between the following lines in dmesg:

[0.00]  Offload RCU callbacks from CPUs: .
[0.00] 
==
[0.00] 
==
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[...]
[0.00] console [ttyS0] enabled

The first message is printed from rcu_init_nohz().
The last message is printed from register_console().

I would expect that the KASAN message is triggered from the following
code:

rcu_init_nohz();
init_timers();
hrtimers_init();
softirq_init();
timekeeping_init();
time_init();
sched_clock_postinit();
printk_safe_init();
perf_event_init();
profile_init();
call_function_init();
WARN(!irqs_disabled(), "Interrupts were enabled early\n");
early_boot_irqs_disabled = false;
local_irq_enable();

kmem_cache_init_late();

/*
 * HACK ALERT! This is early. We're enabling the console before
 * we've done PCI setups etc, and console_init() must be aware of
 * this. But we do want output early, in case something goes wrong.
 */
console_init();


I am just confused that I do not see any of this function on the
stack. Note that this code is still called in the single CPU mode.

I feel lost a bit.

I am really curious what code is proceed on the line
console_unlock+0x185/0x960.

Best Regards,
Petr

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Petr Mladek]

On Wed 2018-02-28 11:23:34, Petr Mladek wrote:
> On Sat 2018-02-24 13:34:05, kernel test robot wrote:
> > TO: Petr Mladek 
> > CC: Cong Wang , Dave Hansen 
> > , Johannes Weiner , Mel Gorman 
> > , Michal Hocko , Vlastimil Babka 
> > , Peter Zijlstra , Linus Torvalds 
> > , Jan Kara , Mathieu Desnoyers 
> > , Tetsuo Handa 
> > , Byungchul Park 
> > , Tejun Heo , Pavel Machek 
> > , Steven Rostedt (VMware) , Sergey 
> > Senozhatsky , LKML 
> > , linux-kernel@vger.kernel.org, l...@01.org
> > 
> > 
> > 
> > FYI, we noticed the following commit (built with gcc-7):
> > 
> > commit: c162d5b4338d72deed61aa65ed0f2f4ba2bbc8ab ("printk: Hide console 
> > waiter logic into helpers")
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> > 
> > in testcase: boot
> > 
> > on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G
> > 
> > caused below changes (please refer to attached dmesg/kmsg for entire 
> > log/backtrace):
> > 
> > 
> > ++++
> > || dbdda842fe | c162d5b433 |
> > ++++
> > | boot_successes | 0  | 0  |
> > | boot_failures  | 18 | 16 |
> > | BUG:KASAN:use-after-scope_in_p | 18 ||
> > | BUG:KASAN:use-after-scope_in_c | 0  | 16 |
> > ++++
> > 
> > 
> > 
> > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> > [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> 
> Is there any change to get disassembly of console_unlock() from the
> problematic build?
> 
> I have troubles to reproduce this myself. Also I was not able to find any
> bug just by looking into the code yet. The disassembly might help
> a lot here.
> 
> 
> Interesting symptoms (for myself and other debuggers):
> 
> The lines are duplicated. Therefore it happened when real
> console was registered and before the early console was unregistered.
> See also the full dmesg for these actions. The related printk messages
> are right after the KASAN report.
> 
> I wonder if it is unsafe to pass the console_lock via
> console_trylock_spinnning() from console_unlock() called
> in register_console(). I do not see any problem but I might
> be blind.

The KASAN report is between the following lines in dmesg:

[0.00]  Offload RCU callbacks from CPUs: .
[0.00] 
==
[0.00] 
==
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[...]
[0.00] console [ttyS0] enabled

The first message is printed from rcu_init_nohz().
The last message is printed from register_console().

I would expect that the KASAN message is triggered from the following
code:

rcu_init_nohz();
init_timers();
hrtimers_init();
softirq_init();
timekeeping_init();
time_init();
sched_clock_postinit();
printk_safe_init();
perf_event_init();
profile_init();
call_function_init();
WARN(!irqs_disabled(), "Interrupts were enabled early\n");
early_boot_irqs_disabled = false;
local_irq_enable();

kmem_cache_init_late();

/*
 * HACK ALERT! This is early. We're enabling the console before
 * we've done PCI setups etc, and console_init() must be aware of
 * this. But we do want output early, in case something goes wrong.
 */
console_init();


I am just confused that I do not see any of this function on the
stack. Note that this code is still called in the single CPU mode.

I feel lost a bit.

I am really curious what code is proceed on the line
console_unlock+0x185/0x960.

Best Regards,
Petr

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Petr Mladek]

On Sat 2018-02-24 13:34:05, kernel test robot wrote:
> TO: Petr Mladek 
> CC: Cong Wang , Dave Hansen 
> , Johannes Weiner , Mel Gorman 
> , Michal Hocko , Vlastimil Babka 
> , Peter Zijlstra , Linus Torvalds 
> , Jan Kara , Mathieu Desnoyers 
> , Tetsuo Handa 
> , Byungchul Park 
> , Tejun Heo , Pavel Machek 
> , Steven Rostedt (VMware) , Sergey 
> Senozhatsky , LKML 
> , linux-kernel@vger.kernel.org, l...@01.org
> 
> 
> 
> FYI, we noticed the following commit (built with gcc-7):
> 
> commit: c162d5b4338d72deed61aa65ed0f2f4ba2bbc8ab ("printk: Hide console 
> waiter logic into helpers")
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> 
> in testcase: boot
> 
> on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G
> 
> caused below changes (please refer to attached dmesg/kmsg for entire 
> log/backtrace):
> 
> 
> ++++
> || dbdda842fe | c162d5b433 |
> ++++
> | boot_successes | 0  | 0  |
> | boot_failures  | 18 | 16 |
> | BUG:KASAN:use-after-scope_in_p | 18 ||
> | BUG:KASAN:use-after-scope_in_c | 0  | 16 |
> ++++
> 
> 
> 
> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960

Is there any change to get disassembly of console_unlock() from the
problematic build?

I have troubles to reproduce this myself. Also I was not able to find any
bug just by looking into the code yet. The disassembly might help
a lot here.


Interesting symptoms (for myself and other debuggers):

The lines are duplicated. Therefore it happened when real
console was registered and before the early console was unregistered.
See also the full dmesg for these actions. The related printk messages
are right after the KASAN report.

I wonder if it is unsafe to pass the console_lock via
console_trylock_spinnning() from console_unlock() called
in register_console(). I do not see any problem but I might
be blind.

Another interesting thing is that the entire KASAN report is
duplicated. I wonder if it is a two level duplication or
if the BUG() was really triggered twice.

> To reproduce:
> 
> git clone https://github.com/intel/lkp-tests.git
> cd lkp-tests
> bin/lkp qemu -k  job-script  # job-script is attached in 
> this email

Also the job-script was not attached. Is it because the problem
happened already during the boot?

Thanks for the report.

Best Regards,
Petr

Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[Petr Mladek]

On Sat 2018-02-24 13:34:05, kernel test robot wrote:
> TO: Petr Mladek 
> CC: Cong Wang , Dave Hansen 
> , Johannes Weiner , Mel Gorman 
> , Michal Hocko , Vlastimil Babka 
> , Peter Zijlstra , Linus Torvalds 
> , Jan Kara , Mathieu Desnoyers 
> , Tetsuo Handa 
> , Byungchul Park 
> , Tejun Heo , Pavel Machek 
> , Steven Rostedt (VMware) , Sergey 
> Senozhatsky , LKML 
> , linux-kernel@vger.kernel.org, l...@01.org
> 
> 
> 
> FYI, we noticed the following commit (built with gcc-7):
> 
> commit: c162d5b4338d72deed61aa65ed0f2f4ba2bbc8ab ("printk: Hide console 
> waiter logic into helpers")
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> 
> in testcase: boot
> 
> on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G
> 
> caused below changes (please refer to attached dmesg/kmsg for entire 
> log/backtrace):
> 
> 
> ++++
> || dbdda842fe | c162d5b433 |
> ++++
> | boot_successes | 0  | 0  |
> | boot_failures  | 18 | 16 |
> | BUG:KASAN:use-after-scope_in_p | 18 ||
> | BUG:KASAN:use-after-scope_in_c | 0  | 16 |
> ++++
> 
> 
> 
> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
> [0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960

Is there any change to get disassembly of console_unlock() from the
problematic build?

I have troubles to reproduce this myself. Also I was not able to find any
bug just by looking into the code yet. The disassembly might help
a lot here.


Interesting symptoms (for myself and other debuggers):

The lines are duplicated. Therefore it happened when real
console was registered and before the early console was unregistered.
See also the full dmesg for these actions. The related printk messages
are right after the KASAN report.

I wonder if it is unsafe to pass the console_lock via
console_trylock_spinnning() from console_unlock() called
in register_console(). I do not see any problem but I might
be blind.

Another interesting thing is that the entire KASAN report is
duplicated. I wonder if it is a two level duplication or
if the BUG() was really triggered twice.

> To reproduce:
> 
> git clone https://github.com/intel/lkp-tests.git
> cd lkp-tests
> bin/lkp qemu -k  job-script  # job-script is attached in 
> this email

Also the job-script was not attached. Is it because the problem
happened already during the boot?

Thanks for the report.

Best Regards,
Petr

[lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[kernel test robot]

TO: Petr Mladek 
CC: Cong Wang , Dave Hansen , 
Johannes Weiner , Mel Gorman , Michal 
Hocko , Vlastimil Babka , Peter Zijlstra 
, Linus Torvalds , Jan 
Kara , Mathieu Desnoyers , Tetsuo 
Handa , Byungchul Park 
, Tejun Heo , Pavel Machek 
, Steven Rostedt (VMware) , Sergey 
Senozhatsky , LKML 
, linux-kernel@vger.kernel.org, l...@01.org



FYI, we noticed the following commit (built with gcc-7):

commit: c162d5b4338d72deed61aa65ed0f2f4ba2bbc8ab ("printk: Hide console waiter 
logic into helpers")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

in testcase: boot

on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G

caused below changes (please refer to attached dmesg/kmsg for entire 
log/backtrace):


++++
|| dbdda842fe | c162d5b433 |
++++
| boot_successes | 0  | 0  |
| boot_failures  | 18 | 16 |
| BUG:KASAN:use-after-scope_in_p | 18 ||
| BUG:KASAN:use-after-scope_in_c | 0  | 16 |
++++



[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] Write of size 1 at addr 828079b8 by task swapper/0
[0.00] Write of size 1 at addr 828079b8 by task swapper/0
[0.00] 
[0.00] 
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b #1
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b #1
[0.00] Call Trace:
[0.00] Call Trace:
[0.00]  ? dump_stack+0x11d/0x1c5
[0.00]  ? dump_stack+0x11d/0x1c5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? arch_local_irq_restore+0x17/0x17
[0.00]  ? arch_local_irq_restore+0x17/0x17
[0.00]  ? do_raw_spin_unlock+0x137/0x169
[0.00]  ? do_raw_spin_unlock+0x137/0x169
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? print_address_description+0x6e/0x23b
[0.00]  ? print_address_description+0x6e/0x23b
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? kasan_report+0x223/0x249
[0.00]  ? kasan_report+0x223/0x249
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? wake_up_klogd+0xdf/0xdf
[0.00]  ? wake_up_klogd+0xdf/0xdf
[0.00]  ? do_raw_spin_unlock+0x145/0x169
[0.00]  ? do_raw_spin_unlock+0x145/0x169
[0.00]  ? do_raw_spin_trylock+0xed/0xed
[0.00]  ? do_raw_spin_trylock+0xed/0xed
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
[0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
[0.00]  ? time_hardirqs_off+0x12/0x2d
[0.00]  ? time_hardirqs_off+0x12/0x2d
[0.00]  ? arch_local_save_flags+0x7/0x8
[0.00]  ? arch_local_save_flags+0x7/0x8
[0.00]  ? trace_hardirqs_off_caller+0x127/0x139
[0.00]  ? trace_hardirqs_off_caller+0x127/0x139
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? vprintk_emit+0x579/0x823
[0.00]  ? vprintk_emit+0x579/0x823
[0.00]  ? __down_trylock_console_sem+0x90/0xa4
[0.00]  ? __down_trylock_console_sem+0x90/0xa4
[0.00]  ? __down_trylock_console_sem+0x9d/0xa4
[0.00]  ? __down_trylock_console_sem+0x9d/0xa4
[0.00]  ? vprintk_emit+0x7ec/0x823
[0.00]  ? vprintk_emit+0x7ec/0x823
[0.00]  ? console_unlock+0x960/0x960
[0.00]  ? console_unlock+0x960/0x960
[0.00]  ? memblock_merge_regions+0x2d/0x154
[0.00]  ? memblock_merge_regions+0x2d/0x154
[0.00]  ? memblock_add_range+0x322/0x333
[0.00]  ? memblock_add_range+0x322/0x333
[0.00]  ? memblock_reserve+0xbb/0xe1
[0.00]  ? memblock_reserve+0xbb/0xe1
[0.00]  ? memblock_add+0xe1/0xe1
[0.00]  ? memblock_add+0xe1/0xe1
[0.00]  ? set_pte+0x24/0x27
[0.00]  ? set_pte+0x24/0x27
[0.00]  ? vprintk_func+0x94/0xa5
[0.00]  ? vprintk_func+0x94/0xa5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? 

[lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c

[kernel test robot]

TO: Petr Mladek 
CC: Cong Wang , Dave Hansen , 
Johannes Weiner , Mel Gorman , Michal 
Hocko , Vlastimil Babka , Peter Zijlstra 
, Linus Torvalds , Jan 
Kara , Mathieu Desnoyers , Tetsuo 
Handa , Byungchul Park 
, Tejun Heo , Pavel Machek 
, Steven Rostedt (VMware) , Sergey 
Senozhatsky , LKML 
, linux-kernel@vger.kernel.org, l...@01.org



FYI, we noticed the following commit (built with gcc-7):

commit: c162d5b4338d72deed61aa65ed0f2f4ba2bbc8ab ("printk: Hide console waiter 
logic into helpers")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

in testcase: boot

on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G

caused below changes (please refer to attached dmesg/kmsg for entire 
log/backtrace):


++++
|| dbdda842fe | c162d5b433 |
++++
| boot_successes | 0  | 0  |
| boot_failures  | 18 | 16 |
| BUG:KASAN:use-after-scope_in_p | 18 ||
| BUG:KASAN:use-after-scope_in_c | 0  | 16 |
++++



[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[0.00] Write of size 1 at addr 828079b8 by task swapper/0
[0.00] Write of size 1 at addr 828079b8 by task swapper/0
[0.00] 
[0.00] 
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b #1
[0.00] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b #1
[0.00] Call Trace:
[0.00] Call Trace:
[0.00]  ? dump_stack+0x11d/0x1c5
[0.00]  ? dump_stack+0x11d/0x1c5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? arch_local_irq_restore+0x17/0x17
[0.00]  ? arch_local_irq_restore+0x17/0x17
[0.00]  ? do_raw_spin_unlock+0x137/0x169
[0.00]  ? do_raw_spin_unlock+0x137/0x169
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? print_address_description+0x6e/0x23b
[0.00]  ? print_address_description+0x6e/0x23b
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? kasan_report+0x223/0x249
[0.00]  ? kasan_report+0x223/0x249
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? console_unlock+0x185/0x960
[0.00]  ? wake_up_klogd+0xdf/0xdf
[0.00]  ? wake_up_klogd+0xdf/0xdf
[0.00]  ? do_raw_spin_unlock+0x145/0x169
[0.00]  ? do_raw_spin_unlock+0x145/0x169
[0.00]  ? do_raw_spin_trylock+0xed/0xed
[0.00]  ? do_raw_spin_trylock+0xed/0xed
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
[0.00]  ? _raw_spin_unlock_irqrestore+0x3b/0x54
[0.00]  ? time_hardirqs_off+0x12/0x2d
[0.00]  ? time_hardirqs_off+0x12/0x2d
[0.00]  ? arch_local_save_flags+0x7/0x8
[0.00]  ? arch_local_save_flags+0x7/0x8
[0.00]  ? trace_hardirqs_off_caller+0x127/0x139
[0.00]  ? trace_hardirqs_off_caller+0x127/0x139
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? irq_trace+0x2e/0x32
[0.00]  ? vprintk_emit+0x579/0x823
[0.00]  ? vprintk_emit+0x579/0x823
[0.00]  ? __down_trylock_console_sem+0x90/0xa4
[0.00]  ? __down_trylock_console_sem+0x90/0xa4
[0.00]  ? __down_trylock_console_sem+0x9d/0xa4
[0.00]  ? __down_trylock_console_sem+0x9d/0xa4
[0.00]  ? vprintk_emit+0x7ec/0x823
[0.00]  ? vprintk_emit+0x7ec/0x823
[0.00]  ? console_unlock+0x960/0x960
[0.00]  ? console_unlock+0x960/0x960
[0.00]  ? memblock_merge_regions+0x2d/0x154
[0.00]  ? memblock_merge_regions+0x2d/0x154
[0.00]  ? memblock_add_range+0x322/0x333
[0.00]  ? memblock_add_range+0x322/0x333
[0.00]  ? memblock_reserve+0xbb/0xe1
[0.00]  ? memblock_reserve+0xbb/0xe1
[0.00]  ? memblock_add+0xe1/0xe1
[0.00]  ? memblock_add+0xe1/0xe1
[0.00]  ? set_pte+0x24/0x27
[0.00]  ? set_pte+0x24/0x27
[0.00]  ? vprintk_func+0x94/0xa5
[0.00]  ? vprintk_func+0x94/0xa5
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? printk+0xb5/0xd1
[0.00]  ? show_regs_print_info+0x41/0x41
[0.00]  ? show_regs_print_info+0x41/0x41
[0.00]  ? kasan_populate_zero_shadow+0x37b/0x3f6
[0.00]  ? kasan_populate_zero_shadow+0x37b/0x3f6
[0.00]  ? native_flush_tlb_global+0x74/0x80
[0.00]  ? native_flush_tlb_global+0x74/0x80
[0.00]  ? kasan_init+0x211/0x22d
[0.00]  ? kasan_init+0x211/0x22d