[PATCH 0/2] kasan,stacktrace: improve error reports

[PATCH 0/2] kasan,stacktrace: improve error reports

[Andrey Konovalov]

This patchset improves KASAN reports by making the following changes:

1. Changes header format from:
[   24.247214] BUG: KASAN: use-after-free in kmalloc_uaf+0xad/0xb9 [test_kasan] at addr ffff88006bbb38a8
[   24.247301] Write of size 1 by task insmod/3852
to
[   19.338308] BUG: KASAN: use-after-free in kmalloc_uaf+0xad/0xb9 [test_kasan]
[   19.338387] Write of size 1 at addr ffff88006af77968 by task insmod/3840

2. Unifies header format between different kinds of bad accesses.

3. Adds empty lines between parts of the report to improve readability.

4. Improves slab object description, before:
[   24.247301] Object at ffff88006bbb38a0, in cache kmalloc-16 size: 16
now:
[   19.338387] The buggy address belongs to the object at ffff88006af77960
[   19.338387]  which belongs to the cache kmalloc-16 of size 16
[   19.338387] The buggy address ffff88006af77968 is located 8 bytes inside
[   19.338387]  of 16-byte region [ffff88006af77960, ffff88006af77970)

5. Fixes printing timeframes twice in alloc and free stack traces.

6. Improves mm/kasan/report.c readability.


This is what a test use-after-free report looks like now:

[   19.337402] ==================================================================
[   19.338308] BUG: KASAN: use-after-free in kmalloc_uaf+0xad/0xb9 [test_kasan]
[   19.338387] Write of size 1 at addr ffff88006af77968 by task insmod/3840
[   19.338387] 
[   19.338387] page:ffffea0001abddc0 count:1 mapcount:0 mapping:          (null) index:0x0
[   19.338387] flags: 0x100000000000080(slab)
[   19.338387] page dumped because: kasan: bad access detected
[   19.338387] 
[   19.338387] CPU: 0 PID: 3840 Comm: insmod Tainted: G    B           4.9.0-rc4+ #394
[   19.338387] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[   19.338387]  ffff880063d6f9a8 ffffffff81b46b74 ffff880063d6fa38 ffff88006af77968
[   19.338387]  00000000000000fa 00000000000000fb ffff880063d6fa28 ffffffff8150aa92
[   19.338387]  ffffffff8120812d ffff880063d6fa00 0000000000000282 0000000000000296
[   19.338387] Call Trace:
[   19.338387]  [<ffffffff81b46b74>] dump_stack+0xb3/0x10f
[   19.338387]  [<ffffffff8150aa92>] kasan_report_error+0x122/0x560
[   19.338387]  [<ffffffff8120812d>] ? trace_hardirqs_on+0xd/0x10
[   19.338387]  [<ffffffffa001928c>] ? copy_user_test+0x24f/0x24f [test_kasan]
[   19.338387]  [<ffffffff8150b04e>] __asan_report_store1_noabort+0x3e/0x40
[   19.338387]  [<ffffffffa0018609>] ? kmalloc_uaf+0xad/0xb9 [test_kasan]
[   19.338387]  [<ffffffffa0018609>] kmalloc_uaf+0xad/0xb9 [test_kasan]
[   19.338387]  [<ffffffffa00192db>] kmalloc_tests_init+0x4f/0x79 [test_kasan]
[   19.338387]  [<ffffffff81000560>] do_one_initcall+0xa0/0x230
[   19.338387]  [<ffffffff810004c0>] ? initcall_blacklisted+0x170/0x170
[   19.338387]  [<ffffffff81509e1b>] ? kasan_kmalloc+0xab/0xe0
[   19.338387]  [<ffffffff81509cb5>] ? kasan_unpoison_shadow+0x35/0x50
[   19.338387]  [<ffffffff81509d4c>] ? __asan_register_globals+0x7c/0xa0
[   19.338387]  [<ffffffff8140d696>] do_init_module+0x1c1/0x516
[   19.338387]  [<ffffffff812bbe1d>] load_module+0x65ed/0x8f90
[   19.338387]  [<ffffffff812b2f70>] ? __symbol_put+0xb0/0xb0
[   19.338387]  [<ffffffffa001002d>] ? __UNIQUE_ID_vermagic8+0x36ff9f20d843/0x36ff9f20d846 [test_kasan]
[   19.338387]  [<ffffffff812b5830>] ? module_frob_arch_sections+0x20/0x20
[   19.338387]  [<ffffffff83fc1f5f>] ? retint_kernel+0x10/0x10
[   19.338387]  [<ffffffff81207f90>] ? trace_hardirqs_on_caller+0x420/0x5b0
[   19.338387]  [<ffffffff8100301a>] ? trace_hardirqs_on_thunk+0x1a/0x1c
[   19.338387]  [<ffffffff83fc1f5f>] ? retint_kernel+0x10/0x10
[   19.338387]  [<ffffffff812be97c>] SYSC_init_module+0x1bc/0x1d0
[   19.338387]  [<ffffffff812be7c0>] ? load_module+0x8f90/0x8f90
[   19.338387]  [<ffffffff81207f90>] ? trace_hardirqs_on_caller+0x420/0x5b0
[   19.338387]  [<ffffffff8100301a>] ? trace_hardirqs_on_thunk+0x1a/0x1c
[   19.338387]  [<ffffffff812beaf9>] SyS_init_module+0x9/0x10
[   19.338387]  [<ffffffff83fc1581>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   19.338387] 
[   19.338387] The buggy address belongs to the object at ffff88006af77960
[   19.338387]  which belongs to the cache kmalloc-16 of size 16
[   19.338387] The buggy address ffff88006af77968 is located 8 bytes inside
[   19.338387]  of 16-byte region [ffff88006af77960, ffff88006af77970)
[   19.338387] 
[   19.338387] Freed by task 3840:
[   19.338387]  [<ffffffff8107e236>] save_stack_trace+0x16/0x20
[   19.338387]  [<ffffffff81509ba6>] save_stack+0x46/0xd0
[   19.338387]  [<ffffffff8150a403>] kasan_slab_free+0x73/0xc0
[   19.338387]  [<ffffffff815068e8>] kfree+0xe8/0x2b0
[   19.338387]  [<ffffffffa00185e1>] kmalloc_uaf+0x85/0xb9 [test_kasan]
[   19.338387]  [<ffffffffa00192db>] kmalloc_tests_init+0x4f/0x79 [test_kasan]
[   19.338387]  [<ffffffff81000560>] do_one_initcall+0xa0/0x230
[   19.338387]  [<ffffffff8140d696>] do_init_module+0x1c1/0x516
[   19.338387]  [<ffffffff812bbe1d>] load_module+0x65ed/0x8f90
[   19.338387]  [<ffffffff812be97c>] SYSC_init_module+0x1bc/0x1d0
[   19.338387]  [<ffffffff812beaf9>] SyS_init_module+0x9/0x10
[   19.338387]  [<ffffffff83fc1581>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   19.338387] 
[   19.338387] Allocated by task 3840:
[   19.338387]  [<ffffffff8107e236>] save_stack_trace+0x16/0x20
[   19.338387]  [<ffffffff81509ba6>] save_stack+0x46/0xd0
[   19.338387]  [<ffffffff81509e1b>] kasan_kmalloc+0xab/0xe0
[   19.338387]  [<ffffffff8150554c>] kmem_cache_alloc_trace+0xec/0x270
[   19.338387]  [<ffffffffa00185b2>] kmalloc_uaf+0x56/0xb9 [test_kasan]
[   19.338387]  [<ffffffffa00192db>] kmalloc_tests_init+0x4f/0x79 [test_kasan]
[   19.338387]  [<ffffffff81000560>] do_one_initcall+0xa0/0x230
[   19.338387]  [<ffffffff8140d696>] do_init_module+0x1c1/0x516
[   19.338387]  [<ffffffff812bbe1d>] load_module+0x65ed/0x8f90
[   19.338387]  [<ffffffff812be97c>] SYSC_init_module+0x1bc/0x1d0
[   19.338387]  [<ffffffff812beaf9>] SyS_init_module+0x9/0x10
[   19.338387]  [<ffffffff83fc1581>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   19.338387] 
[   19.338387] Memory state around the buggy address:
[   19.338387]  ffff88006af77800: 00 00 fc fc 00 00 fc fc 00 00 fc fc fb fb fc fc
[   19.338387]  ffff88006af77880: 00 00 fc fc 00 00 fc fc 00 00 fc fc fb fb fc fc
[   19.338387] >ffff88006af77900: 00 00 fc fc 00 00 fc fc 00 00 fc fc fb fb fc fc
[   19.338387]                                                           ^
[   19.338387]  ffff88006af77980: 00 00 fc fc 00 00 fc fc 00 00 fc fc 00 00 fc fc
[   19.338387]  ffff88006af77a00: 00 00 fc fc 00 00 fc fc 00 00 fc fc fb fb fc fc
[   19.338387] ==================================================================

This is what a test use-after-free report looked like before:

[   24.246351] ==================================================================
[   24.247214] BUG: KASAN: use-after-free in kmalloc_uaf+0xad/0xb9 [test_kasan] at addr ffff88006bbb38a8
[   24.247301] Write of size 1 by task insmod/3852
[   24.247301] CPU: 1 PID: 3852 Comm: insmod Tainted: G    B           4.9.0-rc4+ #393
[   24.247301] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[   24.247301]  ffff88006a647980 ffffffff81b46a64 ffff88006c801b40 ffff88006bbb38a0
[   24.247301]  ffff88006bbb38b0 ffff88006bbb38a0 ffff88006a6479a8 ffffffff8150a86c
[   24.247301]  ffff88006a647a38 ffff88006c801b40 ffff8800ebbb38a8 ffff88006a647a28
[   24.247301] Call Trace:
[   24.247301]  [<ffffffff81b46a64>] dump_stack+0xb3/0x10f
[   24.247301]  [<ffffffff8150a86c>] kasan_object_err+0x1c/0x70
[   24.247301]  [<ffffffff8150ab07>] kasan_report_error+0x1f7/0x4d0
[   24.247301]  [<ffffffff8120812d>] ? trace_hardirqs_on+0xd/0x10
[   24.247301]  [<ffffffffa001928c>] ? copy_user_test+0x24f/0x24f [test_kasan]
[   24.247301]  [<ffffffff8150af5e>] __asan_report_store1_noabort+0x3e/0x40
[   24.247301]  [<ffffffffa0018609>] ? kmalloc_uaf+0xad/0xb9 [test_kasan]
[   24.247301]  [<ffffffffa0018609>] kmalloc_uaf+0xad/0xb9 [test_kasan]
[   24.247301]  [<ffffffffa00192db>] kmalloc_tests_init+0x4f/0x79 [test_kasan]
[   24.247301]  [<ffffffff81000560>] do_one_initcall+0xa0/0x230
[   24.247301]  [<ffffffff810004c0>] ? initcall_blacklisted+0x170/0x170
[   24.247301]  [<ffffffff81509e4b>] ? kasan_kmalloc+0xab/0xe0
[   24.247301]  [<ffffffff81509ce5>] ? kasan_unpoison_shadow+0x35/0x50
[   24.247301]  [<ffffffff81509d7c>] ? __asan_register_globals+0x7c/0xa0
[   24.247301]  [<ffffffff8140d6c6>] do_init_module+0x1c1/0x516
[   24.247301]  [<ffffffff812bbe4d>] load_module+0x65ed/0x8f90
[   24.247301]  [<ffffffff812b2fa0>] ? __symbol_put+0xb0/0xb0
[   24.247301]  [<ffffffffa001002d>] ? __UNIQUE_ID_vermagic8+0x36ff9f26d843/0x36ff9f26d846 [test_kasan]
[   24.247301]  [<ffffffff812b5860>] ? module_frob_arch_sections+0x20/0x20
[   24.247301]  [<ffffffff83fc1f5f>] ? retint_kernel+0x10/0x10
[   24.247301]  [<ffffffff81207f90>] ? trace_hardirqs_on_caller+0x420/0x5b0
[   24.247301]  [<ffffffff8100301a>] ? trace_hardirqs_on_thunk+0x1a/0x1c
[   24.247301]  [<ffffffff83fc1f5f>] ? retint_kernel+0x10/0x10
[   24.247301]  [<ffffffff812be9ac>] SYSC_init_module+0x1bc/0x1d0
[   24.247301]  [<ffffffff812be7f0>] ? load_module+0x8f90/0x8f90
[   24.247301]  [<ffffffff81207f90>] ? trace_hardirqs_on_caller+0x420/0x5b0
[   24.247301]  [<ffffffff8100301a>] ? trace_hardirqs_on_thunk+0x1a/0x1c
[   24.247301]  [<ffffffff812beb29>] SyS_init_module+0x9/0x10
[   24.247301]  [<ffffffff83fc1581>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   24.247301] Object at ffff88006bbb38a0, in cache kmalloc-16 size: 16
[   24.247301] Allocated:
[   24.247301] PID = 3852
[   24.247301]  [   24.247301] [<ffffffff8107e236>] save_stack_trace+0x16/0x20
[   24.247301]  [   24.247301] [<ffffffff81509bd6>] save_stack+0x46/0xd0
[   24.247301]  [   24.247301] [<ffffffff81509e4b>] kasan_kmalloc+0xab/0xe0
[   24.247301]  [   24.247301] [<ffffffff8150557c>] kmem_cache_alloc_trace+0xec/0x270
[   24.247301]  [   24.247301] [<ffffffffa00185b2>] kmalloc_uaf+0x56/0xb9 [test_kasan]
[   24.247301]  [   24.247301] [<ffffffffa00192db>] kmalloc_tests_init+0x4f/0x79 [test_kasan]
[   24.247301]  [   24.247301] [<ffffffff81000560>] do_one_initcall+0xa0/0x230
[   24.247301]  [   24.247301] [<ffffffff8140d6c6>] do_init_module+0x1c1/0x516
[   24.247301]  [   24.247301] [<ffffffff812bbe4d>] load_module+0x65ed/0x8f90
[   24.247301]  [   24.247301] [<ffffffff812be9ac>] SYSC_init_module+0x1bc/0x1d0
[   24.247301]  [   24.247301] [<ffffffff812beb29>] SyS_init_module+0x9/0x10
[   24.247301]  [   24.247301] [<ffffffff83fc1581>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   24.247301] Freed:
[   24.247301] PID = 3852
[   24.247301]  [   24.247301] [<ffffffff8107e236>] save_stack_trace+0x16/0x20
[   24.247301]  [   24.247301] [<ffffffff81509bd6>] save_stack+0x46/0xd0
[   24.247301]  [   24.247301] [<ffffffff8150a433>] kasan_slab_free+0x73/0xc0
[   24.247301]  [   24.247301] [<ffffffff81506918>] kfree+0xe8/0x2b0
[   24.247301]  [   24.247301] [<ffffffffa00185e1>] kmalloc_uaf+0x85/0xb9 [test_kasan]
[   24.247301]  [   24.247301] [<ffffffffa00192db>] kmalloc_tests_init+0x4f/0x79 [test_kasan]
[   24.247301]  [   24.247301] [<ffffffff81000560>] do_one_initcall+0xa0/0x230
[   24.247301]  [   24.247301] [<ffffffff8140d6c6>] do_init_module+0x1c1/0x516
[   24.247301]  [   24.247301] [<ffffffff812bbe4d>] load_module+0x65ed/0x8f90
[   24.247301]  [   24.247301] [<ffffffff812be9ac>] SYSC_init_module+0x1bc/0x1d0
[   24.247301]  [   24.247301] [<ffffffff812beb29>] SyS_init_module+0x9/0x10
[   24.247301]  [   24.247301] [<ffffffff83fc1581>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   24.247301] Memory state around the buggy address:
[   24.247301]  ffff88006bbb3780: fb fb fc fc fb fb fc fc 00 00 fc fc 00 00 fc fc
[   24.247301]  ffff88006bbb3800: 00 00 fc fc fb fb fc fc fb fb fc fc fb fb fc fc
[   24.247301] >ffff88006bbb3880: fb fb fc fc fb fb fc fc 00 00 fc fc fb fb fc fc
[   24.247301]                                   ^
[   24.247301]  ffff88006bbb3900: 00 00 fc fc 00 00 fc fc 00 00 fc fc 00 00 fc fc
[   24.247301]  ffff88006bbb3980: 00 00 fc fc 00 00 fc fc fb fb fc fc 00 00 fc fc
[   24.247301] ==================================================================

Andrey Konovalov (2):
  stacktrace: fix print_stack_trace printing timestamp twice
  kasan: improve error reports

 kernel/stacktrace.c |   6 +-
 mm/kasan/report.c   | 246 +++++++++++++++++++++++++++++++++++-----------------
 2 files changed, 169 insertions(+), 83 deletions(-)

-- 
2.8.0.rc3.226.g39d4020

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

[Andrey Konovalov]

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@google.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;
 
 	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);
 	}
 }
 EXPORT_SYMBOL_GPL(print_stack_trace);
-- 
2.8.0.rc3.226.g39d4020

[PATCH 2/2] kasan: improve error reports

[Andrey Konovalov]

1. Change header format.
2. Unify header format between different kinds of bad accesses.
3. Add empty lines between parts of the report to improve readability.
4. Improve slab object description.
5. Improve mm/kasan/report.c readability.

Signed-off-by: Andrey Konovalov <andreyknvl@google.com>
---
 mm/kasan/report.c | 246 ++++++++++++++++++++++++++++++++++++------------------
 1 file changed, 165 insertions(+), 81 deletions(-)

diff --git a/mm/kasan/report.c b/mm/kasan/report.c
index 24c1211..a2ebea0 100644
--- a/mm/kasan/report.c
+++ b/mm/kasan/report.c
@@ -48,7 +48,7 @@ static const void *find_first_bad_addr(const void *addr, size_t size)
 	return first_bad_addr;
 }
 
-static void print_error_description(struct kasan_access_info *info)
+static const char *get_shadow_bug_type(struct kasan_access_info *info)
 {
 	const char *bug_type = "unknown-crash";
 	u8 *shadow_addr;
@@ -92,53 +92,82 @@ static void print_error_description(struct kasan_access_info *info)
 		break;
 	}
 
-	pr_err("BUG: KASAN: %s in %pS at addr %p\n",
-		bug_type, (void *)info->ip,
-		info->access_addr);
-	pr_err("%s of size %zu by task %s/%d\n",
-		info->is_write ? "Write" : "Read",
-		info->access_size, current->comm, task_pid_nr(current));
+	return bug_type;
 }
 
-static inline bool kernel_or_module_addr(const void *addr)
+static const char *get_wild_bug_type(struct kasan_access_info *info)
 {
-	if (addr >= (void *)_stext && addr < (void *)_end)
-		return true;
-	if (is_module_address((unsigned long)addr))
-		return true;
-	return false;
+	const char *bug_type;
+
+	if ((unsigned long)info->access_addr < PAGE_SIZE)
+		bug_type = "null-ptr-deref";
+	else if ((unsigned long)info->access_addr < TASK_SIZE)
+		bug_type = "user-memory-access";
+	else
+		bug_type = "wild-memory-access";
+
+	return bug_type;
 }
 
-static inline bool init_task_stack_addr(const void *addr)
+static bool addr_has_shadow(struct kasan_access_info *info)
 {
-	return addr >= (void *)&init_thread_union.stack &&
-		(addr <= (void *)&init_thread_union.stack +
-			sizeof(init_thread_union.stack));
+	return (info->access_addr >=
+		 kasan_shadow_to_mem((void *)KASAN_SHADOW_START));
 }
 
-static DEFINE_SPINLOCK(report_lock);
+static const char *get_bug_type(struct kasan_access_info *info)
+{
+	if (addr_has_shadow(info))
+		return get_shadow_bug_type(info);
+	return get_wild_bug_type(info);
+}
 
-static void kasan_start_report(unsigned long *flags)
+static void print_report_header(struct kasan_access_info *info)
 {
-	/*
-	 * Make sure we don't end up in loop.
-	 */
-	kasan_disable_current();
-	spin_lock_irqsave(&report_lock, *flags);
-	pr_err("==================================================================\n");
+	const char *bug_type = get_bug_type(info);
+
+	pr_err("BUG: KASAN: %s in %pS\n",
+		bug_type, (void *)info->ip);
+	pr_err("%s of size %zu at addr %p by task %s/%d\n",
+		info->is_write ? "Write" : "Read", info->access_size,
+		info->access_addr, current->comm, task_pid_nr(current));
 }
 
-static void kasan_end_report(unsigned long *flags)
+static void describe_object_addr(struct kmem_cache *cache, void *object,
+				const void *addr)
 {
-	pr_err("==================================================================\n");
-	add_taint(TAINT_BAD_PAGE, LOCKDEP_NOW_UNRELIABLE);
-	spin_unlock_irqrestore(&report_lock, *flags);
-	kasan_enable_current();
+	unsigned long access_addr = (unsigned long)addr;
+	unsigned long object_addr = (unsigned long)object;
+	const char *rel_type;
+	int rel_bytes;
+
+	pr_err("The buggy address belongs to the object at %p\n"
+	       " which belongs to the cache %s of size %d\n",
+		object, cache->name, cache->object_size);
+
+	if (!addr)
+		return;
+
+	if (access_addr < object_addr) {
+		rel_type = "to the left";
+		rel_bytes = object_addr - access_addr;
+	} else if (access_addr >= object_addr + cache->object_size) {
+		rel_type = "to the right";
+		rel_bytes = access_addr - (object_addr + cache->object_size);
+	} else {
+		rel_type = "inside";
+		rel_bytes = access_addr - object_addr;
+	}
+
+	pr_err("The buggy address %p is located %d bytes %s\n"
+	       " of %d-byte region [%p, %p)\n", addr,
+		rel_bytes, rel_type, cache->object_size, (void *)object_addr,
+		(void *)(object_addr + cache->object_size));
 }
 
-static void print_track(struct kasan_track *track)
+static void print_track(struct kasan_track *track, const char *prefix)
 {
-	pr_err("PID = %u\n", track->pid);
+	pr_err("%s by task %u:\n", prefix, track->pid);
 	if (track->stack) {
 		struct stack_trace trace;
 
@@ -149,39 +178,28 @@ static void print_track(struct kasan_track *track)
 	}
 }
 
-static void kasan_object_err(struct kmem_cache *cache, void *object)
+static void describe_object(struct kmem_cache *cache, void *object,
+				const void *addr)
 {
 	struct kasan_alloc_meta *alloc_info = get_alloc_info(cache, object);
 
-	dump_stack();
-	pr_err("Object at %p, in cache %s size: %d\n", object, cache->name,
-		cache->object_size);
+	describe_object_addr(cache, object, addr);
+	pr_err("\n");
 
 	if (!(cache->flags & SLAB_KASAN))
 		return;
 
-	pr_err("Allocated:\n");
-	print_track(&alloc_info->alloc_track);
-	pr_err("Freed:\n");
-	print_track(&alloc_info->free_track);
-}
-
-void kasan_report_double_free(struct kmem_cache *cache, void *object,
-			s8 shadow)
-{
-	unsigned long flags;
+	if (alloc_info->free_track.stack) {
+		print_track(&alloc_info->free_track, "Freed");
+		pr_err("\n");
+	}
 
-	kasan_start_report(&flags);
-	pr_err("BUG: Double free or freeing an invalid pointer\n");
-	pr_err("Unexpected shadow byte: 0x%hhX\n", shadow);
-	kasan_object_err(cache, object);
-	kasan_end_report(&flags);
+	print_track(&alloc_info->alloc_track, "Allocated");
+	pr_err("\n");
 }
 
-static void print_address_description(struct kasan_access_info *info)
+static bool try_describe_object(const void *addr)
 {
-	const void *addr = info->access_addr;
-
 	if ((addr >= (void *)PAGE_OFFSET) &&
 		(addr < high_memory)) {
 		struct page *page = virt_to_head_page(addr);
@@ -189,19 +207,62 @@ static void print_address_description(struct kasan_access_info *info)
 		if (PageSlab(page)) {
 			void *object;
 			struct kmem_cache *cache = page->slab_cache;
-			object = nearest_obj(cache, page,
-						(void *)info->access_addr);
-			kasan_object_err(cache, object);
-			return;
+			object = nearest_obj(cache, page, (void *)addr);
+			describe_object(cache, object, addr);
+			return true;
 		}
+	}
+
+	return false;
+}
+
+static void try_describe_page(const void *addr)
+{
+	if ((addr >= (void *)PAGE_OFFSET) &&
+		(addr < high_memory)) {
+		struct page *page = virt_to_head_page(addr);
 		dump_page(page, "kasan: bad access detected");
+		pr_err("\n");
 	}
+}
+
+static inline bool kernel_or_module_addr(const void *addr)
+{
+	if (addr >= (void *)_stext && addr < (void *)_end)
+		return true;
+	if (is_module_address((unsigned long)addr))
+		return true;
+	return false;
+}
+
+static inline bool init_task_stack_addr(const void *addr)
+{
+	return addr >= (void *)&init_thread_union.stack &&
+		(addr <= (void *)&init_thread_union.stack +
+			sizeof(init_thread_union.stack));
+}
 
+static void try_describe_variable(const void *addr)
+{
 	if (kernel_or_module_addr(addr)) {
 		if (!init_task_stack_addr(addr))
-			pr_err("Address belongs to variable %pS\n", addr);
+			pr_err("The buggy address %p belongs to\n"
+			       " the variable %pS\n", addr, addr);
+			pr_err("\n");
 	}
+}
+
+static void describe_address(const void *addr)
+{
+	try_describe_page(addr);
+
 	dump_stack();
+	pr_err("\n");
+
+	if (try_describe_object(addr))
+		return;
+
+	try_describe_variable(addr);
 }
 
 static bool row_is_guilty(const void *row, const void *guilty)
@@ -256,35 +317,58 @@ static void print_shadow_for_address(const void *addr)
 	}
 }
 
+static DEFINE_SPINLOCK(report_lock);
+
+static void start_report(unsigned long *flags)
+{
+	/*
+	 * Make sure we don't end up in loop.
+	 */
+	kasan_disable_current();
+	spin_lock_irqsave(&report_lock, *flags);
+	pr_err("==================================================================\n");
+}
+
+static void end_report(unsigned long *flags)
+{
+	pr_err("==================================================================\n");
+	add_taint(TAINT_BAD_PAGE, LOCKDEP_NOW_UNRELIABLE);
+	spin_unlock_irqrestore(&report_lock, *flags);
+	kasan_enable_current();
+}
+
+void kasan_report_double_free(struct kmem_cache *cache, void *object,
+			s8 shadow)
+{
+	unsigned long flags;
+
+	start_report(&flags);
+	pr_err("BUG: double-free or invalid-free\n");
+	pr_err("Unexpected shadow byte: 0x%hhX\n", shadow);
+	pr_err("\n");
+	dump_stack();
+	pr_err("\n");
+	describe_object(cache, object, NULL);
+	end_report(&flags);
+}
+
 static void kasan_report_error(struct kasan_access_info *info)
 {
 	unsigned long flags;
-	const char *bug_type;
 
-	kasan_start_report(&flags);
-
-	if (info->access_addr <
-			kasan_shadow_to_mem((void *)KASAN_SHADOW_START)) {
-		if ((unsigned long)info->access_addr < PAGE_SIZE)
-			bug_type = "null-ptr-deref";
-		else if ((unsigned long)info->access_addr < TASK_SIZE)
-			bug_type = "user-memory-access";
-		else
-			bug_type = "wild-memory-access";
-		pr_err("BUG: KASAN: %s on address %p\n",
-			bug_type, info->access_addr);
-		pr_err("%s of size %zu by task %s/%d\n",
-			info->is_write ? "Write" : "Read",
-			info->access_size, current->comm,
-			task_pid_nr(current));
-		dump_stack();
-	} else {
-		print_error_description(info);
-		print_address_description(info);
+	start_report(&flags);
+
+	print_report_header(info);
+	pr_err("\n");
+
+	if (addr_has_shadow(info)) {
+		describe_address(info->access_addr);
 		print_shadow_for_address(info->first_bad_addr);
+	} else {
+		dump_stack();
 	}
 
-	kasan_end_report(&flags);
+	end_report(&flags);
 }
 
 void kasan_report(unsigned long addr, size_t size,
-- 
2.8.0.rc3.226.g39d4020

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

[Andrey Ryabinin]

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@google.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@virtuozzo.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);
>  	}
>  }
>  EXPORT_SYMBOL_GPL(print_stack_trace);
> 

Re: [PATCH 2/2] kasan: improve error reports

[Andrey Ryabinin]

On 11/08/2016 10:37 PM, Andrey Konovalov wrote:
> 1. Change header format.
> 2. Unify header format between different kinds of bad accesses.
> 3. Add empty lines between parts of the report to improve readability.
> 4. Improve slab object description.
> 5. Improve mm/kasan/report.c readability.
> 

Can you please do not dump everything in one patch? It only makes review process much more complicated.
Please break it up into 'one patch per logical change'.

> Signed-off-by: Andrey Konovalov <andreyknvl@google.com>
> ---

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@virtuozzo.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@google.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@virtuozzo.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);

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

[Joe Perches]

On Fri, 2016-11-25 at 18:40 +0100, Dmitry Vyukov wrote:
> But should we add KERN_CONT to print_ip_sym instead of duplicating it
> everywhere? Or add print_ip_sym_cont?

There are only a couple dozen uses of print_ip_sym.

It might be better to use "[<%p>] %pS" directly
everywhere and remove print_ip_sym instead to
avoid the KERN_CONT and avoid all possible
interleaved output.