linux-kernel - [PATCH] slub: Fix misleading 'age' in verbose slub prints

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-next>] [day] [month] [year] [list]

Date:   Wed,  7 Mar 2018 17:17:46 +0530
From:   Chintan Pandya <cpandya@...eaurora.org>
To:     cl@...ux.com, penberg@...nel.org, rientjes@...gle.com,
        iamjoonsoo.kim@....com, akpm@...ux-foundation.org
Cc:     linux-mm@...ck.org, linux-kernel@...r.kernel.org,
        Chintan Pandya <cpandya@...eaurora.org>
Subject: [PATCH] slub: Fix misleading 'age' in verbose slub prints

When SLUB_DEBUG catches the some issues, it prints
all the required debug info being verbose. However,
in few cases where allocation and free of the object
has have happened in a very short time, 'age' might
mislead. See the example below,

[ 6044.137581] =============================================================================
[ 6044.145863] BUG kmalloc-256 (Tainted: G        W  O   ): Poison overwritten
[ 6044.152889] -----------------------------------------------------------------------------
[ 6044.152889]
[ 6044.162618] INFO: 0xfffffff14956a878-0xfffffff14956a878. First byte 0x67 instead of 0x6b
[ 6044.170804] INFO: Allocated in binder_transaction+0x4b0/0x2448 age=731 cpu=3 pid=5314
[ 6044.178711] __slab_alloc.isra.68.constprop.71+0x58/0x98
[ 6044.184070] kmem_cache_alloc_trace+0x198/0x2c4
[ 6044.188642] binder_transaction+0x4b0/0x2448
[ 6044.192953] binder_thread_write+0x998/0x1410
[ 6044.197350] binder_ioctl_write_read+0x130/0x370
[ 6044.202016] binder_ioctl+0x550/0x7dc
[ 6044.205726] do_vfs_ioctl+0xcc/0x888
[ 6044.209510] SyS_ioctl+0x90/0xa4
[ 6044.212821] __sys_trace_return+0x0/0x4
[ 6044.216696] INFO: Freed in binder_free_transaction+0x2c/0x58 age=735 cpu=6 pid=2079
[ 6044.224415] kfree+0x28c/0x290
[ 6044.227505] binder_free_transaction+0x2c/0x58
[ 6044.231991] binder_transaction+0x1f78/0x2448
[ 6044.236392] binder_thread_write+0x998/0x1410
[ 6044.240789] binder_ioctl_write_read+0x130/0x370
[ 6044.245455] binder_ioctl+0x550/0x7dc
[ 6044.249152] do_vfs_ioctl+0xcc/0x888
[ 6044.252772] SyS_ioctl+0x90/0xa4
[ 6044.256041] __sys_trace_return+0x0/0x4
[ 6044.259924] INFO: Slab 0xffffffbfc5255a00 objects=21 used=20 fp=0xfffffff14956a480 flags=0x4080
[ 6044.268695] INFO: Object 0xfffffff14956a780 @offset=10112 fp=0xfffffff149568680
...
[ 6044.494293] Object fffffff14956a870: 6b 6b 6b 6b 6b 6b 6b 6b 67 6b 6b 6b 6b 6b 6b a5  kkkkkkkkgkkkkkk.

In this case, object got freed later but 'age' shows
otherwise. This could be because, while printing
this info, we print allocation traces first and
free traces thereafter. In between, if we get schedule
out, (jiffies - t->when) could become meaningless.

So, simply print when the object was allocated/freed.

Signed-off-by: Chintan Pandya <cpandya@...eaurora.org>
---
 mm/slub.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/mm/slub.c b/mm/slub.c
index e381728..b173f85 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -603,8 +603,8 @@ static void print_track(const char *s, struct track *t)
 	if (!t->addr)
 		return;
 
-	pr_err("INFO: %s in %pS age=%lu cpu=%u pid=%d\n",
-	       s, (void *)t->addr, jiffies - t->when, t->cpu, t->pid);
+	pr_err("INFO: %s in %pS when=%lu cpu=%u pid=%d\n",
+	       s, (void *)t->addr, t->when, t->cpu, t->pid);
 #ifdef CONFIG_STACKTRACE
 	{
 		int i;
-- 
Qualcomm India Private Limited, on behalf of Qualcomm Innovation
Center, Inc., is a member of Code Aurora Forum, a Linux Foundation
Collaborative Project