linux-kernel - Re: [lkp-robot] [printk] c162d5b433: BUG:KASAN:use-after-scope_in

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20180301013722.GA6763@tigerII.localdomain>
Date:   Thu, 1 Mar 2018 10:37:22 +0900
From:   Sergey Senozhatsky <sergey.senozhatsky@...il.com>
To:     Petr Mladek <pmladek@...e.com>
Cc:     kernel test robot <shun.hao@...el.com>,
        Cong Wang <xiyou.wangcong@...il.com>,
        Dave Hansen <dave.hansen@...el.com>,
        Johannes Weiner <hannes@...xchg.org>,
        Mel Gorman <mgorman@...e.de>, Michal Hocko <mhocko@...nel.org>,
        Vlastimil Babka <vbabka@...e.cz>,
        Peter Zijlstra <peterz@...radead.org>,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        Jan Kara <jack@...e.cz>,
        Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
        Tetsuo Handa <penguin-kernel@...ove.SAKURA.ne.jp>,
        Byungchul Park <byungchul.park@....com>,
        Tejun Heo <tj@...nel.org>, Pavel Machek <pavel@....cz>,
        Steven Rostedt <rostedt@...dmis.org>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        LKML <linux-kernel@...r.kernel.org>, lkp@...org,
        Dmitry Vyukov <dvyukov@...gle.com>,
        kasan-dev <kasan-dev@...glegroups.com>
Subject: Re: [lkp-robot] [printk]  c162d5b433: BUG:KASAN:use-after-scope_in_c

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.

	-ss