[PATCH 0/4] KASan: print output directly to stderr

[PATCH 0/4] KASan: print output directly to stderr

[Ahmad Fatoum]

I recently hunted down a heap memory corruption and this was somewhat
complicated by KASan and dump_stack() themselves allocating memory
off the heap. This series switches them to directly write to the
consoles associated with stderr, while skipping the log.

Ahmad Fatoum (4):
  ARM: unwind: don't allocate while printing stack trace
  ARM64: backtrace: print stacktrace to stderr
  KASan: only print to stderr
  KASan: don't allocate memory while printing report

 arch/arm/lib32/unwind.c     | 20 ++++++++++----------
 arch/arm/lib64/stacktrace.c |  6 +++---
 lib/kasan/generic.c         |  2 --
 lib/kasan/report.c          | 22 +++++++++++-----------
 4 files changed, 24 insertions(+), 26 deletions(-)

-- 
2.39.2

[PATCH 1/4] ARM: unwind: don't allocate while printing stack trace

[Ahmad Fatoum]

Calling dump_stack() in response to failing assertions can be useful to
pinpoint where things started going awry. This is also done in TLSF
code, but dump_stack actually calls malloc, because it uses the logging
functions instead of printing directly to console.

To avoid circular dependencies and dump_stack() falsifying debugging
results, let's use eprintf instead of pr_*: That way, the output still
makes it to stderr, but it's no longer logged. This also removes the
orange WARNING: prefix, but that can be added back if needed.

Signed-off-by: Ahmad Fatoum <a.fatoum@pengutronix.de>
---
 arch/arm/lib32/unwind.c | 20 ++++++++++----------
 1 file changed, 10 insertions(+), 10 deletions(-)

diff --git a/arch/arm/lib32/unwind.c b/arch/arm/lib32/unwind.c
index 6f73cb1b7300..c355bba1b7a4 100644
--- a/arch/arm/lib32/unwind.c
+++ b/arch/arm/lib32/unwind.c
@@ -65,9 +65,9 @@ static void dump_backtrace_entry(unsigned long where, unsigned long from,
 				 unsigned long frame)
 {
 #ifdef CONFIG_KALLSYMS
-	pr_warning("[<%08lx>] (%pS) from [<%08lx>] (%pS)\n", where, (void *)where, from, (void *)from);
+	eprintf("[<%08lx>] (%pS) from [<%08lx>] (%pS)\n", where, (void *)where, from, (void *)from);
 #else
-	pr_warning("Function entered at [<%08lx>] from [<%08lx>]\n", where, from);
+	eprintf("Function entered at [<%08lx>] from [<%08lx>]\n", where, from);
 #endif
 }
 
@@ -124,7 +124,7 @@ static const struct unwind_idx *search_index(unsigned long addr,
 	if (likely(start->addr_offset <= addr_prel31))
 		return start;
 	else {
-		pr_warning("unwind: Unknown symbol address %08lx\n", addr);
+		eprintf("unwind: Unknown symbol address %08lx\n", addr);
 		return NULL;
 	}
 }
@@ -177,7 +177,7 @@ static unsigned long unwind_get_byte(struct unwind_ctrl_block *ctrl)
 	unsigned long ret;
 
 	if (ctrl->entries <= 0) {
-		pr_warning("unwind: Corrupt unwind table\n");
+		eprintf("unwind: Corrupt unwind table\n");
 		return 0;
 	}
 
@@ -214,7 +214,7 @@ static int unwind_exec_insn(struct unwind_ctrl_block *ctrl)
 		insn = (insn << 8) | unwind_get_byte(ctrl);
 		mask = insn & 0x0fff;
 		if (mask == 0) {
-			pr_warning("unwind: 'Refuse to unwind' instruction %04lx\n",
+			eprintf("unwind: 'Refuse to unwind' instruction %04lx\n",
 				   insn);
 			return -URC_FAILURE;
 		}
@@ -253,7 +253,7 @@ static int unwind_exec_insn(struct unwind_ctrl_block *ctrl)
 		int reg = 0;
 
 		if (mask == 0 || mask & 0xf0) {
-			pr_warning("unwind: Spare encoding %04lx\n",
+			eprintf("unwind: Spare encoding %04lx\n",
 			       (insn << 8) | mask);
 			return -URC_FAILURE;
 		}
@@ -271,7 +271,7 @@ static int unwind_exec_insn(struct unwind_ctrl_block *ctrl)
 
 		ctrl->vrs[SP] += 0x204 + (uleb128 << 2);
 	} else {
-		pr_warning("unwind: Unhandled instruction %02lx\n", insn);
+		eprintf("unwind: Unhandled instruction %02lx\n", insn);
 		return -URC_FAILURE;
 	}
 
@@ -303,7 +303,7 @@ int unwind_frame(struct stackframe *frame)
 
 	idx = unwind_find_idx(frame->pc);
 	if (!idx) {
-		pr_warning("unwind: Index not found %08lx\n", frame->pc);
+		eprintf("unwind: Index not found %08lx\n", frame->pc);
 		return -URC_FAILURE;
 	}
 
@@ -322,7 +322,7 @@ int unwind_frame(struct stackframe *frame)
 		/* only personality routine 0 supported in the index */
 		ctrl.insn = &idx->insn;
 	else {
-		pr_warning("unwind: Unsupported personality routine %08lx in the index at %p\n",
+		eprintf("unwind: Unsupported personality routine %08lx in the index at %p\n",
 			   idx->insn, idx);
 		return -URC_FAILURE;
 	}
@@ -335,7 +335,7 @@ int unwind_frame(struct stackframe *frame)
 		ctrl.byte = 1;
 		ctrl.entries = 1 + ((*ctrl.insn & 0x00ff0000) >> 16);
 	} else {
-		pr_warning("unwind: Unsupported personality routine %08lx at %p\n",
+		eprintf("unwind: Unsupported personality routine %08lx at %p\n",
 			   *ctrl.insn, ctrl.insn);
 		return -URC_FAILURE;
 	}
-- 
2.39.2

[PATCH 2/4] ARM64: backtrace: print stacktrace to stderr

[Ahmad Fatoum]

Rule of thumb is to print interactive output to stdout and status
messages to stderr. A stack dump falls into the latter category and part
of the stack trace is already printed to stderr, because of use of the
logging functions, which always prints there.

Signed-off-by: Ahmad Fatoum <a.fatoum@pengutronix.de>
---
 arch/arm/lib64/stacktrace.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/arch/arm/lib64/stacktrace.c b/arch/arm/lib64/stacktrace.c
index db5691a6098c..76aec734e135 100644
--- a/arch/arm/lib64/stacktrace.c
+++ b/arch/arm/lib64/stacktrace.c
@@ -40,9 +40,9 @@ int unwind_frame(struct stackframe *frame)
 static void dump_backtrace_entry(unsigned long where, unsigned long from)
 {
 #ifdef CONFIG_KALLSYMS
-	printf("[<%08lx>] (%pS) from [<%08lx>] (%pS)\n", where, (void *)where, from, (void *)from);
+	eprintf("[<%08lx>] (%pS) from [<%08lx>] (%pS)\n", where, (void *)where, from, (void *)from);
 #else
-	printf("Function entered at [<%08lx>] from [<%08lx>]\n", where, from);
+	eprintf("Function entered at [<%08lx>] from [<%08lx>]\n", where, from);
 #endif
 }
 
@@ -60,7 +60,7 @@ void unwind_backtrace(struct pt_regs *regs)
 		frame.pc = (unsigned long)unwind_backtrace;
 	}
 
-	printf("Call trace:\n");
+	eprintf("Call trace:\n");
 	while (1) {
 		unsigned long where = frame.pc;
 		int ret;
-- 
2.39.2

[PATCH 3/4] KASan: only print to stderr

[Ahmad Fatoum]

Part of KASan output, like the stack trace, is already printed to
stderr, while some others are printed to stdout. Let's print everything
to stderr as not to complicate debugging when stdout and stderr go to
different consoles.

Signed-off-by: Ahmad Fatoum <a.fatoum@pengutronix.de>
---
 lib/kasan/report.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/kasan/report.c b/lib/kasan/report.c
index a67ba8c108f5..3d8f0c3b5162 100644
--- a/lib/kasan/report.c
+++ b/lib/kasan/report.c
@@ -138,7 +138,7 @@ static void print_shadow_for_address(const void *addr)
 			shadow_buf, SHADOW_BYTES_PER_ROW, 0);
 
 		if (row_is_guilty(shadow_row, shadow))
-			printf("%*c\n",
+			eprintf("%*c\n",
 				shadow_pointer_offset(shadow_row, shadow),
 				'^');
 
-- 
2.39.2

[PATCH 4/4] KASan: don't allocate memory while printing report

[Ahmad Fatoum]

The logging functions call the pr_* family of functions, which not only
add pretty-colored prefix, but also allocate memory appending to the
log.

While KASAN protects against recursion while printing the log, this can
falsify debugging results, so let's ensure, we only print to stderr and
nothing more.

Signed-off-by: Ahmad Fatoum <a.fatoum@pengutronix.de>
---
 lib/kasan/generic.c |  2 --
 lib/kasan/report.c  | 20 ++++++++++----------
 2 files changed, 10 insertions(+), 12 deletions(-)

diff --git a/lib/kasan/generic.c b/lib/kasan/generic.c
index 1eccacf2b4b0..3709b8da9aae 100644
--- a/lib/kasan/generic.c
+++ b/lib/kasan/generic.c
@@ -14,8 +14,6 @@
  *
  */
 
-#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt
-
 #include <common.h>
 
 #include "kasan.h"
diff --git a/lib/kasan/report.c b/lib/kasan/report.c
index 3d8f0c3b5162..f701e5fa2ac9 100644
--- a/lib/kasan/report.c
+++ b/lib/kasan/report.c
@@ -48,9 +48,9 @@ EXPORT_SYMBOL_GPL(kasan_restore_multi_shot);
 
 static void print_error_description(struct kasan_access_info *info)
 {
-	pr_err("BUG: KASAN: %s in %pS\n",
+	eprintf("BUG: KASAN: %s in %pS\n",
 		get_bug_type(info), (void *)info->ip);
-	pr_err("%s of size %zu at addr %px\n",
+	eprintf("%s of size %zu at addr %px\n",
 		info->is_write ? "Write" : "Read", info->access_size,
 		info->access_addr);
 }
@@ -67,12 +67,12 @@ static void start_report(unsigned long *flags)
 	 * Make sure we don't end up in loop.
 	 */
 	kasan_disable_current();
-	pr_err("==================================================================\n");
+	eprintf("==================================================================\n");
 }
 
 static void end_report(unsigned long *flags)
 {
-	pr_err("==================================================================\n");
+	eprintf("==================================================================\n");
 	kasan_enable_current();
 }
 
@@ -86,11 +86,11 @@ static inline bool kernel_or_module_addr(const void *addr)
 static void print_address_description(void *addr, u8 tag)
 {
 	dump_stack();
-	pr_err("\n");
+	eprintf("\n");
 
 	if (kernel_or_module_addr(addr)) {
-		pr_err("The buggy address belongs to the variable:\n");
-		pr_err(" %pS\n", addr);
+		eprintf("The buggy address belongs to the variable:\n");
+		eprintf(" %pS\n", addr);
 	}
 }
 
@@ -118,7 +118,7 @@ static void print_shadow_for_address(const void *addr)
 					SHADOW_BYTES_PER_ROW)
 		- SHADOW_ROWS_AROUND_ADDR * SHADOW_BYTES_PER_ROW;
 
-	pr_err("Memory state around the buggy address:\n");
+	eprintf("Memory state around the buggy address:\n");
 
 	for (i = -SHADOW_ROWS_AROUND_ADDR; i <= SHADOW_ROWS_AROUND_ADDR; i++) {
 		const void *kaddr = kasan_shadow_to_mem(shadow_row);
@@ -181,11 +181,11 @@ static void __kasan_report(unsigned long addr, size_t size, bool is_write,
 	start_report(&flags);
 
 	print_error_description(&info);
-	pr_err("\n");
+	eprintf("\n");
 
 	if (addr_has_shadow(untagged_addr)) {
 		print_address_description(untagged_addr, get_tag(tagged_addr));
-		pr_err("\n");
+		eprintf("\n");
 		print_shadow_for_address(info.first_bad_addr);
 	} else {
 		dump_stack();
-- 
2.39.2

Re: [PATCH 0/4] KASan: print output directly to stderr

[Sascha Hauer]

On Mon, Sep 11, 2023 at 02:56:15PM +0200, Ahmad Fatoum wrote:
> I recently hunted down a heap memory corruption and this was somewhat
> complicated by KASan and dump_stack() themselves allocating memory
> off the heap. This series switches them to directly write to the
> consoles associated with stderr, while skipping the log.
> 
> Ahmad Fatoum (4):
>   ARM: unwind: don't allocate while printing stack trace
>   ARM64: backtrace: print stacktrace to stderr
>   KASan: only print to stderr
>   KASan: don't allocate memory while printing report

Applied, thanks

Sascha

> 
>  arch/arm/lib32/unwind.c     | 20 ++++++++++----------
>  arch/arm/lib64/stacktrace.c |  6 +++---
>  lib/kasan/generic.c         |  2 --
>  lib/kasan/report.c          | 22 +++++++++++-----------
>  4 files changed, 24 insertions(+), 26 deletions(-)
> 
> -- 
> 2.39.2
> 
> 
> 

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |