Debug with Linux Slub allocator

Http://thinkiii.blogspot.jp/2014/02/debug-with-slub-allocator.html
The Slub allocator in Linux have useful debug features. Such as poisoning, readzone checking, and Allocate/free traces with timestamps. It ' s very useful during product developing stage. Let ' s create a kernel module and test the debug features.

Make sure Slub allocator are built in your kernel.

CONFIG_SLUB_DEBUG=y
CONFIG_SLUB=y

The Slub allocator creates additional meta data to store Allocate/free traces and timestamps. Everytime Slub Allocator Allocate/free An object, it does poison check (data area) and RedZone Check (boundry).

The module shows how it happens. It allocates bytes from kernel and we overwrite the RedZone by memset.

void try_to_corrupt_redzone(void)
{
        void *p = kmalloc(32, GFP_KERNEL);
        if (p) {
                pr_alert("p: 0x%p\n", p);
                memset(p, 0x12, 36);    /* write too much */
                print_hex_dump(KERN_ALERT, "mem: ", DUMP_PREFIX_ADDRESS,
                                16, 1, p, 512, 1);
                kfree(p);       /* slub.c should catch this error */
        }
}

static int mymodule_init(void)
{
        pr_alert("%s init\n", __FUNCTION__);
        try_to_corrupt_redzone();
        return 0;
}

static void mymodule_exit(void)
{
        pr_alert("%s exit\n", __FUNCTION__);
}

module_init(mymodule_init);
module_exit(mymodule_exit);

After freeing the object, the kernel checks the object and the find, the redzone are overwritten and says:

[ 2050.630002] mymodule_init init
[ 2050.630565] p: 0xddc86680
[ 2050.630653] mem: ddc86680: 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12  ................
[ 2050.630779] mem: ddc86690: 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12  ................
[ 2050.630897] mem: ddc866a0: 12 12 12 12 60 6b c8 dd 16 80 99 e0 fa 8e 2a c1  ....`k........*.
[ 2050.631014] mem: ddc866b0: 16 80 99 e0 ce 92 2a c1 16 80 99 e0 f2 c1 1b c1  ......*.........
[ 2050.631130] mem: ddc866c0: 16 80 99 e0 4c 8b 0a c1 4c 8b 0a c1 61 80 99 e0  ....L...L...a...
[ 2050.631248] mem: ddc866d0: 16 80 99 e0 61 80 99 e0 16 80 99 e0 61 80 99 e0  ....a.......a...
[ 2050.631365] mem: ddc866e0: 75 80 99 e0 48 01 00 c1 2b 36 05 c1 00 00 00 00  u...H...+6......
[ 2050.631483] mem: ddc866f0: 4a 0c 00 00 99 ad 06 00 6d 35 05 c1 9e 8b 2a c1  J.......m5....*.
[ 2050.631599] mem: ddc86700: 6d 35 05 c1 48 8c 2a c1 6d 35 05 c1 ee 89 0a c1  m5..H.*.m5......
[ 2050.631716] mem: ddc86710: ee 89 0a c1 e4 0a 14 c1 e4 0a 14 c1 ee 89 0a c1  ................
[ 2050.631832] mem: ddc86720: ee 89 0a c1 6d 35 05 c1 6d 35 05 c1 6d 35 05 c1  ....m5..m5..m5..
[ 2050.631948] mem: ddc86730: a7 39 05 c1 ef b8 2a c1 00 00 00 00 00 00 00 00  .9....*.........
[ 2050.633948] mem: ddc86740: 4a 0c 00 00 97 ad 06 00 5a 5a 5a 5a 5a 5a 5a 5a  J.......ZZZZZZZZ
[ 2050.634095] mem: ddc86750: 14 dc 46 dd 14 dc 46 dd 00 00 00 00 6b 6b 6b 6b  ..F...F.....kkkk
[ 2050.634236] mem: ddc86760: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5  kkkkkkkkkkkkkkk.
[ 2050.634378] mem: ddc86770: cc cc cc cc c0 69 c8 dd a0 83 20 c1 fa 8e 2a c1  .....i.... ...*.
[ 2050.634629] =============================================================================
[ 2050.634750] BUG kmalloc-32 (Tainted: P    B      O): Redzone overwritten
[ 2050.634828] -----------------------------------------------------------------------------
[ 2050.634828] 
[ 2050.634967] INFO: 0xddc866a0-0xddc866a3. First byte 0x12 instead of 0xcc
[ 2050.635123] INFO: Allocated in try_to_corrupt_redzone+0x16/0x61 [mymodule] age=1 cpu=0 pid=3146
[ 2050.635255]  alloc_debug_processing+0x63/0xd1
[ 2050.635337]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.635423]  __slab_alloc.constprop.73+0x366/0x384
[ 2050.635506]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.635594]  vt_console_print+0x21e/0x226
[ 2050.635672]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.635758]  kmem_cache_alloc_trace+0x43/0xd7
[ 2050.635832]  kmem_cache_alloc_trace+0x43/0xd7
[ 2050.635909]  mymodule_init+0x0/0x19 [mymodule]
[ 2050.635992]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.636003]  mymodule_init+0x0/0x19 [mymodule]
[ 2050.636092]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.636179]  mymodule_init+0x0/0x19 [mymodule]
[ 2050.636261]  mymodule_init+0x14/0x19 [mymodule]
[ 2050.636343]  do_one_initcall+0x6c/0xf4
[ 2050.636428]  load_module+0x1690/0x199a
[ 2050.636508] INFO: Freed in load_module+0x15d2/0x199a age=3 cpu=0 pid=3146
[ 2050.636598]  free_debug_processing+0xd6/0x142
[ 2050.636676]  load_module+0x15d2/0x199a
[ 2050.636749]  __slab_free+0x3e/0x28d
[ 2050.636819]  load_module+0x15d2/0x199a
[ 2050.636888]  kfree+0xe4/0x102
[ 2050.636953]  kfree+0xe4/0x102
[ 2050.637020]  kobject_uevent_env+0x361/0x39a
[ 2050.637091]  kobject_uevent_env+0x361/0x39a
[ 2050.637163]  kfree+0xe4/0x102
[ 2050.637227]  kfree+0xe4/0x102
[ 2050.637294]  load_module+0x15d2/0x199a
[ 2050.637366]  load_module+0x15d2/0x199a
[ 2050.637438]  load_module+0x15d2/0x199a
[ 2050.637509]  SyS_init_module+0x72/0x8a
[ 2050.637581]  syscall_call+0x7/0xb
[ 2050.637649] INFO: Slab 0xdffa90c0 objects=19 used=8 fp=0xddc86000 flags=0x40000080
[ 2050.637749] INFO: Object 0xddc86680 @offset=1664 fp=0xddc86b60
[ 2050.637749] 
[ 2050.637875] Bytes b4 ddc86670: 14 01 00 00 95 ad 06 00 5a 5a 5a 5a 5a 5a 5a 5a  ........ZZZZZZZZ
[ 2050.637875] Object ddc86680: 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12  ................
[ 2050.637875] Object ddc86690: 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12  ................
[ 2050.637875] Redzone ddc866a0: 12 12 12 12                                      ....
[ 2050.637875] Padding ddc86748: 5a 5a 5a 5a 5a 5a 5a 5a                          ZZZZZZZZ
[ 2050.637875] CPU: 0 PID: 3146 Comm: insmod Tainted: P    B      O 3.10.17 #1
[ 2050.637875] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 2050.637875]  00000000 c10a7b59 c10941c5 dffa90c0 ddc86680 de8012cc de801280 ddc86680
[ 2050.637875]  dffa90c0 c10a7bd3 c13689a5 ddc866a0 000000cc 00000004 de801280 ddc86680
[ 2050.637875]  dffa90c0 de800e00 c12a8b2f 000000cc ddc86680 de801280 dffa90c0 dd407e50
[ 2050.637875] Call Trace:
[ 2050.637875]  [&ltc10a7b59&gt] ? check_bytes_and_report+0x6d/0xb0
[ 2050.637875]  [&ltc10941c5&gt] ? page_address+0x1a/0x79
[ 2050.637875]  [&ltc10a7bd3&gt] ? check_object+0x37/0x149
[ 2050.637875]  [&ltc12a8b2f&gt] ? free_debug_processing+0x67/0x142
[ 2050.637875]  [&ltc12a8c48&gt] ? __slab_free+0x3e/0x28d
[ 2050.637875]  [&lte0998075&gt] ? mymodule_init+0x14/0x19 [mymodule]
[ 2050.637875]  [&ltc102063d&gt] ? wake_up_klogd+0x1d/0x1e
[ 2050.637875]  [&ltc10a89ee&gt] ? kfree+0xe4/0x102
[ 2050.637875]  [&ltc10a89ee&gt] ? kfree+0xe4/0x102
[ 2050.637875]  [&lte0998075&gt] ? mymodule_init+0x14/0x19 [mymodule]
[ 2050.637875]  [&lte0998075&gt] ? mymodule_init+0x14/0x19 [mymodule]
[ 2050.637875]  [&lte0998061&gt] ? try_to_corrupt_redzone+0x61/0x61 [mymodule]
[ 2050.637875]  [&lte0998075&gt] ? mymodule_init+0x14/0x19 [mymodule]
[ 2050.637875]  [&ltc1000148&gt] ? do_one_initcall+0x6c/0xf4
[ 2050.637875]  [&ltc105362b&gt] ? load_module+0x1690/0x199a
[ 2050.637875]  [&ltc10539a7&gt] ? SyS_init_module+0x72/0x8a
[ 2050.637875]  [&ltc12ab8ef&gt] ? syscall_call+0x7/0xb
[ 2050.637875] FIX kmalloc-32: Restoring 0xddc866a0-0xddc866a3=0xcc
[ 2050.637875] 
[ 2051.232817] mymodule_exit exit


 

	
  


 

First the Slub allocator print the error type "RedZone overwritten"

[ 2050.634629] =============================================================================
[ 2050.634750] BUG kmalloc-32 (Tainted: P    B      O): Redzone overwritten
[ 2050.634828] -----------------------------------------------------------------------------
[ 2050.634828] 
[ 2050.634967] INFO: 0xddc866a0-0xddc866a3. First byte 0x12 instead of 0xcc

To understand who Readzone is, take a look at the memory content around the object:

[ 2050.637875] Bytes b4 ddc86670: 14 01 00 00 95 ad 06 00 5a 5a 5a 5a 5a 5a 5a 5a  ........ZZZZZZZZ
[ 2050.637875] Object ddc86680: 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12  ................
[ 2050.637875] Object ddc86690: 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12 12  ................
[ 2050.637875] Redzone ddc866a0: 12 12 12 12                                      ....
[ 2050.637875] Padding ddc86748: 5a 5a 5a 5a 5a 5a 5a 5a                          ZZZZZZZZ


  

	
   


  

We Fill bytes of 0x12 from the start of the 36-bytes object (0xddc86680-0xddc8669f) and 4 more 0x12 on the RedZone (n Ormal 0XBB or 0XCC). When the object was returned to the kernel, kernel finds the redzone was neither 0XCC or 0XBB and reports this as a BUG .

The Slub allocator reports the latest Allocate/free history of this object. You can see the object was just allocated by our kernel module function ' Try_to_corrup_redzone '.

Sometime the traces of the object is more useful than function backtrace. For example, if there exists an use-after-free case:function A allocates an object and writes if after freeing the OBJEC T. If The object is allocated by another function B. In this case, function B has a corrupted object, and if we had the free trace of this object, we can trace back to the PR Evious owner of the object, function A.

[ 2050.635123] INFO: Allocated in try_to_corrupt_redzone+0x16/0x61 [mymodule] age=1 cpu=0 pid=3146
[ 2050.635255]  alloc_debug_processing+0x63/0xd1
[ 2050.635337]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.635423]  __slab_alloc.constprop.73+0x366/0x384
[ 2050.635506]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.635594]  vt_console_print+0x21e/0x226
[ 2050.635672]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.635758]  kmem_cache_alloc_trace+0x43/0xd7
[ 2050.635832]  kmem_cache_alloc_trace+0x43/0xd7
[ 2050.635909]  mymodule_init+0x0/0x19 [mymodule]
[ 2050.635992]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.636003]  mymodule_init+0x0/0x19 [mymodule]
[ 2050.636092]  try_to_corrupt_redzone+0x16/0x61 [mymodule]
[ 2050.636179]  mymodule_init+0x0/0x19 [mymodule]
[ 2050.636261]  mymodule_init+0x14/0x19 [mymodule]
[ 2050.636343]  do_one_initcall+0x6c/0xf4
[ 2050.636428]  load_module+0x1690/0x199a
[ 2050.636508] INFO: Freed in load_module+0x15d2/0x199a age=3 cpu=0 pid=3146
[ 2050.636598]  free_debug_processing+0xd6/0x142
[ 2050.636676]  load_module+0x15d2/0x199a
[ 2050.636749]  __slab_free+0x3e/0x28d
[ 2050.636819]  load_module+0x15d2/0x199a
[ 2050.636888]  kfree+0xe4/0x102
[ 2050.636953]  kfree+0xe4/0x102
[ 2050.637020]  kobject_uevent_env+0x361/0x39a
[ 2050.637091]  kobject_uevent_env+0x361/0x39a
[ 2050.637163]  kfree+0xe4/0x102
[ 2050.637227]  kfree+0xe4/0x102
[ 2050.637294]  load_module+0x15d2/0x199a
[ 2050.637366]  load_module+0x15d2/0x199a
[ 2050.637438]  load_module+0x15d2/0x199a
[ 2050.637509]  SyS_init_module+0x72/0x8a

Posted by Miles MH Chen at 7:34 AM Labels:linux

Debug with Linux Slub allocator