[PATCH 0/3] probes: Use trace_printk() in probe handlers

[PATCH 0/3] probes: Use trace_printk() in probe handlers

[Masami Hiramatsu (Google)]

Hi,

Here are patches to update the probe sample code to use trace_printk
instead of normal printk. Since the fprobe and kprobe/kretprobe handlers
can be called from somewhere where console is locked, using printk() is
basically unsafe. Only the unoptimized kprobe on x86 is safe because it
is ran with NMI context (in this case, the kernel uses printk_deferred()
automatically), but optimized kprobe/kretprobe/fprobe are not.

Thus, this series replaces those printk() (pr_*()) with trace_printk()
which should be safe to output the result into trace buffer, and use
trace_dump_stack() instead of stack_trace_print().

The similar issue had been reported by Tiezhu Yang [1] in 2023, but
it was pointed different reason, and not applicable to upstream.
I investigated it again.

[1] https://lore.kernel.org/all/d179086d-78d8-d0e3-e113-9072cffa55f4@loongson.cn/

Thank you,
---
base-commit: bc71431221f5ba8bb33918399552636e059c2c45

Masami Hiramatsu (Google) (3):
      samples/kprobes: Use trace_printk() in probe handlers
      samples/fprobe: Use trace_printk() and trace_dump_stack()
      docs: trace: Warn against using printk() in probe handlers


 Documentation/trace/fprobe.rst      |    5 +++
 Documentation/trace/kprobes.rst     |   11 +++++-
 samples/Kconfig                     |    4 +-
 samples/fprobe/fprobe_example.c     |   49 +++++--------------------
 samples/kprobes/kprobe_example.c    |   69 ++++++++++++++++++-----------------
 samples/kprobes/kretprobe_example.c |   10 +++--
 6 files changed, 66 insertions(+), 82 deletions(-)

--
Masami Hiramatsu (Google) <mhiramat@kernel.org>

[PATCH 1/3] samples/kprobes: Use trace_printk() in probe handlers

[Masami Hiramatsu (Google)]

From: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Probe handlers execute in atomic/non-preemptible contexts. Furthermore,
unless hit via an unoptimized breakpoint on certain architectures,
they do not run with in_nmi() set (e.g. jump-optimized kprobes,
ftrace-based kprobes, or kretprobe return handlers). Calling printk()
from probe handlers can directly attempt to acquire console and
scheduler locks (via console_unlock()), risking a deadlock if the
probed context or interrupted code already holds one of those locks.

Replace printk() (pr_info) in handler_pre(), handler_post(), and
ret_handler() with trace_printk(), and update the comments to direct
users to /sys/kernel/tracing/trace. Also update the stack backtrace
comment in kprobe_example to reference trace_dump_stack(0).

Also fix a minor format string typo ("p->addr," -> "p->addr =") in the
S390 pre and post handlers while touching those lines.

Additionally, update CONFIG_SAMPLE_KPROBES in samples/Kconfig to
depend on EVENT_TRACING so that the tracing subsystem is enabled
when building the samples.

Reported-by: Tiezhu Yang <yangtiezhu@loongson.cn>
Closes: https://lore.kernel.org/all/d179086d-78d8-d0e3-e113-9072cffa55f4@loongson.cn/
Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
 samples/Kconfig                     |    2 +
 samples/kprobes/kprobe_example.c    |   69 ++++++++++++++++++-----------------
 samples/kprobes/kretprobe_example.c |   10 +++--
 3 files changed, 41 insertions(+), 40 deletions(-)

diff --git a/samples/Kconfig b/samples/Kconfig
index 00eed83c07df..54414e57ff75 100644
--- a/samples/Kconfig
+++ b/samples/Kconfig
@@ -71,7 +71,7 @@ config SAMPLE_KOBJECT
 
 config SAMPLE_KPROBES
 	tristate "Build kprobes examples -- loadable modules only"
-	depends on KPROBES && m
+	depends on KPROBES && EVENT_TRACING && m
 	help
 	  This build several kprobes example modules.
 
diff --git a/samples/kprobes/kprobe_example.c b/samples/kprobes/kprobe_example.c
index 53ec6c8b8c40..0f516a2b04be 100644
--- a/samples/kprobes/kprobe_example.c
+++ b/samples/kprobes/kprobe_example.c
@@ -6,7 +6,7 @@
  * For more information on theory of operation of kprobes, see
  * Documentation/trace/kprobes.rst
  *
- * You will see the trace data in /var/log/messages and on the console
+ * You will see the trace data in /sys/kernel/tracing/trace
  * whenever kernel_clone() is invoked to create a new process.
  */
 
@@ -15,6 +15,7 @@
 #include <linux/kernel.h>
 #include <linux/module.h>
 #include <linux/kprobes.h>
+#include <linux/trace_printk.h>
 
 static char symbol[KSYM_NAME_LEN] = "kernel_clone";
 module_param_string(symbol, symbol, KSYM_NAME_LEN, 0644);
@@ -28,39 +29,39 @@ static struct kprobe kp = {
 static int __kprobes handler_pre(struct kprobe *p, struct pt_regs *regs)
 {
 #ifdef CONFIG_X86
-	pr_info("<%s> p->addr = 0x%p, ip = %lx, flags = 0x%lx\n",
-		p->symbol_name, p->addr, regs->ip, regs->flags);
+	trace_printk("<%s> p->addr = 0x%p, ip = %lx, flags = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->ip, regs->flags);
 #endif
 #ifdef CONFIG_PPC
-	pr_info("<%s> p->addr = 0x%p, nip = 0x%lx, msr = 0x%lx\n",
-		p->symbol_name, p->addr, regs->nip, regs->msr);
+	trace_printk("<%s> p->addr = 0x%p, nip = 0x%lx, msr = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->nip, regs->msr);
 #endif
 #ifdef CONFIG_MIPS
-	pr_info("<%s> p->addr = 0x%p, epc = 0x%lx, status = 0x%lx\n",
-		p->symbol_name, p->addr, regs->cp0_epc, regs->cp0_status);
+	trace_printk("<%s> p->addr = 0x%p, epc = 0x%lx, status = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->cp0_epc, regs->cp0_status);
 #endif
 #ifdef CONFIG_ARM64
-	pr_info("<%s> p->addr = 0x%p, pc = 0x%lx, pstate = 0x%lx\n",
-		p->symbol_name, p->addr, (long)regs->pc, (long)regs->pstate);
+	trace_printk("<%s> p->addr = 0x%p, pc = 0x%lx, pstate = 0x%lx\n",
+		     p->symbol_name, p->addr, (long)regs->pc, (long)regs->pstate);
 #endif
 #ifdef CONFIG_ARM
-	pr_info("<%s> p->addr = 0x%p, pc = 0x%lx, cpsr = 0x%lx\n",
-		p->symbol_name, p->addr, (long)regs->ARM_pc, (long)regs->ARM_cpsr);
+	trace_printk("<%s> p->addr = 0x%p, pc = 0x%lx, cpsr = 0x%lx\n",
+		     p->symbol_name, p->addr, (long)regs->ARM_pc, (long)regs->ARM_cpsr);
 #endif
 #ifdef CONFIG_RISCV
-	pr_info("<%s> p->addr = 0x%p, pc = 0x%lx, status = 0x%lx\n",
-		p->symbol_name, p->addr, regs->epc, regs->status);
+	trace_printk("<%s> p->addr = 0x%p, pc = 0x%lx, status = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->epc, regs->status);
 #endif
 #ifdef CONFIG_S390
-	pr_info("<%s> p->addr, 0x%p, ip = 0x%lx, flags = 0x%lx\n",
-		p->symbol_name, p->addr, regs->psw.addr, regs->flags);
+	trace_printk("<%s> p->addr = 0x%p, ip = 0x%lx, flags = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->psw.addr, regs->flags);
 #endif
 #ifdef CONFIG_LOONGARCH
-	pr_info("<%s> p->addr = 0x%p, era = 0x%lx, estat = 0x%lx\n",
-		p->symbol_name, p->addr, regs->csr_era, regs->csr_estat);
+	trace_printk("<%s> p->addr = 0x%p, era = 0x%lx, estat = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->csr_era, regs->csr_estat);
 #endif
 
-	/* A dump_stack() here will give a stack backtrace */
+	/* A trace_dump_stack(0) here will give a stack backtrace */
 	return 0;
 }
 
@@ -69,36 +70,36 @@ static void __kprobes handler_post(struct kprobe *p, struct pt_regs *regs,
 				unsigned long flags)
 {
 #ifdef CONFIG_X86
-	pr_info("<%s> p->addr = 0x%p, flags = 0x%lx\n",
-		p->symbol_name, p->addr, regs->flags);
+	trace_printk("<%s> p->addr = 0x%p, flags = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->flags);
 #endif
 #ifdef CONFIG_PPC
-	pr_info("<%s> p->addr = 0x%p, msr = 0x%lx\n",
-		p->symbol_name, p->addr, regs->msr);
+	trace_printk("<%s> p->addr = 0x%p, msr = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->msr);
 #endif
 #ifdef CONFIG_MIPS
-	pr_info("<%s> p->addr = 0x%p, status = 0x%lx\n",
-		p->symbol_name, p->addr, regs->cp0_status);
+	trace_printk("<%s> p->addr = 0x%p, status = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->cp0_status);
 #endif
 #ifdef CONFIG_ARM64
-	pr_info("<%s> p->addr = 0x%p, pstate = 0x%lx\n",
-		p->symbol_name, p->addr, (long)regs->pstate);
+	trace_printk("<%s> p->addr = 0x%p, pstate = 0x%lx\n",
+		     p->symbol_name, p->addr, (long)regs->pstate);
 #endif
 #ifdef CONFIG_ARM
-	pr_info("<%s> p->addr = 0x%p, cpsr = 0x%lx\n",
-		p->symbol_name, p->addr, (long)regs->ARM_cpsr);
+	trace_printk("<%s> p->addr = 0x%p, cpsr = 0x%lx\n",
+		     p->symbol_name, p->addr, (long)regs->ARM_cpsr);
 #endif
 #ifdef CONFIG_RISCV
-	pr_info("<%s> p->addr = 0x%p, status = 0x%lx\n",
-		p->symbol_name, p->addr, regs->status);
+	trace_printk("<%s> p->addr = 0x%p, status = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->status);
 #endif
 #ifdef CONFIG_S390
-	pr_info("<%s> p->addr, 0x%p, flags = 0x%lx\n",
-		p->symbol_name, p->addr, regs->flags);
+	trace_printk("<%s> p->addr = 0x%p, flags = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->flags);
 #endif
 #ifdef CONFIG_LOONGARCH
-	pr_info("<%s> p->addr = 0x%p, estat = 0x%lx\n",
-		p->symbol_name, p->addr, regs->csr_estat);
+	trace_printk("<%s> p->addr = 0x%p, estat = 0x%lx\n",
+		     p->symbol_name, p->addr, regs->csr_estat);
 #endif
 }
 
diff --git a/samples/kprobes/kretprobe_example.c b/samples/kprobes/kretprobe_example.c
index 65d6dcafd742..9dd5cf9a7432 100644
--- a/samples/kprobes/kretprobe_example.c
+++ b/samples/kprobes/kretprobe_example.c
@@ -14,9 +14,8 @@
  * Documentation/trace/kprobes.rst
  *
  * Build and insert the kernel module as done in the kprobe example.
- * You will see the trace data in /var/log/messages and on the console
- * whenever the probed function returns. (Some messages may be suppressed
- * if syslogd is configured to eliminate duplicate messages.)
+ * You will see the trace data in /sys/kernel/tracing/trace
+ * whenever the probed function returns.
  */
 
 #include <linux/kernel.h>
@@ -24,6 +23,7 @@
 #include <linux/kprobes.h>
 #include <linux/ktime.h>
 #include <linux/sched.h>
+#include <linux/trace_printk.h>
 
 static char func_name[KSYM_NAME_LEN] = "kernel_clone";
 module_param_string(func, func_name, KSYM_NAME_LEN, 0644);
@@ -63,8 +63,8 @@ static int ret_handler(struct kretprobe_instance *ri, struct pt_regs *regs)
 
 	now = ktime_get();
 	delta = ktime_to_ns(ktime_sub(now, data->entry_stamp));
-	pr_info("%s returned %lu and took %lld ns to execute\n",
-			func_name, retval, (long long)delta);
+	trace_printk("%s returned %lu and took %lld ns to execute\n",
+		     func_name, retval, (long long)delta);
 	return 0;
 }
 NOKPROBE_SYMBOL(ret_handler);

[PATCH 2/3] samples/fprobe: Use trace_printk() and trace_dump_stack()

[Masami Hiramatsu (Google)]

From: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Fprobe entry and exit callbacks execute in atomic context with
preemption disabled under ftrace recursion protection. Calling
printk() directly inside handlers can lead to deadlocks if console
or scheduler locks are already held by the probed or interrupted context.

Drop the use_trace module parameter and always use trace_printk()
for handler logging. In addition, replace stack_trace_print() (which
uses printk()) with trace_dump_stack(0) to output backtraces safely
to the ftrace buffer. Also update the module header comment to
reference /sys/kernel/tracing/trace.

Additionally, update CONFIG_SAMPLE_FPROBE in samples/Kconfig to
depend on EVENT_TRACING so that the tracing subsystem is enabled
when building the sample.

Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
 samples/Kconfig                 |    2 +-
 samples/fprobe/fprobe_example.c |   49 ++++++++-------------------------------
 2 files changed, 11 insertions(+), 40 deletions(-)

diff --git a/samples/Kconfig b/samples/Kconfig
index 54414e57ff75..744d991ea620 100644
--- a/samples/Kconfig
+++ b/samples/Kconfig
@@ -88,7 +88,7 @@ config SAMPLE_HW_BREAKPOINT
 
 config SAMPLE_FPROBE
 	tristate "Build fprobe examples -- loadable modules only"
-	depends on FPROBE && m
+	depends on FPROBE && EVENT_TRACING && m
 	help
 	  This builds a fprobe example module. This module has an option 'symbol'.
 	  You can specify a probed symbol or symbols separated with ','.
diff --git a/samples/fprobe/fprobe_example.c b/samples/fprobe/fprobe_example.c
index bfe98ce826f3..3b94839b3199 100644
--- a/samples/fprobe/fprobe_example.c
+++ b/samples/fprobe/fprobe_example.c
@@ -1,12 +1,12 @@
 // SPDX-License-Identifier: GPL-2.0-only
 /*
  * Here's a sample kernel module showing the use of fprobe to dump a
- * stack trace and selected registers when kernel_clone() is called.
+ * stack trace and function entry/exit when kernel_clone() is called.
  *
- * For more information on theory of operation of kprobes, see
- * Documentation/trace/kprobes.rst
+ * For more information on theory of operation of fprobe, see
+ * Documentation/trace/fprobe.rst
  *
- * You will see the trace data in /var/log/messages and on the console
+ * You will see the trace data in /sys/kernel/tracing/trace
  * whenever kernel_clone() is invoked to create a new process.
  */
 
@@ -15,10 +15,9 @@
 #include <linux/kernel.h>
 #include <linux/module.h>
 #include <linux/fprobe.h>
-#include <linux/sched/debug.h>
 #include <linux/slab.h>
+#include <linux/trace_printk.h>
 
-#define BACKTRACE_DEPTH 16
 #define MAX_SYMBOL_LEN 4096
 static struct fprobe sample_probe;
 static unsigned long nhit;
@@ -35,34 +34,14 @@ static bool stackdump = true;
 module_param(stackdump, bool, 0644);
 MODULE_PARM_DESC(stackdump, "Enable stackdump.");
 
-static bool use_trace = false;
-module_param(use_trace, bool, 0644);
-MODULE_PARM_DESC(use_trace, "Use trace_printk instead of printk. This is only for debugging.");
-
-static void show_backtrace(void)
-{
-	unsigned long stacks[BACKTRACE_DEPTH];
-	unsigned int len;
-
-	len = stack_trace_save(stacks, BACKTRACE_DEPTH, 2);
-	stack_trace_print(stacks, len, 24);
-}
-
 static int sample_entry_handler(struct fprobe *fp, unsigned long ip,
 				unsigned long ret_ip,
 				struct ftrace_regs *fregs, void *data)
 {
-	if (use_trace)
-		/*
-		 * This is just an example, no kernel code should call
-		 * trace_printk() except when actively debugging.
-		 */
-		trace_printk("Enter <%pS> ip = 0x%p\n", (void *)ip, (void *)ip);
-	else
-		pr_info("Enter <%pS> ip = 0x%p\n", (void *)ip, (void *)ip);
+	trace_printk("Enter <%pS> ip = 0x%p\n", (void *)ip, (void *)ip);
 	nhit++;
 	if (stackdump)
-		show_backtrace();
+		trace_dump_stack(0);
 	return 0;
 }
 
@@ -72,19 +51,11 @@ static void sample_exit_handler(struct fprobe *fp, unsigned long ip,
 {
 	unsigned long rip = ret_ip;
 
-	if (use_trace)
-		/*
-		 * This is just an example, no kernel code should call
-		 * trace_printk() except when actively debugging.
-		 */
-		trace_printk("Return from <%pS> ip = 0x%p to rip = 0x%p (%pS)\n",
-			(void *)ip, (void *)ip, (void *)rip, (void *)rip);
-	else
-		pr_info("Return from <%pS> ip = 0x%p to rip = 0x%p (%pS)\n",
-			(void *)ip, (void *)ip, (void *)rip, (void *)rip);
+	trace_printk("Return from <%pS> ip = 0x%p to rip = 0x%p (%pS)\n",
+		     (void *)ip, (void *)ip, (void *)rip, (void *)rip);
 	nhit++;
 	if (stackdump)
-		show_backtrace();
+		trace_dump_stack(0);
 }
 
 static int __init fprobe_init(void)

[PATCH 3/3] docs: trace: Warn against using printk() in probe handlers

[Masami Hiramatsu (Google)]

From: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Probe handlers (kprobes, kretprobes, and fprobes) execute in atomic or
non-preemptible contexts. Because handlers do not run in NMI context
(especially when jump-optimized or ftrace-based), calling printk()
directly can attempt to synchronously acquire console driver locks or
scheduler locks (via console_unlock()), risking a deadlock if the probed
or interrupted context already holds those locks.

Document this restriction in both kprobes.rst and fprobe.rst, and
recommend using trace_printk() instead to safely log messages to the
ftrace buffer.

Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
 Documentation/trace/fprobe.rst  |    5 +++++
 Documentation/trace/kprobes.rst |   11 +++++++++--
 2 files changed, 14 insertions(+), 2 deletions(-)

diff --git a/Documentation/trace/fprobe.rst b/Documentation/trace/fprobe.rst
index 46dd46a97c1f..72e0fd9e1808 100644
--- a/Documentation/trace/fprobe.rst
+++ b/Documentation/trace/fprobe.rst
@@ -101,6 +101,11 @@ handler.
 If the entry callback function returns !0, the corresponding exit callback
 will be cancelled.
 
+Since the callbacks run with preemption disabled under ftrace recursion
+protection, calling printk() or pr_*() from these callbacks is not safe
+and can cause deadlocks on console driver or scheduler locks. Use
+trace_printk() instead to log debugging output.
+
 @fp
         This is the address of `fprobe` data structure related to this handler.
         You can embed the `fprobe` to your data structure and get it by
diff --git a/Documentation/trace/kprobes.rst b/Documentation/trace/kprobes.rst
index 5e606730cec6..19c04a91a664 100644
--- a/Documentation/trace/kprobes.rst
+++ b/Documentation/trace/kprobes.rst
@@ -563,8 +563,8 @@ course, has no way to distinguish the deliberately injected faults
 from the accidental ones.  Don't drink and probe.
 
 Kprobes makes no attempt to prevent probe handlers from stepping on
-each other -- e.g., probing printk() and then calling printk() from a
-probe handler.  If a probe handler hits a probe, that second probe's
+each other -- e.g., probing trace_printk() and then calling trace_printk()
+from a probe handler.  If a probe handler hits a probe, that second probe's
 handlers won't be run in that instance, and the kprobe.nmissed member
 of the second probe will be incremented.
 
@@ -579,6 +579,13 @@ which depends on the architecture and optimization state.  (e.g.,
 kretprobe handlers and optimized kprobe handlers run without interrupt
 disabled on x86/x86-64).  In any case, your handler should not yield
 the CPU (e.g., by attempting to acquire a semaphore, or waiting I/O).
+Furthermore, probe handlers should avoid calling printk() or pr_*().
+Because probe handlers execute in atomic/non-preemptible contexts without
+being in NMI context (especially when jump-optimized or ftrace-based),
+calling printk() may attempt to synchronously acquire console driver locks
+or scheduler locks via console_unlock(), risking a deadlock if the probed
+or interrupted context already holds those locks. Use trace_printk()
+instead to safely output messages to the trace buffer.
 
 Since a return probe is implemented by replacing the return
 address with the trampoline's address, stack backtraces and calls