Re: [PATCH 1/2] stacktrace: fix print_stack_trace printing timestamp twice

[Dmitry Vyukov]

On Wed, Nov 9, 2016 at 5:10 PM, Andrey Ryabinin <aryabinin@xxxxxxxxxxxxx> 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@xxxxxxxxxx>
>
>
> 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@xxxxxxxxxxxxx>
>
>> ---
>>  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);