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 <pmla...@suse.com>
> > CC: 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>, Tetsuo Handa
> > <penguin-ker...@i-love.sakura.ne.jp>, Byungchul Park
> > <byungchul.p...@lge.com>, Tejun Heo <t...@kernel.org>, Pavel Machek
> > <pa...@ucw.cz>, Steven Rostedt (VMware) <rost...@goodmis.org>, Sergey
> > Senozhatsky <sergey.senozhat...@gmail.com>, LKML
> > <linux-kernel@vger.kernel.org>, 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.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.
The KASAN report is between the following lines in dmesg:
[ 0.003333] Offload RCU callbacks from CPUs: .
[ 0.003333]
==================================================================
[ 0.003333]
==================================================================
[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[...]
[ 0.003333] 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
