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 +0000, Dmitry Vyukov wrote:
> On Thu, Mar 1, 2018 at 2:37 AM, Sergey Senozhatsky
> <sergey.senozhatsky@xxxxxxxxx> wrote:
> > Hello,
> > 
> > Cc-ing Dmitry Vyukov and kasan-dev on this.
> > 
> > On (02/28/18 16:59), Petr Mladek wrote:
> > [..]
> > > > > 
> > > > > [ÂÂÂÂ0.003333] BUG: KASAN: use-after-scope in
> > > > > console_unlock+0x185/0x960
> > > > > [ÂÂÂÂ0.003333] 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&m=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.003333]ÂÂ? 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 <log_next>
> > ÂÂÂÂÂ1925:ÂÂÂÂÂÂÂ48 89 2d 00 00 00
> > 00ÂÂÂÂmovÂÂÂÂ%rbp,0x0(%rip)ÂÂÂÂÂÂÂÂ# 192c <console_unlock+0x17f>
> > ÂÂÂÂÂ192c:ÂÂÂÂÂÂÂ89 05 00 00 00
> > 00ÂÂÂÂÂÂÂmovÂÂÂÂ%eax,0x0(%rip)ÂÂÂÂÂÂÂÂ# 1932 <console_unlock+0x185>
> > > > Â 1932:ÂÂÂÂÂÂÂeb a9ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂjmpÂÂÂÂ18dd
> > > > <console_unlock+0x130>
> > 
> > ÂÂÂÂÂ1934:ÂÂÂÂÂÂÂ8b 35 00 00 00
> > 00ÂÂÂÂÂÂÂmovÂÂÂÂ0x0(%rip),%esiÂÂÂÂÂÂÂÂ# 193a <console_unlock+0x18d>
> > ÂÂÂÂÂ193a:ÂÂÂÂÂÂÂb9 00 04 00 00ÂÂÂÂÂÂÂÂÂÂmovÂÂÂÂ$0x400,%ecx
> > ÂÂÂÂÂ193f:ÂÂÂÂÂÂÂ4c 89 efÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂmovÂÂÂÂ%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?

Attachment: job-script
Description: job-script