Add architecture specific implementation details for KFENCE and enable
KFENCE for the ppc32 architecture. In particular, this implements the
required interface in <asm/kfence.h>.
KFENCE requires that attributes for pages from its memory pool can
individually be set. Therefore, force the Read/Write linear map to be
mapped at page granularity.
Unit tests succeed on all tests but one:
[ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
[ 15.053324] Expected report_matches(&expect) to be true, but is false
[ 15.068359] not ok 21 - test_invalid_access
Signed-off-by: Christophe Leroy <[email protected]>
---
arch/powerpc/Kconfig | 13 +++++++------
arch/powerpc/include/asm/kfence.h | 32 +++++++++++++++++++++++++++++++
arch/powerpc/mm/book3s32/mmu.c | 2 +-
arch/powerpc/mm/fault.c | 7 ++++++-
arch/powerpc/mm/init_32.c | 3 +++
arch/powerpc/mm/nohash/8xx.c | 5 +++--
6 files changed, 52 insertions(+), 10 deletions(-)
create mode 100644 arch/powerpc/include/asm/kfence.h
diff --git a/arch/powerpc/Kconfig b/arch/powerpc/Kconfig
index 386ae12d8523..d46db0bfb998 100644
--- a/arch/powerpc/Kconfig
+++ b/arch/powerpc/Kconfig
@@ -185,6 +185,7 @@ config PPC
select HAVE_ARCH_KASAN if PPC32 && PPC_PAGE_SHIFT <= 14
select HAVE_ARCH_KASAN_VMALLOC if PPC32 && PPC_PAGE_SHIFT <= 14
select HAVE_ARCH_KGDB
+ select HAVE_ARCH_KFENCE if PPC32
select HAVE_ARCH_MMAP_RND_BITS
select HAVE_ARCH_MMAP_RND_COMPAT_BITS if COMPAT
select HAVE_ARCH_NVRAM_OPS
@@ -786,7 +787,7 @@ config THREAD_SHIFT
config DATA_SHIFT_BOOL
bool "Set custom data alignment"
depends on ADVANCED_OPTIONS
- depends on STRICT_KERNEL_RWX || DEBUG_PAGEALLOC
+ depends on STRICT_KERNEL_RWX || DEBUG_PAGEALLOC || KFENCE
depends on PPC_BOOK3S_32 || (PPC_8xx && !PIN_TLB_DATA && !STRICT_KERNEL_RWX)
help
This option allows you to set the kernel data alignment. When
@@ -798,13 +799,13 @@ config DATA_SHIFT_BOOL
config DATA_SHIFT
int "Data shift" if DATA_SHIFT_BOOL
default 24 if STRICT_KERNEL_RWX && PPC64
- range 17 28 if (STRICT_KERNEL_RWX || DEBUG_PAGEALLOC) && PPC_BOOK3S_32
- range 19 23 if (STRICT_KERNEL_RWX || DEBUG_PAGEALLOC) && PPC_8xx
+ range 17 28 if (STRICT_KERNEL_RWX || DEBUG_PAGEALLOC || KFENCE) && PPC_BOOK3S_32
+ range 19 23 if (STRICT_KERNEL_RWX || DEBUG_PAGEALLOC || KFENCE) && PPC_8xx
default 22 if STRICT_KERNEL_RWX && PPC_BOOK3S_32
- default 18 if DEBUG_PAGEALLOC && PPC_BOOK3S_32
+ default 18 if (DEBUG_PAGEALLOC || KFENCE) && PPC_BOOK3S_32
default 23 if STRICT_KERNEL_RWX && PPC_8xx
- default 23 if DEBUG_PAGEALLOC && PPC_8xx && PIN_TLB_DATA
- default 19 if DEBUG_PAGEALLOC && PPC_8xx
+ default 23 if (DEBUG_PAGEALLOC || KFENCE) && PPC_8xx && PIN_TLB_DATA
+ default 19 if (DEBUG_PAGEALLOC || KFENCE) && PPC_8xx
default PPC_PAGE_SHIFT
help
On Book3S 32 (603+), DBATs are used to map kernel text and rodata RO.
diff --git a/arch/powerpc/include/asm/kfence.h b/arch/powerpc/include/asm/kfence.h
new file mode 100644
index 000000000000..c229ee6a48f0
--- /dev/null
+++ b/arch/powerpc/include/asm/kfence.h
@@ -0,0 +1,32 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * powerpc KFENCE support.
+ *
+ * Copyright (C) 2020 CS GROUP France
+ */
+
+#ifndef __ASM_POWERPC_KFENCE_H
+#define __ASM_POWERPC_KFENCE_H
+
+#include <asm/pgtable.h>
+
+static inline bool arch_kfence_init_pool(void)
+{
+ return true;
+}
+
+static inline bool kfence_protect_page(unsigned long addr, bool protect)
+{
+ pte_t *kpte = virt_to_kpte(addr);
+
+ if (protect) {
+ pte_update(&init_mm, addr, kpte, _PAGE_PRESENT, 0, 0);
+ flush_tlb_kernel_range(addr, addr + PAGE_SIZE);
+ } else {
+ pte_update(&init_mm, addr, kpte, 0, _PAGE_PRESENT, 0);
+ }
+
+ return true;
+}
+
+#endif /* __ASM_POWERPC_KFENCE_H */
diff --git a/arch/powerpc/mm/book3s32/mmu.c b/arch/powerpc/mm/book3s32/mmu.c
index d7eb266a3f7a..4548aec95561 100644
--- a/arch/powerpc/mm/book3s32/mmu.c
+++ b/arch/powerpc/mm/book3s32/mmu.c
@@ -162,7 +162,7 @@ unsigned long __init mmu_mapin_ram(unsigned long base, unsigned long top)
unsigned long border = (unsigned long)__init_begin - PAGE_OFFSET;
- if (debug_pagealloc_enabled() || __map_without_bats) {
+ if (debug_pagealloc_enabled() || __map_without_bats || IS_ENABLED(CONFIG_KFENCE)) {
pr_debug_once("Read-Write memory mapped without BATs\n");
if (base >= border)
return base;
diff --git a/arch/powerpc/mm/fault.c b/arch/powerpc/mm/fault.c
index bb368257b55c..bea13682c909 100644
--- a/arch/powerpc/mm/fault.c
+++ b/arch/powerpc/mm/fault.c
@@ -32,6 +32,7 @@
#include <linux/context_tracking.h>
#include <linux/hugetlb.h>
#include <linux/uaccess.h>
+#include <linux/kfence.h>
#include <asm/firmware.h>
#include <asm/interrupt.h>
@@ -418,8 +419,12 @@ static int ___do_page_fault(struct pt_regs *regs, unsigned long address,
* take a page fault to a kernel address or a page fault to a user
* address outside of dedicated places
*/
- if (unlikely(!is_user && bad_kernel_fault(regs, error_code, address, is_write)))
+ if (unlikely(!is_user && bad_kernel_fault(regs, error_code, address, is_write))) {
+ if (kfence_handle_page_fault(address, is_write, regs))
+ return 0;
+
return SIGSEGV;
+ }
/*
* If we're in an interrupt, have no user context or are running
diff --git a/arch/powerpc/mm/init_32.c b/arch/powerpc/mm/init_32.c
index 02c7db4087cb..3d690be48e84 100644
--- a/arch/powerpc/mm/init_32.c
+++ b/arch/powerpc/mm/init_32.c
@@ -97,6 +97,9 @@ static void __init MMU_setup(void)
if (IS_ENABLED(CONFIG_PPC_8xx))
return;
+ if (IS_ENABLED(CONFIG_KFENCE))
+ __map_without_ltlbs = 1;
+
if (debug_pagealloc_enabled())
__map_without_ltlbs = 1;
diff --git a/arch/powerpc/mm/nohash/8xx.c b/arch/powerpc/mm/nohash/8xx.c
index 19a3eec1d8c5..17051377aed7 100644
--- a/arch/powerpc/mm/nohash/8xx.c
+++ b/arch/powerpc/mm/nohash/8xx.c
@@ -149,7 +149,8 @@ unsigned long __init mmu_mapin_ram(unsigned long base, unsigned long top)
{
unsigned long etext8 = ALIGN(__pa(_etext), SZ_8M);
unsigned long sinittext = __pa(_sinittext);
- bool strict_boundary = strict_kernel_rwx_enabled() || debug_pagealloc_enabled();
+ bool strict_boundary = strict_kernel_rwx_enabled() || debug_pagealloc_enabled() ||
+ IS_ENABLED(CONFIG_KFENCE);
unsigned long boundary = strict_boundary ? sinittext : etext8;
unsigned long einittext8 = ALIGN(__pa(_einittext), SZ_8M);
@@ -161,7 +162,7 @@ unsigned long __init mmu_mapin_ram(unsigned long base, unsigned long top)
return 0;
mmu_mapin_ram_chunk(0, boundary, PAGE_KERNEL_TEXT, true);
- if (debug_pagealloc_enabled()) {
+ if (debug_pagealloc_enabled() || IS_ENABLED(CONFIG_KFENCE)) {
top = boundary;
} else {
mmu_mapin_ram_chunk(boundary, einittext8, PAGE_KERNEL_TEXT, true);
--
2.25.0
Le 02/03/2021 à 09:58, Marco Elver a écrit :
> On Tue, 2 Mar 2021 at 09:37, Christophe Leroy
> <[email protected]> wrote:
>> Add architecture specific implementation details for KFENCE and enable
>> KFENCE for the ppc32 architecture. In particular, this implements the
>> required interface in <asm/kfence.h>.
>
> Nice!
>
>> KFENCE requires that attributes for pages from its memory pool can
>> individually be set. Therefore, force the Read/Write linear map to be
>> mapped at page granularity.
>>
>> Unit tests succeed on all tests but one:
>>
>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
>> [ 15.068359] not ok 21 - test_invalid_access
>
> This is strange, given all the other tests passed. Do you mind sharing
> the full test log?
>
[ 0.000000] Linux version 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty
([email protected]) (powerpc64-linux-gcc (GCC) 10.1.0, GNU ld (GNU Binutils) 2.34) #4674
PREEMPT Tue Mar 2 08:18:49 UTC 2021
[ 0.000000] Using CMPCPRO machine description
[ 0.000000] Found legacy serial port 0 for /soc8321@b0000000/serial@4500
[ 0.000000] mem=b0004500, taddr=b0004500, irq=0, clk=133333334, speed=0
[ 0.000000] Found legacy serial port 1 for /soc8321@b0000000/serial@4600
[ 0.000000] mem=b0004600, taddr=b0004600, irq=0, clk=133333334, speed=0
[ 0.000000] ioremap() called early from find_legacy_serial_ports+0x3e4/0x4d8. Use early_ioremap()
instead
[ 0.000000] printk: bootconsole [udbg0] enabled
[ 0.000000] -----------------------------------------------------
[ 0.000000] phys_mem_size = 0x20000000
[ 0.000000] dcache_bsize = 0x20
[ 0.000000] icache_bsize = 0x20
[ 0.000000] cpu_features = 0x0000000001000140
[ 0.000000] possible = 0x00000000277ce140
[ 0.000000] always = 0x0000000001000000
[ 0.000000] cpu_user_features = 0x84000000 0x00000000
[ 0.000000] mmu_features = 0x00210000
[ 0.000000] Hash_size = 0x0
[ 0.000000] -----------------------------------------------------
[ 0.000000] Top of RAM: 0x20000000, Total RAM: 0x20000000
[ 0.000000] Memory hole size: 0MB
[ 0.000000] Zone ranges:
[ 0.000000] Normal [mem 0x0000000000000000-0x000000001fffffff]
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000000000-0x000000001fffffff]
[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000001fffffff]
[ 0.000000] On node 0 totalpages: 131072
[ 0.000000] Normal zone: 1024 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 131072 pages, LIFO batch:31
[ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[ 0.000000] pcpu-alloc: [0] 0
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 130048
[ 0.000000] Kernel command line: ip=192.168.0.3:192.168.0.1::255.0.0.0:vgoippro:eth0:off
console=ttyS0,115200
[ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes, linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.000000] Memory: 503516K/524288K available (7532K kernel code, 2236K rwdata, 1328K rodata,
1500K init, 931K bss, 20772K reserved, 0K cma-reserved)
[ 0.000000] Kernel virtual memory layout:
[ 0.000000] * 0xff7ff000..0xfffff000 : fixmap
[ 0.000000] * 0xff7fd000..0xff7ff000 : early ioremap
[ 0.000000] * 0xe1000000..0xff7fd000 : vmalloc & ioremap
[ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[ 0.000000] rcu: Preemptible hierarchical RCU implementation.
[ 0.000000] rcu: RCU event tracing is enabled.
[ 0.000000] Trampoline variant of Tasks RCU enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[ 0.000000] NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16
[ 0.000000] IPIC (128 IRQ sources) at (ptrval)
[ 0.000000] kfence: initialized - using 2097152 bytes for 255 objects at 0x(ptrval)-0x(ptrval)
...
[ 4.472455] # Subtest: kfence
[ 4.472490] 1..25
[ 4.476069] # test_out_of_bounds_read: test_alloc: size=32, gfp=cc0, policy=left, cache=0
[ 4.946420] ==================================================================
[ 4.953667] BUG: KFENCE: out-of-bounds read in test_out_of_bounds_read+0x90/0x228
[ 4.953667]
[ 4.962657] Out-of-bounds read at 0x(ptrval) (1B left of kfence-#23):
[ 4.969109] test_out_of_bounds_read+0x90/0x228
[ 4.973663] kunit_try_run_case+0x5c/0xd0
[ 4.977712] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 4.983128] kthread+0x15c/0x174
[ 4.986387] ret_from_kernel_thread+0x14/0x1c
[ 4.990774]
[ 4.992274] kfence-#23 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 91:
[ 5.000997] test_alloc+0x10c/0x384
[ 5.004508] test_out_of_bounds_read+0x90/0x228
[ 5.009057] kunit_try_run_case+0x5c/0xd0
[ 5.013093] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.018505] kthread+0x15c/0x174
[ 5.021758] ret_from_kernel_thread+0x14/0x1c
[ 5.026139]
[ 5.027641] CPU: 0 PID: 91 Comm: kunit_try_catch Not tainted
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 5.037729] ==================================================================
[ 5.045220] # test_out_of_bounds_read: test_alloc: size=32, gfp=cc0, policy=right, cache=0
[ 5.146454] ==================================================================
[ 5.153698] BUG: KFENCE: out-of-bounds read in test_out_of_bounds_read+0x14c/0x228
[ 5.153698]
[ 5.162770] Out-of-bounds read at 0x(ptrval) (32B right of kfence-#24):
[ 5.169395] test_out_of_bounds_read+0x14c/0x228
[ 5.174037] kunit_try_run_case+0x5c/0xd0
[ 5.178085] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.183501] kthread+0x15c/0x174
[ 5.186758] ret_from_kernel_thread+0x14/0x1c
[ 5.191145]
[ 5.192645] kfence-#24 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 91:
[ 5.201366] test_alloc+0x10c/0x384
[ 5.204878] test_out_of_bounds_read+0x14c/0x228
[ 5.209514] kunit_try_run_case+0x5c/0xd0
[ 5.213552] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.218965] kthread+0x15c/0x174
[ 5.222219] ret_from_kernel_thread+0x14/0x1c
[ 5.226600]
[ 5.228103] CPU: 0 PID: 91 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 5.239575] ==================================================================
[ 5.247126] ok 1 - test_out_of_bounds_read
[ 5.247534] # test_out_of_bounds_read-memcache: setup_test_cache: size=32, ctor=0x0
[ 5.260310] # test_out_of_bounds_read-memcache: test_alloc: size=32, gfp=cc0, policy=left,
cache=1
[ 5.356422] ==================================================================
[ 5.363670] BUG: KFENCE: out-of-bounds read in test_out_of_bounds_read+0x90/0x228
[ 5.363670]
[ 5.372661] Out-of-bounds read at 0x(ptrval) (1B left of kfence-#25):
[ 5.379115] test_out_of_bounds_read+0x90/0x228
[ 5.383671] kunit_try_run_case+0x5c/0xd0
[ 5.387720] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.393138] kthread+0x15c/0x174
[ 5.396398] ret_from_kernel_thread+0x14/0x1c
[ 5.400786]
[ 5.402287] kfence-#25 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 92:
[ 5.410490] test_alloc+0xfc/0x384
[ 5.413918] test_out_of_bounds_read+0x90/0x228
[ 5.418470] kunit_try_run_case+0x5c/0xd0
[ 5.422511] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.427926] kthread+0x15c/0x174
[ 5.431180] ret_from_kernel_thread+0x14/0x1c
[ 5.435563]
[ 5.437067] CPU: 0 PID: 92 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 5.448539] ==================================================================
[ 5.456076] # test_out_of_bounds_read-memcache: test_alloc: size=32, gfp=cc0, policy=right,
cache=1
[ 5.556454] ==================================================================
[ 5.563701] BUG: KFENCE: out-of-bounds read in test_out_of_bounds_read+0x14c/0x228
[ 5.563701]
[ 5.572774] Out-of-bounds read at 0x(ptrval) (32B right of kfence-#26):
[ 5.579400] test_out_of_bounds_read+0x14c/0x228
[ 5.584042] kunit_try_run_case+0x5c/0xd0
[ 5.588091] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.593509] kthread+0x15c/0x174
[ 5.596768] ret_from_kernel_thread+0x14/0x1c
[ 5.601155]
[ 5.602656] kfence-#26 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 92:
[ 5.610861] test_alloc+0xfc/0x384
[ 5.614288] test_out_of_bounds_read+0x14c/0x228
[ 5.618927] kunit_try_run_case+0x5c/0xd0
[ 5.622966] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.628382] kthread+0x15c/0x174
[ 5.631637] ret_from_kernel_thread+0x14/0x1c
[ 5.636019]
[ 5.637522] CPU: 0 PID: 92 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 5.648993] ==================================================================
[ 5.656810] ok 2 - test_out_of_bounds_read-memcache
[ 5.657178] # test_out_of_bounds_write: test_alloc: size=32, gfp=cc0, policy=left, cache=0
[ 5.766441] ==================================================================
[ 5.773686] BUG: KFENCE: out-of-bounds write in test_out_of_bounds_write+0x78/0x164
[ 5.773686]
[ 5.782848] Out-of-bounds write at 0x(ptrval) (1B left of kfence-#27):
[ 5.789387] test_out_of_bounds_write+0x78/0x164
[ 5.794029] kunit_try_run_case+0x5c/0xd0
[ 5.798078] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.803494] kthread+0x15c/0x174
[ 5.806753] ret_from_kernel_thread+0x14/0x1c
[ 5.811138]
[ 5.812638] kfence-#27 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 93:
[ 5.821357] test_alloc+0x10c/0x384
[ 5.824868] test_out_of_bounds_write+0x78/0x164
[ 5.829503] kunit_try_run_case+0x5c/0xd0
[ 5.833538] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 5.838949] kthread+0x15c/0x174
[ 5.842202] ret_from_kernel_thread+0x14/0x1c
[ 5.846580]
[ 5.848083] CPU: 0 PID: 93 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 5.859554] ==================================================================
[ 5.867115] ok 3 - test_out_of_bounds_write
[ 5.867476] # test_out_of_bounds_write-memcache: setup_test_cache: size=32, ctor=0x0
[ 5.880408] # test_out_of_bounds_write-memcache: test_alloc: size=32, gfp=cc0, policy=left,
cache=1
[ 5.976421] ==================================================================
[ 5.983669] BUG: KFENCE: out-of-bounds write in test_out_of_bounds_write+0x78/0x164
[ 5.983669]
[ 5.992834] Out-of-bounds write at 0x(ptrval) (1B left of kfence-#28):
[ 5.999374] test_out_of_bounds_write+0x78/0x164
[ 6.004016] kunit_try_run_case+0x5c/0xd0
[ 6.008065] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.013481] kthread+0x15c/0x174
[ 6.016741] ret_from_kernel_thread+0x14/0x1c
[ 6.021128]
[ 6.022631] kfence-#28 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 94:
[ 6.030835] test_alloc+0xfc/0x384
[ 6.034263] test_out_of_bounds_write+0x78/0x164
[ 6.038903] kunit_try_run_case+0x5c/0xd0
[ 6.042944] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.048359] kthread+0x15c/0x174
[ 6.051615] ret_from_kernel_thread+0x14/0x1c
[ 6.055998]
[ 6.057501] CPU: 0 PID: 94 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 6.068973] ==================================================================
[ 6.076743] ok 4 - test_out_of_bounds_write-memcache
[ 6.077110] # test_use_after_free_read: test_alloc: size=32, gfp=cc0, policy=any, cache=0
[ 6.186527] ==================================================================
[ 6.193773] BUG: KFENCE: use-after-free read in test_use_after_free_read+0xa0/0x158
[ 6.193773]
[ 6.202934] Use-after-free read at 0x(ptrval) (in kfence-#29):
[ 6.208777] test_use_after_free_read+0xa0/0x158
[ 6.213417] kunit_try_run_case+0x5c/0xd0
[ 6.217466] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.222882] kthread+0x15c/0x174
[ 6.226140] ret_from_kernel_thread+0x14/0x1c
[ 6.230526]
[ 6.232026] kfence-#29 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 95:
[ 6.240746] test_alloc+0x10c/0x384
[ 6.244257] test_use_after_free_read+0x7c/0x158
[ 6.248892] kunit_try_run_case+0x5c/0xd0
[ 6.252927] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.258337] kthread+0x15c/0x174
[ 6.261590] ret_from_kernel_thread+0x14/0x1c
[ 6.265969]
[ 6.265969] freed by task 95:
[ 6.270467] test_use_after_free_read+0xa0/0x158
[ 6.275108] kunit_try_run_case+0x5c/0xd0
[ 6.279141] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.284551] kthread+0x15c/0x174
[ 6.287802] ret_from_kernel_thread+0x14/0x1c
[ 6.292180]
[ 6.293682] CPU: 0 PID: 95 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 6.305153] ==================================================================
[ 6.312658] ok 5 - test_use_after_free_read
[ 6.313020] # test_use_after_free_read-memcache: setup_test_cache: size=32, ctor=0x0
[ 6.325976] # test_use_after_free_read-memcache: test_alloc: size=32, gfp=cc0, policy=any,
cache=1
[ 6.416496] ==================================================================
[ 6.423743] BUG: KFENCE: use-after-free read in test_use_after_free_read+0x98/0x158
[ 6.423743]
[ 6.432908] Use-after-free read at 0x(ptrval) (in kfence-#30):
[ 6.438752] test_use_after_free_read+0x98/0x158
[ 6.443395] kunit_try_run_case+0x5c/0xd0
[ 6.447445] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.452863] kthread+0x15c/0x174
[ 6.456124] ret_from_kernel_thread+0x14/0x1c
[ 6.460511]
[ 6.462014] kfence-#30 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 96:
[ 6.470219] test_alloc+0xfc/0x384
[ 6.473646] test_use_after_free_read+0x7c/0x158
[ 6.478286] kunit_try_run_case+0x5c/0xd0
[ 6.482327] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.487742] kthread+0x15c/0x174
[ 6.490998] ret_from_kernel_thread+0x14/0x1c
[ 6.495381]
[ 6.495381] freed by task 96:
[ 6.499849] test_use_after_free_read+0x98/0x158
[ 6.504490] kunit_try_run_case+0x5c/0xd0
[ 6.508530] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.513945] kthread+0x15c/0x174
[ 6.517201] ret_from_kernel_thread+0x14/0x1c
[ 6.521583]
[ 6.523086] CPU: 0 PID: 96 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 6.534558] ==================================================================
[ 6.542222] ok 6 - test_use_after_free_read-memcache
[ 6.542587] # test_double_free: test_alloc: size=32, gfp=cc0, policy=any, cache=0
[ 6.646612] ==================================================================
[ 6.653855] BUG: KFENCE: invalid free in test_double_free+0xc0/0x170
[ 6.653855]
[ 6.661704] Invalid free of 0x(ptrval) (in kfence-#31):
[ 6.666940] test_double_free+0xc0/0x170
[ 6.670889] kunit_try_run_case+0x5c/0xd0
[ 6.674928] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.680341] kthread+0x15c/0x174
[ 6.683596] ret_from_kernel_thread+0x14/0x1c
[ 6.687977]
[ 6.689478] kfence-#31 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 97:
[ 6.698196] test_alloc+0x10c/0x384
[ 6.701706] test_double_free+0x7c/0x170
[ 6.705649] kunit_try_run_case+0x5c/0xd0
[ 6.709685] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.715096] kthread+0x15c/0x174
[ 6.718347] ret_from_kernel_thread+0x14/0x1c
[ 6.722725]
[ 6.722725] freed by task 97:
[ 6.727222] test_double_free+0xa0/0x170
[ 6.731169] kunit_try_run_case+0x5c/0xd0
[ 6.735203] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.740615] kthread+0x15c/0x174
[ 6.743865] ret_from_kernel_thread+0x14/0x1c
[ 6.748243]
[ 6.749746] CPU: 0 PID: 97 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 6.761217] ==================================================================
[ 6.768683] ok 7 - test_double_free
[ 6.769043] # test_double_free-memcache: setup_test_cache: size=32, ctor=0x0
[ 6.780589] # test_double_free-memcache: test_alloc: size=32, gfp=cc0, policy=any, cache=1
[ 6.876516] ==================================================================
[ 6.883761] BUG: KFENCE: invalid free in test_double_free+0xb4/0x170
[ 6.883761]
[ 6.891612] Invalid free of 0x(ptrval) (in kfence-#32):
[ 6.896854] test_double_free+0xb4/0x170
[ 6.900807] kunit_try_run_case+0x5c/0xd0
[ 6.904857] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.910277] kthread+0x15c/0x174
[ 6.913540] ret_from_kernel_thread+0x14/0x1c
[ 6.917930]
[ 6.919432] kfence-#32 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 98:
[ 6.927637] test_alloc+0xfc/0x384
[ 6.931067] test_double_free+0x7c/0x170
[ 6.935015] kunit_try_run_case+0x5c/0xd0
[ 6.939057] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.944473] kthread+0x15c/0x174
[ 6.947728] ret_from_kernel_thread+0x14/0x1c
[ 6.952113]
[ 6.952113] freed by task 98:
[ 6.956579] test_double_free+0x98/0x170
[ 6.960528] kunit_try_run_case+0x5c/0xd0
[ 6.964570] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 6.969985] kthread+0x15c/0x174
[ 6.973242] ret_from_kernel_thread+0x14/0x1c
[ 6.977626]
[ 6.979130] CPU: 0 PID: 98 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 6.990602] ==================================================================
[ 6.998260] ok 8 - test_double_free-memcache
[ 6.998626] # test_invalid_addr_free: test_alloc: size=32, gfp=cc0, policy=any, cache=0
[ 7.106546] ==================================================================
[ 7.113790] BUG: KFENCE: invalid free in test_invalid_addr_free+0xa4/0x178
[ 7.113790]
[ 7.122159] Invalid free of 0x(ptrval) (in kfence-#33):
[ 7.127397] test_invalid_addr_free+0xa4/0x178
[ 7.131867] kunit_try_run_case+0x5c/0xd0
[ 7.135907] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 7.141323] kthread+0x15c/0x174
[ 7.144576] ret_from_kernel_thread+0x14/0x1c
[ 7.148959]
[ 7.150460] kfence-#33 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 99:
[ 7.159179] test_alloc+0x10c/0x384
[ 7.162692] test_invalid_addr_free+0x78/0x178
[ 7.167157] kunit_try_run_case+0x5c/0xd0
[ 7.171195] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 7.176608] kthread+0x15c/0x174
[ 7.179862] ret_from_kernel_thread+0x14/0x1c
[ 7.184245]
[ 7.185748] CPU: 0 PID: 99 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 7.197220] ==================================================================
[ 7.204816] ok 9 - test_invalid_addr_free
[ 7.205177] # test_invalid_addr_free-memcache: setup_test_cache: size=32, ctor=0x0
[ 7.217849] # test_invalid_addr_free-memcache: test_alloc: size=32, gfp=cc0, policy=any, cache=1
[ 7.306455] ==================================================================
[ 7.313701] BUG: KFENCE: invalid free in test_invalid_addr_free+0x98/0x178
[ 7.313701]
[ 7.322070] Invalid free of 0x(ptrval) (in kfence-#34):
[ 7.327310] test_invalid_addr_free+0x98/0x178
[ 7.331781] kunit_try_run_case+0x5c/0xd0
[ 7.335832] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 7.341252] kthread+0x15c/0x174
[ 7.344514] ret_from_kernel_thread+0x14/0x1c
[ 7.348903]
[ 7.350405] kfence-#34 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 100:
[ 7.358695] test_alloc+0xfc/0x384
[ 7.362125] test_invalid_addr_free+0x78/0x178
[ 7.366591] kunit_try_run_case+0x5c/0xd0
[ 7.370631] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 7.376047] kthread+0x15c/0x174
[ 7.379303] ret_from_kernel_thread+0x14/0x1c
[ 7.383687]
[ 7.385191] CPU: 0 PID: 100 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 7.396751] ==================================================================
[ 7.404531] ok 10 - test_invalid_addr_free-memcache
[ 7.404897] # test_corruption: test_alloc: size=32, gfp=cc0, policy=left, cache=0
[ 7.506510] ==================================================================
[ 7.513754] BUG: KFENCE: memory corruption in test_corruption+0xac/0x20c
[ 7.513754]
[ 7.521951] Corrupted memory at 0x(ptrval) [ ! . . . . . . . . . . . . . . . ] (in kfence-#35):
[ 7.530760] test_corruption+0xac/0x20c
[ 7.534624] kunit_try_run_case+0x5c/0xd0
[ 7.538664] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 7.544080] kthread+0x15c/0x174
[ 7.547335] ret_from_kernel_thread+0x14/0x1c
[ 7.551719]
[ 7.553219] kfence-#35 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 101:
[ 7.562027] test_alloc+0x10c/0x384
[ 7.565540] test_corruption+0x7c/0x20c
[ 7.569399] kunit_try_run_case+0x5c/0xd0
[ 7.573437] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 7.578850] kthread+0x15c/0x174
[ 7.582104] ret_from_kernel_thread+0x14/0x1c
[ 7.586485]
[ 7.587988] CPU: 0 PID: 101 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 7.599545] ==================================================================
[ 7.606994] # test_corruption: test_alloc: size=32, gfp=cc0, policy=right, cache=0
[ 7.976603] ==================================================================
[ 7.983846] BUG: KFENCE: memory corruption in test_corruption+0x168/0x20c
[ 7.983846]
[ 7.992128] Corrupted memory at 0x(ptrval) [ ! ] (in kfence-#38):
[ 7.998258] test_corruption+0x168/0x20c
[ 8.002208] kunit_try_run_case+0x5c/0xd0
[ 8.006247] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 8.011661] kthread+0x15c/0x174
[ 8.014915] ret_from_kernel_thread+0x14/0x1c
[ 8.019297]
[ 8.020797] kfence-#38 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 101:
[ 8.029603] test_alloc+0x10c/0x384
[ 8.033114] test_corruption+0x138/0x20c
[ 8.037057] kunit_try_run_case+0x5c/0xd0
[ 8.041092] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 8.046503] kthread+0x15c/0x174
[ 8.049752] ret_from_kernel_thread+0x14/0x1c
[ 8.054131]
[ 8.055633] CPU: 0 PID: 101 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 8.067190] ==================================================================
[ 8.074671] ok 11 - test_corruption
[ 8.075043] # test_corruption-memcache: setup_test_cache: size=32, ctor=0x0
[ 8.086586] # test_corruption-memcache: test_alloc: size=32, gfp=cc0, policy=left, cache=1
[ 8.436449] ==================================================================
[ 8.443694] BUG: KFENCE: memory corruption in test_corruption+0xa4/0x20c
[ 8.443694]
[ 8.451888] Corrupted memory at 0x(ptrval) [ ! . . . . . . . . . . . . . . . ] (in kfence-#41):
[ 8.460709] test_corruption+0xa4/0x20c
[ 8.464573] kunit_try_run_case+0x5c/0xd0
[ 8.468622] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 8.474039] kthread+0x15c/0x174
[ 8.477298] ret_from_kernel_thread+0x14/0x1c
[ 8.481685]
[ 8.483187] kfence-#41 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 102:
[ 8.491476] test_alloc+0xfc/0x384
[ 8.494904] test_corruption+0x7c/0x20c
[ 8.498763] kunit_try_run_case+0x5c/0xd0
[ 8.502801] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 8.508215] kthread+0x15c/0x174
[ 8.511468] ret_from_kernel_thread+0x14/0x1c
[ 8.515849]
[ 8.517352] CPU: 0 PID: 102 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 8.528910] ==================================================================
[ 8.536421] # test_corruption-memcache: test_alloc: size=32, gfp=cc0, policy=right, cache=1
[ 8.646543] ==================================================================
[ 8.653786] BUG: KFENCE: memory corruption in test_corruption+0x160/0x20c
[ 8.653786]
[ 8.662066] Corrupted memory at 0x(ptrval) [ ! ] (in kfence-#42):
[ 8.668201] test_corruption+0x160/0x20c
[ 8.672151] kunit_try_run_case+0x5c/0xd0
[ 8.676199] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 8.681615] kthread+0x15c/0x174
[ 8.684872] ret_from_kernel_thread+0x14/0x1c
[ 8.689259]
[ 8.690760] kfence-#42 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 102:
[ 8.699050] test_alloc+0xfc/0x384
[ 8.702477] test_corruption+0x138/0x20c
[ 8.706422] kunit_try_run_case+0x5c/0xd0
[ 8.710461] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 8.715875] kthread+0x15c/0x174
[ 8.719130] ret_from_kernel_thread+0x14/0x1c
[ 8.723511]
[ 8.725014] CPU: 0 PID: 102 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 8.736572] ==================================================================
[ 8.744274] ok 12 - test_corruption-memcache
[ 8.744642] # test_free_bulk: test_alloc: size=108, gfp=cc0, policy=right, cache=0
[ 8.846447] # test_free_bulk: test_alloc: size=108, gfp=cc0, policy=none, cache=0
[ 8.854317] # test_free_bulk: test_alloc: size=108, gfp=cc0, policy=left, cache=0
[ 8.976407] # test_free_bulk: test_alloc: size=108, gfp=cc0, policy=none, cache=0
[ 8.984275] # test_free_bulk: test_alloc: size=108, gfp=cc0, policy=none, cache=0
[ 8.992322] # test_free_bulk: test_alloc: size=279, gfp=cc0, policy=right, cache=0
[ 9.496452] # test_free_bulk: test_alloc: size=279, gfp=cc0, policy=none, cache=0
[ 9.504323] # test_free_bulk: test_alloc: size=279, gfp=cc0, policy=left, cache=0
[ 9.626404] # test_free_bulk: test_alloc: size=279, gfp=cc0, policy=none, cache=0
[ 9.634272] # test_free_bulk: test_alloc: size=279, gfp=cc0, policy=none, cache=0
[ 9.642331] # test_free_bulk: test_alloc: size=168, gfp=cc0, policy=right, cache=0
[ 9.886438] # test_free_bulk: test_alloc: size=168, gfp=cc0, policy=none, cache=0
[ 9.894309] # test_free_bulk: test_alloc: size=168, gfp=cc0, policy=left, cache=0
[ 10.146407] # test_free_bulk: test_alloc: size=168, gfp=cc0, policy=none, cache=0
[ 10.154277] # test_free_bulk: test_alloc: size=168, gfp=cc0, policy=none, cache=0
[ 10.162329] # test_free_bulk: test_alloc: size=95, gfp=cc0, policy=right, cache=0
[ 10.406442] # test_free_bulk: test_alloc: size=95, gfp=cc0, policy=none, cache=0
[ 10.414225] # test_free_bulk: test_alloc: size=95, gfp=cc0, policy=left, cache=0
[ 10.796405] # test_free_bulk: test_alloc: size=95, gfp=cc0, policy=none, cache=0
[ 10.804189] # test_free_bulk: test_alloc: size=95, gfp=cc0, policy=none, cache=0
[ 10.812156] # test_free_bulk: test_alloc: size=214, gfp=cc0, policy=right, cache=0
[ 11.056442] # test_free_bulk: test_alloc: size=214, gfp=cc0, policy=none, cache=0
[ 11.064312] # test_free_bulk: test_alloc: size=214, gfp=cc0, policy=left, cache=0
[ 11.186407] # test_free_bulk: test_alloc: size=214, gfp=cc0, policy=none, cache=0
[ 11.194276] # test_free_bulk: test_alloc: size=214, gfp=cc0, policy=none, cache=0
[ 11.202357] ok 13 - test_free_bulk
[ 11.202730] # test_free_bulk-memcache: setup_test_cache: size=264, ctor=0x0
[ 11.214213] # test_free_bulk-memcache: test_alloc: size=264, gfp=cc0, policy=right, cache=1
[ 11.316443] # test_free_bulk-memcache: test_alloc: size=264, gfp=cc0, policy=none, cache=1
[ 11.325092] # test_free_bulk-memcache: test_alloc: size=264, gfp=cc0, policy=left, cache=1
[ 11.706404] # test_free_bulk-memcache: test_alloc: size=264, gfp=cc0, policy=none, cache=1
[ 11.715052] # test_free_bulk-memcache: test_alloc: size=264, gfp=cc0, policy=none, cache=1
[ 11.724042] # test_free_bulk-memcache: setup_test_cache: size=58, ctor=ctor_set_x
[ 11.732296] # test_free_bulk-memcache: test_alloc: size=58, gfp=cc0, policy=right, cache=1
[ 12.486442] # test_free_bulk-memcache: test_alloc: size=58, gfp=cc0, policy=none, cache=1
[ 12.495083] # test_free_bulk-memcache: test_alloc: size=58, gfp=cc0, policy=left, cache=1
[ 12.616406] # test_free_bulk-memcache: test_alloc: size=58, gfp=cc0, policy=none, cache=1
[ 12.624967] # test_free_bulk-memcache: test_alloc: size=58, gfp=cc0, policy=none, cache=1
[ 12.633885] # test_free_bulk-memcache: setup_test_cache: size=260, ctor=0x0
[ 12.641609] # test_free_bulk-memcache: test_alloc: size=260, gfp=cc0, policy=right, cache=1
[ 12.746443] # test_free_bulk-memcache: test_alloc: size=260, gfp=cc0, policy=none, cache=1
[ 12.755091] # test_free_bulk-memcache: test_alloc: size=260, gfp=cc0, policy=left, cache=1
[ 13.136401] # test_free_bulk-memcache: test_alloc: size=260, gfp=cc0, policy=none, cache=1
[ 13.145052] # test_free_bulk-memcache: test_alloc: size=260, gfp=cc0, policy=none, cache=1
[ 13.154042] # test_free_bulk-memcache: setup_test_cache: size=155, ctor=ctor_set_x
[ 13.162383] # test_free_bulk-memcache: test_alloc: size=155, gfp=cc0, policy=right, cache=1
[ 13.526458] # test_free_bulk-memcache: test_alloc: size=155, gfp=cc0, policy=none, cache=1
[ 13.535107] # test_free_bulk-memcache: test_alloc: size=155, gfp=cc0, policy=left, cache=1
[ 13.786404] # test_free_bulk-memcache: test_alloc: size=155, gfp=cc0, policy=none, cache=1
[ 13.795051] # test_free_bulk-memcache: test_alloc: size=155, gfp=cc0, policy=none, cache=1
[ 13.804047] # test_free_bulk-memcache: setup_test_cache: size=173, ctor=0x0
[ 13.811768] # test_free_bulk-memcache: test_alloc: size=173, gfp=cc0, policy=right, cache=1
[ 13.916446] # test_free_bulk-memcache: test_alloc: size=173, gfp=cc0, policy=none, cache=1
[ 13.925094] # test_free_bulk-memcache: test_alloc: size=173, gfp=cc0, policy=left, cache=1
[ 14.046408] # test_free_bulk-memcache: test_alloc: size=173, gfp=cc0, policy=none, cache=1
[ 14.055057] # test_free_bulk-memcache: test_alloc: size=173, gfp=cc0, policy=none, cache=1
[ 14.064085] ok 14 - test_free_bulk-memcache
[ 14.064468] ok 15 - test_init_on_free
[ 14.069584] ok 16 - test_init_on_free-memcache
[ 14.073956] # test_kmalloc_aligned_oob_read: test_alloc: size=73, gfp=cc0, policy=right, cache=0
[ 14.176456] ==================================================================
[ 14.183702] BUG: KFENCE: out-of-bounds read in test_kmalloc_aligned_oob_read+0x60/0x200
[ 14.183702]
[ 14.193213] Out-of-bounds read at 0x(ptrval) (81B right of kfence-#84):
[ 14.199839] test_kmalloc_aligned_oob_read+0x60/0x200
[ 14.204914] kunit_try_run_case+0x5c/0xd0
[ 14.208964] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 14.214380] kthread+0x15c/0x174
[ 14.217640] ret_from_kernel_thread+0x14/0x1c
[ 14.222026]
[ 14.223527] kfence-#84 [0x(ptrval)-0x(ptrval), size=73, cache=kmalloc-96] allocated by task 107:
[ 14.232335] test_alloc+0x10c/0x384
[ 14.235847] test_kmalloc_aligned_oob_read+0x60/0x200
[ 14.240916] kunit_try_run_case+0x5c/0xd0
[ 14.244953] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 14.250365] kthread+0x15c/0x174
[ 14.253617] ret_from_kernel_thread+0x14/0x1c
[ 14.257998]
[ 14.259501] CPU: 0 PID: 107 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 14.271058] ==================================================================
[ 14.278626] ok 17 - test_kmalloc_aligned_oob_read
[ 14.278987] # test_kmalloc_aligned_oob_write: test_alloc: size=73, gfp=cc0, policy=right, cache=0
[ 14.646606] ==================================================================
[ 14.653849] BUG: KFENCE: memory corruption in test_kmalloc_aligned_oob_write+0x104/0x1b0
[ 14.653849]
[ 14.663430] Corrupted memory at 0x(ptrval) [ ! . . . . . . ] (in kfence-#87):
[ 14.670630] test_kmalloc_aligned_oob_write+0x104/0x1b0
[ 14.675880] kunit_try_run_case+0x5c/0xd0
[ 14.679921] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 14.685337] kthread+0x15c/0x174
[ 14.688592] ret_from_kernel_thread+0x14/0x1c
[ 14.692975]
[ 14.694477] kfence-#87 [0x(ptrval)-0x(ptrval), size=73, cache=kmalloc-96] allocated by task 108:
[ 14.703285] test_alloc+0x10c/0x384
[ 14.706800] test_kmalloc_aligned_oob_write+0x58/0x1b0
[ 14.711959] kunit_try_run_case+0x5c/0xd0
[ 14.715997] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 14.721411] kthread+0x15c/0x174
[ 14.724666] ret_from_kernel_thread+0x14/0x1c
[ 14.729047]
[ 14.730551] CPU: 0 PID: 108 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 14.742108] ==================================================================
[ 14.749627] ok 18 - test_kmalloc_aligned_oob_write
[ 14.749989] # test_shrink_memcache: setup_test_cache: size=32, ctor=0x0
[ 14.762405] # test_shrink_memcache: test_alloc: size=32, gfp=cc0, policy=any, cache=1
[ 14.856686] ok 19 - test_shrink_memcache
[ 14.857052] # test_memcache_ctor: setup_test_cache: size=32, ctor=ctor_set_x
[ 14.869060] # test_memcache_ctor: test_alloc: size=32, gfp=cc0, policy=any, cache=1
[ 14.986723] ok 20 - test_memcache_ctor
[ 14.987102] ==================================================================
[ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
[ 14.998426]
[ 15.007061] Invalid read at 0x(ptrval):
[ 15.010906] finish_task_switch.isra.0+0x54/0x23c
[ 15.015633] kunit_try_run_case+0x5c/0xd0
[ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 15.025099] kthread+0x15c/0x174
[ 15.028359] ret_from_kernel_thread+0x14/0x1c
[ 15.032747]
[ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 15.045811] ==================================================================
[ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
[ 15.053324] Expected report_matches(&expect) to be true, but is false
[ 15.068359] not ok 21 - test_invalid_access
[ 15.068722] # test_gfpzero: test_alloc: size=4096, gfp=cc0, policy=any, cache=0
[ 15.156430] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 15.286387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 15.416379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 15.546385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 15.676382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 15.806388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 15.936382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.066420] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.196384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.326379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.456381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.586400] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.716382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.846389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 16.976382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 17.106388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 17.236380] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 17.366395] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 17.496385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 17.626383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 17.756398] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 17.886386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.016387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.146383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.276385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.406388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.536389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.666387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.796386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 18.926381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.056383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.186384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.316388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.446382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.576387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.706386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.836379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 19.966387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 20.096387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 20.226387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 20.356381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 20.486386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 20.616380] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 20.746387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 20.876379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.006383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.136389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.266385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.396385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.526382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.656387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.786385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 21.916385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.046381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.176381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.306401] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.436383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.566381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.696411] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.826388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 22.956383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.086387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.216405] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.346379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.476381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.606387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.736385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.866383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 23.996386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 24.126390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 24.256386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 24.386382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 24.516388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 24.646385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 24.776381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 24.906385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.036379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.166381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.296391] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.426385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.556380] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.686385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.816387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 25.946382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.076379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.206384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.336389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.466383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.596385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.726379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.856389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 26.986384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 27.116383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 27.246381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 27.376387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 27.506395] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 27.636381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 27.766386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 27.896381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.026387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.156386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.286393] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.416388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.546385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.676380] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.806384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 28.936387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.066390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.196384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.326416] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.456388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.586383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.716385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.846402] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 29.976396] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 30.106385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 30.236379] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 30.366395] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 30.496386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 30.626387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 30.756380] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 30.886386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.016381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.146383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.276388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.406386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.536383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.666388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.796384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 31.926384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.056391] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.186382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.316385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.446391] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.576385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.706381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.836388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 32.966388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 33.096378] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 33.226386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 33.356383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 33.486389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 33.616386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 33.746383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 33.876385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.006383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.136389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.266384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.396385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.526382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.656385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.786383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 34.916383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.046390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.176387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.306386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.436385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.566382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.696386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.826383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 35.956415] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.086386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.216382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.346378] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.476404] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.606382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.736386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.866381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 36.996388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 37.126390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 37.256395] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 37.386388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 37.516386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 37.646382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 37.776385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 37.906385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.036389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.166382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.296389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.426387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.556388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.686388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.816386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 38.946381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.076382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.206387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.336386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.466382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.596392] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.726382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.856390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 39.986389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 40.116382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 40.246382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 40.376381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 40.506387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 40.636388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 40.766387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 40.896381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.026390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.156384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.286380] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.416384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.546383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.676388] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.806386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 41.936381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.066390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.196389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.326386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.456390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.586414] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.716380] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.846386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 42.976381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 43.106404] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 43.236385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 43.366387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 43.496382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 43.626385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 43.756378] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 43.886387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.016390] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.146385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.276389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.406382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.536384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.666391] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.796382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 44.926387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.056381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.186384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.316389] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.446382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.576385] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.706382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.836387] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 45.966383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 46.096383] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 46.226382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 46.356382] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 46.486384] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 46.616391] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 46.746386] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 46.876381] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 47.006399] # test_gfpzero: test_alloc: size=4096, gfp=dc0, policy=any, cache=0
[ 47.136923] ok 22 - test_gfpzero
[ 47.137299] # test_memcache_typesafe_by_rcu: setup_test_cache: size=32, ctor=0x0
[ 47.148950] # test_memcache_typesafe_by_rcu: test_alloc: size=32, gfp=cc0, policy=any, cache=1
[ 47.296422] ==================================================================
[ 47.303670] BUG: KFENCE: use-after-free read in test_memcache_typesafe_by_rcu+0x210/0x34c
[ 47.303670]
[ 47.313354] Use-after-free read at 0x(ptrval) (in kfence-#91):
[ 47.319199] test_memcache_typesafe_by_rcu+0x210/0x34c
[ 47.324363] kunit_try_run_case+0x5c/0xd0
[ 47.328412] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 47.333830] kthread+0x15c/0x174
[ 47.337090] ret_from_kernel_thread+0x14/0x1c
[ 47.341476]
[ 47.342979] kfence-#91 [0x(ptrval)-0x(ptrval), size=32, cache=test] allocated by task 113:
[ 47.351269] test_alloc+0xfc/0x384
[ 47.354696] test_memcache_typesafe_by_rcu+0x100/0x34c
[ 47.359855] kunit_try_run_case+0x5c/0xd0
[ 47.363896] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 47.369311] kthread+0x15c/0x174
[ 47.372568] ret_from_kernel_thread+0x14/0x1c
[ 47.376951]
[ 47.376951] freed by task 0:
[ 47.381401] rcu_core+0x1c8/0x900
[ 47.384741] __do_softirq+0x13c/0x374
[ 47.388431] irq_exit+0x9c/0xf8
[ 47.391599] ret_from_except+0x0/0x14
[ 47.395289] default_idle_call+0x5c/0x10c
[ 47.399326] do_idle+0x8c/0x118
[ 47.402495] cpu_startup_entry+0x14/0x1c
[ 47.406441] start_kernel+0x4e4/0x530
[ 47.410123] 0x37d0
[ 47.412239]
[ 47.413742] CPU: 0 PID: 113 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 47.425300] ==================================================================
[ 47.432931] ok 23 - test_memcache_typesafe_by_rcu
[ 47.433487] # test_krealloc: test_alloc: size=32, gfp=cc0, policy=any, cache=0
[ 47.556587] ==================================================================
[ 47.563835] BUG: KFENCE: use-after-free read in test_krealloc+0x3dc/0x578
[ 47.563835]
[ 47.572130] Use-after-free read at 0x(ptrval) (in kfence-#93):
[ 47.577973] test_krealloc+0x3dc/0x578
[ 47.581751] kunit_try_run_case+0x5c/0xd0
[ 47.585800] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 47.591218] kthread+0x15c/0x174
[ 47.594476] ret_from_kernel_thread+0x14/0x1c
[ 47.598863]
[ 47.600364] kfence-#93 [0x(ptrval)-0x(ptrval), size=32, cache=kmalloc-32] allocated by task 114:
[ 47.609170] test_alloc+0x10c/0x384
[ 47.612684] test_krealloc+0x4c/0x578
[ 47.616369] kunit_try_run_case+0x5c/0xd0
[ 47.620411] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 47.625825] kthread+0x15c/0x174
[ 47.629078] ret_from_kernel_thread+0x14/0x1c
[ 47.633460]
[ 47.633460] freed by task 114:
[ 47.638066] krealloc+0xc4/0x124
[ 47.641327] test_krealloc+0x170/0x578
[ 47.645103] kunit_try_run_case+0x5c/0xd0
[ 47.649140] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 47.654554] kthread+0x15c/0x174
[ 47.657808] ret_from_kernel_thread+0x14/0x1c
[ 47.662188]
[ 47.663691] CPU: 0 PID: 114 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 47.675248] ==================================================================
[ 47.682686] ok 24 - test_krealloc
[ 47.683045] # test_memcache_alloc_bulk: setup_test_cache: size=32, ctor=0x0
[ 47.786755] ok 25 - test_memcache_alloc_bulk
[ 47.786799] not ok 1 - kfence
Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
>> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>> [ 14.998426]
>> [ 15.007061] Invalid read at 0x(ptrval):
>> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
>> [ 15.015633] kunit_try_run_case+0x5c/0xd0
>> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
>> [ 15.025099] kthread+0x15c/0x174
>> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
>> [ 15.032747]
>> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>> [ 15.045811] ==================================================================
>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
>> [ 15.068359] not ok 21 - test_invalid_access
>
> The test expects the function name to be test_invalid_access, i. e.
> the first line should be "BUG: KFENCE: invalid read in
> test_invalid_access".
> The error reporting function unwinds the stack, skips a couple of
> "uninteresting" frames
> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
> and uses the first "interesting" one frame to print the report header
> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
>
> It's strange that test_invalid_access is missing altogether from the
> stack trace - is that expected?
> Can you try printing the whole stacktrace without skipping any frames
> to see if that function is there?
>
Booting with 'no_hash_pointers" I get the following. Does it helps ?
[ 16.837198] ==================================================================
[ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
[ 16.848521]
[ 16.857158] Invalid read at 0xdf98800a:
[ 16.861004] finish_task_switch.isra.0+0x54/0x23c
[ 16.865731] kunit_try_run_case+0x5c/0xd0
[ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 16.875199] kthread+0x15c/0x174
[ 16.878460] ret_from_kernel_thread+0x14/0x1c
[ 16.882847]
[ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
[ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
[ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
(5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
[ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
[ 16.918153] DAR: df98800a DSISR: 20000000
[ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
[ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
[ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
[ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
[ 16.947292] Call Trace:
[ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
[ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
[ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
[ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
[ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
[ 16.981896] Instruction dump:
[ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
[ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
[ 17.000711] ==================================================================
[ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
[ 17.008223] Expected report_matches(&expect) to be true, but is false
[ 17.023243] not ok 21 - test_invalid_access
> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
> [ 14.998426]
> [ 15.007061] Invalid read at 0x(ptrval):
> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
> [ 15.015633] kunit_try_run_case+0x5c/0xd0
> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
> [ 15.025099] kthread+0x15c/0x174
> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
> [ 15.032747]
> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
> [ 15.045811] ==================================================================
> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> [ 15.053324] Expected report_matches(&expect) to be true, but is false
> [ 15.068359] not ok 21 - test_invalid_access
The test expects the function name to be test_invalid_access, i. e.
the first line should be "BUG: KFENCE: invalid read in
test_invalid_access".
The error reporting function unwinds the stack, skips a couple of
"uninteresting" frames
(https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
and uses the first "interesting" one frame to print the report header
(https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
It's strange that test_invalid_access is missing altogether from the
stack trace - is that expected?
Can you try printing the whole stacktrace without skipping any frames
to see if that function is there?
On Tue, 2 Mar 2021 at 10:27, Christophe Leroy
<[email protected]> wrote:
> Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
> >> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
> >> [ 14.998426]
> >> [ 15.007061] Invalid read at 0x(ptrval):
> >> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
> >> [ 15.015633] kunit_try_run_case+0x5c/0xd0
> >> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
> >> [ 15.025099] kthread+0x15c/0x174
> >> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
> >> [ 15.032747]
> >> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
> >> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
> >> [ 15.045811] ==================================================================
> >> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> >> [ 15.053324] Expected report_matches(&expect) to be true, but is false
> >> [ 15.068359] not ok 21 - test_invalid_access
> >
> > The test expects the function name to be test_invalid_access, i. e.
> > the first line should be "BUG: KFENCE: invalid read in
> > test_invalid_access".
> > The error reporting function unwinds the stack, skips a couple of
> > "uninteresting" frames
> > (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
> > and uses the first "interesting" one frame to print the report header
> > (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
> >
> > It's strange that test_invalid_access is missing altogether from the
> > stack trace - is that expected?
> > Can you try printing the whole stacktrace without skipping any frames
> > to see if that function is there?
> >
>
> Booting with 'no_hash_pointers" I get the following. Does it helps ?
>
> [ 16.837198] ==================================================================
> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
> [ 16.848521]
> [ 16.857158] Invalid read at 0xdf98800a:
> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
> [ 16.865731] kunit_try_run_case+0x5c/0xd0
> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
> [ 16.875199] kthread+0x15c/0x174
> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
> [ 16.882847]
> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
> [ 16.918153] DAR: df98800a DSISR: 20000000
> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
> [ 16.947292] Call Trace:
> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
The "(unreliable)" might be a clue that it's related to ppc32 stack
unwinding. Any ppc expert know what this is about?
> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
> [ 16.981896] Instruction dump:
> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
> [ 17.000711] ==================================================================
> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> [ 17.008223] Expected report_matches(&expect) to be true, but is false
> [ 17.023243] not ok 21 - test_invalid_access
On a fault in test_invalid_access, KFENCE prints the stack trace based
on the information in pt_regs. So we do not think there's anything we
can do to improve stack printing pe-se.
What's confusing is that it's only this test, and none of the others.
Given that, it might be code-gen related, which results in some subtle
issue with stack unwinding. There are a few things to try, if you feel
like it:
-- Change the unwinder, if it's possible for ppc32.
-- Add code to test_invalid_access(), to get the compiler to emit
different code. E.g. add a bunch (unnecessary) function calls, or add
barriers, etc.
-- Play with compiler options. We already pass
-fno-optimize-sibling-calls for kfence_test.o to avoid tail-call
optimizations that'd hide stack trace entries. But perhaps there's
something ppc-specific we missed?
Well, the good thing is that KFENCE detects the bad access just fine.
Since, according to the test, everything works from KFENCE's side, I'd
be happy to give my Ack:
Acked-by: Marco Elver <[email protected]>
Thanks,
-- Marco
On Tue, 2 Mar 2021 at 09:37, Christophe Leroy
<[email protected]> wrote:
> Add architecture specific implementation details for KFENCE and enable
> KFENCE for the ppc32 architecture. In particular, this implements the
> required interface in <asm/kfence.h>.
Nice!
> KFENCE requires that attributes for pages from its memory pool can
> individually be set. Therefore, force the Read/Write linear map to be
> mapped at page granularity.
>
> Unit tests succeed on all tests but one:
>
> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> [ 15.053324] Expected report_matches(&expect) to be true, but is false
> [ 15.068359] not ok 21 - test_invalid_access
This is strange, given all the other tests passed. Do you mind sharing
the full test log?
Thanks,
-- Marco
Le 02/03/2021 à 10:53, Marco Elver a écrit :
> On Tue, 2 Mar 2021 at 10:27, Christophe Leroy
> <[email protected]> wrote:
>> Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
>>>> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>> [ 14.998426]
>>>> [ 15.007061] Invalid read at 0x(ptrval):
>>>> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
>>>> [ 15.015633] kunit_try_run_case+0x5c/0xd0
>>>> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 15.025099] kthread+0x15c/0x174
>>>> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
>>>> [ 15.032747]
>>>> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>> [ 15.045811] ==================================================================
>>>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
>>>> [ 15.068359] not ok 21 - test_invalid_access
>>>
>>> The test expects the function name to be test_invalid_access, i. e.
>>> the first line should be "BUG: KFENCE: invalid read in
>>> test_invalid_access".
>>> The error reporting function unwinds the stack, skips a couple of
>>> "uninteresting" frames
>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
>>> and uses the first "interesting" one frame to print the report header
>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
>>>
>>> It's strange that test_invalid_access is missing altogether from the
>>> stack trace - is that expected?
>>> Can you try printing the whole stacktrace without skipping any frames
>>> to see if that function is there?
>>>
>>
>> Booting with 'no_hash_pointers" I get the following. Does it helps ?
>>
>> [ 16.837198] ==================================================================
>> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>> [ 16.848521]
>> [ 16.857158] Invalid read at 0xdf98800a:
>> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
>> [ 16.865731] kunit_try_run_case+0x5c/0xd0
>> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
>> [ 16.875199] kthread+0x15c/0x174
>> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
>> [ 16.882847]
>> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
>> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
>> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
>> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
>> [ 16.918153] DAR: df98800a DSISR: 20000000
>> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
>> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
>> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
>> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
>> [ 16.947292] Call Trace:
>> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
>
> The "(unreliable)" might be a clue that it's related to ppc32 stack
> unwinding. Any ppc expert know what this is about?
>
>> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
>> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
>> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
>> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
>> [ 16.981896] Instruction dump:
>> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
>> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
>> [ 17.000711] ==================================================================
>> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>> [ 17.008223] Expected report_matches(&expect) to be true, but is false
>> [ 17.023243] not ok 21 - test_invalid_access
>
> On a fault in test_invalid_access, KFENCE prints the stack trace based
> on the information in pt_regs. So we do not think there's anything we
> can do to improve stack printing pe-se.
stack printing, probably not. Would be good anyway to mark the last level [unreliable] as the ppc does.
IIUC, on ppc the address in the stack frame of the caller is written by the caller. In most tests,
there is some function call being done before the fault, for instance
test_kmalloc_aligned_oob_read() does a call to kunit_do_assertion which populates the address of the
call in the stack. However this is fragile.
This works for function calls because in order to call a subfunction, a function has to set up a
stack frame in order to same the value in the Link Register, which contains the address of the
function's parent and that will be clobbered by the sub-function call.
However, it cannot be done by exceptions, because exceptions can happen in a function that has no
stack frame (because that function has no need to call a subfunction and doesn't need to same
anything on the stack). If the exception handler was writting the caller's address in the stack
frame, it would in fact write it in the parent's frame, leading to a mess.
But in fact the information is in pt_regs, it is in regs->nip so KFENCE should be able to use that
instead of the stack.
>
> What's confusing is that it's only this test, and none of the others.
> Given that, it might be code-gen related, which results in some subtle
> issue with stack unwinding. There are a few things to try, if you feel
> like it:
>
> -- Change the unwinder, if it's possible for ppc32.
I don't think it is possible.
>
> -- Add code to test_invalid_access(), to get the compiler to emit
> different code. E.g. add a bunch (unnecessary) function calls, or add
> barriers, etc.
The following does the trick
diff --git a/mm/kfence/kfence_test.c b/mm/kfence/kfence_test.c
index 4acf4251ee04..22550676cd1f 100644
--- a/mm/kfence/kfence_test.c
+++ b/mm/kfence/kfence_test.c
@@ -631,8 +631,11 @@ static void test_invalid_access(struct kunit *test)
.addr = &__kfence_pool[10],
.is_write = false,
};
+ char *buf;
+ buf = test_alloc(test, 4, GFP_KERNEL, ALLOCATE_RIGHT);
READ_ONCE(__kfence_pool[10]);
+ test_free(buf);
KUNIT_EXPECT_TRUE(test, report_matches(&expect));
}
But as I said above, this is fragile. If for some reason one day test_alloc() gets inlined, it may
not work anymore.
>
> -- Play with compiler options. We already pass
> -fno-optimize-sibling-calls for kfence_test.o to avoid tail-call
> optimizations that'd hide stack trace entries. But perhaps there's
> something ppc-specific we missed?
>
> Well, the good thing is that KFENCE detects the bad access just fine.
> Since, according to the test, everything works from KFENCE's side, I'd
> be happy to give my Ack:
>
> Acked-by: Marco Elver <[email protected]>
>
Thanks
Christophe
On Tue, 2 Mar 2021 at 12:21, Christophe Leroy
<[email protected]> wrote:
[...]
> >> Booting with 'no_hash_pointers" I get the following. Does it helps ?
> >>
> >> [ 16.837198] ==================================================================
> >> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
> >> [ 16.848521]
> >> [ 16.857158] Invalid read at 0xdf98800a:
> >> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
> >> [ 16.865731] kunit_try_run_case+0x5c/0xd0
> >> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
> >> [ 16.875199] kthread+0x15c/0x174
> >> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
> >> [ 16.882847]
> >> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
> >> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
> >> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
> >> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
> >> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
> >> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
> >> [ 16.918153] DAR: df98800a DSISR: 20000000
> >> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
> >> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
> >> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
> >> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
> >> [ 16.947292] Call Trace:
> >> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
> >
> > The "(unreliable)" might be a clue that it's related to ppc32 stack
> > unwinding. Any ppc expert know what this is about?
> >
> >> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
> >> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
> >> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
> >> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
> >> [ 16.981896] Instruction dump:
> >> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
> >> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
> >> [ 17.000711] ==================================================================
> >> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> >> [ 17.008223] Expected report_matches(&expect) to be true, but is false
> >> [ 17.023243] not ok 21 - test_invalid_access
> >
> > On a fault in test_invalid_access, KFENCE prints the stack trace based
> > on the information in pt_regs. So we do not think there's anything we
> > can do to improve stack printing pe-se.
>
> stack printing, probably not. Would be good anyway to mark the last level [unreliable] as the ppc does.
We use stack_trace_save_regs() + stack_trace_print().
> IIUC, on ppc the address in the stack frame of the caller is written by the caller. In most tests,
> there is some function call being done before the fault, for instance
> test_kmalloc_aligned_oob_read() does a call to kunit_do_assertion which populates the address of the
> call in the stack. However this is fragile.
Interesting, this might explain it.
> This works for function calls because in order to call a subfunction, a function has to set up a
> stack frame in order to same the value in the Link Register, which contains the address of the
> function's parent and that will be clobbered by the sub-function call.
>
> However, it cannot be done by exceptions, because exceptions can happen in a function that has no
> stack frame (because that function has no need to call a subfunction and doesn't need to same
> anything on the stack). If the exception handler was writting the caller's address in the stack
> frame, it would in fact write it in the parent's frame, leading to a mess.
>
> But in fact the information is in pt_regs, it is in regs->nip so KFENCE should be able to use that
> instead of the stack.
Perhaps stack_trace_save_regs() needs fixing for ppc32? Although that
seems to use arch_stack_walk().
> > What's confusing is that it's only this test, and none of the others.
> > Given that, it might be code-gen related, which results in some subtle
> > issue with stack unwinding. There are a few things to try, if you feel
> > like it:
> >
> > -- Change the unwinder, if it's possible for ppc32.
>
> I don't think it is possible.
>
> >
> > -- Add code to test_invalid_access(), to get the compiler to emit
> > different code. E.g. add a bunch (unnecessary) function calls, or add
> > barriers, etc.
>
> The following does the trick
>
> diff --git a/mm/kfence/kfence_test.c b/mm/kfence/kfence_test.c
> index 4acf4251ee04..22550676cd1f 100644
> --- a/mm/kfence/kfence_test.c
> +++ b/mm/kfence/kfence_test.c
> @@ -631,8 +631,11 @@ static void test_invalid_access(struct kunit *test)
> .addr = &__kfence_pool[10],
> .is_write = false,
> };
> + char *buf;
>
> + buf = test_alloc(test, 4, GFP_KERNEL, ALLOCATE_RIGHT);
> READ_ONCE(__kfence_pool[10]);
> + test_free(buf);
> KUNIT_EXPECT_TRUE(test, report_matches(&expect));
> }
>
>
> But as I said above, this is fragile. If for some reason one day test_alloc() gets inlined, it may
> not work anymore.
Yeah, obviously that's hack, but interesting nevertheless.
Based on what you say above, however, it seems that
stack_trace_save_regs()/arch_stack_walk() don't exactly do what they
should? Can they be fixed for ppc32?
Thanks,
-- Marco
Christophe Leroy <[email protected]> writes:
> Le 02/03/2021 à 10:53, Marco Elver a écrit :
>> On Tue, 2 Mar 2021 at 10:27, Christophe Leroy
>> <[email protected]> wrote:
>>> Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
>>>>> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>>> [ 14.998426]
>>>>> [ 15.007061] Invalid read at 0x(ptrval):
>>>>> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
>>>>> [ 15.015633] kunit_try_run_case+0x5c/0xd0
>>>>> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>>> [ 15.025099] kthread+0x15c/0x174
>>>>> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
>>>>> [ 15.032747]
>>>>> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>>> [ 15.045811] ==================================================================
>>>>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
>>>>> [ 15.068359] not ok 21 - test_invalid_access
>>>>
>>>> The test expects the function name to be test_invalid_access, i. e.
>>>> the first line should be "BUG: KFENCE: invalid read in
>>>> test_invalid_access".
>>>> The error reporting function unwinds the stack, skips a couple of
>>>> "uninteresting" frames
>>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
>>>> and uses the first "interesting" one frame to print the report header
>>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
>>>>
>>>> It's strange that test_invalid_access is missing altogether from the
>>>> stack trace - is that expected?
>>>> Can you try printing the whole stacktrace without skipping any frames
>>>> to see if that function is there?
>>>>
>>>
>>> Booting with 'no_hash_pointers" I get the following. Does it helps ?
>>>
>>> [ 16.837198] ==================================================================
>>> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>> [ 16.848521]
>>> [ 16.857158] Invalid read at 0xdf98800a:
>>> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
>>> [ 16.865731] kunit_try_run_case+0x5c/0xd0
>>> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
>>> [ 16.875199] kthread+0x15c/0x174
>>> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
>>> [ 16.882847]
>>> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
>>> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
>>> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
>>> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
>>> [ 16.918153] DAR: df98800a DSISR: 20000000
>>> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
>>> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
>>> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
>>> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>> [ 16.947292] Call Trace:
>>> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
>>
>> The "(unreliable)" might be a clue that it's related to ppc32 stack
>> unwinding. Any ppc expert know what this is about?
>>
>>> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
>>> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
>>> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
>>> [ 16.981896] Instruction dump:
>>> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
>>> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
>>> [ 17.000711] ==================================================================
>>> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>> [ 17.008223] Expected report_matches(&expect) to be true, but is false
>>> [ 17.023243] not ok 21 - test_invalid_access
>>
>> On a fault in test_invalid_access, KFENCE prints the stack trace based
>> on the information in pt_regs. So we do not think there's anything we
>> can do to improve stack printing pe-se.
>
> stack printing, probably not. Would be good anyway to mark the last level [unreliable] as the ppc does.
>
> IIUC, on ppc the address in the stack frame of the caller is written by the caller. In most tests,
> there is some function call being done before the fault, for instance
> test_kmalloc_aligned_oob_read() does a call to kunit_do_assertion which populates the address of the
> call in the stack. However this is fragile.
>
> This works for function calls because in order to call a subfunction, a function has to set up a
> stack frame in order to same the value in the Link Register, which contains the address of the
> function's parent and that will be clobbered by the sub-function call.
>
> However, it cannot be done by exceptions, because exceptions can happen in a function that has no
> stack frame (because that function has no need to call a subfunction and doesn't need to same
> anything on the stack). If the exception handler was writting the caller's address in the stack
> frame, it would in fact write it in the parent's frame, leading to a mess.
>
> But in fact the information is in pt_regs, it is in regs->nip so KFENCE should be able to use that
> instead of the stack.
>
>>
>> What's confusing is that it's only this test, and none of the others.
>> Given that, it might be code-gen related, which results in some subtle
>> issue with stack unwinding. There are a few things to try, if you feel
>> like it:
>>
>> -- Change the unwinder, if it's possible for ppc32.
>
> I don't think it is possible.
I think this actually is the solution.
It seems the good architectures have all added support for
arch_stack_walk(), and we have not.
Looking at some of the implementations of arch_stack_walk() it seems
it's expected that the first entry emitted includes the PC (or NIP on
ppc).
For us stack_trace_save() calls save_stack_trace() which only emits
entries from the stack, which doesn't necessarily include the function
NIP is pointing to.
So I think it's probably on us to update to that new API. Or at least
update our save_stack_trace() to fabricate an entry using the NIP, as it
seems that's what callers expect.
cheers
Le 02/03/2021 à 12:40, Michael Ellerman a écrit :
> Christophe Leroy <[email protected]> writes:
>> Le 02/03/2021 à 10:53, Marco Elver a écrit :
>>> On Tue, 2 Mar 2021 at 10:27, Christophe Leroy
>>> <[email protected]> wrote:
>>>> Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
>>>>>> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>>>> [ 14.998426]
>>>>>> [ 15.007061] Invalid read at 0x(ptrval):
>>>>>> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
>>>>>> [ 15.015633] kunit_try_run_case+0x5c/0xd0
>>>>>> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>>>> [ 15.025099] kthread+0x15c/0x174
>>>>>> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
>>>>>> [ 15.032747]
>>>>>> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>>>> [ 15.045811] ==================================================================
>>>>>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>>>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
>>>>>> [ 15.068359] not ok 21 - test_invalid_access
>>>>>
>>>>> The test expects the function name to be test_invalid_access, i. e.
>>>>> the first line should be "BUG: KFENCE: invalid read in
>>>>> test_invalid_access".
>>>>> The error reporting function unwinds the stack, skips a couple of
>>>>> "uninteresting" frames
>>>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
>>>>> and uses the first "interesting" one frame to print the report header
>>>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
>>>>>
>>>>> It's strange that test_invalid_access is missing altogether from the
>>>>> stack trace - is that expected?
>>>>> Can you try printing the whole stacktrace without skipping any frames
>>>>> to see if that function is there?
>>>>>
>>>>
>>>> Booting with 'no_hash_pointers" I get the following. Does it helps ?
>>>>
>>>> [ 16.837198] ==================================================================
>>>> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>> [ 16.848521]
>>>> [ 16.857158] Invalid read at 0xdf98800a:
>>>> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
>>>> [ 16.865731] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 16.875199] kthread+0x15c/0x174
>>>> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
>>>> [ 16.882847]
>>>> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
>>>> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
>>>> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
>>>> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
>>>> [ 16.918153] DAR: df98800a DSISR: 20000000
>>>> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
>>>> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
>>>> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
>>>> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.947292] Call Trace:
>>>> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
>>>
>>> The "(unreliable)" might be a clue that it's related to ppc32 stack
>>> unwinding. Any ppc expert know what this is about?
>>>
>>>> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
>>>> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
>>>> [ 16.981896] Instruction dump:
>>>> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
>>>> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
>>>> [ 17.000711] ==================================================================
>>>> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>> [ 17.008223] Expected report_matches(&expect) to be true, but is false
>>>> [ 17.023243] not ok 21 - test_invalid_access
>>>
>>> On a fault in test_invalid_access, KFENCE prints the stack trace based
>>> on the information in pt_regs. So we do not think there's anything we
>>> can do to improve stack printing pe-se.
>>
>> stack printing, probably not. Would be good anyway to mark the last level [unreliable] as the ppc does.
>>
>> IIUC, on ppc the address in the stack frame of the caller is written by the caller. In most tests,
>> there is some function call being done before the fault, for instance
>> test_kmalloc_aligned_oob_read() does a call to kunit_do_assertion which populates the address of the
>> call in the stack. However this is fragile.
>>
>> This works for function calls because in order to call a subfunction, a function has to set up a
>> stack frame in order to same the value in the Link Register, which contains the address of the
>> function's parent and that will be clobbered by the sub-function call.
>>
>> However, it cannot be done by exceptions, because exceptions can happen in a function that has no
>> stack frame (because that function has no need to call a subfunction and doesn't need to same
>> anything on the stack). If the exception handler was writting the caller's address in the stack
>> frame, it would in fact write it in the parent's frame, leading to a mess.
>>
>> But in fact the information is in pt_regs, it is in regs->nip so KFENCE should be able to use that
>> instead of the stack.
>>
>>>
>>> What's confusing is that it's only this test, and none of the others.
>>> Given that, it might be code-gen related, which results in some subtle
>>> issue with stack unwinding. There are a few things to try, if you feel
>>> like it:
>>>
>>> -- Change the unwinder, if it's possible for ppc32.
>>
>> I don't think it is possible.
>
> I think this actually is the solution.
>
> It seems the good architectures have all added support for
> arch_stack_walk(), and we have not.
>
> Looking at some of the implementations of arch_stack_walk() it seems
> it's expected that the first entry emitted includes the PC (or NIP on
> ppc).
I don't see a direct link between arch_stack_walk() and that expectation. Looks like those
architectures where already doing this before being converted to arch_stack_walk().
>
> For us stack_trace_save() calls save_stack_trace() which only emits
> entries from the stack, which doesn't necessarily include the function
> NIP is pointing to.
Yes, as the name save_stack says, it emits the entries from the stack. I think it is correct.
>
> So I think it's probably on us to update to that new API. Or at least
> update our save_stack_trace() to fabricate an entry using the NIP, as it
> seems that's what callers expect.
As mentionned above, that doesn't seem to be directly linked to the new API. That new API only is an
intermediate step anyway, the consumers like KFENCE still use the old API which is serviced by the
generic code now.
For me it looks odd to present a stack trace where entry[0] is not from the stack and where entry[1]
is unreliable (possibly non existing) because we don't know if we are coming from a frameless
function or not and even if the function as a frame we don't know if it saved LR in the parent's
frame or not.
I would deeply prefer if KFENCE could avoid making assumptions on entry[0] of the stack trace.
What about the following change to KFENCE ?
diff --git a/mm/kfence/report.c b/mm/kfence/report.c
index ab83d5a59bb1..c2fef4eeb192 100644
--- a/mm/kfence/report.c
+++ b/mm/kfence/report.c
@@ -171,12 +171,15 @@ void kfence_report_error(unsigned long address, bool is_write, struct pt_regs *r
const ptrdiff_t object_index = meta ? meta - kfence_metadata : -1;
int num_stack_entries;
int skipnr = 0;
+ void *ip;
if (regs) {
num_stack_entries = stack_trace_save_regs(regs, stack_entries, KFENCE_STACK_DEPTH, 0);
+ ip = (void *)instruction_pointer(regs);
} else {
num_stack_entries = stack_trace_save(stack_entries, KFENCE_STACK_DEPTH, 1);
skipnr = get_stack_skipnr(stack_entries, num_stack_entries, &type);
+ ip = (void *)stack_entries[skipnr];
}
/* Require non-NULL meta, except if KFENCE_ERROR_INVALID. */
@@ -202,8 +205,7 @@ void kfence_report_error(unsigned long address, bool is_write, struct pt_regs *r
case KFENCE_ERROR_OOB: {
const bool left_of_object = address < meta->addr;
- pr_err("BUG: KFENCE: out-of-bounds %s in %pS\n\n", get_access_type(is_write),
- (void *)stack_entries[skipnr]);
+ pr_err("BUG: KFENCE: out-of-bounds %s in %pS\n\n", get_access_type(is_write), ip);
pr_err("Out-of-bounds %s at 0x%p (%luB %s of kfence-#%zd):\n",
get_access_type(is_write), (void *)address,
left_of_object ? meta->addr - address : address - meta->addr,
@@ -211,25 +213,23 @@ void kfence_report_error(unsigned long address, bool is_write, struct pt_regs *r
break;
}
case KFENCE_ERROR_UAF:
- pr_err("BUG: KFENCE: use-after-free %s in %pS\n\n", get_access_type(is_write),
- (void *)stack_entries[skipnr]);
+ pr_err("BUG: KFENCE: use-after-free %s in %pS\n\n", get_access_type(is_write), ip);
pr_err("Use-after-free %s at 0x%p (in kfence-#%zd):\n",
get_access_type(is_write), (void *)address, object_index);
break;
case KFENCE_ERROR_CORRUPTION:
- pr_err("BUG: KFENCE: memory corruption in %pS\n\n", (void *)stack_entries[skipnr]);
+ pr_err("BUG: KFENCE: memory corruption in %pS\n\n", ip);
pr_err("Corrupted memory at 0x%p ", (void *)address);
print_diff_canary(address, 16, meta);
pr_cont(" (in kfence-#%zd):\n", object_index);
break;
case KFENCE_ERROR_INVALID:
- pr_err("BUG: KFENCE: invalid %s in %pS\n\n", get_access_type(is_write),
- (void *)stack_entries[skipnr]);
+ pr_err("BUG: KFENCE: invalid %s in %pS\n\n", get_access_type(is_write), ip);
pr_err("Invalid %s at 0x%p:\n", get_access_type(is_write),
(void *)address);
break;
case KFENCE_ERROR_INVALID_FREE:
- pr_err("BUG: KFENCE: invalid free in %pS\n\n", (void *)stack_entries[skipnr]);
+ pr_err("BUG: KFENCE: invalid free in %pS\n\n", ip);
pr_err("Invalid free of 0x%p (in kfence-#%zd):\n", (void *)address,
object_index);
break;
---
Christophe
On Wed, 3 Mar 2021 at 11:32, Christophe Leroy
<[email protected]> wrote:
>
>
>
> Le 02/03/2021 à 10:53, Marco Elver a écrit :
> > On Tue, 2 Mar 2021 at 10:27, Christophe Leroy
> > <[email protected]> wrote:
> >> Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
> >>>> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
> >>>> [ 14.998426]
> >>>> [ 15.007061] Invalid read at 0x(ptrval):
> >>>> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
> >>>> [ 15.015633] kunit_try_run_case+0x5c/0xd0
> >>>> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
> >>>> [ 15.025099] kthread+0x15c/0x174
> >>>> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
> >>>> [ 15.032747]
> >>>> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
> >>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
> >>>> [ 15.045811] ==================================================================
> >>>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> >>>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
> >>>> [ 15.068359] not ok 21 - test_invalid_access
> >>>
> >>> The test expects the function name to be test_invalid_access, i. e.
> >>> the first line should be "BUG: KFENCE: invalid read in
> >>> test_invalid_access".
> >>> The error reporting function unwinds the stack, skips a couple of
> >>> "uninteresting" frames
> >>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
> >>> and uses the first "interesting" one frame to print the report header
> >>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
> >>>
> >>> It's strange that test_invalid_access is missing altogether from the
> >>> stack trace - is that expected?
> >>> Can you try printing the whole stacktrace without skipping any frames
> >>> to see if that function is there?
> >>>
> >>
> >> Booting with 'no_hash_pointers" I get the following. Does it helps ?
> >>
> >> [ 16.837198] ==================================================================
> >> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
> >> [ 16.848521]
> >> [ 16.857158] Invalid read at 0xdf98800a:
> >> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
> >> [ 16.865731] kunit_try_run_case+0x5c/0xd0
> >> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
> >> [ 16.875199] kthread+0x15c/0x174
> >> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
> >> [ 16.882847]
> >> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
> >> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
> >> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
> >> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
> >> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
> >> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
> >> [ 16.918153] DAR: df98800a DSISR: 20000000
> >> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
> >> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
> >> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
> >> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
> >> [ 16.947292] Call Trace:
> >> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
> >
> > The "(unreliable)" might be a clue that it's related to ppc32 stack
> > unwinding. Any ppc expert know what this is about?
> >
> >> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
> >> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
> >> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
> >> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
> >> [ 16.981896] Instruction dump:
> >> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
> >> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
> >> [ 17.000711] ==================================================================
> >> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> >> [ 17.008223] Expected report_matches(&expect) to be true, but is false
> >> [ 17.023243] not ok 21 - test_invalid_access
> >
> > On a fault in test_invalid_access, KFENCE prints the stack trace based
> > on the information in pt_regs. So we do not think there's anything we
> > can do to improve stack printing pe-se.
> >
> > What's confusing is that it's only this test, and none of the others.
> > Given that, it might be code-gen related, which results in some subtle
> > issue with stack unwinding. There are a few things to try, if you feel
> > like it:
> >
> > -- Change the unwinder, if it's possible for ppc32.
> >
> > -- Add code to test_invalid_access(), to get the compiler to emit
> > different code. E.g. add a bunch (unnecessary) function calls, or add
> > barriers, etc.
> >
> > -- Play with compiler options. We already pass
> > -fno-optimize-sibling-calls for kfence_test.o to avoid tail-call
> > optimizations that'd hide stack trace entries. But perhaps there's
> > something ppc-specific we missed?
> >
> > Well, the good thing is that KFENCE detects the bad access just fine.
> > Since, according to the test, everything works from KFENCE's side, I'd
> > be happy to give my Ack:
> >
> > Acked-by: Marco Elver <[email protected]>
> >
>
> Thanks.
>
> For you information, I've got a pile of warnings from mm/kfence/report.o . Is that expected ?
>
> CC mm/kfence/report.o
> In file included from ./include/linux/printk.h:7,
> from ./include/linux/kernel.h:16,
> from mm/kfence/report.c:10:
> mm/kfence/report.c: In function 'kfence_report_error':
> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
> but argument 6 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
> | ^~~~~~
> ./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
> 11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
> | ^~~~~~~~
> ./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
> 343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
> | ^~~~~~~~
> mm/kfence/report.c:207:3: note: in expansion of macro 'pr_err'
> 207 | pr_err("Out-of-bounds %s at 0x%p (%luB %s of kfence-#%zd):\n",
> | ^~~~~~
> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
> but argument 4 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
> | ^~~~~~
> ./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
> 11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
> | ^~~~~~~~
> ./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
> 343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
> | ^~~~~~~~
> mm/kfence/report.c:216:3: note: in expansion of macro 'pr_err'
> 216 | pr_err("Use-after-free %s at 0x%p (in kfence-#%zd):\n",
> | ^~~~~~
> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
> but argument 2 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
> | ^~~~~~
> ./include/linux/kern_levels.h:24:19: note: in expansion of macro 'KERN_SOH'
> 24 | #define KERN_CONT KERN_SOH "c"
> | ^~~~~~~~
> ./include/linux/printk.h:385:9: note: in expansion of macro 'KERN_CONT'
> 385 | printk(KERN_CONT fmt, ##__VA_ARGS__)
> | ^~~~~~~~~
> mm/kfence/report.c:223:3: note: in expansion of macro 'pr_cont'
> 223 | pr_cont(" (in kfence-#%zd):\n", object_index);
> | ^~~~~~~
> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
> but argument 3 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
> | ^~~~~~
> ./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
> 11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
> | ^~~~~~~~
> ./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
> 343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
> | ^~~~~~~~
> mm/kfence/report.c:233:3: note: in expansion of macro 'pr_err'
> 233 | pr_err("Invalid free of 0x%p (in kfence-#%zd):\n", (void *)address,
> | ^~~~~~
>
> Christophe
No this is not expected. Is 'signed size_t' != 'long int' on ppc32?
Le 02/03/2021 à 12:39, Marco Elver a écrit :
> On Tue, 2 Mar 2021 at 12:21, Christophe Leroy
> <[email protected]> wrote:
> [...]
>>>> Booting with 'no_hash_pointers" I get the following. Does it helps ?
>>>>
>>>> [ 16.837198] ==================================================================
>>>> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>> [ 16.848521]
>>>> [ 16.857158] Invalid read at 0xdf98800a:
>>>> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
>>>> [ 16.865731] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 16.875199] kthread+0x15c/0x174
>>>> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
>>>> [ 16.882847]
>>>> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
>>>> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
>>>> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
>>>> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
>>>> [ 16.918153] DAR: df98800a DSISR: 20000000
>>>> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
>>>> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
>>>> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
>>>> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.947292] Call Trace:
>>>> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
>>>
>>> The "(unreliable)" might be a clue that it's related to ppc32 stack
>>> unwinding. Any ppc expert know what this is about?
>>>
>>>> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
>>>> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
>>>> [ 16.981896] Instruction dump:
>>>> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
>>>> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
>>>> [ 17.000711] ==================================================================
>>>> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>> [ 17.008223] Expected report_matches(&expect) to be true, but is false
>>>> [ 17.023243] not ok 21 - test_invalid_access
>>>
>>> On a fault in test_invalid_access, KFENCE prints the stack trace based
>>> on the information in pt_regs. So we do not think there's anything we
>>> can do to improve stack printing pe-se.
>>
>> stack printing, probably not. Would be good anyway to mark the last level [unreliable] as the ppc does.
>
> We use stack_trace_save_regs() + stack_trace_print().
>
>> IIUC, on ppc the address in the stack frame of the caller is written by the caller. In most tests,
>> there is some function call being done before the fault, for instance
>> test_kmalloc_aligned_oob_read() does a call to kunit_do_assertion which populates the address of the
>> call in the stack. However this is fragile.
>
> Interesting, this might explain it.
>
>> This works for function calls because in order to call a subfunction, a function has to set up a
>> stack frame in order to same the value in the Link Register, which contains the address of the
>> function's parent and that will be clobbered by the sub-function call.
>>
>> However, it cannot be done by exceptions, because exceptions can happen in a function that has no
>> stack frame (because that function has no need to call a subfunction and doesn't need to same
>> anything on the stack). If the exception handler was writting the caller's address in the stack
>> frame, it would in fact write it in the parent's frame, leading to a mess.
>>
>> But in fact the information is in pt_regs, it is in regs->nip so KFENCE should be able to use that
>> instead of the stack.
>
> Perhaps stack_trace_save_regs() needs fixing for ppc32? Although that
> seems to use arch_stack_walk().
>
>>> What's confusing is that it's only this test, and none of the others.
>>> Given that, it might be code-gen related, which results in some subtle
>>> issue with stack unwinding. There are a few things to try, if you feel
>>> like it:
>>>
>>> -- Change the unwinder, if it's possible for ppc32.
>>
>> I don't think it is possible.
>>
>>>
>>> -- Add code to test_invalid_access(), to get the compiler to emit
>>> different code. E.g. add a bunch (unnecessary) function calls, or add
>>> barriers, etc.
>>
>> The following does the trick
>>
>> diff --git a/mm/kfence/kfence_test.c b/mm/kfence/kfence_test.c
>> index 4acf4251ee04..22550676cd1f 100644
>> --- a/mm/kfence/kfence_test.c
>> +++ b/mm/kfence/kfence_test.c
>> @@ -631,8 +631,11 @@ static void test_invalid_access(struct kunit *test)
>> .addr = &__kfence_pool[10],
>> .is_write = false,
>> };
>> + char *buf;
>>
>> + buf = test_alloc(test, 4, GFP_KERNEL, ALLOCATE_RIGHT);
>> READ_ONCE(__kfence_pool[10]);
>> + test_free(buf);
>> KUNIT_EXPECT_TRUE(test, report_matches(&expect));
>> }
>>
>>
>> But as I said above, this is fragile. If for some reason one day test_alloc() gets inlined, it may
>> not work anymore.
>
> Yeah, obviously that's hack, but interesting nevertheless.
>
> Based on what you say above, however, it seems that
> stack_trace_save_regs()/arch_stack_walk() don't exactly do what they
> should? Can they be fixed for ppc32?
Can we really consider they don't do what they should ?
I have the feeling that excepting entry[0] of the stack trace to match the instruction pointer is
not a valid expectation. That's probably correct on architectures that always have a stack frame for
any function, but for powerpc who can have frameless functions, we can't expect that I think.
I have proposed a change to KFENCE in another response to this mail thread, could it be the solution ?
Thanks
Christophe
On Wed, 3 Mar 2021 at 11:39, Christophe Leroy
<[email protected]> wrote:
>
>
>
> Le 02/03/2021 à 12:39, Marco Elver a écrit :
> > On Tue, 2 Mar 2021 at 12:21, Christophe Leroy
> > <[email protected]> wrote:
> > [...]
> >>>> Booting with 'no_hash_pointers" I get the following. Does it helps ?
> >>>>
> >>>> [ 16.837198] ==================================================================
> >>>> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
> >>>> [ 16.848521]
> >>>> [ 16.857158] Invalid read at 0xdf98800a:
> >>>> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
> >>>> [ 16.865731] kunit_try_run_case+0x5c/0xd0
> >>>> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
> >>>> [ 16.875199] kthread+0x15c/0x174
> >>>> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
> >>>> [ 16.882847]
> >>>> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
> >>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
> >>>> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
> >>>> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
> >>>> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
> >>>> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
> >>>> [ 16.918153] DAR: df98800a DSISR: 20000000
> >>>> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
> >>>> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
> >>>> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
> >>>> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
> >>>> [ 16.947292] Call Trace:
> >>>> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
> >>>
> >>> The "(unreliable)" might be a clue that it's related to ppc32 stack
> >>> unwinding. Any ppc expert know what this is about?
> >>>
> >>>> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
> >>>> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
> >>>> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
> >>>> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
> >>>> [ 16.981896] Instruction dump:
> >>>> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
> >>>> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
> >>>> [ 17.000711] ==================================================================
> >>>> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
> >>>> [ 17.008223] Expected report_matches(&expect) to be true, but is false
> >>>> [ 17.023243] not ok 21 - test_invalid_access
> >>>
> >>> On a fault in test_invalid_access, KFENCE prints the stack trace based
> >>> on the information in pt_regs. So we do not think there's anything we
> >>> can do to improve stack printing pe-se.
> >>
> >> stack printing, probably not. Would be good anyway to mark the last level [unreliable] as the ppc does.
> >
> > We use stack_trace_save_regs() + stack_trace_print().
> >
> >> IIUC, on ppc the address in the stack frame of the caller is written by the caller. In most tests,
> >> there is some function call being done before the fault, for instance
> >> test_kmalloc_aligned_oob_read() does a call to kunit_do_assertion which populates the address of the
> >> call in the stack. However this is fragile.
> >
> > Interesting, this might explain it.
> >
> >> This works for function calls because in order to call a subfunction, a function has to set up a
> >> stack frame in order to same the value in the Link Register, which contains the address of the
> >> function's parent and that will be clobbered by the sub-function call.
> >>
> >> However, it cannot be done by exceptions, because exceptions can happen in a function that has no
> >> stack frame (because that function has no need to call a subfunction and doesn't need to same
> >> anything on the stack). If the exception handler was writting the caller's address in the stack
> >> frame, it would in fact write it in the parent's frame, leading to a mess.
> >>
> >> But in fact the information is in pt_regs, it is in regs->nip so KFENCE should be able to use that
> >> instead of the stack.
> >
> > Perhaps stack_trace_save_regs() needs fixing for ppc32? Although that
> > seems to use arch_stack_walk().
> >
> >>> What's confusing is that it's only this test, and none of the others.
> >>> Given that, it might be code-gen related, which results in some subtle
> >>> issue with stack unwinding. There are a few things to try, if you feel
> >>> like it:
> >>>
> >>> -- Change the unwinder, if it's possible for ppc32.
> >>
> >> I don't think it is possible.
> >>
> >>>
> >>> -- Add code to test_invalid_access(), to get the compiler to emit
> >>> different code. E.g. add a bunch (unnecessary) function calls, or add
> >>> barriers, etc.
> >>
> >> The following does the trick
> >>
> >> diff --git a/mm/kfence/kfence_test.c b/mm/kfence/kfence_test.c
> >> index 4acf4251ee04..22550676cd1f 100644
> >> --- a/mm/kfence/kfence_test.c
> >> +++ b/mm/kfence/kfence_test.c
> >> @@ -631,8 +631,11 @@ static void test_invalid_access(struct kunit *test)
> >> .addr = &__kfence_pool[10],
> >> .is_write = false,
> >> };
> >> + char *buf;
> >>
> >> + buf = test_alloc(test, 4, GFP_KERNEL, ALLOCATE_RIGHT);
> >> READ_ONCE(__kfence_pool[10]);
> >> + test_free(buf);
> >> KUNIT_EXPECT_TRUE(test, report_matches(&expect));
> >> }
> >>
> >>
> >> But as I said above, this is fragile. If for some reason one day test_alloc() gets inlined, it may
> >> not work anymore.
> >
> > Yeah, obviously that's hack, but interesting nevertheless.
> >
> > Based on what you say above, however, it seems that
> > stack_trace_save_regs()/arch_stack_walk() don't exactly do what they
> > should? Can they be fixed for ppc32?
>
> Can we really consider they don't do what they should ?
>
> I have the feeling that excepting entry[0] of the stack trace to match the instruction pointer is
> not a valid expectation. That's probably correct on architectures that always have a stack frame for
> any function, but for powerpc who can have frameless functions, we can't expect that I think.
>
> I have proposed a change to KFENCE in another response to this mail thread, could it be the solution ?
You're going to have to change all users of stack_trace_print/save
across the kernel, because the assumption is that the current frame is
included.
It is just bad design if we add special code to all users of the
<linux/stacktrace.h> API just so we can print the current frame at the
top of the trace. Therefore, I'm afraid your proposed patch to KFENCE
is not acceptable.
Instead, we have to either extend the <linux/stacktrace.h> API, or
simply accept that all current users of the API expect the current
frame to be included. If you do not want to include the current frame,
that API even provides a way to skip it already (just pass +1 as
skipnr).
<linux/stacktrace.h> writes this about arch_stack_walk():
* task NULL Stack trace from task (can be current)
* current regs Stack trace starting on regs->stackpointer
This is a bit vague, and unfortunately seems outdated, but I'd assume
that when it says "Stack trace from task" would be the stack trace
including the current function (at IP) being executed.
Somewhat tangentially, I also note that e.g. show_regs(regs) (which
was printed along the KFENCE report above) didn't include the top
frame in the "Call Trace", so this assumption is definitely not
isolated to KFENCE.
Thanks,
-- Marco
Le 03/03/2021 à 11:39, Marco Elver a écrit :
> On Wed, 3 Mar 2021 at 11:32, Christophe Leroy
> <[email protected]> wrote:
>>
>>
>>
>> Le 02/03/2021 à 10:53, Marco Elver a écrit :
>>> On Tue, 2 Mar 2021 at 10:27, Christophe Leroy
>>> <[email protected]> wrote:
>>>> Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
>>>>>> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>>>> [ 14.998426]
>>>>>> [ 15.007061] Invalid read at 0x(ptrval):
>>>>>> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
>>>>>> [ 15.015633] kunit_try_run_case+0x5c/0xd0
>>>>>> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>>>> [ 15.025099] kthread+0x15c/0x174
>>>>>> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
>>>>>> [ 15.032747]
>>>>>> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>>>> [ 15.045811] ==================================================================
>>>>>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>>>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
>>>>>> [ 15.068359] not ok 21 - test_invalid_access
>>>>>
>>>>> The test expects the function name to be test_invalid_access, i. e.
>>>>> the first line should be "BUG: KFENCE: invalid read in
>>>>> test_invalid_access".
>>>>> The error reporting function unwinds the stack, skips a couple of
>>>>> "uninteresting" frames
>>>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
>>>>> and uses the first "interesting" one frame to print the report header
>>>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
>>>>>
>>>>> It's strange that test_invalid_access is missing altogether from the
>>>>> stack trace - is that expected?
>>>>> Can you try printing the whole stacktrace without skipping any frames
>>>>> to see if that function is there?
>>>>>
>>>>
>>>> Booting with 'no_hash_pointers" I get the following. Does it helps ?
>>>>
>>>> [ 16.837198] ==================================================================
>>>> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>> [ 16.848521]
>>>> [ 16.857158] Invalid read at 0xdf98800a:
>>>> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
>>>> [ 16.865731] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 16.875199] kthread+0x15c/0x174
>>>> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
>>>> [ 16.882847]
>>>> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
>>>> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
>>>> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
>>>> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
>>>> [ 16.918153] DAR: df98800a DSISR: 20000000
>>>> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
>>>> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
>>>> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
>>>> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.947292] Call Trace:
>>>> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
>>>
>>> The "(unreliable)" might be a clue that it's related to ppc32 stack
>>> unwinding. Any ppc expert know what this is about?
>>>
>>>> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
>>>> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
>>>> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
>>>> [ 16.981896] Instruction dump:
>>>> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
>>>> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
>>>> [ 17.000711] ==================================================================
>>>> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>> [ 17.008223] Expected report_matches(&expect) to be true, but is false
>>>> [ 17.023243] not ok 21 - test_invalid_access
>>>
>>> On a fault in test_invalid_access, KFENCE prints the stack trace based
>>> on the information in pt_regs. So we do not think there's anything we
>>> can do to improve stack printing pe-se.
>>>
>>> What's confusing is that it's only this test, and none of the others.
>>> Given that, it might be code-gen related, which results in some subtle
>>> issue with stack unwinding. There are a few things to try, if you feel
>>> like it:
>>>
>>> -- Change the unwinder, if it's possible for ppc32.
>>>
>>> -- Add code to test_invalid_access(), to get the compiler to emit
>>> different code. E.g. add a bunch (unnecessary) function calls, or add
>>> barriers, etc.
>>>
>>> -- Play with compiler options. We already pass
>>> -fno-optimize-sibling-calls for kfence_test.o to avoid tail-call
>>> optimizations that'd hide stack trace entries. But perhaps there's
>>> something ppc-specific we missed?
>>>
>>> Well, the good thing is that KFENCE detects the bad access just fine.
>>> Since, according to the test, everything works from KFENCE's side, I'd
>>> be happy to give my Ack:
>>>
>>> Acked-by: Marco Elver <[email protected]>
>>>
>>
>> Thanks.
>>
>> For you information, I've got a pile of warnings from mm/kfence/report.o . Is that expected ?
>>
>> CC mm/kfence/report.o
>> In file included from ./include/linux/printk.h:7,
>> from ./include/linux/kernel.h:16,
>> from mm/kfence/report.c:10:
>> mm/kfence/report.c: In function 'kfence_report_error':
>> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
>> but argument 6 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
>> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
>> | ^~~~~~
>> ./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
>> 11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
>> | ^~~~~~~~
>> ./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
>> 343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
>> | ^~~~~~~~
>> mm/kfence/report.c:207:3: note: in expansion of macro 'pr_err'
>> 207 | pr_err("Out-of-bounds %s at 0x%p (%luB %s of kfence-#%zd):\n",
>> | ^~~~~~
>> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
>> but argument 4 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
>> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
>> | ^~~~~~
>> ./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
>> 11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
>> | ^~~~~~~~
>> ./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
>> 343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
>> | ^~~~~~~~
>> mm/kfence/report.c:216:3: note: in expansion of macro 'pr_err'
>> 216 | pr_err("Use-after-free %s at 0x%p (in kfence-#%zd):\n",
>> | ^~~~~~
>> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
>> but argument 2 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
>> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
>> | ^~~~~~
>> ./include/linux/kern_levels.h:24:19: note: in expansion of macro 'KERN_SOH'
>> 24 | #define KERN_CONT KERN_SOH "c"
>> | ^~~~~~~~
>> ./include/linux/printk.h:385:9: note: in expansion of macro 'KERN_CONT'
>> 385 | printk(KERN_CONT fmt, ##__VA_ARGS__)
>> | ^~~~~~~~~
>> mm/kfence/report.c:223:3: note: in expansion of macro 'pr_cont'
>> 223 | pr_cont(" (in kfence-#%zd):\n", object_index);
>> | ^~~~~~~
>> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
>> but argument 3 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
>> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
>> | ^~~~~~
>> ./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
>> 11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
>> | ^~~~~~~~
>> ./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
>> 343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
>> | ^~~~~~~~
>> mm/kfence/report.c:233:3: note: in expansion of macro 'pr_err'
>> 233 | pr_err("Invalid free of 0x%p (in kfence-#%zd):\n", (void *)address,
>> | ^~~~~~
>>
>> Christophe
>
> No this is not expected. Is 'signed size_t' != 'long int' on ppc32?
>
No, it is an 'int' not a 'long int', see arch/powerpc/include/uapi/asm/posix_types.h
#ifdef __powerpc64__
typedef unsigned long __kernel_old_dev_t;
#define __kernel_old_dev_t __kernel_old_dev_t
#else
typedef unsigned int __kernel_size_t;
typedef int __kernel_ssize_t;
typedef long __kernel_ptrdiff_t;
#define __kernel_size_t __kernel_size_t
What is probably specific to powerpc is that ptrdiff_t is not same as ssize_t unlike in
include/uapi/asm-generic/posix_types.h :
/*
* Most 32 bit architectures use "unsigned int" size_t,
* and all 64 bit architectures use "unsigned long" size_t.
*/
#ifndef __kernel_size_t
#if __BITS_PER_LONG != 64
typedef unsigned int __kernel_size_t;
typedef int __kernel_ssize_t;
typedef int __kernel_ptrdiff_t;
#else
typedef __kernel_ulong_t __kernel_size_t;
typedef __kernel_long_t __kernel_ssize_t;
typedef __kernel_long_t __kernel_ptrdiff_t;
#endif
#endif
I have no warning on ppc64.
Christophe
Le 04/03/2021 à 12:31, Marco Elver a écrit :
> On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
> <[email protected]> wrote:
>> Le 03/03/2021 à 11:56, Marco Elver a écrit :
>>>
>>> Somewhat tangentially, I also note that e.g. show_regs(regs) (which
>>> was printed along the KFENCE report above) didn't include the top
>>> frame in the "Call Trace", so this assumption is definitely not
>>> isolated to KFENCE.
>>>
>>
>> Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
>> applied), and I get many failures. Any idea ?
>>
>> [ 17.653751][ T58] ==================================================================
>> [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
>> [ 17.654379][ T58]
>> [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
>> [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
>> [ 17.655775][ T58] .__slab_free+0x320/0x5a0
>> [ 17.656039][ T58] .test_double_free+0xe0/0x198
>> [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
>> [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>> [ 17.657161][ T58] .kthread+0x18c/0x1a0
>> [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
>> [ 17.659869][ T58]
>> [ 17.663954][ T58] kfence-#77 [0xc00000003c9c0000-0xc00000003c9c001f, size=32, cache=kmalloc-32]
>> allocated by task 58:
>> [ 17.666113][ T58] .__kfence_alloc+0x1bc/0x510
>> [ 17.667069][ T58] .__kmalloc+0x280/0x4f0
>> [ 17.667452][ T58] .test_alloc+0x19c/0x430
>> [ 17.667732][ T58] .test_double_free+0x88/0x198
>> [ 17.667971][ T58] .kunit_try_run_case+0x80/0x110
>> [ 17.668283][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>> [ 17.668553][ T58] .kthread+0x18c/0x1a0
>> [ 17.669315][ T58] .ret_from_kernel_thread+0x58/0x70
>> [ 17.669711][ T58]
>> [ 17.669711][ T58] freed by task 58:
>> [ 17.670116][ T58] .kfence_guarded_free+0x3d0/0x530
>> [ 17.670421][ T58] .__slab_free+0x320/0x5a0
>> [ 17.670603][ T58] .test_double_free+0xb4/0x198
>> [ 17.670827][ T58] .kunit_try_run_case+0x80/0x110
>> [ 17.671073][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>> [ 17.671410][ T58] .kthread+0x18c/0x1a0
>> [ 17.671618][ T58] .ret_from_kernel_thread+0x58/0x70
>> [ 17.671972][ T58]
>> [ 17.672638][ T58] CPU: 0 PID: 58 Comm: kunit_try_catch Tainted: G B
>> 5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
>> [ 17.673768][ T58] ==================================================================
>> [ 17.677031][ T58] # test_double_free: EXPECTATION FAILED at mm/kfence/kfence_test.c:380
>> [ 17.677031][ T58] Expected report_matches(&expect) to be true, but is false
>> [ 17.684397][ T1] not ok 7 - test_double_free
>> [ 17.686463][ T59] # test_double_free-memcache: setup_test_cache: size=32, ctor=0x0
>> [ 17.688403][ T59] # test_double_free-memcache: test_alloc: size=32, gfp=cc0, policy=any,
>> cache=1
>
> Looks like something is prepending '.' to function names. We expect
> the function name to appear as-is, e.g. "kfence_guarded_free",
> "test_double_free", etc.
>
> Is there something special on ppc64, where the '.' is some convention?
>
I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
Also see commit https://github.com/linuxppc/linux/commit/02424d896
Christophe
On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
<[email protected]> wrote:
> Le 03/03/2021 à 11:56, Marco Elver a écrit :
> >
> > Somewhat tangentially, I also note that e.g. show_regs(regs) (which
> > was printed along the KFENCE report above) didn't include the top
> > frame in the "Call Trace", so this assumption is definitely not
> > isolated to KFENCE.
> >
>
> Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
> applied), and I get many failures. Any idea ?
>
> [ 17.653751][ T58] ==================================================================
> [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
> [ 17.654379][ T58]
> [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
> [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
> [ 17.655775][ T58] .__slab_free+0x320/0x5a0
> [ 17.656039][ T58] .test_double_free+0xe0/0x198
> [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
> [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> [ 17.657161][ T58] .kthread+0x18c/0x1a0
> [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
> [ 17.659869][ T58]
> [ 17.663954][ T58] kfence-#77 [0xc00000003c9c0000-0xc00000003c9c001f, size=32, cache=kmalloc-32]
> allocated by task 58:
> [ 17.666113][ T58] .__kfence_alloc+0x1bc/0x510
> [ 17.667069][ T58] .__kmalloc+0x280/0x4f0
> [ 17.667452][ T58] .test_alloc+0x19c/0x430
> [ 17.667732][ T58] .test_double_free+0x88/0x198
> [ 17.667971][ T58] .kunit_try_run_case+0x80/0x110
> [ 17.668283][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> [ 17.668553][ T58] .kthread+0x18c/0x1a0
> [ 17.669315][ T58] .ret_from_kernel_thread+0x58/0x70
> [ 17.669711][ T58]
> [ 17.669711][ T58] freed by task 58:
> [ 17.670116][ T58] .kfence_guarded_free+0x3d0/0x530
> [ 17.670421][ T58] .__slab_free+0x320/0x5a0
> [ 17.670603][ T58] .test_double_free+0xb4/0x198
> [ 17.670827][ T58] .kunit_try_run_case+0x80/0x110
> [ 17.671073][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> [ 17.671410][ T58] .kthread+0x18c/0x1a0
> [ 17.671618][ T58] .ret_from_kernel_thread+0x58/0x70
> [ 17.671972][ T58]
> [ 17.672638][ T58] CPU: 0 PID: 58 Comm: kunit_try_catch Tainted: G B
> 5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
> [ 17.673768][ T58] ==================================================================
> [ 17.677031][ T58] # test_double_free: EXPECTATION FAILED at mm/kfence/kfence_test.c:380
> [ 17.677031][ T58] Expected report_matches(&expect) to be true, but is false
> [ 17.684397][ T1] not ok 7 - test_double_free
> [ 17.686463][ T59] # test_double_free-memcache: setup_test_cache: size=32, ctor=0x0
> [ 17.688403][ T59] # test_double_free-memcache: test_alloc: size=32, gfp=cc0, policy=any,
> cache=1
Looks like something is prepending '.' to function names. We expect
the function name to appear as-is, e.g. "kfence_guarded_free",
"test_double_free", etc.
Is there something special on ppc64, where the '.' is some convention?
Thanks,
-- Marco
On Thu, 4 Mar 2021 at 13:00, Christophe Leroy
<[email protected]> wrote:
>
>
>
> Le 04/03/2021 à 12:48, Christophe Leroy a écrit :
> >
> >
> > Le 04/03/2021 à 12:31, Marco Elver a écrit :
> >> On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
> >> <[email protected]> wrote:
> >>> Le 03/03/2021 à 11:56, Marco Elver a écrit :
> >>>>
> >>>> Somewhat tangentially, I also note that e.g. show_regs(regs) (which
> >>>> was printed along the KFENCE report above) didn't include the top
> >>>> frame in the "Call Trace", so this assumption is definitely not
> >>>> isolated to KFENCE.
> >>>>
> >>>
> >>> Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
> >>> applied), and I get many failures. Any idea ?
> >>>
> >>> [ 17.653751][ T58] ==================================================================
> >>> [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
> >>> [ 17.654379][ T58]
> >>> [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
> >>> [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
> >>> [ 17.655775][ T58] .__slab_free+0x320/0x5a0
> >>> [ 17.656039][ T58] .test_double_free+0xe0/0x198
> >>> [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
> >>> [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> >>> [ 17.657161][ T58] .kthread+0x18c/0x1a0
> >>> [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
> >>> [ 17.659869][ T58]
> >>> [ 17.663954][ T58] kfence-#77 [0xc00000003c9c0000-0xc00000003c9c001f, size=32, cache=kmalloc-32]
> >>> allocated by task 58:
> >>> [ 17.666113][ T58] .__kfence_alloc+0x1bc/0x510
> >>> [ 17.667069][ T58] .__kmalloc+0x280/0x4f0
> >>> [ 17.667452][ T58] .test_alloc+0x19c/0x430
> >>> [ 17.667732][ T58] .test_double_free+0x88/0x198
> >>> [ 17.667971][ T58] .kunit_try_run_case+0x80/0x110
> >>> [ 17.668283][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> >>> [ 17.668553][ T58] .kthread+0x18c/0x1a0
> >>> [ 17.669315][ T58] .ret_from_kernel_thread+0x58/0x70
> >>> [ 17.669711][ T58]
> >>> [ 17.669711][ T58] freed by task 58:
> >>> [ 17.670116][ T58] .kfence_guarded_free+0x3d0/0x530
> >>> [ 17.670421][ T58] .__slab_free+0x320/0x5a0
> >>> [ 17.670603][ T58] .test_double_free+0xb4/0x198
> >>> [ 17.670827][ T58] .kunit_try_run_case+0x80/0x110
> >>> [ 17.671073][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> >>> [ 17.671410][ T58] .kthread+0x18c/0x1a0
> >>> [ 17.671618][ T58] .ret_from_kernel_thread+0x58/0x70
> >>> [ 17.671972][ T58]
> >>> [ 17.672638][ T58] CPU: 0 PID: 58 Comm: kunit_try_catch Tainted: G B
> >>> 5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
> >>> [ 17.673768][ T58] ==================================================================
> >>> [ 17.677031][ T58] # test_double_free: EXPECTATION FAILED at mm/kfence/kfence_test.c:380
> >>> [ 17.677031][ T58] Expected report_matches(&expect) to be true, but is false
> >>> [ 17.684397][ T1] not ok 7 - test_double_free
> >>> [ 17.686463][ T59] # test_double_free-memcache: setup_test_cache: size=32, ctor=0x0
> >>> [ 17.688403][ T59] # test_double_free-memcache: test_alloc: size=32, gfp=cc0, policy=any,
> >>> cache=1
> >>
> >> Looks like something is prepending '.' to function names. We expect
> >> the function name to appear as-is, e.g. "kfence_guarded_free",
> >> "test_double_free", etc.
> >>
> >> Is there something special on ppc64, where the '.' is some convention?
> >>
> >
> > I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
> >
> > Also see commit https://github.com/linuxppc/linux/commit/02424d896
> >
>
> But I'm wondering, if the dot is the problem, how so is the following one ok ?
>
> [ 79.574457][ T75] # test_krealloc: test_alloc: size=32, gfp=cc0, policy=any, cache=0
> [ 79.682728][ T75] ==================================================================
> [ 79.684017][ T75] BUG: KFENCE: use-after-free read in .test_krealloc+0x4fc/0x5b8
> [ 79.684017][ T75]
> [ 79.684955][ T75] Use-after-free read at 0xc00000003d060000 (in kfence-#130):
> [ 79.687581][ T75] .test_krealloc+0x4fc/0x5b8
> [ 79.688216][ T75] .test_krealloc+0x4e4/0x5b8
> [ 79.688824][ T75] .kunit_try_run_case+0x80/0x110
> [ 79.689737][ T75] .kunit_generic_run_threadfn_adapter+0x38/0x50
> [ 79.690335][ T75] .kthread+0x18c/0x1a0
> [ 79.691092][ T75] .ret_from_kernel_thread+0x58/0x70
> [ 79.692081][ T75]
> [ 79.692671][ T75] kfence-#130 [0xc00000003d060000-0xc00000003d06001f, size=32,
> cache=kmalloc-32] allocated by task 75:
> [ 79.700977][ T75] .__kfence_alloc+0x1bc/0x510
> [ 79.701812][ T75] .__kmalloc+0x280/0x4f0
> [ 79.702695][ T75] .test_alloc+0x19c/0x430
> [ 79.703051][ T75] .test_krealloc+0xa8/0x5b8
> [ 79.703276][ T75] .kunit_try_run_case+0x80/0x110
> [ 79.703693][ T75] .kunit_generic_run_threadfn_adapter+0x38/0x50
> [ 79.704223][ T75] .kthread+0x18c/0x1a0
> [ 79.704586][ T75] .ret_from_kernel_thread+0x58/0x70
> [ 79.704968][ T75]
> [ 79.704968][ T75] freed by task 75:
> [ 79.705756][ T75] .kfence_guarded_free+0x3d0/0x530
> [ 79.706754][ T75] .__slab_free+0x320/0x5a0
> [ 79.708575][ T75] .krealloc+0xe8/0x180
> [ 79.708970][ T75] .test_krealloc+0x1c8/0x5b8
> [ 79.709606][ T75] .kunit_try_run_case+0x80/0x110
> [ 79.710204][ T75] .kunit_generic_run_threadfn_adapter+0x38/0x50
> [ 79.710639][ T75] .kthread+0x18c/0x1a0
> [ 79.710996][ T75] .ret_from_kernel_thread+0x58/0x70
> [ 79.711349][ T75]
> [ 79.717435][ T75] CPU: 0 PID: 75 Comm: kunit_try_catch Tainted: G B
> 5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
> [ 79.718124][ T75] NIP: c000000000468a40 LR: c000000000468a28 CTR: 0000000000000000
> [ 79.727741][ T75] REGS: c000000007dd3830 TRAP: 0300 Tainted: G B
> (5.12.0-rc1-01540-g0783285cc1b8-dirty)
> [ 79.733377][ T75] MSR: 8000000002009032 <SF,VEC,EE,ME,IR,DR,RI> CR: 28000440 XER: 00000000
> [ 79.738770][ T75] CFAR: c000000000888c7c DAR: c00000003d060000 DSISR: 40000000 IRQMASK: 0
> [ 79.738770][ T75] GPR00: c000000000468a28 c000000007dd3ad0 c000000001eaad00 c0000000073c3988
> [ 79.738770][ T75] GPR04: c000000007dd3b60 0000000000000001 0000000000000000 c00000003d060000
> [ 79.738770][ T75] GPR08: 00000000000002c8 0000000000000001 c0000000011bb410 c00000003fe903d8
> [ 79.738770][ T75] GPR12: 0000000028000440 c0000000020f0000 c0000000001a6460 c00000000724bb80
> [ 79.738770][ T75] GPR16: 0000000000000000 c00000000731749f c0000000011bb278 c00000000731749f
> [ 79.738770][ T75] GPR20: 00000001000002c1 0000000000000000 c0000000011bb278 c0000000011bb3b8
> [ 79.738770][ T75] GPR24: c0000000073174a0 c0000000011aa7b8 c000000001e35328 c00000000208ad00
> [ 79.738770][ T75] GPR28: 0000000000000000 c0000000011bb0b8 c0000000073c3988 c000000007dd3ad0
> [ 79.751744][ T75] NIP [c000000000468a40] .test_krealloc+0x4fc/0x5b8
> [ 79.752243][ T75] LR [c000000000468a28] .test_krealloc+0x4e4/0x5b8
> [ 79.752699][ T75] Call Trace:
> [ 79.753027][ T75] [c000000007dd3ad0] [c000000000468a28] .test_krealloc+0x4e4/0x5b8 (unreliable)
> [ 79.753878][ T75] [c000000007dd3c40] [c0000000008886d0] .kunit_try_run_case+0x80/0x110
> [ 79.754641][ T75] [c000000007dd3cd0] [c00000000088a808]
> .kunit_generic_run_threadfn_adapter+0x38/0x50
> [ 79.755494][ T75] [c000000007dd3d50] [c0000000001a65ec] .kthread+0x18c/0x1a0
> [ 79.757254][ T75] [c000000007dd3e10] [c00000000000dd68] .ret_from_kernel_thread+0x58/0x70
> [ 79.775521][ T75] Instruction dump:
> [ 79.776890][ T75] 68a50001 9b9f00c8 fbdf0090 fbbf00a0 fb5f00b8 484201cd 60000000 e8ff0080
> [ 79.783146][ T75] 3d42ff31 390002c8 394a0710 39200001 <88e70000> 38a00000 fb9f00a8 e8fbe80e
> [ 79.787563][ T75] ==================================================================
> [ 79.804667][ T1] ok 24 - test_krealloc
This one is using pt_regs, and therefore isn't trying to determine how
many entries we can skip in the stack trace to avoid showing
internals. I'll reply with a potential solution you can test shortly.
Thanks,
-- Marco
Le 04/03/2021 à 13:48, Marco Elver a écrit :
> From d118080eb9552073f5dcf1f86198f3d86d5ea850 Mon Sep 17 00:00:00 2001
> From: Marco Elver <[email protected]>
> Date: Thu, 4 Mar 2021 13:15:51 +0100
> Subject: [PATCH] kfence: fix reports if constant function prefixes exist
>
> Some architectures prefix all functions with a constant string ('.' on
> ppc64). Add ARCH_FUNC_PREFIX, which may optionally be defined in
> <asm/kfence.h>, so that get_stack_skipnr() can work properly.
It works, thanks.
>
> Link: https://lkml.kernel.org/r/[email protected]
> Reported-by: Christophe Leroy <[email protected]>
> Signed-off-by: Marco Elver <[email protected]>
Tested-by: Christophe Leroy <[email protected]>
> ---
> mm/kfence/report.c | 18 ++++++++++++------
> 1 file changed, 12 insertions(+), 6 deletions(-)
>
> diff --git a/mm/kfence/report.c b/mm/kfence/report.c
> index 519f037720f5..e3f71451ad9e 100644
> --- a/mm/kfence/report.c
> +++ b/mm/kfence/report.c
> @@ -20,6 +20,11 @@
>
> #include "kfence.h"
>
> +/* May be overridden by <asm/kfence.h>. */
> +#ifndef ARCH_FUNC_PREFIX
> +#define ARCH_FUNC_PREFIX ""
> +#endif
> +
> extern bool no_hash_pointers;
>
> /* Helper function to either print to a seq_file or to console. */
> @@ -67,8 +72,9 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
> for (skipnr = 0; skipnr < num_entries; skipnr++) {
> int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
>
> - if (str_has_prefix(buf, "kfence_") || str_has_prefix(buf, "__kfence_") ||
> - !strncmp(buf, "__slab_free", len)) {
> + if (str_has_prefix(buf, ARCH_FUNC_PREFIX "kfence_") ||
> + str_has_prefix(buf, ARCH_FUNC_PREFIX "__kfence_") ||
> + !strncmp(buf, ARCH_FUNC_PREFIX "__slab_free", len)) {
> /*
> * In case of tail calls from any of the below
> * to any of the above.
> @@ -77,10 +83,10 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
> }
>
> /* Also the *_bulk() variants by only checking prefixes. */
> - if (str_has_prefix(buf, "kfree") ||
> - str_has_prefix(buf, "kmem_cache_free") ||
> - str_has_prefix(buf, "__kmalloc") ||
> - str_has_prefix(buf, "kmem_cache_alloc"))
> + if (str_has_prefix(buf, ARCH_FUNC_PREFIX "kfree") ||
> + str_has_prefix(buf, ARCH_FUNC_PREFIX "kmem_cache_free") ||
> + str_has_prefix(buf, ARCH_FUNC_PREFIX "__kmalloc") ||
> + str_has_prefix(buf, ARCH_FUNC_PREFIX "kmem_cache_alloc"))
> goto found;
> }
> if (fallback < num_entries)
>
On Thu, 4 Mar 2021 at 15:08, Christophe Leroy
<[email protected]> wrote:
>
>
>
> Le 04/03/2021 à 13:48, Marco Elver a écrit :
> > From d118080eb9552073f5dcf1f86198f3d86d5ea850 Mon Sep 17 00:00:00 2001
> > From: Marco Elver <[email protected]>
> > Date: Thu, 4 Mar 2021 13:15:51 +0100
> > Subject: [PATCH] kfence: fix reports if constant function prefixes exist
> >
> > Some architectures prefix all functions with a constant string ('.' on
> > ppc64). Add ARCH_FUNC_PREFIX, which may optionally be defined in
> > <asm/kfence.h>, so that get_stack_skipnr() can work properly.
>
>
> It works, thanks.
>
> >
> > Link: https://lkml.kernel.org/r/[email protected]
> > Reported-by: Christophe Leroy <[email protected]>
> > Signed-off-by: Marco Elver <[email protected]>
>
> Tested-by: Christophe Leroy <[email protected]>
Thanks, I'll send this to Andrew for inclusion in -mm, since this is
not a strict dependency (it'll work without the patch, just the stack
traces aren't that pretty but still useful). If the ppc patches and
this make it into the next merge window, everything should be good for
5.13.
> > ---
> > mm/kfence/report.c | 18 ++++++++++++------
> > 1 file changed, 12 insertions(+), 6 deletions(-)
> >
> > diff --git a/mm/kfence/report.c b/mm/kfence/report.c
> > index 519f037720f5..e3f71451ad9e 100644
> > --- a/mm/kfence/report.c
> > +++ b/mm/kfence/report.c
> > @@ -20,6 +20,11 @@
> >
> > #include "kfence.h"
> >
> > +/* May be overridden by <asm/kfence.h>. */
> > +#ifndef ARCH_FUNC_PREFIX
> > +#define ARCH_FUNC_PREFIX ""
> > +#endif
> > +
> > extern bool no_hash_pointers;
> >
> > /* Helper function to either print to a seq_file or to console. */
> > @@ -67,8 +72,9 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
> > for (skipnr = 0; skipnr < num_entries; skipnr++) {
> > int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
> >
> > - if (str_has_prefix(buf, "kfence_") || str_has_prefix(buf, "__kfence_") ||
> > - !strncmp(buf, "__slab_free", len)) {
> > + if (str_has_prefix(buf, ARCH_FUNC_PREFIX "kfence_") ||
> > + str_has_prefix(buf, ARCH_FUNC_PREFIX "__kfence_") ||
> > + !strncmp(buf, ARCH_FUNC_PREFIX "__slab_free", len)) {
> > /*
> > * In case of tail calls from any of the below
> > * to any of the above.
> > @@ -77,10 +83,10 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
> > }
> >
> > /* Also the *_bulk() variants by only checking prefixes. */
> > - if (str_has_prefix(buf, "kfree") ||
> > - str_has_prefix(buf, "kmem_cache_free") ||
> > - str_has_prefix(buf, "__kmalloc") ||
> > - str_has_prefix(buf, "kmem_cache_alloc"))
> > + if (str_has_prefix(buf, ARCH_FUNC_PREFIX "kfree") ||
> > + str_has_prefix(buf, ARCH_FUNC_PREFIX "kmem_cache_free") ||
> > + str_has_prefix(buf, ARCH_FUNC_PREFIX "__kmalloc") ||
> > + str_has_prefix(buf, ARCH_FUNC_PREFIX "kmem_cache_alloc"))
> > goto found;
> > }
> > if (fallback < num_entries)
> >
On Tue, Mar 02, 2021 at 10:40:03PM +1100, Michael Ellerman wrote:
> >> -- Change the unwinder, if it's possible for ppc32.
> >
> > I don't think it is possible.
>
> I think this actually is the solution.
>
> It seems the good architectures have all added support for
> arch_stack_walk(), and we have not.
I have no idea what arch_stack_walk does, but some background info:
PowerPC functions that do save the LR (== the return address), and/or
that set up a new stack frame, do not do this at the start of the
function necessarily (it is a lot faster to postpone this, even if you
always have to do it). So, in a leaf function it isn't always known if
this has been done (in all callers further up it is always done, of
course). If you have DWARF unwind info all is fine of course, but you
do not have that in the kernel.
> So I think it's probably on us to update to that new API. Or at least
> update our save_stack_trace() to fabricate an entry using the NIP, as it
> seems that's what callers expect.
This sounds very expensive? If it is only a debug feature that won't
be used in production that does not matter, but it worries me.
Segher
On Mär 03 2021, Marco Elver wrote:
> On Wed, 3 Mar 2021 at 11:32, Christophe Leroy
> <[email protected]> wrote:
>> ./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
>> but argument 3 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
>> 5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
>> | ^~~~~~
>> ./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
>> 11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
>> | ^~~~~~~~
>> ./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
>> 343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
>> | ^~~~~~~~
>> mm/kfence/report.c:233:3: note: in expansion of macro 'pr_err'
>> 233 | pr_err("Invalid free of 0x%p (in kfence-#%zd):\n", (void *)address,
>> | ^~~~~~
>>
>> Christophe
>
> No this is not expected. Is 'signed size_t' != 'long int' on ppc32?
If you want to format a ptrdiff_t you should use %td.
Andreas.
--
Andreas Schwab, [email protected]
GPG Key fingerprint = 7578 EB47 D4E5 4D69 2510 2552 DF73 E780 A9DA AEC1
"And now for something completely different."
Le 02/03/2021 à 10:53, Marco Elver a écrit :
> On Tue, 2 Mar 2021 at 10:27, Christophe Leroy
> <[email protected]> wrote:
>> Le 02/03/2021 à 10:21, Alexander Potapenko a écrit :
>>>> [ 14.998426] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>>>> [ 14.998426]
>>>> [ 15.007061] Invalid read at 0x(ptrval):
>>>> [ 15.010906] finish_task_switch.isra.0+0x54/0x23c
>>>> [ 15.015633] kunit_try_run_case+0x5c/0xd0
>>>> [ 15.019682] kunit_generic_run_threadfn_adapter+0x24/0x30
>>>> [ 15.025099] kthread+0x15c/0x174
>>>> [ 15.028359] ret_from_kernel_thread+0x14/0x1c
>>>> [ 15.032747]
>>>> [ 15.034251] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>>>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>>>> [ 15.045811] ==================================================================
>>>> [ 15.053324] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>>>> [ 15.053324] Expected report_matches(&expect) to be true, but is false
>>>> [ 15.068359] not ok 21 - test_invalid_access
>>>
>>> The test expects the function name to be test_invalid_access, i. e.
>>> the first line should be "BUG: KFENCE: invalid read in
>>> test_invalid_access".
>>> The error reporting function unwinds the stack, skips a couple of
>>> "uninteresting" frames
>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L43)
>>> and uses the first "interesting" one frame to print the report header
>>> (https://elixir.bootlin.com/linux/v5.12-rc1/source/mm/kfence/report.c#L226).
>>>
>>> It's strange that test_invalid_access is missing altogether from the
>>> stack trace - is that expected?
>>> Can you try printing the whole stacktrace without skipping any frames
>>> to see if that function is there?
>>>
>>
>> Booting with 'no_hash_pointers" I get the following. Does it helps ?
>>
>> [ 16.837198] ==================================================================
>> [ 16.848521] BUG: KFENCE: invalid read in finish_task_switch.isra.0+0x54/0x23c
>> [ 16.848521]
>> [ 16.857158] Invalid read at 0xdf98800a:
>> [ 16.861004] finish_task_switch.isra.0+0x54/0x23c
>> [ 16.865731] kunit_try_run_case+0x5c/0xd0
>> [ 16.869780] kunit_generic_run_threadfn_adapter+0x24/0x30
>> [ 16.875199] kthread+0x15c/0x174
>> [ 16.878460] ret_from_kernel_thread+0x14/0x1c
>> [ 16.882847]
>> [ 16.884351] CPU: 0 PID: 111 Comm: kunit_try_catch Tainted: G B
>> 5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty #4674
>> [ 16.895908] NIP: c016eb8c LR: c02f50dc CTR: c016eb38
>> [ 16.900963] REGS: e2449d90 TRAP: 0301 Tainted: G B
>> (5.12.0-rc1-s3k-dev-01534-g4f14ae75edf0-dirty)
>> [ 16.911386] MSR: 00009032 <EE,ME,IR,DR,RI> CR: 22000004 XER: 00000000
>> [ 16.918153] DAR: df98800a DSISR: 20000000
>> [ 16.918153] GPR00: c02f50dc e2449e50 c1140d00 e100dd24 c084b13c 00000008 c084b32b c016eb38
>> [ 16.918153] GPR08: c0850000 df988000 c0d10000 e2449eb0 22000288
>> [ 16.936695] NIP [c016eb8c] test_invalid_access+0x54/0x108
>> [ 16.942125] LR [c02f50dc] kunit_try_run_case+0x5c/0xd0
>> [ 16.947292] Call Trace:
>> [ 16.949746] [e2449e50] [c005a5ec] finish_task_switch.isra.0+0x54/0x23c (unreliable)
>
> The "(unreliable)" might be a clue that it's related to ppc32 stack
> unwinding. Any ppc expert know what this is about?
>
>> [ 16.957443] [e2449eb0] [c02f50dc] kunit_try_run_case+0x5c/0xd0
>> [ 16.963319] [e2449ed0] [c02f63ec] kunit_generic_run_threadfn_adapter+0x24/0x30
>> [ 16.970574] [e2449ef0] [c004e710] kthread+0x15c/0x174
>> [ 16.975670] [e2449f30] [c001317c] ret_from_kernel_thread+0x14/0x1c
>> [ 16.981896] Instruction dump:
>> [ 16.984879] 8129d608 38e7eb38 81020280 911f004c 39000000 995f0024 907f0028 90ff001c
>> [ 16.992710] 3949000a 915f0020 3d40c0d1 3d00c085 <8929000a> 3908adb0 812a4b98 3d40c02f
>> [ 17.000711] ==================================================================
>> [ 17.008223] # test_invalid_access: EXPECTATION FAILED at mm/kfence/kfence_test.c:636
>> [ 17.008223] Expected report_matches(&expect) to be true, but is false
>> [ 17.023243] not ok 21 - test_invalid_access
>
> On a fault in test_invalid_access, KFENCE prints the stack trace based
> on the information in pt_regs. So we do not think there's anything we
> can do to improve stack printing pe-se.
>
> What's confusing is that it's only this test, and none of the others.
> Given that, it might be code-gen related, which results in some subtle
> issue with stack unwinding. There are a few things to try, if you feel
> like it:
>
> -- Change the unwinder, if it's possible for ppc32.
>
> -- Add code to test_invalid_access(), to get the compiler to emit
> different code. E.g. add a bunch (unnecessary) function calls, or add
> barriers, etc.
>
> -- Play with compiler options. We already pass
> -fno-optimize-sibling-calls for kfence_test.o to avoid tail-call
> optimizations that'd hide stack trace entries. But perhaps there's
> something ppc-specific we missed?
>
> Well, the good thing is that KFENCE detects the bad access just fine.
> Since, according to the test, everything works from KFENCE's side, I'd
> be happy to give my Ack:
>
> Acked-by: Marco Elver <[email protected]>
>
Thanks.
For you information, I've got a pile of warnings from mm/kfence/report.o . Is that expected ?
CC mm/kfence/report.o
In file included from ./include/linux/printk.h:7,
from ./include/linux/kernel.h:16,
from mm/kfence/report.c:10:
mm/kfence/report.c: In function 'kfence_report_error':
./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
but argument 6 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
| ^~~~~~~~
./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
| ^~~~~~~~
mm/kfence/report.c:207:3: note: in expansion of macro 'pr_err'
207 | pr_err("Out-of-bounds %s at 0x%p (%luB %s of kfence-#%zd):\n",
| ^~~~~~
./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
but argument 4 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
| ^~~~~~~~
./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
| ^~~~~~~~
mm/kfence/report.c:216:3: note: in expansion of macro 'pr_err'
216 | pr_err("Use-after-free %s at 0x%p (in kfence-#%zd):\n",
| ^~~~~~
./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
but argument 2 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
./include/linux/kern_levels.h:24:19: note: in expansion of macro 'KERN_SOH'
24 | #define KERN_CONT KERN_SOH "c"
| ^~~~~~~~
./include/linux/printk.h:385:9: note: in expansion of macro 'KERN_CONT'
385 | printk(KERN_CONT fmt, ##__VA_ARGS__)
| ^~~~~~~~~
mm/kfence/report.c:223:3: note: in expansion of macro 'pr_cont'
223 | pr_cont(" (in kfence-#%zd):\n", object_index);
| ^~~~~~~
./include/linux/kern_levels.h:5:18: warning: format '%zd' expects argument of type 'signed size_t',
but argument 3 has type 'ptrdiff_t' {aka 'const long int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
./include/linux/kern_levels.h:11:18: note: in expansion of macro 'KERN_SOH'
11 | #define KERN_ERR KERN_SOH "3" /* error conditions */
| ^~~~~~~~
./include/linux/printk.h:343:9: note: in expansion of macro 'KERN_ERR'
343 | printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
| ^~~~~~~~
mm/kfence/report.c:233:3: note: in expansion of macro 'pr_err'
233 | pr_err("Invalid free of 0x%p (in kfence-#%zd):\n", (void *)address,
| ^~~~~~
Christophe
Le 03/03/2021 à 11:56, Marco Elver a écrit :
>
> Somewhat tangentially, I also note that e.g. show_regs(regs) (which
> was printed along the KFENCE report above) didn't include the top
> frame in the "Call Trace", so this assumption is definitely not
> isolated to KFENCE.
>
Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
applied), and I get many failures. Any idea ?
[ 17.653751][ T58] ==================================================================
[ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
[ 17.654379][ T58]
[ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
[ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
[ 17.655775][ T58] .__slab_free+0x320/0x5a0
[ 17.656039][ T58] .test_double_free+0xe0/0x198
[ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
[ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.657161][ T58] .kthread+0x18c/0x1a0
[ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
[ 17.659869][ T58]
[ 17.663954][ T58] kfence-#77 [0xc00000003c9c0000-0xc00000003c9c001f, size=32, cache=kmalloc-32]
allocated by task 58:
[ 17.666113][ T58] .__kfence_alloc+0x1bc/0x510
[ 17.667069][ T58] .__kmalloc+0x280/0x4f0
[ 17.667452][ T58] .test_alloc+0x19c/0x430
[ 17.667732][ T58] .test_double_free+0x88/0x198
[ 17.667971][ T58] .kunit_try_run_case+0x80/0x110
[ 17.668283][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.668553][ T58] .kthread+0x18c/0x1a0
[ 17.669315][ T58] .ret_from_kernel_thread+0x58/0x70
[ 17.669711][ T58]
[ 17.669711][ T58] freed by task 58:
[ 17.670116][ T58] .kfence_guarded_free+0x3d0/0x530
[ 17.670421][ T58] .__slab_free+0x320/0x5a0
[ 17.670603][ T58] .test_double_free+0xb4/0x198
[ 17.670827][ T58] .kunit_try_run_case+0x80/0x110
[ 17.671073][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.671410][ T58] .kthread+0x18c/0x1a0
[ 17.671618][ T58] .ret_from_kernel_thread+0x58/0x70
[ 17.671972][ T58]
[ 17.672638][ T58] CPU: 0 PID: 58 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 17.673768][ T58] ==================================================================
[ 17.677031][ T58] # test_double_free: EXPECTATION FAILED at mm/kfence/kfence_test.c:380
[ 17.677031][ T58] Expected report_matches(&expect) to be true, but is false
[ 17.684397][ T1] not ok 7 - test_double_free
[ 17.686463][ T59] # test_double_free-memcache: setup_test_cache: size=32, ctor=0x0
[ 17.688403][ T59] # test_double_free-memcache: test_alloc: size=32, gfp=cc0, policy=any,
cache=1
[ 17.797584][ T59] ==================================================================
[ 17.801260][ T59] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
[ 17.801260][ T59]
[ 17.801512][ T59] Invalid free of 0xc00000003c9effe0 (in kfence-#78):
[ 17.801668][ T59] .kfence_guarded_free+0x2e4/0x530
[ 17.801849][ T59] .__slab_free+0x320/0x5a0
[ 17.801983][ T59] .kmem_cache_free+0x31c/0x5c0
[ 17.802109][ T59] .test_double_free+0xd0/0x198
[ 17.802227][ T59] .kunit_try_run_case+0x80/0x110
[ 17.802494][ T59] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.802641][ T59] .kthread+0x18c/0x1a0
[ 17.802821][ T59] .ret_from_kernel_thread+0x58/0x70
[ 17.802989][ T59]
[ 17.803303][ T59] kfence-#78 [0xc00000003c9effe0-0xc00000003c9effff, size=32, cache=test]
allocated by task 59:
[ 17.803666][ T59] .__kfence_alloc+0x1bc/0x510
[ 17.803898][ T59] .kmem_cache_alloc+0x290/0x440
[ 17.804036][ T59] .test_alloc+0x188/0x430
[ 17.804151][ T59] .test_double_free+0x88/0x198
[ 17.804363][ T59] .kunit_try_run_case+0x80/0x110
[ 17.804637][ T59] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.805099][ T59] .kthread+0x18c/0x1a0
[ 17.805313][ T59] .ret_from_kernel_thread+0x58/0x70
[ 17.806035][ T59]
[ 17.806035][ T59] freed by task 59:
[ 17.806495][ T59] .kfence_guarded_free+0x3d0/0x530
[ 17.806689][ T59] .__slab_free+0x320/0x5a0
[ 17.806941][ T59] .kmem_cache_free+0x31c/0x5c0
[ 17.807122][ T59] .test_double_free+0xa8/0x198
[ 17.807360][ T59] .kunit_try_run_case+0x80/0x110
[ 17.807538][ T59] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.807703][ T59] .kthread+0x18c/0x1a0
[ 17.808015][ T59] .ret_from_kernel_thread+0x58/0x70
[ 17.808220][ T59]
[ 17.808406][ T59] CPU: 0 PID: 59 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 17.808670][ T59] ==================================================================
[ 17.809882][ T59] # test_double_free-memcache: EXPECTATION FAILED at
mm/kfence/kfence_test.c:380
[ 17.809882][ T59] Expected report_matches(&expect) to be true, but is false
[ 17.812462][ T1] not ok 8 - test_double_free-memcache
[ 17.813872][ T60] # test_invalid_addr_free: test_alloc: size=32, gfp=cc0, policy=any, cache=0
[ 17.920432][ T60] ==================================================================
[ 17.920747][ T60] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
[ 17.920747][ T60]
[ 17.921003][ T60] Invalid free of 0xc00000003ca0ffe1 (in kfence-#79):
[ 17.921137][ T60] .kfence_guarded_free+0x2e4/0x530
[ 17.921268][ T60] .__slab_free+0x320/0x5a0
[ 17.921461][ T60] .test_invalid_addr_free+0xc0/0x1a8
[ 17.921607][ T60] .kunit_try_run_case+0x80/0x110
[ 17.921739][ T60] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.921946][ T60] .kthread+0x18c/0x1a0
[ 17.922065][ T60] .ret_from_kernel_thread+0x58/0x70
[ 17.922215][ T60]
[ 17.922327][ T60] kfence-#79 [0xc00000003ca0ffe0-0xc00000003ca0ffff, size=32, cache=kmalloc-32]
allocated by task 60:
[ 17.922585][ T60] .__kfence_alloc+0x1bc/0x510
[ 17.922730][ T60] .__kmalloc+0x280/0x4f0
[ 17.922903][ T60] .test_alloc+0x19c/0x430
[ 17.923032][ T60] .test_invalid_addr_free+0x8c/0x1a8
[ 17.923164][ T60] .kunit_try_run_case+0x80/0x110
[ 17.923333][ T60] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 17.923489][ T60] .kthread+0x18c/0x1a0
[ 17.923608][ T60] .ret_from_kernel_thread+0x58/0x70
[ 17.923773][ T60]
[ 17.923913][ T60] CPU: 0 PID: 60 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 17.924128][ T60] ==================================================================
[ 17.925133][ T60] # test_invalid_addr_free: EXPECTATION FAILED at mm/kfence/kfence_test.c:397
[ 17.925133][ T60] Expected report_matches(&expect) to be true, but is false
[ 17.927243][ T1] not ok 9 - test_invalid_addr_free
[ 17.931185][ T61] # test_invalid_addr_free-memcache: setup_test_cache: size=32, ctor=0x0
[ 17.932183][ T61] # test_invalid_addr_free-memcache: test_alloc: size=32, gfp=cc0,
policy=any, cache=1
[ 18.149594][ T61] ==================================================================
[ 18.149909][ T61] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
[ 18.149909][ T61]
[ 18.150129][ T61] Invalid free of 0xc00000003ca20001 (in kfence-#80):
[ 18.150267][ T61] .kfence_guarded_free+0x2e4/0x530
[ 18.150465][ T61] .__slab_free+0x320/0x5a0
[ 18.150643][ T61] .kmem_cache_free+0x31c/0x5c0
[ 18.150873][ T61] .test_invalid_addr_free+0xb0/0x1a8
[ 18.151097][ T61] .kunit_try_run_case+0x80/0x110
[ 18.151286][ T61] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 18.151578][ T61] .kthread+0x18c/0x1a0
[ 18.151762][ T61] .ret_from_kernel_thread+0x58/0x70
[ 18.152085][ T61]
[ 18.152260][ T61] kfence-#80 [0xc00000003ca20000-0xc00000003ca2001f, size=32, cache=test]
allocated by task 61:
[ 18.152660][ T61] .__kfence_alloc+0x1bc/0x510
[ 18.152883][ T61] .kmem_cache_alloc+0x290/0x440
[ 18.153128][ T61] .test_alloc+0x188/0x430
[ 18.153325][ T61] .test_invalid_addr_free+0x8c/0x1a8
[ 18.153584][ T61] .kunit_try_run_case+0x80/0x110
[ 18.153796][ T61] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 18.154094][ T61] .kthread+0x18c/0x1a0
[ 18.154279][ T61] .ret_from_kernel_thread+0x58/0x70
[ 18.154555][ T61]
[ 18.154762][ T61] CPU: 0 PID: 61 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 18.155179][ T61] ==================================================================
[ 18.157795][ T61] # test_invalid_addr_free-memcache: EXPECTATION FAILED at
mm/kfence/kfence_test.c:397
[ 18.157795][ T61] Expected report_matches(&expect) to be true, but is false
[ 18.165055][ T1] not ok 10 - test_invalid_addr_free-memcache
[ 18.166459][ T62] # test_corruption: test_alloc: size=32, gfp=cc0, policy=left, cache=0
[ 18.514038][ T62] ==================================================================
[ 18.514772][ T62] BUG: KFENCE: memory corruption in .kfence_guarded_free+0x23c/0x530
[ 18.514772][ T62]
[ 18.515235][ T62] Corrupted memory at 0xc00000003ca60020 [ 0x2a . . . . . . . . . . . . . . . ]
(in kfence-#82):
[ 18.516308][ T62] .kfence_guarded_free+0x23c/0x530
[ 18.516550][ T62] .__slab_free+0x320/0x5a0
[ 18.516814][ T62] .test_corruption+0xcc/0x248
[ 18.517053][ T62] .kunit_try_run_case+0x80/0x110
[ 18.517347][ T62] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 18.517609][ T62] .kthread+0x18c/0x1a0
[ 18.517841][ T62] .ret_from_kernel_thread+0x58/0x70
[ 18.518271][ T62]
[ 18.518405][ T62] kfence-#82 [0xc00000003ca60000-0xc00000003ca6001f, size=32, cache=kmalloc-32]
allocated by task 62:
[ 18.518858][ T62] .__kfence_alloc+0x1bc/0x510
[ 18.519180][ T62] .__kmalloc+0x280/0x4f0
[ 18.519370][ T62] .test_alloc+0x19c/0x430
[ 18.519583][ T62] .test_corruption+0x94/0x248
[ 18.519864][ T62] .kunit_try_run_case+0x80/0x110
[ 18.520135][ T62] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 18.520368][ T62] .kthread+0x18c/0x1a0
[ 18.520569][ T62] .ret_from_kernel_thread+0x58/0x70
[ 18.520825][ T62]
[ 18.520990][ T62] CPU: 0 PID: 62 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 18.521803][ T62] ==================================================================
[ 18.523184][ T62] # test_corruption: EXPECTATION FAILED at mm/kfence/kfence_test.c:417
[ 18.523184][ T62] Expected report_matches(&expect) to be true, but is false
[ 18.524015][ T62] # test_corruption: test_alloc: size=32, gfp=cc0, policy=right, cache=0
[ 18.741141][ T62] ==================================================================
[ 18.741476][ T62] BUG: KFENCE: memory corruption in .kfence_guarded_free+0x160/0x530
[ 18.741476][ T62]
[ 18.741746][ T62] Corrupted memory at 0xc00000003ca8ffdf [ 0x2a ] (in kfence-#83):
[ 18.741995][ T62] .kfence_guarded_free+0x160/0x530
[ 18.742140][ T62] .__slab_free+0x320/0x5a0
[ 18.742402][ T62] .test_corruption+0x19c/0x248
[ 18.742586][ T62] .kunit_try_run_case+0x80/0x110
[ 18.742809][ T62] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 18.743027][ T62] .kthread+0x18c/0x1a0
[ 18.743488][ T62] .ret_from_kernel_thread+0x58/0x70
[ 18.743970][ T62]
[ 18.744156][ T62] kfence-#83 [0xc00000003ca8ffe0-0xc00000003ca8ffff, size=32, cache=kmalloc-32]
allocated by task 62:
[ 18.745071][ T62] .__kfence_alloc+0x1bc/0x510
[ 18.746079][ T62] .__kmalloc+0x280/0x4f0
[ 18.746595][ T62] .test_alloc+0x19c/0x430
[ 18.746879][ T62] .test_corruption+0x164/0x248
[ 18.748178][ T62] .kunit_try_run_case+0x80/0x110
[ 18.749636][ T62] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 18.749949][ T62] .kthread+0x18c/0x1a0
[ 18.750201][ T62] .ret_from_kernel_thread+0x58/0x70
[ 18.750369][ T62]
[ 18.750485][ T62] CPU: 0 PID: 62 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 18.750762][ T62] ==================================================================
[ 18.751578][ T62] # test_corruption: EXPECTATION FAILED at mm/kfence/kfence_test.c:423
[ 18.751578][ T62] Expected report_matches(&expect) to be true, but is false
[ 18.753340][ T1] not ok 11 - test_corruption
[ 18.754944][ T63] # test_corruption-memcache: setup_test_cache: size=32, ctor=0x0
[ 18.756995][ T63] # test_corruption-memcache: test_alloc: size=32, gfp=cc0, policy=left,
cache=1
[ 19.109763][ T63] ==================================================================
[ 19.110515][ T63] BUG: KFENCE: memory corruption in .kfence_guarded_free+0x23c/0x530
[ 19.110515][ T63]
[ 19.110978][ T63] Corrupted memory at 0xc00000003cac0020 [ 0x2a . . . . . . . . . . . . . . . ]
(in kfence-#85):
[ 19.111848][ T63] .kfence_guarded_free+0x23c/0x530
[ 19.112763][ T63] .__slab_free+0x320/0x5a0
[ 19.113121][ T63] .kmem_cache_free+0x31c/0x5c0
[ 19.113351][ T63] .test_corruption+0xc0/0x248
[ 19.113806][ T63] .kunit_try_run_case+0x80/0x110
[ 19.114019][ T63] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 19.114173][ T63] .kthread+0x18c/0x1a0
[ 19.114292][ T63] .ret_from_kernel_thread+0x58/0x70
[ 19.114535][ T63]
[ 19.114681][ T63] kfence-#85 [0xc00000003cac0000-0xc00000003cac001f, size=32, cache=test]
allocated by task 63:
[ 19.115287][ T63] .__kfence_alloc+0x1bc/0x510
[ 19.115597][ T63] .kmem_cache_alloc+0x290/0x440
[ 19.115875][ T63] .test_alloc+0x188/0x430
[ 19.116456][ T63] .test_corruption+0x94/0x248
[ 19.116689][ T63] .kunit_try_run_case+0x80/0x110
[ 19.117021][ T63] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 19.117383][ T63] .kthread+0x18c/0x1a0
[ 19.117572][ T63] .ret_from_kernel_thread+0x58/0x70
[ 19.117713][ T63]
[ 19.117816][ T63] CPU: 0 PID: 63 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 19.118706][ T63] ==================================================================
[ 19.119719][ T63] # test_corruption-memcache: EXPECTATION FAILED at mm/kfence/kfence_test.c:417
[ 19.119719][ T63] Expected report_matches(&expect) to be true, but is false
[ 19.120669][ T63] # test_corruption-memcache: test_alloc: size=32, gfp=cc0, policy=right,
cache=1
[ 19.339842][ T63] ==================================================================
[ 19.340238][ T63] BUG: KFENCE: memory corruption in .kfence_guarded_free+0x160/0x530
[ 19.340238][ T63]
[ 19.340487][ T63] Corrupted memory at 0xc00000003caeffdf [ 0x2a ] (in kfence-#86):
[ 19.340748][ T63] .kfence_guarded_free+0x160/0x530
[ 19.340885][ T63] .__slab_free+0x320/0x5a0
[ 19.341095][ T63] .kmem_cache_free+0x31c/0x5c0
[ 19.341285][ T63] .test_corruption+0x190/0x248
[ 19.341480][ T63] .kunit_try_run_case+0x80/0x110
[ 19.341921][ T63] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 19.342298][ T63] .kthread+0x18c/0x1a0
[ 19.342816][ T63] .ret_from_kernel_thread+0x58/0x70
[ 19.343799][ T63]
[ 19.345941][ T63] kfence-#86 [0xc00000003caeffe0-0xc00000003caeffff, size=32, cache=test]
allocated by task 63:
[ 19.347301][ T63] .__kfence_alloc+0x1bc/0x510
[ 19.347620][ T63] .kmem_cache_alloc+0x290/0x440
[ 19.347820][ T63] .test_alloc+0x188/0x430
[ 19.348202][ T63] .test_corruption+0x164/0x248
[ 19.348400][ T63] .kunit_try_run_case+0x80/0x110
[ 19.348609][ T63] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 19.348810][ T63] .kthread+0x18c/0x1a0
[ 19.349131][ T63] .ret_from_kernel_thread+0x58/0x70
[ 19.349429][ T63]
[ 19.349612][ T63] CPU: 0 PID: 63 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 19.349985][ T63] ==================================================================
[ 19.351145][ T63] # test_corruption-memcache: EXPECTATION FAILED at mm/kfence/kfence_test.c:423
[ 19.351145][ T63] Expected report_matches(&expect) to be true, but is false
[ 19.353730][ T1] not ok 12 - test_corruption-memcache
[ 26.350432][ T69] ==================================================================
[ 26.350757][ T69] BUG: KFENCE: memory corruption in .kfence_guarded_free+0x23c/0x530
[ 26.350757][ T69]
[ 26.350961][ T69] Corrupted memory at 0xc00000003cfcfff9 [ 0xac . . . . . . ] (in kfence-#125):
[ 26.351333][ T69] .kfence_guarded_free+0x23c/0x530
[ 26.351517][ T69] .__slab_free+0x320/0x5a0
[ 26.351645][ T69] .test_kmalloc_aligned_oob_write+0x12c/0x1e4
[ 26.351774][ T69] .kunit_try_run_case+0x80/0x110
[ 26.351902][ T69] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 26.352066][ T69] .kthread+0x18c/0x1a0
[ 26.352180][ T69] .ret_from_kernel_thread+0x58/0x70
[ 26.352294][ T69]
[ 26.352367][ T69] kfence-#125 [0xc00000003cfcffb0-0xc00000003cfcfff8, size=73,
cache=kmalloc-96] allocated by task 69:
[ 26.352668][ T69] .__kfence_alloc+0x1bc/0x510
[ 26.352804][ T69] .__kmalloc+0x280/0x4f0
[ 26.352913][ T69] .test_alloc+0x19c/0x430
[ 26.353092][ T69] .test_kmalloc_aligned_oob_write+0x80/0x1e4
[ 26.353290][ T69] .kunit_try_run_case+0x80/0x110
[ 26.353505][ T69] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 26.353724][ T69] .kthread+0x18c/0x1a0
[ 26.353896][ T69] .ret_from_kernel_thread+0x58/0x70
[ 26.354153][ T69]
[ 26.354309][ T69] CPU: 0 PID: 69 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 26.354714][ T69] ==================================================================
[ 26.355421][ T69] # test_kmalloc_aligned_oob_write: EXPECTATION FAILED at
mm/kfence/kfence_test.c:489
[ 26.355421][ T69] Expected report_matches(&expect) to be true, but is false
[ 26.357224][ T1] not ok 18 - test_kmalloc_aligned_oob_write
Christophe
Le 04/03/2021 à 12:48, Christophe Leroy a écrit :
>
>
> Le 04/03/2021 à 12:31, Marco Elver a écrit :
>> On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
>> <[email protected]> wrote:
>>> Le 03/03/2021 à 11:56, Marco Elver a écrit :
>>>>
>>>> Somewhat tangentially, I also note that e.g. show_regs(regs) (which
>>>> was printed along the KFENCE report above) didn't include the top
>>>> frame in the "Call Trace", so this assumption is definitely not
>>>> isolated to KFENCE.
>>>>
>>>
>>> Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
>>> applied), and I get many failures. Any idea ?
>>>
>>> [ 17.653751][ T58] ==================================================================
>>> [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
>>> [ 17.654379][ T58]
>>> [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
>>> [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
>>> [ 17.655775][ T58] .__slab_free+0x320/0x5a0
>>> [ 17.656039][ T58] .test_double_free+0xe0/0x198
>>> [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
>>> [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>>> [ 17.657161][ T58] .kthread+0x18c/0x1a0
>>> [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
>>> [ 17.659869][ T58]
>>> [ 17.663954][ T58] kfence-#77 [0xc00000003c9c0000-0xc00000003c9c001f, size=32, cache=kmalloc-32]
>>> allocated by task 58:
>>> [ 17.666113][ T58] .__kfence_alloc+0x1bc/0x510
>>> [ 17.667069][ T58] .__kmalloc+0x280/0x4f0
>>> [ 17.667452][ T58] .test_alloc+0x19c/0x430
>>> [ 17.667732][ T58] .test_double_free+0x88/0x198
>>> [ 17.667971][ T58] .kunit_try_run_case+0x80/0x110
>>> [ 17.668283][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>>> [ 17.668553][ T58] .kthread+0x18c/0x1a0
>>> [ 17.669315][ T58] .ret_from_kernel_thread+0x58/0x70
>>> [ 17.669711][ T58]
>>> [ 17.669711][ T58] freed by task 58:
>>> [ 17.670116][ T58] .kfence_guarded_free+0x3d0/0x530
>>> [ 17.670421][ T58] .__slab_free+0x320/0x5a0
>>> [ 17.670603][ T58] .test_double_free+0xb4/0x198
>>> [ 17.670827][ T58] .kunit_try_run_case+0x80/0x110
>>> [ 17.671073][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>>> [ 17.671410][ T58] .kthread+0x18c/0x1a0
>>> [ 17.671618][ T58] .ret_from_kernel_thread+0x58/0x70
>>> [ 17.671972][ T58]
>>> [ 17.672638][ T58] CPU: 0 PID: 58 Comm: kunit_try_catch Tainted: G B
>>> 5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
>>> [ 17.673768][ T58] ==================================================================
>>> [ 17.677031][ T58] # test_double_free: EXPECTATION FAILED at mm/kfence/kfence_test.c:380
>>> [ 17.677031][ T58] Expected report_matches(&expect) to be true, but is false
>>> [ 17.684397][ T1] not ok 7 - test_double_free
>>> [ 17.686463][ T59] # test_double_free-memcache: setup_test_cache: size=32, ctor=0x0
>>> [ 17.688403][ T59] # test_double_free-memcache: test_alloc: size=32, gfp=cc0, policy=any,
>>> cache=1
>>
>> Looks like something is prepending '.' to function names. We expect
>> the function name to appear as-is, e.g. "kfence_guarded_free",
>> "test_double_free", etc.
>>
>> Is there something special on ppc64, where the '.' is some convention?
>>
>
> I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
>
> Also see commit https://github.com/linuxppc/linux/commit/02424d896
>
But I'm wondering, if the dot is the problem, how so is the following one ok ?
[ 79.574457][ T75] # test_krealloc: test_alloc: size=32, gfp=cc0, policy=any, cache=0
[ 79.682728][ T75] ==================================================================
[ 79.684017][ T75] BUG: KFENCE: use-after-free read in .test_krealloc+0x4fc/0x5b8
[ 79.684017][ T75]
[ 79.684955][ T75] Use-after-free read at 0xc00000003d060000 (in kfence-#130):
[ 79.687581][ T75] .test_krealloc+0x4fc/0x5b8
[ 79.688216][ T75] .test_krealloc+0x4e4/0x5b8
[ 79.688824][ T75] .kunit_try_run_case+0x80/0x110
[ 79.689737][ T75] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 79.690335][ T75] .kthread+0x18c/0x1a0
[ 79.691092][ T75] .ret_from_kernel_thread+0x58/0x70
[ 79.692081][ T75]
[ 79.692671][ T75] kfence-#130 [0xc00000003d060000-0xc00000003d06001f, size=32,
cache=kmalloc-32] allocated by task 75:
[ 79.700977][ T75] .__kfence_alloc+0x1bc/0x510
[ 79.701812][ T75] .__kmalloc+0x280/0x4f0
[ 79.702695][ T75] .test_alloc+0x19c/0x430
[ 79.703051][ T75] .test_krealloc+0xa8/0x5b8
[ 79.703276][ T75] .kunit_try_run_case+0x80/0x110
[ 79.703693][ T75] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 79.704223][ T75] .kthread+0x18c/0x1a0
[ 79.704586][ T75] .ret_from_kernel_thread+0x58/0x70
[ 79.704968][ T75]
[ 79.704968][ T75] freed by task 75:
[ 79.705756][ T75] .kfence_guarded_free+0x3d0/0x530
[ 79.706754][ T75] .__slab_free+0x320/0x5a0
[ 79.708575][ T75] .krealloc+0xe8/0x180
[ 79.708970][ T75] .test_krealloc+0x1c8/0x5b8
[ 79.709606][ T75] .kunit_try_run_case+0x80/0x110
[ 79.710204][ T75] .kunit_generic_run_threadfn_adapter+0x38/0x50
[ 79.710639][ T75] .kthread+0x18c/0x1a0
[ 79.710996][ T75] .ret_from_kernel_thread+0x58/0x70
[ 79.711349][ T75]
[ 79.717435][ T75] CPU: 0 PID: 75 Comm: kunit_try_catch Tainted: G B
5.12.0-rc1-01540-g0783285cc1b8-dirty #4685
[ 79.718124][ T75] NIP: c000000000468a40 LR: c000000000468a28 CTR: 0000000000000000
[ 79.727741][ T75] REGS: c000000007dd3830 TRAP: 0300 Tainted: G B
(5.12.0-rc1-01540-g0783285cc1b8-dirty)
[ 79.733377][ T75] MSR: 8000000002009032 <SF,VEC,EE,ME,IR,DR,RI> CR: 28000440 XER: 00000000
[ 79.738770][ T75] CFAR: c000000000888c7c DAR: c00000003d060000 DSISR: 40000000 IRQMASK: 0
[ 79.738770][ T75] GPR00: c000000000468a28 c000000007dd3ad0 c000000001eaad00 c0000000073c3988
[ 79.738770][ T75] GPR04: c000000007dd3b60 0000000000000001 0000000000000000 c00000003d060000
[ 79.738770][ T75] GPR08: 00000000000002c8 0000000000000001 c0000000011bb410 c00000003fe903d8
[ 79.738770][ T75] GPR12: 0000000028000440 c0000000020f0000 c0000000001a6460 c00000000724bb80
[ 79.738770][ T75] GPR16: 0000000000000000 c00000000731749f c0000000011bb278 c00000000731749f
[ 79.738770][ T75] GPR20: 00000001000002c1 0000000000000000 c0000000011bb278 c0000000011bb3b8
[ 79.738770][ T75] GPR24: c0000000073174a0 c0000000011aa7b8 c000000001e35328 c00000000208ad00
[ 79.738770][ T75] GPR28: 0000000000000000 c0000000011bb0b8 c0000000073c3988 c000000007dd3ad0
[ 79.751744][ T75] NIP [c000000000468a40] .test_krealloc+0x4fc/0x5b8
[ 79.752243][ T75] LR [c000000000468a28] .test_krealloc+0x4e4/0x5b8
[ 79.752699][ T75] Call Trace:
[ 79.753027][ T75] [c000000007dd3ad0] [c000000000468a28] .test_krealloc+0x4e4/0x5b8 (unreliable)
[ 79.753878][ T75] [c000000007dd3c40] [c0000000008886d0] .kunit_try_run_case+0x80/0x110
[ 79.754641][ T75] [c000000007dd3cd0] [c00000000088a808]
.kunit_generic_run_threadfn_adapter+0x38/0x50
[ 79.755494][ T75] [c000000007dd3d50] [c0000000001a65ec] .kthread+0x18c/0x1a0
[ 79.757254][ T75] [c000000007dd3e10] [c00000000000dd68] .ret_from_kernel_thread+0x58/0x70
[ 79.775521][ T75] Instruction dump:
[ 79.776890][ T75] 68a50001 9b9f00c8 fbdf0090 fbbf00a0 fb5f00b8 484201cd 60000000 e8ff0080
[ 79.783146][ T75] 3d42ff31 390002c8 394a0710 39200001 <88e70000> 38a00000 fb9f00a8 e8fbe80e
[ 79.787563][ T75] ==================================================================
[ 79.804667][ T1] ok 24 - test_krealloc
Christophe
On Thu, Mar 04, 2021 at 12:48PM +0100, Christophe Leroy wrote:
> Le 04/03/2021 ? 12:31, Marco Elver a ?crit?:
> > On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
> > <[email protected]> wrote:
> > > Le 03/03/2021 ? 11:56, Marco Elver a ?crit :
> > > >
> > > > Somewhat tangentially, I also note that e.g. show_regs(regs) (which
> > > > was printed along the KFENCE report above) didn't include the top
> > > > frame in the "Call Trace", so this assumption is definitely not
> > > > isolated to KFENCE.
> > > >
> > >
> > > Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
> > > applied), and I get many failures. Any idea ?
> > >
> > > [ 17.653751][ T58] ==================================================================
> > > [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
> > > [ 17.654379][ T58]
> > > [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
> > > [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
> > > [ 17.655775][ T58] .__slab_free+0x320/0x5a0
> > > [ 17.656039][ T58] .test_double_free+0xe0/0x198
> > > [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
> > > [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> > > [ 17.657161][ T58] .kthread+0x18c/0x1a0
> > > [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
> > > [ 17.659869][ T58]
[...]
> >
> > Looks like something is prepending '.' to function names. We expect
> > the function name to appear as-is, e.g. "kfence_guarded_free",
> > "test_double_free", etc.
> >
> > Is there something special on ppc64, where the '.' is some convention?
> >
>
> I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
>
> Also see commit https://github.com/linuxppc/linux/commit/02424d896
Thanks -- could you try the below patch? You'll need to define
ARCH_FUNC_PREFIX accordingly.
We think, since there are only very few architectures that add a prefix,
requiring <asm/kfence.h> to define something like ARCH_FUNC_PREFIX is
the simplest option. Let me know if this works for you.
There an alternative option, which is to dynamically figure out the
prefix, but if this simpler option is fine with you, we'd prefer it.
Thanks,
-- Marco
------ >8 ------
From d118080eb9552073f5dcf1f86198f3d86d5ea850 Mon Sep 17 00:00:00 2001
From: Marco Elver <[email protected]>
Date: Thu, 4 Mar 2021 13:15:51 +0100
Subject: [PATCH] kfence: fix reports if constant function prefixes exist
Some architectures prefix all functions with a constant string ('.' on
ppc64). Add ARCH_FUNC_PREFIX, which may optionally be defined in
<asm/kfence.h>, so that get_stack_skipnr() can work properly.
Link: https://lkml.kernel.org/r/[email protected]
Reported-by: Christophe Leroy <[email protected]>
Signed-off-by: Marco Elver <[email protected]>
---
mm/kfence/report.c | 18 ++++++++++++------
1 file changed, 12 insertions(+), 6 deletions(-)
diff --git a/mm/kfence/report.c b/mm/kfence/report.c
index 519f037720f5..e3f71451ad9e 100644
--- a/mm/kfence/report.c
+++ b/mm/kfence/report.c
@@ -20,6 +20,11 @@
#include "kfence.h"
+/* May be overridden by <asm/kfence.h>. */
+#ifndef ARCH_FUNC_PREFIX
+#define ARCH_FUNC_PREFIX ""
+#endif
+
extern bool no_hash_pointers;
/* Helper function to either print to a seq_file or to console. */
@@ -67,8 +72,9 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
for (skipnr = 0; skipnr < num_entries; skipnr++) {
int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
- if (str_has_prefix(buf, "kfence_") || str_has_prefix(buf, "__kfence_") ||
- !strncmp(buf, "__slab_free", len)) {
+ if (str_has_prefix(buf, ARCH_FUNC_PREFIX "kfence_") ||
+ str_has_prefix(buf, ARCH_FUNC_PREFIX "__kfence_") ||
+ !strncmp(buf, ARCH_FUNC_PREFIX "__slab_free", len)) {
/*
* In case of tail calls from any of the below
* to any of the above.
@@ -77,10 +83,10 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
}
/* Also the *_bulk() variants by only checking prefixes. */
- if (str_has_prefix(buf, "kfree") ||
- str_has_prefix(buf, "kmem_cache_free") ||
- str_has_prefix(buf, "__kmalloc") ||
- str_has_prefix(buf, "kmem_cache_alloc"))
+ if (str_has_prefix(buf, ARCH_FUNC_PREFIX "kfree") ||
+ str_has_prefix(buf, ARCH_FUNC_PREFIX "kmem_cache_free") ||
+ str_has_prefix(buf, ARCH_FUNC_PREFIX "__kmalloc") ||
+ str_has_prefix(buf, ARCH_FUNC_PREFIX "kmem_cache_alloc"))
goto found;
}
if (fallback < num_entries)
--
2.30.1.766.gb4fecdf3b7-goog
Marco Elver <[email protected]> writes:
> On Thu, Mar 04, 2021 at 12:48PM +0100, Christophe Leroy wrote:
>> Le 04/03/2021 à 12:31, Marco Elver a écrit :
>> > On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
>> > <[email protected]> wrote:
>> > > Le 03/03/2021 à 11:56, Marco Elver a écrit :
>> > > >
>> > > > Somewhat tangentially, I also note that e.g. show_regs(regs) (which
>> > > > was printed along the KFENCE report above) didn't include the top
>> > > > frame in the "Call Trace", so this assumption is definitely not
>> > > > isolated to KFENCE.
>> > > >
>> > >
>> > > Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
>> > > applied), and I get many failures. Any idea ?
>> > >
>> > > [ 17.653751][ T58] ==================================================================
>> > > [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
>> > > [ 17.654379][ T58]
>> > > [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
>> > > [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
>> > > [ 17.655775][ T58] .__slab_free+0x320/0x5a0
>> > > [ 17.656039][ T58] .test_double_free+0xe0/0x198
>> > > [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
>> > > [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>> > > [ 17.657161][ T58] .kthread+0x18c/0x1a0
>> > > [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
>> > > [ 17.659869][ T58]
> [...]
>> >
>> > Looks like something is prepending '.' to function names. We expect
>> > the function name to appear as-is, e.g. "kfence_guarded_free",
>> > "test_double_free", etc.
>> >
>> > Is there something special on ppc64, where the '.' is some convention?
>> >
>>
>> I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
>>
>> Also see commit https://github.com/linuxppc/linux/commit/02424d896
>
> Thanks -- could you try the below patch? You'll need to define
> ARCH_FUNC_PREFIX accordingly.
>
> We think, since there are only very few architectures that add a prefix,
> requiring <asm/kfence.h> to define something like ARCH_FUNC_PREFIX is
> the simplest option. Let me know if this works for you.
>
> There an alternative option, which is to dynamically figure out the
> prefix, but if this simpler option is fine with you, we'd prefer it.
We have rediscovered this problem in basically every tracing / debugging
feature added in the last 20 years :)
I think the simplest solution is the one tools/perf/util/symbol.c uses,
which is to just skip a leading '.'.
Does that work?
diff --git a/mm/kfence/report.c b/mm/kfence/report.c
index ab83d5a59bb1..67b49dc54b38 100644
--- a/mm/kfence/report.c
+++ b/mm/kfence/report.c
@@ -67,6 +67,9 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
for (skipnr = 0; skipnr < num_entries; skipnr++) {
int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
+ if (buf[0] == '.')
+ buf++;
+
if (str_has_prefix(buf, "kfence_") || str_has_prefix(buf, "__kfence_") ||
!strncmp(buf, "__slab_free", len)) {
/*
cheers
On Fri, Mar 05, 2021 at 04:01PM +1100, Michael Ellerman wrote:
> Marco Elver <[email protected]> writes:
> > On Thu, Mar 04, 2021 at 12:48PM +0100, Christophe Leroy wrote:
> >> Le 04/03/2021 ? 12:31, Marco Elver a ?crit?:
> >> > On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
> >> > <[email protected]> wrote:
> >> > > Le 03/03/2021 ? 11:56, Marco Elver a ?crit :
> >> > > >
> >> > > > Somewhat tangentially, I also note that e.g. show_regs(regs) (which
> >> > > > was printed along the KFENCE report above) didn't include the top
> >> > > > frame in the "Call Trace", so this assumption is definitely not
> >> > > > isolated to KFENCE.
> >> > > >
> >> > >
> >> > > Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
> >> > > applied), and I get many failures. Any idea ?
> >> > >
> >> > > [ 17.653751][ T58] ==================================================================
> >> > > [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
> >> > > [ 17.654379][ T58]
> >> > > [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
> >> > > [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
> >> > > [ 17.655775][ T58] .__slab_free+0x320/0x5a0
> >> > > [ 17.656039][ T58] .test_double_free+0xe0/0x198
> >> > > [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
> >> > > [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> >> > > [ 17.657161][ T58] .kthread+0x18c/0x1a0
> >> > > [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
> >> > > [ 17.659869][ T58]
> > [...]
> >> >
> >> > Looks like something is prepending '.' to function names. We expect
> >> > the function name to appear as-is, e.g. "kfence_guarded_free",
> >> > "test_double_free", etc.
> >> >
> >> > Is there something special on ppc64, where the '.' is some convention?
> >> >
> >>
> >> I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
> >>
> >> Also see commit https://github.com/linuxppc/linux/commit/02424d896
> >
> > Thanks -- could you try the below patch? You'll need to define
> > ARCH_FUNC_PREFIX accordingly.
> >
> > We think, since there are only very few architectures that add a prefix,
> > requiring <asm/kfence.h> to define something like ARCH_FUNC_PREFIX is
> > the simplest option. Let me know if this works for you.
> >
> > There an alternative option, which is to dynamically figure out the
> > prefix, but if this simpler option is fine with you, we'd prefer it.
>
> We have rediscovered this problem in basically every tracing / debugging
> feature added in the last 20 years :)
>
> I think the simplest solution is the one tools/perf/util/symbol.c uses,
> which is to just skip a leading '.'.
>
> Does that work?
>
> diff --git a/mm/kfence/report.c b/mm/kfence/report.c
> index ab83d5a59bb1..67b49dc54b38 100644
> --- a/mm/kfence/report.c
> +++ b/mm/kfence/report.c
> @@ -67,6 +67,9 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
> for (skipnr = 0; skipnr < num_entries; skipnr++) {
> int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
>
> + if (buf[0] == '.')
> + buf++;
> +
Unfortunately this does not work, since buf is an array. We'd need an
offset, and it should be determined outside the loop. I had a solution
like this, but it turned out quite complex (see below). And since most
architectures do not require this, decided that the safest option is to
use the macro approach with ARCH_FUNC_PREFIX, for which Christophe
already prepared a patch and tested:
https://lore.kernel.org/linux-mm/[email protected]/
https://lkml.kernel.org/r/afaec81a551ef15345cb7d7563b3fac3d7041c3a.1614868445.git.christophe.leroy@csgroup.eu
Since KFENCE requires <asm/kfence.h> anyway, we'd prefer this approach
(vs. dynamically detecting).
Thanks,
-- Marco
------ >8 ------
diff --git a/mm/kfence/report.c b/mm/kfence/report.c
index 519f037720f5..b0590199b039 100644
--- a/mm/kfence/report.c
+++ b/mm/kfence/report.c
@@ -43,8 +43,8 @@ static void seq_con_printf(struct seq_file *seq, const char *fmt, ...)
static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries,
const enum kfence_error_type *type)
{
+ int skipnr, fallback = 0, fprefix_chars = 0;
char buf[64];
- int skipnr, fallback = 0;
if (type) {
/* Depending on error type, find different stack entries. */
@@ -64,11 +64,24 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
}
}
+ if (scnprintf(buf, sizeof(buf), "%ps", (void *)kfree)) {
+ /*
+ * Some architectures (e.g. ppc64) add a constant prefix to
+ * function names. Determine if such a prefix exists.
+ */
+ const char *str = strstr(buf, "kfree");
+
+ if (str)
+ fprefix_chars = str - buf;
+ }
+
for (skipnr = 0; skipnr < num_entries; skipnr++) {
- int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
+ int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]) -
+ fprefix_chars;
- if (str_has_prefix(buf, "kfence_") || str_has_prefix(buf, "__kfence_") ||
- !strncmp(buf, "__slab_free", len)) {
+ if (str_has_prefix(buf + fprefix_chars, "kfence_") ||
+ str_has_prefix(buf + fprefix_chars, "__kfence_") ||
+ !strncmp(buf + fprefix_chars, "__slab_free", len)) {
/*
* In case of tail calls from any of the below
* to any of the above.
@@ -77,10 +90,10 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
}
/* Also the *_bulk() variants by only checking prefixes. */
- if (str_has_prefix(buf, "kfree") ||
- str_has_prefix(buf, "kmem_cache_free") ||
- str_has_prefix(buf, "__kmalloc") ||
- str_has_prefix(buf, "kmem_cache_alloc"))
+ if (str_has_prefix(buf + fprefix_chars, "kfree") ||
+ str_has_prefix(buf + fprefix_chars, "kmem_cache_free") ||
+ str_has_prefix(buf + fprefix_chars, "__kmalloc") ||
+ str_has_prefix(buf + fprefix_chars, "kmem_cache_alloc"))
goto found;
}
if (fallback < num_entries)
Le 05/03/2021 à 08:50, Marco Elver a écrit :
> On Fri, Mar 05, 2021 at 04:01PM +1100, Michael Ellerman wrote:
>> Marco Elver <[email protected]> writes:
>>> On Thu, Mar 04, 2021 at 12:48PM +0100, Christophe Leroy wrote:
>>>> Le 04/03/2021 à 12:31, Marco Elver a écrit :
>>>>> On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
>>>>> <[email protected]> wrote:
>>>>>> Le 03/03/2021 à 11:56, Marco Elver a écrit :
>>>>>>>
>>>>>>> Somewhat tangentially, I also note that e.g. show_regs(regs) (which
>>>>>>> was printed along the KFENCE report above) didn't include the top
>>>>>>> frame in the "Call Trace", so this assumption is definitely not
>>>>>>> isolated to KFENCE.
>>>>>>>
>>>>>>
>>>>>> Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
>>>>>> applied), and I get many failures. Any idea ?
>>>>>>
>>>>>> [ 17.653751][ T58] ==================================================================
>>>>>> [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
>>>>>> [ 17.654379][ T58]
>>>>>> [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
>>>>>> [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
>>>>>> [ 17.655775][ T58] .__slab_free+0x320/0x5a0
>>>>>> [ 17.656039][ T58] .test_double_free+0xe0/0x198
>>>>>> [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
>>>>>> [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
>>>>>> [ 17.657161][ T58] .kthread+0x18c/0x1a0
>>>>>> [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
>>>>>> [ 17.659869][ T58]
>>> [...]
>>>>>
>>>>> Looks like something is prepending '.' to function names. We expect
>>>>> the function name to appear as-is, e.g. "kfence_guarded_free",
>>>>> "test_double_free", etc.
>>>>>
>>>>> Is there something special on ppc64, where the '.' is some convention?
>>>>>
>>>>
>>>> I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
>>>>
>>>> Also see commit https://github.com/linuxppc/linux/commit/02424d896
>>>
>>> Thanks -- could you try the below patch? You'll need to define
>>> ARCH_FUNC_PREFIX accordingly.
>>>
>>> We think, since there are only very few architectures that add a prefix,
>>> requiring <asm/kfence.h> to define something like ARCH_FUNC_PREFIX is
>>> the simplest option. Let me know if this works for you.
>>>
>>> There an alternative option, which is to dynamically figure out the
>>> prefix, but if this simpler option is fine with you, we'd prefer it.
>>
>> We have rediscovered this problem in basically every tracing / debugging
>> feature added in the last 20 years :)
>>
>> I think the simplest solution is the one tools/perf/util/symbol.c uses,
>> which is to just skip a leading '.'.
>>
>> Does that work?
>>
>> diff --git a/mm/kfence/report.c b/mm/kfence/report.c
>> index ab83d5a59bb1..67b49dc54b38 100644
>> --- a/mm/kfence/report.c
>> +++ b/mm/kfence/report.c
>> @@ -67,6 +67,9 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
>> for (skipnr = 0; skipnr < num_entries; skipnr++) {
>> int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
>>
>> + if (buf[0] == '.')
>> + buf++;
>> +
>
> Unfortunately this does not work, since buf is an array. We'd need an
> offset, and it should be determined outside the loop. I had a solution
> like this, but it turned out quite complex (see below). And since most
> architectures do not require this, decided that the safest option is to
> use the macro approach with ARCH_FUNC_PREFIX, for which Christophe
> already prepared a patch and tested:
> https://lore.kernel.org/linux-mm/[email protected]/
> https://lkml.kernel.org/r/afaec81a551ef15345cb7d7563b3fac3d7041c3a.1614868445.git.christophe.leroy@csgroup.eu
>
> Since KFENCE requires <asm/kfence.h> anyway, we'd prefer this approach
> (vs. dynamically detecting).
>
> Thanks,
> -- Marco
>
What about
diff --git a/mm/kfence/report.c b/mm/kfence/report.c
index 519f037720f5..5e196625fb34 100644
--- a/mm/kfence/report.c
+++ b/mm/kfence/report.c
@@ -43,7 +43,7 @@ static void seq_con_printf(struct seq_file *seq, const char *fmt, ...)
static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries,
const enum kfence_error_type *type)
{
- char buf[64];
+ char _buf[64];
int skipnr, fallback = 0;
if (type) {
@@ -65,7 +65,11 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
}
for (skipnr = 0; skipnr < num_entries; skipnr++) {
- int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
+ char *buf = _buf;
+ int len = scnprintf(_buf, sizeof(_buf), "%ps", (void *)stack_entries[skipnr]);
+
+ if (_buf[0] == '.')
+ buf++, len--;
if (str_has_prefix(buf, "kfence_") || str_has_prefix(buf, "__kfence_") ||
!strncmp(buf, "__slab_free", len)) {
---
Christophe
On Fri, 5 Mar 2021 at 09:23, Christophe Leroy
<[email protected]> wrote:
>
>
>
> Le 05/03/2021 à 08:50, Marco Elver a écrit :
> > On Fri, Mar 05, 2021 at 04:01PM +1100, Michael Ellerman wrote:
> >> Marco Elver <[email protected]> writes:
> >>> On Thu, Mar 04, 2021 at 12:48PM +0100, Christophe Leroy wrote:
> >>>> Le 04/03/2021 à 12:31, Marco Elver a écrit :
> >>>>> On Thu, 4 Mar 2021 at 12:23, Christophe Leroy
> >>>>> <[email protected]> wrote:
> >>>>>> Le 03/03/2021 à 11:56, Marco Elver a écrit :
> >>>>>>>
> >>>>>>> Somewhat tangentially, I also note that e.g. show_regs(regs) (which
> >>>>>>> was printed along the KFENCE report above) didn't include the top
> >>>>>>> frame in the "Call Trace", so this assumption is definitely not
> >>>>>>> isolated to KFENCE.
> >>>>>>>
> >>>>>>
> >>>>>> Now, I have tested PPC64 (with the patch I sent yesterday to modify save_stack_trace_regs()
> >>>>>> applied), and I get many failures. Any idea ?
> >>>>>>
> >>>>>> [ 17.653751][ T58] ==================================================================
> >>>>>> [ 17.654379][ T58] BUG: KFENCE: invalid free in .kfence_guarded_free+0x2e4/0x530
> >>>>>> [ 17.654379][ T58]
> >>>>>> [ 17.654831][ T58] Invalid free of 0xc00000003c9c0000 (in kfence-#77):
> >>>>>> [ 17.655358][ T58] .kfence_guarded_free+0x2e4/0x530
> >>>>>> [ 17.655775][ T58] .__slab_free+0x320/0x5a0
> >>>>>> [ 17.656039][ T58] .test_double_free+0xe0/0x198
> >>>>>> [ 17.656308][ T58] .kunit_try_run_case+0x80/0x110
> >>>>>> [ 17.656523][ T58] .kunit_generic_run_threadfn_adapter+0x38/0x50
> >>>>>> [ 17.657161][ T58] .kthread+0x18c/0x1a0
> >>>>>> [ 17.659148][ T58] .ret_from_kernel_thread+0x58/0x70
> >>>>>> [ 17.659869][ T58]
> >>> [...]
> >>>>>
> >>>>> Looks like something is prepending '.' to function names. We expect
> >>>>> the function name to appear as-is, e.g. "kfence_guarded_free",
> >>>>> "test_double_free", etc.
> >>>>>
> >>>>> Is there something special on ppc64, where the '.' is some convention?
> >>>>>
> >>>>
> >>>> I think so, see https://refspecs.linuxfoundation.org/ELF/ppc64/PPC-elf64abi.html#FUNC-DES
> >>>>
> >>>> Also see commit https://github.com/linuxppc/linux/commit/02424d896
> >>>
> >>> Thanks -- could you try the below patch? You'll need to define
> >>> ARCH_FUNC_PREFIX accordingly.
> >>>
> >>> We think, since there are only very few architectures that add a prefix,
> >>> requiring <asm/kfence.h> to define something like ARCH_FUNC_PREFIX is
> >>> the simplest option. Let me know if this works for you.
> >>>
> >>> There an alternative option, which is to dynamically figure out the
> >>> prefix, but if this simpler option is fine with you, we'd prefer it.
> >>
> >> We have rediscovered this problem in basically every tracing / debugging
> >> feature added in the last 20 years :)
> >>
> >> I think the simplest solution is the one tools/perf/util/symbol.c uses,
> >> which is to just skip a leading '.'.
> >>
> >> Does that work?
> >>
> >> diff --git a/mm/kfence/report.c b/mm/kfence/report.c
> >> index ab83d5a59bb1..67b49dc54b38 100644
> >> --- a/mm/kfence/report.c
> >> +++ b/mm/kfence/report.c
> >> @@ -67,6 +67,9 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
> >> for (skipnr = 0; skipnr < num_entries; skipnr++) {
> >> int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
> >>
> >> + if (buf[0] == '.')
> >> + buf++;
> >> +
> >
> > Unfortunately this does not work, since buf is an array. We'd need an
> > offset, and it should be determined outside the loop. I had a solution
> > like this, but it turned out quite complex (see below). And since most
> > architectures do not require this, decided that the safest option is to
> > use the macro approach with ARCH_FUNC_PREFIX, for which Christophe
> > already prepared a patch and tested:
> > https://lore.kernel.org/linux-mm/[email protected]/
> > https://lkml.kernel.org/r/afaec81a551ef15345cb7d7563b3fac3d7041c3a.1614868445.git.christophe.leroy@csgroup.eu
> >
> > Since KFENCE requires <asm/kfence.h> anyway, we'd prefer this approach
> > (vs. dynamically detecting).
> >
> > Thanks,
> > -- Marco
> >
>
> What about
Sure something like that would work. But I explicitly did *not* want
to hard-code the '.' in non-arch code.
The choice is between:
1. ARCH_FUNC_PREFIX (as a matter of fact, the ARCH_FUNC_PREFIX patch
is already in -mm). Perhaps we could optimize it further, by checking
ARCH_FUNC_PREFIX in buf, and advancing buf like you propose, but I'm
not sure it's worth worrying about.
2. The dynamic solution that I proposed that does not use a hard-coded
'.' (or some variation thereof).
Please tell me which solution you prefer, 1 or 2 -- I'd like to stop
bikeshedding here. If there's a compelling argument for hard-coding
the '.' in non-arch code, please clarify, but otherwise I'd like to
keep arch-specific things out of generic code.
Thanks.
> diff --git a/mm/kfence/report.c b/mm/kfence/report.c
> index 519f037720f5..5e196625fb34 100644
> --- a/mm/kfence/report.c
> +++ b/mm/kfence/report.c
> @@ -43,7 +43,7 @@ static void seq_con_printf(struct seq_file *seq, const char *fmt, ...)
> static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries,
> const enum kfence_error_type *type)
> {
> - char buf[64];
> + char _buf[64];
> int skipnr, fallback = 0;
>
> if (type) {
> @@ -65,7 +65,11 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries
> }
>
> for (skipnr = 0; skipnr < num_entries; skipnr++) {
> - int len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skipnr]);
> + char *buf = _buf;
> + int len = scnprintf(_buf, sizeof(_buf), "%ps", (void *)stack_entries[skipnr]);
> +
> + if (_buf[0] == '.')
> + buf++, len--;
>
> if (str_has_prefix(buf, "kfence_") || str_has_prefix(buf, "__kfence_") ||
> !strncmp(buf, "__slab_free", len)) {
> ---
>
> Christophe
Marco Elver <[email protected]> writes:
...
>
> The choice is between:
>
> 1. ARCH_FUNC_PREFIX (as a matter of fact, the ARCH_FUNC_PREFIX patch
> is already in -mm). Perhaps we could optimize it further, by checking
> ARCH_FUNC_PREFIX in buf, and advancing buf like you propose, but I'm
> not sure it's worth worrying about.
>
> 2. The dynamic solution that I proposed that does not use a hard-coded
> '.' (or some variation thereof).
>
> Please tell me which solution you prefer, 1 or 2 -- I'd like to stop
> bikeshedding here. If there's a compelling argument for hard-coding
> the '.' in non-arch code, please clarify, but otherwise I'd like to
> keep arch-specific things out of generic code.
It's your choice, I was just trying to minimise the size of the wart you
have to carry in kfence code to deal with it.
The ARCH_FUNC_PREFIX solution is fine by me.
cheers
On Fri, 5 Mar 2021 at 12:49, Michael Ellerman <[email protected]> wrote:
> Marco Elver <[email protected]> writes:
> ...
> >
> > The choice is between:
> >
> > 1. ARCH_FUNC_PREFIX (as a matter of fact, the ARCH_FUNC_PREFIX patch
> > is already in -mm). Perhaps we could optimize it further, by checking
> > ARCH_FUNC_PREFIX in buf, and advancing buf like you propose, but I'm
> > not sure it's worth worrying about.
> >
> > 2. The dynamic solution that I proposed that does not use a hard-coded
> > '.' (or some variation thereof).
> >
> > Please tell me which solution you prefer, 1 or 2 -- I'd like to stop
> > bikeshedding here. If there's a compelling argument for hard-coding
> > the '.' in non-arch code, please clarify, but otherwise I'd like to
> > keep arch-specific things out of generic code.
>
> It's your choice, I was just trying to minimise the size of the wart you
> have to carry in kfence code to deal with it.
>
> The ARCH_FUNC_PREFIX solution is fine by me.
Thank you -- the ARCH_FUNC_PREFIX version is already in -mm, so let's
keep it. It's purely static vs the other options. Should another
debugging tool need something similar we can revisit whether to change
or move it.
Thanks,
-- Marco