TechVolve: slub_debug: Detect Kernel heap memory corruption

What is slub_debug?

slub_debug helps detect various run-time memory errors (only in memory managed by SLUB) for linux kernel or kernel modules. slub_debug does it's job in alloc/free context.

How to enable slub_debug?

Earlier kernels required a kernel re-compilation. In latest linux kernels, slub_debug can be enabled at boot time. I edited boot options during linux booting to add slub_debug boot option at boot time:

How to find/verify whether slub_debug is enabled or not on a running kernel?

/sys/kernel/slab contains information about slab caches. We can enable/disable status of various slub_debug options by inspecting the proc files of any of the caches. I am taking TCP slab cache to show the enable/disable status.

Below is the output of "TCP" slab cache when slub_debug is disabled:

root@babu-VirtualBox:/sys/kernel/slab/TCP# find . -type f -print -exec cat {} \;

./ctor

./destroy_by_rcu

./align

./reserved

./order

./slabs

./trace

./slabs_cpu_partial

0(0)

./min_partial

./objects_partial

./cache_dma

./sanity_checks

0 <----- 'F' option disabled

./hwcache_align

./free_calls

cat: ./free_calls: Function not implemented

./total_objects

./objects

./poison

0 <----- 'P' flag disabled: Object and padding

./shrink

./slab_size

1344

./alloc_calls

cat: ./alloc_calls: Function not implemented

./object_size

1324

./objs_per_slab

./aliases

./store_user

0 <--- 'S" flag disabled: free/alloc tracking

./cpu_partial

./partial

./reclaim_account

./cpu_slabs

./validate

./red_zone

0 <--- 'Z' flag disabled

root@babu-VirtualBox:/sys/kernel/slab/TCP#

Below is the output of "TCP" slab cache when slub_debug is disabled:

root@babu-VirtualBox:/sys/kernel/slab/UDP# find . -type f -print -exec cat {} \;

./ctor

./destroy_by_rcu

./align

./reserved

./order

./slabs

./trace

./slabs_cpu_partial

0(0)

./min_partial

./objects_partial

./cache_dma

./sanity_checks

1 <--- 'F' option enabled

./hwcache_align

./free_calls

2 <not-available> age=1604946 pid=0 cpus=0

4 __sk_free+0x27b/0x3a0 age=1676017/1676378/1676878 pid=483-718 cpus=0-1

./total_objects

./objects

./poison

1 <--- 'P' flag enabled: Object and padding

./shrink

./slab_size

832

./alloc_calls

6 sk_prot_alloc+0x3f/0x280 age=1676027/1676678/1677324 pid=411-718 cpus=1

./object_size

640

./objs_per_slab

./aliases

./store_user

1 <--- 'S" flag enabled: free/alloc tracking

./cpu_partial

./partial

./reclaim_account

./cpu_slabs

./validate

./red_zone

1 <--- 'Z' flag enabled

root@babu-VirtualBox:/sys/kernel/slab/UDP#

How does slub_debug report the heap corruption?

Use after free errors: slub_debug flags them as poison errors.

I used the following code to test write after free:

         void use_after_free_test(void) /* also, poison test */
         {
            char *ptr = kmalloc(100, GFP_KERNEL);
            kfree(ptr);
            printk("Using buffer memory after free to test whether slub_debug catches use after free \r\n");
            memset(ptr, 'c', 100); /* this bug would be detected when this ptr memory gets allocated to some other kmalloc, at that time, this gets reported as poison error with the kmalloc/kfree stack trace of this function */
         }

root@babu-VirtualBox:~/tools/slub_debug_tests# insmod slub_dbg_tests.ko

[53257.640055] Slub_debug tests start!

[53257.695340] Using buffer memory after free to test whether slub_debug catches use after free

root@babu-VirtualBox:~/tools/slub_debug_tests#

slub_debug detects poison error only when this "use after free" memory is next attempted by slub for allocation. Until then, this remains undetected.

However, we can detect this poison error even before that by running slabinfo tool from command line:

root@babu-VirtualBox:~/tools/slub_debug_tests# /usr/src/linux-3.13.5/tools/vm/slabinfo -v

[53267.799257] =============================================================================

[53267.809964] BUG kmalloc-128 (Tainted: GF B O): Poison overwritten

[53267.809964] -----------------------------------------------------------------------------

[53267.809964]

[53267.809964] INFO: 0xf102e720-0xf102e783. First byte 0x63 instead of 0x6b

[53267.809964] INFO: Allocated in use_after_free_test+0x20/0xa0 [slub_dbg_tests] age=2655 cpu=0 pid=8025

[53267.809964] __slab_alloc.constprop.55+0x76c/0x807

[53267.809964] kmem_cache_alloc_trace+0x2d9/0x320

[53267.809964] use_after_free_test+0x20/0xa0 [slub_dbg_tests] <-- in this case, the owner of this memory is the source of corruption. So, this stack trace happened to be useful to trace the source of memory corruption. However, its not necessary that owner is always the source of corruption.

[53267.809964] 0xf8474015

[53267.809964] do_one_initcall+0x160/0x2c0

[53267.809964] load_module+0x20de/0x25e0

[53267.809964] SyS_init_module+0x17b/0x220

[53267.809964] sysenter_do_call+0x12/0x28

[53267.809964] INFO: Freed in use_after_free_test+0x27/0xa0 [slub_dbg_tests] age=2843 cpu=0 pid=8025

[53267.809964] __slab_free+0x59/0x547

[53267.809964] kfree+0x24a/0x2d0

[53267.809964] use_after_free_test+0x27/0xa0 [slub_dbg_tests]

[53267.809964] 0xf8474015

[53267.809964] do_one_initcall+0x160/0x2c0

[53267.809964] load_module+0x20de/0x25e0

[53267.809964] SyS_init_module+0x17b/0x220

[53267.809964] sysenter_do_call+0x12/0x28

[53267.809964] INFO: Slab 0xf7a1e5c0 objects=13 used=13 fp=0x (null) flags=0x40000080

[53267.809964] INFO: Object 0xf102e720 @offset=1824 fp=0xf102ee40

[53267.809964]

[53267.809964] Bytes b4 f102e710: 73 02 00 00 f7 01 ff ff 5a 5a 5a 5a 5a 5a 5a 5a s.......ZZZZZZZZ

[53267.809964] Object f102e720: 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 cccccccccccccccc

[53267.809964] Object f102e730: 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 cccccccccccccccc

[53267.809964] Object f102e740: 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 cccccccccccccccc

[53267.809964] Object f102e750: 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 cccccccccccccccc

[53267.809964] Object f102e760: 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 cccccccccccccccc

[53267.809964] Object f102e770: 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 63 cccccccccccccccc

[53267.809964] Object f102e780: 63 63 63 63 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b cccckkkkkkkkkkkk

[53267.809964] Object f102e790: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.

[53267.809964] Redzone f102e7a0: bb bb bb bb ....

[53267.809964] Padding f102e848: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ

[53267.809964] CPU: 0 PID: 8027 Comm: bash Tainted: GF B O 3.13.5 #2

[53267.809964] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006

[53267.809964] f102e848 edad5d64 c1c5798b f6c01a00 edad5d90 c12c9615 00000010 00000001

[53267.809964] f102e848 00000008 00000001 f102e000 f102e720 f6c01a00 f102e720 edad5dd4

[53267.809964] c12cb169 c2005db8 f102e720 f102e783 00000063 0000006b f102e720 f6c01a00

[53267.809964] Call Trace:

[53267.809964] [<c1c5798b>] dump_stack+0xb1/0xfa <-- this stack trace belongs to slabinfo & so is not useful

[53267.809964] [<c12c9615>] print_trailer+0x195/0x280

[53267.809964] [<c12cb169>] check_bytes_and_report+0x169/0x1a0

[53267.809964] [<c12cc117>] check_object+0x377/0x400

[53267.809964] [<c1c52b0a>] alloc_debug_processing+0xbf/0x1ba

[53267.809964] [<c1c53a24>] __slab_alloc.constprop.55+0x76c/0x807

[53267.809964] [<c138aac9>] ? load_elf_binary+0x49/0x1e10

[53267.809964] [<c1606c10>] ? strrchr+0x20/0xd0

[53267.809964] [<c12ceaf9>] kmem_cache_alloc_trace+0x2d9/0x320

[53267.809964] [<c138aac9>] ? load_elf_binary+0x49/0x1e10

[53267.809964] [<c138aac9>] load_elf_binary+0x49/0x1e10

[53267.809964] [<c1292c98>] ? get_user_pages+0x88/0xb0

[53267.809964] [<c1303699>] ? get_arg_page+0xb9/0x140

[53267.809964] [<c160f8da>] ? _copy_from_user+0x3a/0x80

[53267.809964] [<c1303b71>] ? copy_strings+0x301/0x380

[53267.809964] [<c13032e9>] search_binary_handler+0x109/0x310

[53267.809964] [<c1306002>] do_execve_common+0x9b2/0xd70

[53267.809964] [<c13067d5>] SyS_execve+0x65/0xc0

[53267.809964] [<c1c77acd>] sysenter_do_call+0x12/0x28

[53267.809964] FIX kmalloc-128: Restoring 0xf102e720-0xf102e783=0x6b

[53267.809964]

[53267.809964] FIX kmalloc-128: Marking all objects used

[53274.013611] SLUB: kmalloc-128 25 slabs counted but counter=29

[53274.093506] SLUB: names_cache 6 slabs counted but counter=7

Double free errors: These are flagged as double free errors. Slub_debug detects this as and when the second free is attempted on an already freed memory:

I used the following code to test double free:

         void double_free_test(void)
         {
              char *ptr = kmalloc(100, GFP_KERNEL);
              kfree(ptr);
              printk("Double freeing memory to test whether slub_debug catches double free\r\n");
              kfree(ptr); /* This is where the double free is detected by slub_debug */
         }

root@babu-VirtualBox:~/tools/slub_debug_tests# insmod slub_dbg_tests.ko

[17869.841399] Slub_debug tests start!

[17869.886384] Double freeing memory to test whether slub_debug catches double free

[17870.007227] =============================================================================

[17870.010861] BUG kmalloc-128 (Tainted: GF B O): Object already free

[17870.010861] -----------------------------------------------------------------------------

[17870.010861]

[17870.010861] INFO: Allocated in double_free_test+0x20/0x40 [slub_dbg_tests] age=30 cpu=0 pid=6579

[17870.010861] __slab_alloc.constprop.55+0x76c/0x807

[17870.010861] kmem_cache_alloc_trace+0x2d9/0x320

[17870.010861] double_free_test+0x20/0x40 [slub_dbg_tests]

[17870.010861] slub_dbg_init+0x15/0x1000 [slub_dbg_tests]

[17870.010861] do_one_initcall+0x160/0x2c0

[17870.010861] load_module+0x20de/0x25e0

[17870.010861] SyS_init_module+0x17b/0x220

[17870.010861] sysenter_do_call+0x12/0x28

[17870.010861] INFO: Freed in double_free_test+0x27/0x40 [slub_dbg_tests] age=30 cpu=0 pid=6579

[17870.010861] __slab_free+0x59/0x547

[17870.010861] kfree+0x24a/0x2d0

[17870.010861] double_free_test+0x27/0x40 [slub_dbg_tests]

[17870.010861] slub_dbg_init+0x15/0x1000 [slub_dbg_tests]

[17870.010861] do_one_initcall+0x160/0x2c0

[17870.010861] load_module+0x20de/0x25e0

[17870.010861] SyS_init_module+0x17b/0x220

[17870.010861] sysenter_do_call+0x12/0x28

[17870.010861] INFO: Slab 0xf7a24420 objects=13 used=7 fp=0xf13215f0 flags=0x40000081

[17870.010861] INFO: Object 0xf13215f0 @offset=1520 fp=0xf13214c0

[17870.010861]

[17870.010861] Bytes b4 f13215e0: a3 19 00 00 b9 f6 42 00 5a 5a 5a 5a 5a 5a 5a 5a ......B.ZZZZZZZZ

[17870.010861] Object f13215f0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[17870.010861] Object f1321600: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[17870.010861] Object f1321610: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[17870.010861] Object f1321620: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[17870.010861] Object f1321630: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[17870.010861] Object f1321640: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[17870.010861] Object f1321650: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[17870.010861] Object f1321660: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.

[17870.010861] Redzone f1321670: bb bb bb bb ....

[17870.010861] Padding f1321718: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ

[17870.010861] CPU: 0 PID: 6579 Comm: insmod Tainted: GF B O 3.13.5 #2

[17870.010861] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006

[17870.010861] f1321718 f3e0fd0c c1c5798b f6c01a00 f3e0fd38 c12c9615 00000010 00000001

[17870.010861] f1321718 00000008 00000001 f1321000 f7a24420 f6c01a00 f13215f0 f3e0fd68

[17870.010861] c1c52817 f6c01a00 c20876d4 c20029f2 f3e0fdc8 f6c00380 00000002 f6c00380

[17870.010861] Call Trace:

[17870.010861] [<c1c5798b>] dump_stack+0xb1/0xfa

[17870.010861] [<c12c9615>] print_trailer+0x195/0x280

[17870.010861] [<c1c52817>] free_debug_processing+0x12a/0x35e

[17870.010861] [<c1c52dca>] __slab_free+0x59/0x547

[17870.010861] [<f864003a>] ? double_free_test+0x3a/0x40 [slub_dbg_tests] <-- This is the stack trace that is trying to double free the already freed memory

[17870.010861] [<c114577b>] ? vprintk_emit+0x3bb/0xad0

[17870.010861] [<f8434000>] ? 0xf8433fff

[17870.010861] [<c12cd2ea>] kfree+0x24a/0x2d0

[17870.010861] [<f864003a>] ? double_free_test+0x3a/0x40 [slub_dbg_tests]

[17870.010861] [<f8434000>] ? 0xf8433fff

[17870.010861] [<f864003a>] double_free_test+0x3a/0x40 [slub_dbg_tests]

[17870.010861] [<f8434015>] slub_dbg_init+0x15/0x1000 [slub_dbg_tests]

[17870.010861] [<c10021f0>] do_one_initcall+0x160/0x2c0

[17870.010861] [<f8434000>] ? 0xf8433fff

[17870.010861] [<c1092189>] ? set_memory_nx+0x99/0xc0

[17870.010861] [<c11875ce>] load_module+0x20de/0x25e0

[17870.010861] [<c117fde0>] ? store_uevent+0x70/0x70

[17870.010861] [<c1187c4b>] SyS_init_module+0x17b/0x220

[17870.010861] [<c1c77acd>] sysenter_do_call+0x12/0x28

[17871.305870] FIX kmalloc-128: Object at 0xf13215f0 not freed

root@babu-VirtualBox:~/tools/slub_debug_tests#

Buffer overrun errors: These are flagged as redzone errors. Slub_debug detects this as and when a kfree is attempted on the memory.

In a kernel module, I allocated 100 bytes & wrote 300 bytes (buffer overrun). This overruns around two or three memory blocks. The following log shows the error thrown by slub_debug when the first block of memory of this 300 bytes is kfreed:

         void buffer_overrun_test(void) /* Also, red zone test */
         {
              char *ptr = kmalloc(100, GFP_KERNEL);
              printk("Overwriting a buffer memory to test whether slub_debug catches buffer overrun\r\n");
              memset(ptr, 'd', 300);
              kfree(ptr);   /* This catches the buffer overrun by detecting it as redzone violation error*/
         }

[55017.957576] Slub_debug tests start!

[55017.973762] Overwriting a buffer memory to test whether slub_debug catches buffer overrun

[55018.074238] =============================================================================

[55018.078149] BUG kmalloc-128 (Tainted: GF B O): Redzone overwritten

[55018.078149] -----------------------------------------------------------------------------

[55018.078149]

[55018.078149] INFO: 0xf5981a00-0xf5981a03. First byte 0x64 instead of 0xcc

[55018.078149] INFO: Allocated in 0x64646464 age=2624345915 cpu=1684300900 pid=1684300900

[55018.078149] 0x64646464 <-- even the stack trace is corrupted/overrun, so this is not useful

[55018.078149] 0x64646464

[55018.078149] INFO: Freed in 0x64646464 age=2624345915 cpu=1684300900 pid=1684300900

[55018.078149] 0x64646464

[55018.078149] INFO: Slab 0xf7ab1020 objects=13 used=11 fp=0xf5981000 flags=0x40000081

[55018.078149] INFO: Object 0xf5981980 @offset=2432 fp=0x64646464

[55018.078149]

[55018.078149] Bytes b4 f5981970: bb 21 00 00 cc b6 d0 00 5a 5a 5a 5a 5a 5a 5a 5a .!......ZZZZZZZZ

[55018.078149] Object f5981980: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Object f5981990: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Object f59819a0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Object f59819b0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Object f59819c0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Object f59819d0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Object f59819e0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Object f59819f0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[55018.078149] Redzone f5981a00: 64 64 64 64 dddd

[55018.078149] Padding f5981aa8: 64 64 64 64 5a 5a 5a 5a ddddZZZZ

[55018.078149] CPU: 1 PID: 8813 Comm: insmod Tainted: GF B O 3.13.5 #2

[55018.078149] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006

[55018.078149] f5981aa8 edbcbca0 c1c5798b f6c01a00 edbcbccc c12c9615 00000010 00000001

[55018.078149] f5981aa8 00000008 00000001 f5981000 f5981a00 f6c01a00 f5981980 edbcbd10

[55018.078149] c12cb169 c2005db8 f5981a00 f5981a03 00000064 000000cc e4c3a542 f7ab1020

[55018.078149] Call Trace:

[55018.078149] [<c1c5798b>] dump_stack+0xb1/0xfa

[55018.078149] [<c12c9615>] print_trailer+0x195/0x280

[55018.078149] [<c12cb169>] check_bytes_and_report+0x169/0x1a0

[55018.078149] [<c12cc047>] check_object+0x2a7/0x400

[55018.078149] [<c1c5284a>] free_debug_processing+0x15d/0x35e

[55018.078149] [<c1c697fc>] ? apic_timer_interrupt+0x34/0x3c

[55018.078149] [<c1c52dca>] __slab_free+0x59/0x547

[55018.078149] [<f85460af>] ? buffer_overrun_test+0x6f/0xa0 [slub_dbg_tests]

[55018.078149] [<c114577b>] ? vprintk_emit+0x3bb/0xad0

[55018.078149] [<f8474000>] ? 0xf8473fff

[55018.078149] [<c12cd2ea>] kfree+0x24a/0x2d0 <-- kfree path in which slub_debug detected this buffer overrun, in this case this is useful because the code that is freeing is the one which is causing buffer overrun

[55018.078149] [<f85460af>] ? buffer_overrun_test+0x6f/0xa0 [slub_dbg_tests]

[55018.078149] [<f8474000>] ? 0xf8473fff

[55018.078149] [<f85460af>] buffer_overrun_test+0x6f/0xa0 [slub_dbg_tests]

[55018.078149] [<f8474015>] slub_dbg_init+0x15/0x1000 [slub_dbg_tests]

[55018.078149] [<c10021f0>] do_one_initcall+0x160/0x2c0

[55018.078149] [<f8474000>] ? 0xf8473fff

[55018.078149] [<c1092189>] ? set_memory_nx+0x99/0xc0

[55018.078149] [<c11875ce>] load_module+0x20de/0x25e0

[55018.078149] [<c117fde0>] ? store_uevent+0x70/0x70

[55018.078149] [<c1187c4b>] SyS_init_module+0x17b/0x220

[55018.078149] [<c1c77acd>] sysenter_do_call+0x12/0x28

[55018.078149] FIX kmalloc-128: Restoring 0xf5981a00-0xf5981a03=0xcc

[55018.078149]

The above trace shows log for only overrun portion of just one block among 300 bytes. The rest of adjacent memory blocks that are overrun will be typically caught when slub attempts alloc/free of those blocks.

However, I ran slabinfo to verify these overruns:

[66089.669107] =============================================================================

[66089.673010] BUG kmalloc-128 (Tainted: GF B O): Redzone overwritten

[66089.673010] -----------------------------------------------------------------------------

[66089.673010]

[66089.673010] INFO: 0xd8c072e0-0xd8c072e3. First byte 0xcc instead of 0xbb

[66089.673010] INFO: Allocated in 0x64646464 age=2627113937 cpu=1684300900 pid=1684300900

[66090.167801] 0x64646464 <-- even the stack trace is corrupted, so this is not useful

[66090.167801] 0x64646464

[66090.167801] INFO: Freed in 0x64646464 age=2627114101 cpu=1684300900 pid=1684300900

[66090.167801] 0x64646464

[66090.167801] INFO: Slab 0xf77160e0 objects=13 used=13 fp=0x (null) flags=0x40000080

[66090.167801] INFO: Object 0xd8c07260 @offset=608 fp=0xd8c07e40

[66090.167801]

[66090.167801] Bytes b4 d8c07250: 14 26 00 00 af eb fa 00 5a 5a 5a 5a 5a 5a 5a 5a .&......ZZZZZZZZ

[66090.167801] Object d8c07260: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Object d8c07270: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Object d8c07280: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Object d8c07290: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Object d8c072a0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Object d8c072b0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Object d8c072c0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Object d8c072d0: 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 64 dddddddddddddddd

[66090.167801] Redzone d8c072e0: cc cc cc cc ....

[66090.167801] Padding d8c07388: 64 64 64 64 5a 5a 5a 5a ddddZZZZ

[66090.167801] CPU: 0 PID: 9756 Comm: bash Tainted: GF B O 3.13.5 #2

[66090.167801] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006

[66090.167801] d8c07388 f2401d64 c1c5798b f6c01a00 f2401d90 c12c9615 00000010 00000001

[66090.167801] d8c07388 00000008 00000001 d8c07000 d8c072e0 f6c01a00 d8c07260 f2401dd4

[66090.167801] c12cb169 c2005db8 d8c072e0 d8c072e3 000000cc 000000bb c12e5363 ffffff70

[66090.167801] Call Trace:

[66090.167801] [<c1c5798b>] dump_stack+0xb1/0xfa <-- this trace belongs to slabinfo, so this is not useful too. So, even if slub_debug detected these errors, we would be clueless about the source of buffer run for this memory block

[66090.167801] [<c12c9615>] print_trailer+0x195/0x280

[66090.167801] [<c12cb169>] check_bytes_and_report+0x169/0x1a0

[66090.167801] [<c12e5363>] ? __mem_cgroup_commit_charge+0x373/0x8d0

[66090.167801] [<c12cc047>] check_object+0x2a7/0x400

[66090.167801] [<c1c52b0a>] alloc_debug_processing+0xbf/0x1ba

[66090.167801] [<c1c53a24>] __slab_alloc.constprop.55+0x76c/0x807

[66090.167801] [<c138aac9>] ? load_elf_binary+0x49/0x1e10

[66090.167801] [<c1606c10>] ? strrchr+0x20/0xd0

[66090.167801] [<c12ceaf9>] kmem_cache_alloc_trace+0x2d9/0x320

[66090.167801] [<c138aac9>] ? load_elf_binary+0x49/0x1e10

[66090.167801] [<c138aac9>] load_elf_binary+0x49/0x1e10

[66090.167801] [<c1292c98>] ? get_user_pages+0x88/0xb0

[66090.167801] [<c1303699>] ? get_arg_page+0xb9/0x140

[66090.167801] [<c160f8da>] ? _copy_from_user+0x3a/0x80

[66090.167801] [<c1303b71>] ? copy_strings+0x301/0x380

[66090.167801] [<c13032e9>] search_binary_handler+0x109/0x310

[66090.167801] [<c1306002>] do_execve_common+0x9b2/0xd70

[66090.167801] [<c13067d5>] SyS_execve+0x65/0xc0

[66090.167801] [<c1c77acd>] sysenter_do_call+0x12/0x28

[66090.167801] FIX kmalloc-128: Restoring 0xd8c072e0-0xd8c072e3=0xbb

[66090.167801]

[66090.167801] FIX kmalloc-128: Marking all objects used

[66096.799275] =============================================================================

[66096.800869] BUG kmalloc-128 (Tainted: GF B O): Redzone overwritten

[66096.800869] -----------------------------------------------------------------------------

[66096.800869]

[66096.800869] INFO: 0xd8c07080-0xd8c07083. First byte 0xbb instead of 0xcc

[66096.800869] INFO: Allocated in load_elf_binary+0x49/0x1e10 age=4944 cpu=0 pid=9750

[66096.800869] __slab_alloc.constprop.55+0x76c/0x807

[66096.800869] kmem_cache_alloc_trace+0x2d9/0x320

[66096.800869] load_elf_binary+0x49/0x1e10

[66096.800869] search_binary_handler+0x109/0x310

[66096.800869] do_execve_common+0x9b2/0xd70

[66096.800869] SyS_execve+0x65/0xc0

[66096.800869] sysenter_do_call+0x12/0x28

[66096.800869] INFO: Freed in load_elf_binary+0x102/0x1e10 age=4944 cpu=0 pid=9750

[66096.800869] __slab_free+0x59/0x547

[66096.800869] kfree+0x24a/0x2d0

[66096.800869] load_elf_binary+0x102/0x1e10

[66096.800869] search_binary_handler+0x109/0x310

[66096.800869] do_execve_common+0x9b2/0xd70

[66096.800869] SyS_execve+0x65/0xc0

[66096.800869] sysenter_do_call+0x12/0x28

[66097.724626] INFO: Slab 0xf77160e0 objects=13 used=13 fp=0x (null) flags=0x40000081

[66097.724626] INFO: Object 0xd8c07000 @offset=0 fp=0xd8c07130

[66097.724626]

[66097.724626] Object d8c07000: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object d8c07010: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object d8c07020: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object d8c07030: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object d8c07040: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object d8c07050: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object d8c07060: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object d8c07070: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.

[66097.724626] Redzone d8c07080: bb bb bb bb ....

[66097.724626] Padding d8c07128: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ

[66097.724626] CPU: 1 PID: 9756 Comm: slabinfo Tainted: GF B O 3.13.5 #2

[66097.724626] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006

[66097.724626] d8c07128 f2401e20 c1c5798b f6c01a00 f2401e4c c12c9615 00000010 00000001

[66097.724626] d8c07128 00000008 00000001 d8c07000 d8c07080 f6c01a00 d8c07000 f2401e90

[66097.724626] c12cb169 c2005db8 d8c07080 d8c07083 000000bb 000000cc c117c3f6 ffffff70

[66097.724626] Call Trace:

[66097.724626] [<c1c5798b>] dump_stack+0xb1/0xfa <-- this trace belongs to slabinfo, so this is not useful. So, even if slub_debug detected these errors, we would be clueless about the source of buffer run for this memory block

[66097.724626] [<c12c9615>] print_trailer+0x195/0x280

[66097.724626] [<c12cb169>] check_bytes_and_report+0x169/0x1a0

[66097.724626] [<c117c3f6>] ? smp_call_function_many+0x86/0x520

[66097.724626] [<c12cc047>] check_object+0x2a7/0x400

[66097.724626] [<c12ccc85>] validate_slab_slab+0x3a5/0x3c0

[66097.724626] [<c12d0165>] validate_store+0x1a5/0x2e0

[66097.724626] [<c12cffc0>] ? alloc_calls_show+0x50/0x50

[66097.724626] [<c12c8d99>] slab_attr_store+0x39/0x60

[66097.724626] [<c13bc377>] sysfs_write_file+0x1d7/0x380

[66097.724626] [<c13bc1a0>] ? sysfs_open_file+0x740/0x740

[66097.724626] [<c12f9989>] vfs_write+0xf9/0x350

[66097.724626] [<c13bc1a0>] ? sysfs_open_file+0x740/0x740

[66097.724626] [<c12fa1f5>] SyS_write+0x85/0x110

[66097.724626] [<c1c77acd>] sysenter_do_call+0x12/0x28

[66097.724626] FIX kmalloc-128: Restoring 0xd8c07080-0xd8c07083=0xcc

[66097.724626]

[66097.724626] =============================================================================

[66097.724626] BUG kmalloc-128 (Tainted: GF B O): Redzone overwritten

[66097.724626] -----------------------------------------------------------------------------

[66097.724626]

[66097.724626] INFO: 0xf3a511b0-0xf3a511b3. First byte 0xbb instead of 0xcc

[66097.724626] INFO: Allocated in load_elf_binary+0x49/0x1e10 age=21055 cpu=1 pid=9437

[66097.724626] __slab_alloc.constprop.55+0x76c/0x807

[66097.724626] kmem_cache_alloc_trace+0x2d9/0x320

[66097.724626] load_elf_binary+0x49/0x1e10

[66097.724626] search_binary_handler+0x109/0x310

[66097.724626] do_execve_common+0x9b2/0xd70

[66097.724626] SyS_execve+0x65/0xc0

[66097.724626] sysenter_do_call+0x12/0x28

[66097.724626] INFO: Freed in load_elf_binary+0x102/0x1e10 age=21155 cpu=1 pid=9437

[66097.724626] __slab_free+0x59/0x547

[66097.724626] kfree+0x24a/0x2d0

[66097.724626] load_elf_binary+0x102/0x1e10

[66097.724626] search_binary_handler+0x109/0x310

[66097.724626] do_execve_common+0x9b2/0xd70

[66097.724626] SyS_execve+0x65/0xc0

[66097.724626] sysenter_do_call+0x12/0x28

[66097.724626] INFO: Slab 0xf7a72a20 objects=13 used=13 fp=0x (null) flags=0x40000081

[66097.724626] INFO: Object 0xf3a51130 @offset=304 fp=0xf3a51260

[66097.724626]

[66097.724626] Bytes b4 f3a51120: 1f 25 00 00 25 b0 fa 00 5a 5a 5a 5a 5a 5a 5a 5a .%..%...ZZZZZZZZ

[66097.724626] Object f3a51130: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object f3a51140: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object f3a51150: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object f3a51160: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object f3a51170: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object f3a51180: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object f3a51190: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk

[66097.724626] Object f3a511a0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.

[66097.724626] Redzone f3a511b0: bb bb bb bb ....

[66097.724626] Padding f3a51258: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ

[66097.724626] CPU: 1 PID: 9756 Comm: slabinfo Tainted: GF B O 3.13.5 #2

[66097.724626] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006

[66097.724626] f3a51258 f2401e20 c1c5798b f6c01a00 f2401e4c c12c9615 00000010 00000001

[66097.724626] f3a51258 00000008 00000001 f3a51000 f3a511b0 f6c01a00 f3a51130 f2401e90

[66097.724626] c12cb169 c2005db8 f3a511b0 f3a511b3 000000bb 000000cc c117c3f6 ffffff70

[66097.724626] Call Trace:

[66097.724626] [<c12c9615>] print_trailer+0x195/0x280

[66097.724626] [<c12cb169>] check_bytes_and_report+0x169/0x1a0

[66097.724626] [<c117c3f6>] ? smp_call_function_many+0x86/0x520

[66097.724626] [<c12cc047>] check_object+0x2a7/0x400

[66097.724626] [<c12ccc85>] validate_slab_slab+0x3a5/0x3c0

[66097.724626] [<c12d0165>] validate_store+0x1a5/0x2e0

[66097.724626] [<c12cffc0>] ? alloc_calls_show+0x50/0x50

[66097.724626] [<c12c8d99>] slab_attr_store+0x39/0x60

[66097.724626] [<c13bc377>] sysfs_write_file+0x1d7/0x380

[66097.724626] [<c13bc1a0>] ? sysfs_open_file+0x740/0x740

[66097.724626] [<c12f9989>] vfs_write+0xf9/0x350

[66097.724626] [<c13bc1a0>] ? sysfs_open_file+0x740/0x740

[66097.724626] [<c12fa1f5>] SyS_write+0x85/0x110

[66097.724626] [<c1c77acd>] sysenter_do_call+0x12/0x28

[66097.724626] FIX kmalloc-128: Restoring 0xf3a511b0-0xf3a511b3=0xcc

[66097.724626]

[66097.724626] SLUB: kmalloc-128 27 slabs counted but counter=32

[66103.155162] SLUB: names_cache 6 slabs counted but counter=7

Limitations of slub_debug

TBD.

References:

https://www.kernel.org/doc/Documentation/vm/slub.txt

TechVolve

Monday, March 3, 2014

slub_debug: Detect Kernel heap memory corruption

No comments: