http://thinkiii.blogspot.jp/2014/02/debug-with-slub-allocator.html
The slub allocator in Linux has 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 is built in your kernel.
The slub allocator creates additional meta data to store allocate/free traces and timestamps. Everytime slub allocator allocate/free an object, it do poison check (data area) and redzone check (boundry).
The module shows how it happens. It allocates 32 bytes from kernel and we overwrite the redzone by memset 36 bytes.
After freeing the object, the kernel checks the object and find that the redzone is overwritten and says:
First the slub allocator print the error type "redzone overwritten"
To understand what readzone is, take a look at the memory content around the object:
We fill 38 bytes of 0x12 from the start of the 36-bytes object (0xddc86680 - 0xddc8669f) and 4 more 0x12 on the redzone (normal 0xbb or 0xcc). When the object is returned to the kernel, kernel finds that the redzone is 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 is just allocated by our kernel module function 'try_to_corrup_redzone'.
Sometime the traces of the object are 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 object. If the object is allocated by another function B. In this case, function B has a corrupted object, and if we have the free trace of this object, we can trace back to the previous owner of the object, function A.
Make sure slub allocator is 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 do poison check (data area) and redzone check (boundry).
The module shows how it happens. It allocates 32 bytes from kernel and we overwrite the redzone by memset 36 bytes.
void try_to_corrupt_redzone(void)
{
void *p = kmalloc(32, GFP_KERNEL);
if (p) {
pr_alert("p: 0x%p
", 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
", __FUNCTION__);
try_to_corrupt_redzone();
return 0;
}
static void mymodule_exit(void)
{
pr_alert("%s exit
", __FUNCTION__);
}
module_init(mymodule_init);
module_exit(mymodule_exit);
After freeing the object, the kernel checks the object and find that the redzone is 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] [<c10a7b59>] ? check_bytes_and_report+0x6d/0xb0 [ 2050.637875] [<c10941c5>] ? page_address+0x1a/0x79 [ 2050.637875] [<c10a7bd3>] ? check_object+0x37/0x149 [ 2050.637875] [<c12a8b2f>] ? free_debug_processing+0x67/0x142 [ 2050.637875] [<c12a8c48>] ? __slab_free+0x3e/0x28d [ 2050.637875] [<e0998075>] ? mymodule_init+0x14/0x19 [mymodule] [ 2050.637875] [<c102063d>] ? wake_up_klogd+0x1d/0x1e [ 2050.637875] [<c10a89ee>] ? kfree+0xe4/0x102 [ 2050.637875] [<c10a89ee>] ? kfree+0xe4/0x102 [ 2050.637875] [<e0998075>] ? mymodule_init+0x14/0x19 [mymodule] [ 2050.637875] [<e0998075>] ? mymodule_init+0x14/0x19 [mymodule] [ 2050.637875] [<e0998061>] ? try_to_corrupt_redzone+0x61/0x61 [mymodule] [ 2050.637875] [<e0998075>] ? mymodule_init+0x14/0x19 [mymodule] [ 2050.637875] [<c1000148>] ? do_one_initcall+0x6c/0xf4 [ 2050.637875] [<c105362b>] ? load_module+0x1690/0x199a [ 2050.637875] [<c10539a7>] ? SyS_init_module+0x72/0x8a [ 2050.637875] [<c12ab8ef>] ? 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 what 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 38 bytes of 0x12 from the start of the 36-bytes object (0xddc86680 - 0xddc8669f) and 4 more 0x12 on the redzone (normal 0xbb or 0xcc). When the object is returned to the kernel, kernel finds that the redzone is 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 is just allocated by our kernel module function 'try_to_corrup_redzone'.
Sometime the traces of the object are 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 object. If the object is allocated by another function B. In this case, function B has a corrupted object, and if we have the free trace of this object, we can trace back to the previous 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