Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c
From: Tetsuo Handa
Date: Thu Mar 01 2018 - 05:07:15 EST
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-kernel@xxxxxxxxxxxxxxxxxxx
----------------------- Original Message -----------------------
From: Tetsuo Handa <penguin-kernel@xxxxxxxxxxxxxxxxxxx>
To: Petr Mladek <pmladek@xxxxxxxx>
Cc: kernel test robot <shun.hao@xxxxxxxxx>, Cong Wang <xiyou.wangcong@xxxxxxxxx>, Dave Hansen <dave.hansen@xxxxxxxxx>, Johannes Weiner <hannes@xxxxxxxxxxx>, Mel Gorman <mgorman@xxxxxxx>, Michal Hocko <mhocko@xxxxxxxxxx>, Vlastimil Babka <vbabka@xxxxxxx>, Peter Zijlstra <peterz@xxxxxxxxxxxxx>, Linus Torvalds <torvalds@xxxxxxxxxxxxxxxxxxxx>, Jan Kara <jack@xxxxxxx>, Mathieu Desnoyers <mathieu.desnoyers@xxxxxxxxxxxx>, Byungchul Park <byungchul.park@xxxxxxx>, Tejun Heo <tj@xxxxxxxxxx>, Pavel Machek <pavel@xxxxxx>, Steven Rostedt <rostedt@xxxxxxxxxxx>, Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>, LKML <linux-kernel@xxxxxxxxxxxxxxx>, lkp@xxxxxx
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(&console_owner_lock) ?
[ 0.000000] 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.000000] sysrq: sysrq always enabled.
[ 0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[ 0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[ 0.000000] Memory: 3045216K/4193716K available (15633K kernel code, 6278K rwdata, 6948K rodata, 3592K init, 24228K bss, 1148500K reserved, 0K cma-reserved)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=64, Nodes=1
[ 0.000000] ftrace: allocating 34522 entries in 135 pages
[ 0.003333] Running RCU self tests
[ 0.003333] Hierarchical RCU implementation.
[ 0.003333] RCU event tracing is enabled.
[ 0.003333] RCU dyntick-idle grace-period acceleration is enabled.
[ 0.003333] RCU lockdep checking is enabled.
[ 0.003333] Tasks RCU enabled.
[ 0.003333] NR_IRQS: 4352, nr_irqs: 936, preallocated irqs: 16
[ 0.003333] Offload RCU callbacks from CPUs: .
[ 0.003333] ==================================================================
[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[ 0.003333] Write of size 1 at addr ffffffff828079b8 by task swapper/0
[ 0.003333]
[ 0.003333] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b #414
[ 0.003333] Call Trace:
[ 0.003333] ? dump_stack+0x11d/0x1c5
[ 0.003333] ? printk+0xb5/0xd1
[ 0.003333] ? arch_local_irq_restore+0x17/0x17
[ 0.003333] ? do_raw_spin_unlock+0x137/0x169
[ 0.003333] ? irq_trace+0x2e/0x32
[ 0.003333] ? console_unlock+0x185/0x960
[ 0.003333] ? print_address_description+0x6e/0x23b
[ 0.003333] ? console_unlock+0x185/0x960
[ 0.003333] ? kasan_report+0x223/0x249
[ 0.003333] ? console_unlock+0x185/0x960
[ 0.003333] ? wake_up_klogd+0xdf/0xdf
[ 0.003333] ? do_raw_spin_unlock+0x145/0x169
[ 0.003333] ? do_raw_spin_trylock+0xed/0xed
[ 0.003333] ? irq_trace+0x2e/0x32
[ 0.003333] ? _raw_spin_unlock_irqrestore+0x3b/0x54
[ 0.003333] ? time_hardirqs_off+0x12/0x2d
[ 0.003333] ? arch_local_save_flags+0x7/0x8
[ 0.003333] ? trace_hardirqs_off_caller+0x127/0x139
[ 0.003333] ? irq_trace+0x2e/0x32
[ 0.003333] ? vprintk_emit+0x579/0x823
[ 0.003333] ? __down_trylock_console_sem+0x90/0xa4
[ 0.003333] ? __down_trylock_console_sem+0x9d/0xa4
[ 0.003333] ? vprintk_emit+0x7ec/0x823
[ 0.003333] ? console_unlock+0x960/0x960
[ 0.003333] ? memblock_merge_regions+0x2d/0x154
[ 0.003333] ? memblock_add_range+0x322/0x333
[ 0.003333] ? memblock_reserve+0xbb/0xe1
[ 0.003333] ? memblock_add+0xe1/0xe1
[ 0.003333] ? set_pte+0x24/0x27
[ 0.003333] ? vprintk_func+0x94/0xa5
[ 0.003333] ? printk+0xb5/0xd1
[ 0.003333] ? show_regs_print_info+0x41/0x41
[ 0.003333] ? kasan_populate_zero_shadow+0x37b/0x3f6
[ 0.003333] ? native_flush_tlb_global+0x74/0x80
[ 0.003333] ? kasan_init+0x211/0x22d
[ 0.003333] ? setup_arch+0xdfa/0xf3c
[ 0.003333] ? css_set_populated+0x79/0x79
[ 0.003333] ? reserve_standard_io_resources+0x39/0x39
[ 0.003333] ? vprintk_func+0x9d/0xa5
[ 0.003333] ? printk+0xb5/0xd1
[ 0.003333] ? show_regs_print_info+0x41/0x41
[ 0.003333] ? start_kernel+0xa2/0x515
[ 0.003333] ? mem_encrypt_init+0xa/0xa
[ 0.003333] ? x86_family+0x2e/0x33
[ 0.003333] ? load_ucode_bsp+0x58/0xec
[ 0.003333] ? secondary_startup_64+0xa5/0xb0
[ 0.003333]
[ 0.003333]
[ 0.003333] Memory state around the buggy address:
[ 0.003333] ffffffff82807880: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 0.003333] ffffffff82807900: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 0.003333] >ffffffff82807980: 00 00 00 f1 f1 f1 f1 f8 f2 f2 f2 f2 f2 f2 f2 01
[ 0.003333] ^
[ 0.003333] ffffffff82807a00: f2 f2 f2 f2 f2 f2 f2 00 f2 f2 f2 f3 f3 f3 f3 00
[ 0.003333] ffffffff82807a80: 00 00 00 00 00 00 00 00 00 00 00 00 00 f1 f1 f1
[ 0.003333] ==================================================================
[ 0.003333] Disabling lock debugging due to kernel taint
[ 0.003333] ==================================================================
[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x185/0x960
[ 0.003333] Write of size 1 at addr ffffffff828079b8 by task swapper/0
[ 0.003333]
[ 0.003333] CPU: 0 PID: 0 Comm: swapper Not tainted 4.14.0-12953-gc162d5b #414
[ 0.003333] Call Trace:
[ 0.003333] ? dump_stack+0x11d/0x1c5
[ 0.003333] ? printk+0xb5/0xd1
[ 0.003333] ? arch_local_irq_restore+0x17/0x17
[ 0.003333] ? do_raw_spin_unlock+0x137/0x169
[ 0.003333] ? irq_trace+0x2e/0x32
[ 0.003333] ? console_unlock+0x185/0x960
[ 0.003333] ? print_address_description+0x6e/0x23b
[ 0.003333] ? console_unlock+0x185/0x960
[ 0.003333] ? kasan_report+0x223/0x249
[ 0.003333] ? console_unlock+0x185/0x960
[ 0.003333] ? wake_up_klogd+0xdf/0xdf
[ 0.003333] ? do_raw_spin_unlock+0x145/0x169
[ 0.003333] ? do_raw_spin_trylock+0xed/0xed
[ 0.003333] ? irq_trace+0x2e/0x32
[ 0.003333] ? _raw_spin_unlock_irqrestore+0x3b/0x54
[ 0.003333] ? time_hardirqs_off+0x12/0x2d
[ 0.003333] ? arch_local_save_flags+0x7/0x8
[ 0.003333] ? trace_hardirqs_off_caller+0x127/0x139
[ 0.003333] ? irq_trace+0x2e/0x32
[ 0.003333] ? vprintk_emit+0x579/0x823
[ 0.003333] ? __down_trylock_console_sem+0x90/0xa4
[ 0.003333] ? __down_trylock_console_sem+0x9d/0xa4
[ 0.003333] ? vprintk_emit+0x7ec/0x823
[ 0.003333] ? console_unlock+0x960/0x960
[ 0.003333] ? memblock_merge_regions+0x2d/0x154
[ 0.003333] ? memblock_add_range+0x322/0x333
[ 0.003333] ? memblock_reserve+0xbb/0xe1
[ 0.003333] ? memblock_add+0xe1/0xe1
[ 0.003333] ? set_pte+0x24/0x27
[ 0.003333] ? vprintk_func+0x94/0xa5
[ 0.003333] ? printk+0xb5/0xd1
[ 0.003333] ? show_regs_print_info+0x41/0x41
[ 0.003333] ? kasan_populate_zero_shadow+0x37b/0x3f6
[ 0.003333] ? native_flush_tlb_global+0x74/0x80
[ 0.003333] ? kasan_init+0x211/0x22d
[ 0.003333] ? setup_arch+0xdfa/0xf3c
[ 0.003333] ? css_set_populated+0x79/0x79
[ 0.003333] ? reserve_standard_io_resources+0x39/0x39
[ 0.003333] ? vprintk_func+0x9d/0xa5
[ 0.003333] ? printk+0xb5/0xd1
[ 0.003333] ? show_regs_print_info+0x41/0x41
[ 0.003333] ? start_kernel+0xa2/0x515
[ 0.003333] ? mem_encrypt_init+0xa/0xa
[ 0.003333] ? x86_family+0x2e/0x33
[ 0.003333] ? load_ucode_bsp+0x58/0xec
[ 0.003333] ? secondary_startup_64+0xa5/0xb0
[ 0.003333]
[ 0.003333]
[ 0.003333] Memory state around the buggy address:
[ 0.003333] ffffffff82807880: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 0.003333] ffffffff82807900: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 0.003333] >ffffffff82807980: 00 00 00 f1 f1 f1 f1 f8 f2 f2 f2 f2 f2 f2 f2 01
[ 0.003333] ^
[ 0.003333] ffffffff82807a00: f2 f2 f2 f2 f2 f2 f2 00 f2 f2 f2 f3 f3 f3 f3 00
[ 0.003333] ffffffff82807a80: 00 00 00 00 00 00 00 00 00 00 00 00 00 f1 f1 f1
[ 0.003333] ==================================================================
[ 0.003333] Disabling lock debugging due to kernel taint
[ 0.003333] ==================================================================
# ./scripts/faddr2line vmlinux console_unlock+0x185/0x960
console_unlock+0x185/0x960:
console_lock_spinning_disable_and_check at kernel/printk/printk.c:1600
(inlined by) console_unlock at kernel/printk/printk.c:2386
ffffffff81190da4 <console_unlock>:
* If there is output waiting, we wake /dev/kmsg and syslog() users.
*
* console_unlock(); may be called from any context.
*/
void console_unlock(void)
{
ffffffff81190da4: e8 57 e1 da 00 callq ffffffff81f3ef00 <__fentry__>
ffffffff81190da9: 55 push %rbp
ffffffff81190daa: 48 89 e5 mov %rsp,%rbp
ffffffff81190dad: 41 57 push %r15
ffffffff81190daf: 41 56 push %r14
ffffffff81190db1: 48 8d 85 f8 fe ff ff lea -0x108(%rbp),%rax
ffffffff81190db8: 41 55 push %r13
ffffffff81190dba: 41 54 push %r12
ffffffff81190dbc: 53 push %rbx
ffffffff81190dbd: 48 bb 00 00 00 00 00 movabs $0xdffffc0000000000,%rbx
ffffffff81190dc4: fc ff df
ffffffff81190dc7: 48 c1 e8 03 shr $0x3,%rax
ffffffff81190dcb: 48 81 ec 20 01 00 00 sub $0x120,%rsp
ffffffff81190dd2: 48 89 85 d0 fe ff ff mov %rax,-0x130(%rbp)
ffffffff81190dd9: 48 01 d8 add %rbx,%rax
ffffffff81190ddc: 48 c7 85 f8 fe ff ff movq $0x41b58ab3,-0x108(%rbp)
ffffffff81190de3: b3 8a b5 41
ffffffff81190de7: 48 c7 85 00 ff ff ff movq $0xffffffff825fb4c2,-0x100(%rbp)
ffffffff81190dee: c2 b4 5f 82
ffffffff81190df2: 48 c7 85 08 ff ff ff movq $0xffffffff81190da4,-0xf8(%rbp)
ffffffff81190df9: a4 0d 19 81
ffffffff81190dfd: c7 00 f1 f1 f1 f1 movl $0xf1f1f1f1,(%rax)
ffffffff81190e03: c7 40 04 01 f2 f2 f2 movl $0xf2f2f201,0x4(%rax)
ffffffff81190e0a: c7 40 08 f2 f2 f2 f2 movl $0xf2f2f2f2,0x8(%rax)
ffffffff81190e11: c7 40 0c 01 f2 f2 f2 movl $0xf2f2f201,0xc(%rax)
ffffffff81190e18: c7 40 10 f2 f2 f2 f2 movl $0xf2f2f2f2,0x10(%rax)
ffffffff81190e1f: c7 40 14 00 f2 f2 f2 movl $0xf2f2f200,0x14(%rax)
ffffffff81190e26: c7 40 18 f3 f3 f3 f3 movl $0xf3f3f3f3,0x18(%rax)
static u64 seen_seq;
unsigned long flags;
bool wake_klogd = false;
bool do_cond_resched, retry;
if (console_suspended) {
ffffffff81190e2d: e8 3f 82 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190e32: 83 3d a7 c2 14 03 00 cmpl $0x0,0x314c2a7(%rip) # ffffffff842dd0e0 <console_suspended>
ffffffff81190e39: 74 0a je ffffffff81190e45 <console_unlock+0xa1>
up_console_sem();
ffffffff81190e3b: e8 31 82 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190e40: e9 85 08 00 00 jmpq ffffffff811916ca <console_unlock+0x926>
*
* console_trylock() is not able to detect the preemptive
* context reliably. Therefore the value must be stored before
* and cleared after the the "again" goto label.
*/
do_cond_resched = console_may_schedule;
ffffffff81190e45: e8 27 82 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190e4a: 8b 05 b0 c0 14 03 mov 0x314c0b0(%rip),%eax # ffffffff842dcf00 <console_may_schedule>
{
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[LOG_LINE_MAX + PREFIX_MAX];
static u64 seen_seq;
unsigned long flags;
bool wake_klogd = false;
ffffffff81190e50: 45 31 ed xor %r13d,%r13d
ffffffff81190e53: 48 89 9d e8 fe ff ff mov %rbx,-0x118(%rbp)
*
* console_trylock() is not able to detect the preemptive
* context reliably. Therefore the value must be stored before
* and cleared after the the "again" goto label.
*/
do_cond_resched = console_may_schedule;
ffffffff81190e5a: 89 85 cc fe ff ff mov %eax,-0x134(%rbp)
again:
console_may_schedule = 0;
ffffffff81190e60: e8 0c 82 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
* unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
* call them until this CPU is officially up.
*/
static inline int can_use_console(void)
{
return cpu_online(raw_smp_processor_id()) || have_callable_console();
ffffffff81190e65: 65 8b 05 bc 22 e8 7e mov %gs:0x7ee822bc(%rip),%eax # 13128 <cpu_number>
* context reliably. Therefore the value must be stored before
* and cleared after the the "again" goto label.
*/
do_cond_resched = console_may_schedule;
again:
console_may_schedule = 0;
ffffffff81190e6c: c7 05 8a c0 14 03 00 movl $0x0,0x314c08a(%rip) # ffffffff842dcf00 <console_may_schedule>
ffffffff81190e73: 00 00 00
*
* Returns 1 if @cpu is set in @cpumask, else returns 0
*/
static inline int cpumask_test_cpu(int cpu, const struct cpumask *cpumask)
{
return test_bit(cpumask_check(cpu), cpumask_bits((cpumask)));
ffffffff81190e76: 89 c0 mov %eax,%eax
static __always_inline bool variable_test_bit(long nr, volatile const unsigned long *addr)
{
bool oldbit;
asm volatile("bt %2,%1"
ffffffff81190e78: 48 0f a3 05 a8 ad c8 bt %rax,0x1c8ada8(%rip) # ffffffff82e1bc28 <__cpu_online_mask>
ffffffff81190e7f: 01
ffffffff81190e80: 49 c7 c6 28 bc e1 82 mov $0xffffffff82e1bc28,%r14
* unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
* call them until this CPU is officially up.
*/
static inline int can_use_console(void)
{
return cpu_online(raw_smp_processor_id()) || have_callable_console();
ffffffff81190e87: 0f 82 a3 01 00 00 jb ffffffff81191030 <console_unlock+0x28c>
*/
static int have_callable_console(void)
{
struct console *con;
for_each_console(con)
ffffffff81190e8d: e8 df 81 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190e92: 48 8b 1d 07 c3 14 03 mov 0x314c307(%rip),%rbx # ffffffff842dd1a0 <console_drivers>
ffffffff81190e99: e8 d3 81 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190e9e: 48 85 db test %rbx,%rbx
ffffffff81190ea1: 0f 84 14 08 00 00 je ffffffff811916bb <console_unlock+0x917>
if ((con->flags & CON_ENABLED) &&
ffffffff81190ea7: e8 c5 81 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190eac: 48 8d 7b 40 lea 0x40(%rbx),%rdi
ffffffff81190eb0: e8 bd 51 1f 00 callq ffffffff81386072 <__asan_load2>
ffffffff81190eb5: 8b 43 40 mov 0x40(%rbx),%eax
ffffffff81190eb8: 83 e0 14 and $0x14,%eax
ffffffff81190ebb: 66 83 f8 14 cmp $0x14,%ax
ffffffff81190ebf: 0f 84 6b 01 00 00 je ffffffff81191030 <console_unlock+0x28c>
*/
static int have_callable_console(void)
{
struct console *con;
for_each_console(con)
ffffffff81190ec5: e8 a7 81 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190eca: 48 8d 7b 50 lea 0x50(%rbx),%rdi
ffffffff81190ece: e8 89 53 1f 00 callq ffffffff8138625c <__asan_load8>
ffffffff81190ed3: 48 8b 5b 50 mov 0x50(%rbx),%rbx
ffffffff81190ed7: eb c0 jmp ffffffff81190e99 <console_unlock+0xf5>
ffffffff81190ed9: e8 93 81 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190ede: 65 8b 05 43 22 e8 7e mov %gs:0x7ee82243(%rip),%eax # 13128 <cpu_number>
ffffffff81190ee5: 89 c0 mov %eax,%eax
ffffffff81190ee7: 49 0f a3 06 bt %rax,(%r14)
ffffffff81190eeb: 0f 82 6c 04 00 00 jb ffffffff8119135d <console_unlock+0x5b9>
{
struct console *con;
trace_console_rcuidle(text, len);
if (!console_drivers)
ffffffff81190ef1: e8 7b 81 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190ef6: 48 8b 1d a3 c2 14 03 mov 0x314c2a3(%rip),%rbx # ffffffff842dd1a0 <console_drivers>
ffffffff81190efd: 48 85 db test %rbx,%rbx
ffffffff81190f00: 0f 85 5c 05 00 00 jne ffffffff81191462 <console_unlock+0x6be>
ffffffff81190f06: 48 8d 9d 18 ff ff ff lea -0xe8(%rbp),%rbx
ffffffff81190f0d: 4c 8d a5 58 ff ff ff lea -0xa8(%rbp),%r12
*/
console_lock_spinning_enable();
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(ext_text, ext_len, text, len);
start_critical_timings();
ffffffff81190f14: e8 58 81 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190f19: e8 18 a2 0c 00 callq ffffffff8125b136 <start_critical_timings>
ffffffff81190f1e: 48 89 df mov %rbx,%rdi
static int console_lock_spinning_disable_and_check(void)
{
int waiter;
raw_spin_lock(&console_owner_lock);
waiter = READ_ONCE(console_waiter);
ffffffff81190f21: 49 89 df mov %rbx,%r15
ffffffff81190f24: e8 04 51 1f 00 callq ffffffff8138602d <__asan_store1>
ffffffff81190f29: 4c 89 e7 mov %r12,%rdi /*** console_unlock+0x185/0x960 ***/
ffffffff81190f2c: c6 85 18 ff ff ff 00 movb $0x0,-0xe8(%rbp)
ffffffff81190f33: 49 c1 ef 03 shr $0x3,%r15
ffffffff81190f37: e8 f1 50 1f 00 callq ffffffff8138602d <__asan_store1>
*/
static int console_lock_spinning_disable_and_check(void)
{
int waiter;
raw_spin_lock(&console_owner_lock);
ffffffff81190f3c: 48 c7 c7 e0 96 95 82 mov $0xffffffff829596e0,%rdi /*** ffffffff829596e0 d console_owner_lock ***/
ffffffff81190f43: c6 85 58 ff ff ff 00 movb $0x0,-0xa8(%rbp)
ffffffff81190f4a: e8 9a bd da 00 callq ffffffff81f3cce9 <_raw_spin_lock>
waiter = READ_ONCE(console_waiter);
ffffffff81190f4f: 4c 03 bd e8 fe ff ff add -0x118(%rbp),%r15
ffffffff81190f56: 8a 05 c4 bb 04 03 mov 0x304bbc4(%rip),%al # ffffffff841dcb20 <console_waiter>
ffffffff81190f5c: 48 89 df mov %rbx,%rdi
ffffffff81190f5f: 88 85 e0 fe ff ff mov %al,-0x120(%rbp)
ffffffff81190f65: 41 c6 07 01 movb $0x1,(%r15)
ffffffff81190f69: e8 bf 50 1f 00 callq ffffffff8138602d <__asan_store1>
ffffffff81190f6e: 8a 85 e0 fe ff ff mov -0x120(%rbp),%al
ffffffff81190f74: 48 89 df mov %rbx,%rdi
ffffffff81190f77: 88 85 18 ff ff ff mov %al,-0xe8(%rbp)
ffffffff81190f7d: e8 69 50 1f 00 callq ffffffff81385feb <__asan_load1>
ffffffff81190f82: 8a 85 18 ff ff ff mov -0xe8(%rbp),%al
console_owner = NULL;
raw_spin_unlock(&console_owner_lock);
ffffffff81190f88: 48 c7 c7 e0 96 95 82 mov $0xffffffff829596e0,%rdi
ffffffff81190f8f: 41 c6 07 f8 movb $0xf8,(%r15)
{
int waiter;
raw_spin_lock(&console_owner_lock);
waiter = READ_ONCE(console_waiter);
console_owner = NULL;
ffffffff81190f93: 48 c7 05 c2 bb 04 03 movq $0x0,0x304bbc2(%rip) # ffffffff841dcb60 <console_owner>
ffffffff81190f9a: 00 00 00 00
static int console_lock_spinning_disable_and_check(void)
{
int waiter;
raw_spin_lock(&console_owner_lock);
waiter = READ_ONCE(console_waiter);
ffffffff81190f9e: 88 85 e0 fe ff ff mov %al,-0x120(%rbp)
console_owner = NULL;
raw_spin_unlock(&console_owner_lock);
ffffffff81190fa4: e8 9b bf da 00 callq ffffffff81f3cf44 <_raw_spin_unlock>
ffffffff81190fa9: 48 8b 9d f0 fe ff ff mov -0x110(%rbp),%rbx
if (!waiter) {
ffffffff81190fb0: 8a 85 e0 fe ff ff mov -0x120(%rbp),%al
ffffffff81190fb6: 81 e3 00 02 00 00 and $0x200,%ebx
ffffffff81190fbc: 84 c0 test %al,%al
ffffffff81190fbe: 0f 85 54 05 00 00 jne ffffffff81191518 <console_unlock+0x774>
spin_release(&console_owner_dep_map, 1, _THIS_IP_);
ffffffff81190fc4: e8 a8 80 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190fc9: 48 c7 c2 c4 0f 19 81 mov $0xffffffff81190fc4,%rdx
ffffffff81190fd0: be 01 00 00 00 mov $0x1,%esi
ffffffff81190fd5: 48 c7 c7 60 97 95 82 mov $0xffffffff82959760,%rdi
ffffffff81190fdc: e8 0d 19 fe ff callq ffffffff811728ee <lock_release>
if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
return;
}
printk_safe_exit_irqrestore(flags);
ffffffff81190fe1: e8 82 2d 00 00 callq ffffffff81193d68 <__printk_safe_exit>
ffffffff81190fe6: 48 85 db test %rbx,%rbx
ffffffff81190fe9: 0f 85 d6 05 00 00 jne ffffffff811915c5 <console_unlock+0x821>
ffffffff81190fef: e8 7d 80 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81190ff4: 48 8b bd f0 fe ff ff mov -0x110(%rbp),%rdi
ffffffff81190ffb: e8 48 ca ff ff callq ffffffff8118da48 <arch_local_irq_restore>
ffffffff81191000: e8 42 9f fd ff callq ffffffff8116af47 <trace_hardirqs_off>
if (do_cond_resched)
ffffffff81191005: e8 67 80 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff8119100a: 83 bd cc fe ff ff 00 cmpl $0x0,-0x134(%rbp)
ffffffff81191011: 74 1d je ffffffff81191030 <console_unlock+0x28c>
cond_resched();
ffffffff81191013: e8 59 80 08 00 callq ffffffff81219071 <__sanitizer_cov_trace_pc>
ffffffff81191018: 31 d2 xor %edx,%edx
ffffffff8119101a: be 5a 09 00 00 mov $0x95a,%esi
ffffffff8119101f: 48 c7 c7 00 65 07 82 mov $0xffffffff82076500,%rdi
ffffffff81191026: e8 91 77 fa ff callq ffffffff811387bc <___might_sleep>
ffffffff8119102b: e8 43 66 da 00 callq ffffffff81f37673 <_cond_resched>
Forwarded by penguin-kernel@xxxxxxxxxxxxxxxxxxx
----------------------- Original Message -----------------------
From: Tetsuo Handa <penguin-kernel@xxxxxxxxxxxxxxxxxxx>
To: Petr Mladek <pmladek@xxxxxxxx>
Cc: kernel test robot <shun.hao@xxxxxxxxx>, Cong Wang <xiyou.wangcong@xxxxxxxxx>, Dave Hansen <dave.hansen@xxxxxxxxx>, Johannes Weiner <hannes@xxxxxxxxxxx>, Mel Gorman <mgorman@xxxxxxx>, Michal Hocko <mhocko@xxxxxxxxxx>, Vlastimil Babka <vbabka@xxxxxxx>, Peter Zijlstra <peterz@xxxxxxxxxxxxx>, Linus Torvalds <torvalds@xxxxxxxxxxxxxxxxxxxx>, Jan Kara <jack@xxxxxxx>, Mathieu Desnoyers <mathieu.desnoyers@xxxxxxxxxxxx>, Byungchul Park <byungchul.park@xxxxxxx>, Tejun Heo <tj@xxxxxxxxxx>, Pavel Machek <pavel@xxxxxx>, Steven Rostedt <rostedt@xxxxxxxxxxx>, Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>, LKML <linux-kernel@xxxxxxxxxxxxxxx>, lkp@xxxxxx
Date: Thu, 01 Mar 2018 12:26:15 +0900
Subject: Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in_c
----
Tetsuo Handa wrote:
> 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(&console_owner_lock) ?
>
Interesting thing is that as of commit 97ace515f01439d4 on linux.git, there is no
such __asan_store1() before calling raw_spin_lock(&console_owner_lock) and hence
cannot reproduce this warning. Maybe a KASAN bug as of commit c162d5b4338d72de ?
ffffffff8115d3a1 <console_unlock>:
* If there is output waiting, we wake /dev/kmsg and syslog() users.
*
* console_unlock(); may be called from any context.
*/
void console_unlock(void)
{
ffffffff8115d3a1: e8 5a 44 ca 00 callq ffffffff81e01800 <__fentry__>
ffffffff8115d3a6: 41 57 push %r15
ffffffff8115d3a8: 41 56 push %r14
ffffffff8115d3aa: 41 55 push %r13
ffffffff8115d3ac: 41 54 push %r12
ffffffff8115d3ae: 55 push %rbp
ffffffff8115d3af: 53 push %rbx
ffffffff8115d3b0: 48 83 ec 28 sub $0x28,%rsp
static u64 seen_seq;
unsigned long flags;
bool wake_klogd = false;
bool do_cond_resched, retry;
if (console_suspended) {
ffffffff8115d3b4: e8 6e e6 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d3b9: 83 3d 60 e1 34 03 00 cmpl $0x0,0x334e160(%rip) # ffffffff844ab520 <console_suspended>
ffffffff8115d3c0: 74 0a je ffffffff8115d3cc <console_unlock+0x2b>
up_console_sem();
ffffffff8115d3c2: e8 60 e6 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d3c7: e9 4d 07 00 00 jmpq ffffffff8115db19 <console_unlock+0x778>
*
* console_trylock() is not able to detect the preemptive
* context reliably. Therefore the value must be stored before
* and cleared after the the "again" goto label.
*/
do_cond_resched = console_may_schedule;
ffffffff8115d3cc: e8 56 e6 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d3d1: 8b 05 69 df 34 03 mov 0x334df69(%rip),%eax # ffffffff844ab340 <console_may_schedule>
{
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[LOG_LINE_MAX + PREFIX_MAX];
static u64 seen_seq;
unsigned long flags;
bool wake_klogd = false;
ffffffff8115d3d7: 45 31 f6 xor %r14d,%r14d
static __always_inline bool variable_test_bit(long nr, volatile const unsigned long *addr)
{
bool oldbit;
asm volatile("bt %2,%1"
ffffffff8115d3da: 49 c7 c5 e8 92 01 83 mov $0xffffffff830192e8,%r13
*
* console_trylock() is not able to detect the preemptive
* context reliably. Therefore the value must be stored before
* and cleared after the the "again" goto label.
*/
do_cond_resched = console_may_schedule;
ffffffff8115d3e1: 89 44 24 18 mov %eax,0x18(%rsp)
again:
console_may_schedule = 0;
ffffffff8115d3e5: e8 3d e6 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
* unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
* call them until this CPU is officially up.
*/
static inline int can_use_console(void)
{
return cpu_online(raw_smp_processor_id()) || have_callable_console();
ffffffff8115d3ea: 65 8b 05 3f ad eb 7e mov %gs:0x7eebad3f(%rip),%eax # 18130 <cpu_number>
* context reliably. Therefore the value must be stored before
* and cleared after the the "again" goto label.
*/
do_cond_resched = console_may_schedule;
again:
console_may_schedule = 0;
ffffffff8115d3f1: c7 05 45 df 34 03 00 movl $0x0,0x334df45(%rip) # ffffffff844ab340 <console_may_schedule>
ffffffff8115d3f8: 00 00 00
*
* Returns 1 if @cpu is set in @cpumask, else returns 0
*/
static inline int cpumask_test_cpu(int cpu, const struct cpumask *cpumask)
{
return test_bit(cpumask_check(cpu), cpumask_bits((cpumask)));
ffffffff8115d3fb: 89 c0 mov %eax,%eax
ffffffff8115d3fd: 49 0f a3 45 00 bt %rax,0x0(%r13)
* unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
* call them until this CPU is officially up.
*/
static inline int can_use_console(void)
{
return cpu_online(raw_smp_processor_id()) || have_callable_console();
ffffffff8115d402: 0f 82 26 01 00 00 jb ffffffff8115d52e <console_unlock+0x18d>
*/
static int have_callable_console(void)
{
struct console *con;
for_each_console(con)
ffffffff8115d408: e8 1a e6 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d40d: 48 8b 1d cc e1 34 03 mov 0x334e1cc(%rip),%rbx # ffffffff844ab5e0 <console_drivers>
ffffffff8115d414: e8 0e e6 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d419: 48 85 db test %rbx,%rbx
ffffffff8115d41c: 0f 84 e8 06 00 00 je ffffffff8115db0a <console_unlock+0x769>
if ((con->flags & CON_ENABLED) &&
ffffffff8115d422: e8 00 e6 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d427: 48 8d 7b 40 lea 0x40(%rbx),%rdi
ffffffff8115d42b: e8 4c 1c 1a 00 callq ffffffff812ff07c <__asan_load2>
ffffffff8115d430: 8b 43 40 mov 0x40(%rbx),%eax
ffffffff8115d433: 83 e0 14 and $0x14,%eax
ffffffff8115d436: 66 83 f8 14 cmp $0x14,%ax
ffffffff8115d43a: 0f 84 ee 00 00 00 je ffffffff8115d52e <console_unlock+0x18d>
*/
static int have_callable_console(void)
{
struct console *con;
for_each_console(con)
ffffffff8115d440: e8 e2 e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d445: 48 8d 7b 50 lea 0x50(%rbx),%rdi
ffffffff8115d449: e8 18 1e 1a 00 callq ffffffff812ff266 <__asan_load8>
ffffffff8115d44e: 48 8b 5b 50 mov 0x50(%rbx),%rbx
ffffffff8115d452: eb c0 jmp ffffffff8115d414 <console_unlock+0x73>
ffffffff8115d454: e8 ce e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d459: 65 8b 05 d0 ac eb 7e mov %gs:0x7eebacd0(%rip),%eax # 18130 <cpu_number>
ffffffff8115d460: 89 c0 mov %eax,%eax
ffffffff8115d462: 49 0f a3 45 00 bt %rax,0x0(%r13)
ffffffff8115d467: 0f 82 b1 03 00 00 jb ffffffff8115d81e <console_unlock+0x47d>
{
struct console *con;
trace_console_rcuidle(text, len);
if (!console_drivers)
ffffffff8115d46d: e8 b5 e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d472: 48 8b 1d 67 e1 34 03 mov 0x334e167(%rip),%rbx # ffffffff844ab5e0 <console_drivers>
ffffffff8115d479: 48 85 db test %rbx,%rbx
ffffffff8115d47c: 0f 85 63 04 00 00 jne ffffffff8115d8e5 <console_unlock+0x544>
*/
console_lock_spinning_enable();
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(ext_text, ext_len, text, len);
start_critical_timings();
ffffffff8115d482: e8 a0 e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d487: e8 ce 49 0a 00 callq ffffffff81201e5a <start_critical_timings>
*/
static int console_lock_spinning_disable_and_check(void)
{
int waiter;
raw_spin_lock(&console_owner_lock);
ffffffff8115d48c: 48 c7 c7 00 38 b5 82 mov $0xffffffff82b53800,%rdi /*** ffffffff82b53800 d console_owner_lock ***/
ffffffff8115d493: 48 89 eb mov %rbp,%rbx
ffffffff8115d496: e8 5e b3 bf 00 callq ffffffff81d587f9 <_raw_spin_lock>
ffffffff8115d49b: 44 8a 25 7e da 24 03 mov 0x324da7e(%rip),%r12b # ffffffff843aaf20 <console_waiter>
waiter = READ_ONCE(console_waiter);
console_owner = NULL;
raw_spin_unlock(&console_owner_lock);
ffffffff8115d4a2: 48 c7 c7 00 38 b5 82 mov $0xffffffff82b53800,%rdi
{
int waiter;
raw_spin_lock(&console_owner_lock);
waiter = READ_ONCE(console_waiter);
console_owner = NULL;
ffffffff8115d4a9: 48 c7 05 ac da 24 03 movq $0x0,0x324daac(%rip) # ffffffff843aaf60 <console_owner>
ffffffff8115d4b0: 00 00 00 00
ffffffff8115d4b4: 81 e3 00 02 00 00 and $0x200,%ebx
raw_spin_unlock(&console_owner_lock);
ffffffff8115d4ba: e8 95 b5 bf 00 callq ffffffff81d58a54 <_raw_spin_unlock>
if (!waiter) {
ffffffff8115d4bf: 45 84 e4 test %r12b,%r12b
ffffffff8115d4c2: 0f 85 cf 04 00 00 jne ffffffff8115d997 <console_unlock+0x5f6>
spin_release(&console_owner_dep_map, 1, _THIS_IP_);
ffffffff8115d4c8: e8 5a e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d4cd: 48 c7 c2 c8 d4 15 81 mov $0xffffffff8115d4c8,%rdx
ffffffff8115d4d4: be 01 00 00 00 mov $0x1,%esi
ffffffff8115d4d9: 48 c7 c7 80 38 b5 82 mov $0xffffffff82b53880,%rdi
ffffffff8115d4e0: e8 97 82 fe ff callq ffffffff8114577c <lock_release>
if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
return;
}
printk_safe_exit_irqrestore(flags);
ffffffff8115d4e5: e8 f3 25 00 00 callq ffffffff8115fadd <__printk_safe_exit>
ffffffff8115d4ea: 48 85 db test %rbx,%rbx
ffffffff8115d4ed: 0f 85 22 05 00 00 jne ffffffff8115da15 <console_unlock+0x674>
ffffffff8115d4f3: e8 2f e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d4f8: 48 89 ef mov %rbp,%rdi
ffffffff8115d4fb: e8 f4 cf ff ff callq ffffffff8115a4f4 <arch_local_irq_restore>
ffffffff8115d500: e8 94 25 fe ff callq ffffffff8113fa99 <trace_hardirqs_off>
if (do_cond_resched)
ffffffff8115d505: e8 1d e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d50a: 83 7c 24 18 00 cmpl $0x0,0x18(%rsp)
ffffffff8115d50f: 74 1d je ffffffff8115d52e <console_unlock+0x18d>
cond_resched();
ffffffff8115d511: e8 11 e5 06 00 callq ffffffff811cba27 <__sanitizer_cov_trace_pc>
ffffffff8115d516: 31 d2 xor %edx,%edx
ffffffff8115d518: be 66 09 00 00 mov $0x966,%esi
ffffffff8115d51d: 48 c7 c7 20 85 27 82 mov $0xffffffff82278520,%rdi
ffffffff8115d524: e8 24 8b fb ff callq ffffffff8111604d <___might_sleep>
ffffffff8115d529: e8 ad 68 bf 00 callq ffffffff81d53ddb <_cond_resched>