tracing: Show real address instead of hashed pointer

To help debugging kernel, show real address for trace event arguments in tracefs/trace{,pipe} instead of hashed pointer value.

Since ftrace human-readable format uses vsprintf(), all %p are translated to hash values instead of pointer address.

However, when debugging the kernel, raw address value gives a hint when comparing with the memory mapping in the kernel. (Those are sometimes used with crash log, which is not hashed too) So converting %p with %px when calling trace_seq_printf().

Moreover, this is not improving the security because the tracefs can be used only by root user and the raw address values are readable from tracefs/percpu/cpu*/trace_pipe_raw file.

Signed-off-by Masami Hiramatsu <[email protected]>

I have encountered the following crash on a couple of our ARM64 Jetson platforms and bisect is pointing to this change. The crash I am seeing is on boot when I am directing the trace prints to the console by adding 'tp_printk trace_event="cpu_frequency,cpu_frequency_limits"' to the kernel command line and enabling CONFIG_BOOTTIME_TRACING. Reverting this change does fix the problem. Let me know if you have any thoughts.

Quoted 6 lines · On Mon, 19 Apr 2021 14:08:14 +0100 Jon Hunter <[email protected]> wrote:

I have encountered the following crash on a couple of our ARM64 Jetson platforms and bisect is pointing to this change. The crash I am seeing is on boot when I am directing the trace prints to the console by adding 'tp_printk trace_event="cpu_frequency,cpu_frequency_limits"' to the kernel command line and enabling CONFIG_BOOTTIME_TRACING. Reverting this change does fix the problem. Let me know if you have any thoughts.

Thanks for the report. I was able to reproduce this on x86 as well.

It's the tp_printk that's the problem. Does this fix it for you?

-- Steve

kernel/trace/trace.c +6 -2

index 66a4ad93b5e9..f1ce4be7a499 100644
@@ -3580,7 +3580,11 @@ static char *trace_iter_expand_format(struct trace_iterator *iter)
 {
 	char *tmp;
 
-	if (iter->fmt == static_fmt_buf)
+	/*
+	 * iter->tr is NULL when used with tp_printk, which makes
+	 * this get called where it is not safe to call krealloc().
+	 */
+	if (!iter->tr || iter->fmt == static_fmt_buf)
 		return NULL;
 
 	tmp = krealloc(iter->fmt, iter->fmt_size + STATIC_FMT_BUF_SIZE,

@@ -3799,7 +3803,7 @@ const char *trace_event_format(struct trace_iterator *iter, const char *fmt)
 	if (WARN_ON_ONCE(!fmt))
 		return fmt;
 
-	if (iter->tr->trace_flags & TRACE_ITER_HASH_PTR)
+	if (!iter->tr || iter->tr->trace_flags & TRACE_ITER_HASH_PTR)
 		return fmt;
 
 	p = fmt;

Add tracefs/options/hash-ptr option to show hashed pointer value by %p in event printk format string.

For the security reason, normal printk will show the hashed pointer value (encrypted by random number) with %p to printk buffer to hide the real address. But the tracefs/trace always shows real address for debug. To bridge those outputs, add an option to switch the output format. Ftrace users can use it to find the hashed value corresponding to the real address in trace log.

Signed-off-by Masami Hiramatsu <[email protected]>

---
 Documentation/trace/ftrace.rst |    6 ++++++
 kernel/trace/trace.c           |    3 +++
 kernel/trace/trace.h           |    1 +
 3 files changed, 10 insertions(+)

Documentation/trace/ftrace.rst +0 -0

index 87cf5c010d5d..62c98e9bbdd9 100644

Documentation/trace/ftrace.rst +0 -0

   record-cmd
 	When any event or tracer is enabled, a hook is enabled
 	in the sched_switch trace point to fill comm cache

kernel/trace/trace.c +3 -0

index 75395293d8df..b88cccf224cd 100644
@@ -3543,6 +3543,9 @@ const char *trace_event_format(struct trace_iterator *iter, const char *fmt)
 	if (WARN_ON_ONCE(!fmt))
 		return fmt;
 
+	if (iter->tr->trace_flags & TRACE_ITER_HASH_PTR)
+		return fmt;
+
 	p = fmt;
 	new_fmt = q = iter->fmt;
 	while (*p) {

kernel/trace/trace.h +1 -0

index 524502d1f60a..c34187bd22a9 100644
@@ -1347,6 +1347,7 @@ extern int trace_get_user(struct trace_parser *parser, const char __user *ubuf,
 		C(MARKERS,		"markers"),		\
 		C(EVENT_FORK,		"event-fork"),		\
 		C(PAUSE_ON_TRACE,	"pause-on-trace"),	\
+		C(HASH_PTR,		"hash-ptr"),	/* Print hashed pointer */ \
 		FUNCTION_FLAGS					\
 		FGRAPH_FLAGS					\
 		STACK_FLAGS					\

Hi Masami,

I noticed theses sitting in my patchwork and I said I was going to hold off to the next merge window, and these got pushed down in my stack :-/

Quoted 23 lines · On Thu, 15 Oct 2020 23:55:25 +0900 Masami Hiramatsu <[email protected]> wrote:

Add tracefs/options/hash-ptr option to show hashed pointer value by %p in event printk format string.

For the security reason, normal printk will show the hashed pointer value (encrypted by random number) with %p to printk buffer to hide the real address. But the tracefs/trace always shows real address for debug. To bridge those outputs, add an option to switch the output format. Ftrace users can use it to find the hashed value corresponding to the real address in trace log.

Signed-off-by Masami Hiramatsu <[email protected]>

---
 Documentation/trace/ftrace.rst |    6 ++++++
 kernel/trace/trace.c           |    3 +++
 kernel/trace/trace.h           |    1 +
 3 files changed, 10 insertions(+)

Documentation/trace/ftrace.rst +0 -0

index 87cf5c010d5d..62c98e9bbdd9 100644

Documentation/trace/ftrace.rst Here are the available options: · line 1167

Quoted 9 lines

Documentation/trace/ftrace.rst +6 -0

@@ -1159,6 +1159,12 @@ Here are the available options:
 	This simulates the original behavior of the trace file.
 	When the file is closed, tracing will be enabled again.
 
+  hash-ptr
+        When set, "%p" in the event printk format displays the
+        hashed pointer value instead of real address.
+        This will be useful if you want to find out which hashed
+        value is corresponding to the real value in trace log.
+

I'm thinking of making this the default. I'll add a patch to make it enabled by default "for security reasons", but still allow people to clear it this value.

Are you OK with that?

-- Steve

Quoted 29 lines

Documentation/trace/ftrace.rst +0 -0

   record-cmd
 	When any event or tracer is enabled, a hook is enabled
 	in the sched_switch trace point to fill comm cache

kernel/trace/trace.c +3 -0

index 75395293d8df..b88cccf224cd 100644
@@ -3543,6 +3543,9 @@ const char *trace_event_format(struct trace_iterator *iter, const char *fmt)
 	if (WARN_ON_ONCE(!fmt))
 		return fmt;
 
+	if (iter->tr->trace_flags & TRACE_ITER_HASH_PTR)
+		return fmt;
+
 	p = fmt;
 	new_fmt = q = iter->fmt;
 	while (*p) {

kernel/trace/trace.h +1 -0

index 524502d1f60a..c34187bd22a9 100644
@@ -1347,6 +1347,7 @@ extern int trace_get_user(struct trace_parser *parser, const char __user *ubuf,
 		C(MARKERS,		"markers"),		\
 		C(EVENT_FORK,		"event-fork"),		\
 		C(PAUSE_ON_TRACE,	"pause-on-trace"),	\
+		C(HASH_PTR,		"hash-ptr"),	/* Print hashed pointer */ \
 		FUNCTION_FLAGS					\
 		FGRAPH_FLAGS					\
 		STACK_FLAGS					\

Hi,

Here is the 3rd version of the series for real address printing in trace log.

Here is the previous version, I've fixed [1/3] to use krealloc(), fix memory allocation error check and add __printf() attribute, according to Steve's comment.

https://lore.kernel.org/lkml/160275239876.115066.10891356497426857018.stgit@devnote2/

Since trace_seq_printf() use in-kernel vsprintf() at last, the %p is always converted to the hash value instead of real address.

For the dmesg it maybe secure, but for the ftrace, I think it is meaningless because

- tracefs is used by root user, so no need to hide it.
- tracefs user can access percpu/cpu*/trace_pipe_raw which stores real address on the trace buffer.
- external commands like perf doesn't convert to the hash value.

And when debugging kernel, we would like to know real address which tells us the address is in which area in the kernel by comparing with kernel memory mapping.

However, to compare the trace log with dmesg, we also need a bridging information. So 3/3 gives the options/hash-ptr knob which switches the output format.

Quoted 22 lines · On Thu, 15 Oct 2020 23:54:58 +0900 Masami Hiramatsu <[email protected]> wrote:

Hi,

Here is the 3rd version of the series for real address printing in trace log.

Here is the previous version, I've fixed [1/3] to use krealloc(), fix memory allocation error check and add __printf() attribute, according to Steve's comment.

https://lore.kernel.org/lkml/160275239876.115066.10891356497426857018.stgit@devnote2/

Since trace_seq_printf() use in-kernel vsprintf() at last, the %p is always converted to the hash value instead of real address.

For the dmesg it maybe secure, but for the ftrace, I think it is meaningless because

- tracefs is used by root user, so no need to hide it.
- tracefs user can access percpu/cpu*/trace_pipe_raw which stores real address on the trace buffer.
- external commands like perf doesn't convert to the hash value.

Quoted 8 lines

And when debugging kernel, we would like to know real address which tells us the address is in which area in the kernel by comparing with kernel memory mapping.

However, to compare the trace log with dmesg, we also need a bridging information. So 3/3 gives the options/hash-ptr knob which switches the output format.

Thanks Masami,

I'm going to hold off on adding this for this merge window, and look at applying it for the next window.