linux-kernel - Re: [PATCH 1/2] stacktrace: fix print_stack

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: <CACT4Y+YB1QBzzdBbPWrq6u2M3B7WuavHZn6KswJi0Qi2DhqDLA@mail.gmail.com>
Date:   Fri, 25 Nov 2016 18:40:27 +0100
From:   Dmitry Vyukov <dvyukov@...gle.com>
To:     Andrey Ryabinin <aryabinin@...tuozzo.com>
Cc:     Andrey Konovalov <andreyknvl@...gle.com>,
        Alexander Potapenko <glider@...gle.com>,
        kasan-dev <kasan-dev@...glegroups.com>,
        "linux-mm@...ck.org" <linux-mm@...ck.org>,
        LKML <linux-kernel@...r.kernel.org>,
        Ingo Molnar <mingo@...hat.com>,
        Kostya Serebryany <kcc@...gle.com>,
        Peter Zijlstra <peterz@...radead.org>
Subject: Re: [PATCH 1/2] stacktrace: fix print_stack_trace printing timestamp twice

On Wed, Nov 9, 2016 at 5:10 PM, Andrey Ryabinin <aryabinin@...tuozzo.com> wrote:
> On 11/08/2016 10:37 PM, Andrey Konovalov wrote:
>> Right now print_stack_trace prints timestamp twice, the first time
>> it's done by printk when printing spaces, the second - by print_ip_sym.
>> As a result, stack traces in KASAN reports have double timestamps:
>> [   18.822232] Allocated by task 3838:
>> [   18.822232]  [   18.822232] [<ffffffff8107e236>] save_stack_trace+0x16/0x20
>> [   18.822232]  [   18.822232] [<ffffffff81509bd6>] save_stack+0x46/0xd0
>> [   18.822232]  [   18.822232] [<ffffffff81509e4b>] kasan_kmalloc+0xab/0xe0
>> ....
>>
>> Fix by calling printk only once.
>>
>> Signed-off-by: Andrey Konovalov <andreyknvl@...gle.com>
>
>
> Right, since commit 4bcc595ccd80 ("printk: reinstate KERN_CONT for printing continuation lines")
> printk requires KERN_CONT to continue log messages, and print_ip_sym() doesn't have it.
>
> After a small nit bellow fixed:
>         Acked-by: Andrey Ryabinin <aryabinin@...tuozzo.com>
>
>> ---
>>  kernel/stacktrace.c | 6 ++++--
>>  1 file changed, 4 insertions(+), 2 deletions(-)
>>
>> diff --git a/kernel/stacktrace.c b/kernel/stacktrace.c
>> index b6e4c16..56f510f 100644
>> --- a/kernel/stacktrace.c
>> +++ b/kernel/stacktrace.c
>> @@ -14,13 +14,15 @@
>>  void print_stack_trace(struct stack_trace *trace, int spaces)
>>  {
>>       int i;
>> +     unsigned long ip;
>
> This can be inside for loop.
>>
>>       if (WARN_ON(!trace->entries))
>>               return;
>>
>>       for (i = 0; i < trace->nr_entries; i++) {
>> -             printk("%*c", 1 + spaces, ' ');
>> -             print_ip_sym(trace->entries[i]);
>> +             ip = trace->entries[i];
>> +             printk("%*c[<%p>] %pS\n", 1 + spaces, ' ',
>> +                             (void *) ip, (void *) ip);


There is another similar case in lockdep's print_lock:

print_lock_name(lock_classes + class_idx - 1);
printk(", at: ");
print_ip_sym(hlock->acquire_ip);

This used to be a single line, but now 3.

[  131.449807] swapper/2/0 is trying to acquire lock:
[  131.449859]  (&port_lock_key){-.-...}, at: [<c036a6dc>]
serial8250_console_write+0x108/0x134

vs:

[  337.270069] syz-executor/3125 is trying to acquire lock:
[  337.270069]  ([  337.270069] rtnl_mutex
){+.+.+.}[  337.270069] , at:
[  337.270069] [<ffffffff86b3d34c>] rtnl_lock+0x1c/0x20


printk(", at: "); requires KERN_CONT.
But should we add KERN_CONT to print_ip_sym instead of duplicating it
everywhere? Or add print_ip_sym_cont?



>>       }
>>  }
>>  EXPORT_SYMBOL_GPL(print_stack_trace);