On Wed, Nov 9, 2016 at 5:10 PM, Andrey Ryabinin <[email protected]> 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 <[email protected]>
>
>
> 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 <[email protected]>
>
>> ---
>> 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);
