[PATCH v3 0/3] tracing: Show real address instead of hashed pointer

[PATCH v3 0/3] tracing: Show real address instead of hashed pointer

[Masami Hiramatsu]

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.

Thank you,

---

Masami Hiramatsu (3):
      tracing: Show real address for trace event arguments
      tracing: Update the stage 3 of trace event macro comment
      tracing: Add ptr-hash option to show the hashed pointer value


 Documentation/trace/ftrace.rst |    6 +++
 include/linux/trace_events.h   |    4 ++
 include/trace/trace_events.h   |   31 +++++++++++------
 kernel/trace/trace.c           |   74 +++++++++++++++++++++++++++++++++++++++-
 kernel/trace/trace.h           |    3 ++
 kernel/trace/trace_output.c    |   12 ++++++
 6 files changed, 118 insertions(+), 12 deletions(-)

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

[PATCH v3 1/3] tracing: Show real address for trace event arguments

[Masami Hiramatsu]

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 <mhiramat@kernel.org>
---
 Changes in v3:
   - Use krealloc() and remove goto label.
   - Fix to add memory allocation failure check
   - Add __printf() attribute to enable the printf format check.
---
 include/linux/trace_events.h |    4 ++
 include/trace/trace_events.h |    2 +
 kernel/trace/trace.c         |   71 +++++++++++++++++++++++++++++++++++++++++-
 kernel/trace/trace.h         |    2 +
 kernel/trace/trace_output.c  |   12 +++++++
 5 files changed, 88 insertions(+), 3 deletions(-)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 5c6943354049..a71a766b571d 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -55,6 +55,8 @@ struct trace_event;
 
 int trace_raw_output_prep(struct trace_iterator *iter,
 			  struct trace_event *event);
+extern __printf(2, 3)
+void trace_event_printf(struct trace_iterator *iter, const char *fmt, ...);
 
 /*
  * The trace entry - the most basic unit of tracing. This is what
@@ -87,6 +89,8 @@ struct trace_iterator {
 	unsigned long		iter_flags;
 	void			*temp;	/* temp holder */
 	unsigned int		temp_size;
+	char			*fmt;	/* modified format holder */
+	unsigned int		fmt_size;
 
 	/* trace_seq for __print_flags() and __print_symbolic() etc. */
 	struct trace_seq	tmp_seq;
diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index 1bc3e7bba9a4..4ad9abf465b0 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.h
@@ -364,7 +364,7 @@ trace_raw_output_##call(struct trace_iterator *iter, int flags,		\
 	if (ret != TRACE_TYPE_HANDLED)					\
 		return ret;						\
 									\
-	trace_seq_printf(s, print);					\
+	trace_event_printf(iter, print);				\
 									\
 	return trace_handle_return(s);					\
 }									\
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 0806fa9f2815..75395293d8df 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3515,6 +3515,62 @@ __find_next_entry(struct trace_iterator *iter, int *ent_cpu,
 	return next;
 }
 
+#define STATIC_FMT_BUF_SIZE	128
+static char static_fmt_buf[STATIC_FMT_BUF_SIZE];
+
+static char *trace_iter_expand_format(struct trace_iterator *iter)
+{
+	char *tmp;
+
+	if (iter->fmt == static_fmt_buf)
+		return NULL;
+
+	tmp = krealloc(iter->fmt, iter->fmt_size + STATIC_FMT_BUF_SIZE,
+		       GFP_KERNEL);
+	if (tmp) {
+		iter->fmt_size += STATIC_FMT_BUF_SIZE;
+		iter->fmt = tmp;
+	}
+
+	return tmp;
+}
+
+const char *trace_event_format(struct trace_iterator *iter, const char *fmt)
+{
+	const char *p, *new_fmt;
+	char *q;
+
+	if (WARN_ON_ONCE(!fmt))
+		return fmt;
+
+	p = fmt;
+	new_fmt = q = iter->fmt;
+	while (*p) {
+		if (unlikely(q - new_fmt + 3 > iter->fmt_size)) {
+			if (!trace_iter_expand_format(iter))
+				return fmt;
+
+			q += iter->fmt - new_fmt;
+			new_fmt = iter->fmt;
+		}
+
+		*q++ = *p++;
+
+		/* Replace %p with %px */
+		if (p[-1] == '%') {
+			if (p[0] == '%') {
+				*q++ = *p++;
+			} else if (p[0] == 'p' && !isalnum(p[1])) {
+				*q++ = *p++;
+				*q++ = 'x';
+			}
+		}
+	}
+	*q = '\0';
+
+	return new_fmt;
+}
+
 #define STATIC_TEMP_BUF_SIZE	128
 static char static_temp_buf[STATIC_TEMP_BUF_SIZE];
 
@@ -4305,6 +4361,16 @@ __tracing_open(struct inode *inode, struct file *file, bool snapshot)
 	if (iter->temp)
 		iter->temp_size = 128;
 
+	/*
+	 * trace_event_printf() may need to modify given format
+	 * string to replace %p with %px so that it shows real address
+	 * instead of hash value. However, that is only for the event
+	 * tracing, other tracer may not need. Defer the allocation
+	 * until it is needed.
+	 */
+	iter->fmt = NULL;
+	iter->fmt_size = 0;
+
 	/*
 	 * We make a copy of the current tracer to avoid concurrent
 	 * changes on it while we are reading.
@@ -4456,6 +4522,7 @@ static int tracing_release(struct inode *inode, struct file *file)
 
 	mutex_destroy(&iter->mutex);
 	free_cpumask_var(iter->started);
+	kfree(iter->fmt);
 	kfree(iter->temp);
 	kfree(iter->trace);
 	kfree(iter->buffer_iter);
@@ -9286,9 +9353,11 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode)
 
 	/* Simulate the iterator */
 	trace_init_global_iter(&iter);
-	/* Can not use kmalloc for iter.temp */
+	/* Can not use kmalloc for iter.temp and iter.fmt */
 	iter.temp = static_temp_buf;
 	iter.temp_size = STATIC_TEMP_BUF_SIZE;
+	iter.fmt = static_fmt_buf;
+	iter.fmt_size = STATIC_FMT_BUF_SIZE;
 
 	for_each_tracing_cpu(cpu) {
 		atomic_inc(&per_cpu_ptr(iter.array_buffer->data, cpu)->disabled);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 5b0e797cacdd..524502d1f60a 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -757,6 +757,8 @@ struct trace_entry *trace_find_next_entry(struct trace_iterator *iter,
 void trace_buffer_unlock_commit_nostack(struct trace_buffer *buffer,
 					struct ring_buffer_event *event);
 
+const char *trace_event_format(struct trace_iterator *iter, const char *fmt);
+
 int trace_empty(struct trace_iterator *iter);
 
 void *trace_find_next_entry_inc(struct trace_iterator *iter);
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 000e9dc224c6..861544204f5f 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -312,13 +312,23 @@ int trace_raw_output_prep(struct trace_iterator *iter,
 }
 EXPORT_SYMBOL(trace_raw_output_prep);
 
+void trace_event_printf(struct trace_iterator *iter, const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	trace_seq_vprintf(&iter->seq, trace_event_format(iter, fmt), ap);
+	va_end(ap);
+}
+EXPORT_SYMBOL(trace_event_printf);
+
 static int trace_output_raw(struct trace_iterator *iter, char *name,
 			    char *fmt, va_list ap)
 {
 	struct trace_seq *s = &iter->seq;
 
 	trace_seq_printf(s, "%s: ", name);
-	trace_seq_vprintf(s, fmt, ap);
+	trace_seq_vprintf(s, trace_event_format(iter, fmt), ap);
 
 	return trace_handle_return(s);
 }

[PATCH v3 2/3] tracing: Update the stage 3 of trace event macro comment

[Masami Hiramatsu]

Update the comment of the 3rd stage of trace event macro
expansion code. Now there are 2 macros makes different
trace_raw_output_<call>() functions.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 include/trace/trace_events.h |   29 ++++++++++++++++++++---------
 1 file changed, 20 insertions(+), 9 deletions(-)

diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index 4ad9abf465b0..a96301317842 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.h
@@ -231,9 +231,11 @@ TRACE_MAKE_SYSTEM_STR();
  * {
  *	struct trace_seq *s = &iter->seq;
  *	struct trace_event_raw_<call> *field; <-- defined in stage 1
- *	struct trace_entry *entry;
  *	struct trace_seq *p = &iter->tmp_seq;
- *	int ret;
+ *
+ * -------(for event)-------
+ *
+ *	struct trace_entry *entry;
  *
  *	entry = iter->ent;
  *
@@ -245,14 +247,23 @@ TRACE_MAKE_SYSTEM_STR();
  *	field = (typeof(field))entry;
  *
  *	trace_seq_init(p);
- *	ret = trace_seq_printf(s, "%s: ", <call>);
- *	if (ret)
- *		ret = trace_seq_printf(s, <TP_printk> "\n");
- *	if (!ret)
- *		return TRACE_TYPE_PARTIAL_LINE;
+ *	return trace_output_call(iter, <call>, <TP_printk> "\n");
  *
- *	return TRACE_TYPE_HANDLED;
- * }
+ * ------(or, for event class)------
+ *
+ *	int ret;
+ *
+ *	field = (typeof(field))iter->ent;
+ *
+ *	ret = trace_raw_output_prep(iter, trace_event);
+ *	if (ret != TRACE_TYPE_HANDLED)
+ *		return ret;
+ *
+ *	trace_event_printf(iter, <TP_printk> "\n");
+ *
+ *	return trace_handle_return(s);
+ * -------
+ *  }
  *
  * This is the method used to print the raw event to the trace
  * output format. Note, this is not needed if the data is read

[PATCH v3 3/3] tracing: Add ptr-hash option to show the hashed pointer value

[Masami Hiramatsu]

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 <mhiramat@kernel.org>
---
 Documentation/trace/ftrace.rst |    6 ++++++
 kernel/trace/trace.c           |    3 +++
 kernel/trace/trace.h           |    1 +
 3 files changed, 10 insertions(+)

diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
index 87cf5c010d5d..62c98e9bbdd9 100644
--- a/Documentation/trace/ftrace.rst
+++ b/Documentation/trace/ftrace.rst
@@ -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.
+
   record-cmd
 	When any event or tracer is enabled, a hook is enabled
 	in the sched_switch trace point to fill comm cache
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 75395293d8df..b88cccf224cd 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -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) {
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 524502d1f60a..c34187bd22a9 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -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					\

Re: [PATCH v3 0/3] tracing: Show real address instead of hashed pointer

[Steven Rostedt]

On Thu, 15 Oct 2020 23:54:58 +0900
Masami Hiramatsu <mhiramat@kernel.org> 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.
> 
> 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.

-- Steve

Re: [PATCH v3 0/3] tracing: Show real address instead of hashed pointer

[Masami Hiramatsu]

On Thu, 15 Oct 2020 11:49:31 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Thu, 15 Oct 2020 23:54:58 +0900
> Masami Hiramatsu <mhiramat@kernel.org> 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.
> > 
> > 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.

Thank you very much!
I got it, anyway I can use kernelshark or perf script to decode raw event
data, or I will use kprobe event to fetch the real address :)

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v3 3/3] tracing: Add ptr-hash option to show the hashed pointer value

[Steven Rostedt]

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 :-/


On Thu, 15 Oct 2020 23:55:25 +0900
Masami Hiramatsu <mhiramat@kernel.org> 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 <mhiramat@kernel.org>
> ---
>  Documentation/trace/ftrace.rst |    6 ++++++
>  kernel/trace/trace.c           |    3 +++
>  kernel/trace/trace.h           |    1 +
>  3 files changed, 10 insertions(+)
> 
> diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
> index 87cf5c010d5d..62c98e9bbdd9 100644
> --- a/Documentation/trace/ftrace.rst
> +++ b/Documentation/trace/ftrace.rst
> @@ -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



>    record-cmd
>  	When any event or tracer is enabled, a hook is enabled
>  	in the sched_switch trace point to fill comm cache
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 75395293d8df..b88cccf224cd 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -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) {
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 524502d1f60a..c34187bd22a9 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -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					\

Re: [PATCH v3 3/3] tracing: Add ptr-hash option to show the hashed pointer value

[Masami Hiramatsu]

On Fri, 12 Feb 2021 10:33:10 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> 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 :-/

Yeah, managing random topics is a hard task ;)

> 
> 
> On Thu, 15 Oct 2020 23:55:25 +0900
> Masami Hiramatsu <mhiramat@kernel.org> 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 <mhiramat@kernel.org>
> > ---
> >  Documentation/trace/ftrace.rst |    6 ++++++
> >  kernel/trace/trace.c           |    3 +++
> >  kernel/trace/trace.h           |    1 +
> >  3 files changed, 10 insertions(+)
> > 
> > diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
> > index 87cf5c010d5d..62c98e9bbdd9 100644
> > --- a/Documentation/trace/ftrace.rst
> > +++ b/Documentation/trace/ftrace.rst
> > @@ -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?

Yes, I agreed. It will be good for both security and debug reasons. :)

Thank you,

> 
> -- Steve
> 
> 
> 
> >    record-cmd
> >  	When any event or tracer is enabled, a hook is enabled
> >  	in the sched_switch trace point to fill comm cache
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index 75395293d8df..b88cccf224cd 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -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) {
> > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> > index 524502d1f60a..c34187bd22a9 100644
> > --- a/kernel/trace/trace.h
> > +++ b/kernel/trace/trace.h
> > @@ -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					\
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v3 1/3] tracing: Show real address for trace event arguments

[Jon Hunter]

On 15/10/2020 15:55, Masami Hiramatsu wrote:
> 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 <mhiramat@kernel.org>


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.

[    5.731301] Unable to handle kernel paging request at virtual address
fbf80000800040f8
[    5.739215] Mem abort info:
[    5.742004]   ESR = 0x96000004
[    5.745054]   EC = 0x25: DABT (current EL), IL = 32 bits
[    5.750359]   SET = 0, FnV = 0
[    5.753408]   EA = 0, S1PTW = 0
[    5.756543] Data abort info:
[    5.759416]   ISV = 0, ISS = 0x00000004
[    5.763244]   CM = 0, WnR = 0
[    5.766205] [fbf80000800040f8] address between user and kernel
address ranges
[    5.773332] Internal error: Oops: 96000004 [#1] PREEMPT SMP
[    5.778898] Modules linked in:
[    5.781952] CPU: 5 PID: 44 Comm: kworker/5:1 Tainted: G S
    5.12.0-rc8 #1
[    5.789861] Hardware name: NVIDIA Jetson TX2 Developer Kit (DT)
[    5.795773] Workqueue: events deferred_probe_work_func
[    5.800913] pstate: 60000085 (nZCv daIf -PAN -UAO -TCO BTYPE=--)
[    5.806911] pc : trace_event_format+0x28/0x1a0
[    5.811353] lr : trace_event_printf+0x50/0x98
[    5.815706] sp : ffff80001230b760
[    5.819014] x29: ffff80001230b760 x28: ffff800011e99c10
[    5.824324] x27: ffff000082d9ce18 x26: ffff8000115abd30
[    5.829630] x25: 0000000000000000 x24: ffff800011f3e040
[    5.834937] x23: ffff0000800050c8 x22: ffff000080004000
[    5.840242] x21: ffff800012276e38 x20: ffff000080004000
[    5.845549] x19: ffff800011e99948 x18: ffffffffffffffff
[    5.850854] x17: 0000000000000007 x16: 0000000000000001
[    5.856161] x15: ffff800011e99948 x14: ffff000082d15688
[    5.861468] x13: ffff000082d15687 x12: 0000000000000018
[    5.866774] x11: 0101010101010101 x10: 7f7f7f7f7f7f7f7f
[    5.872082] x9 : 0000000000000090 x8 : 0000000000000095
[    5.877389] x7 : 0000000000000014 x6 : ffff0000800050de
[    5.882695] x5 : 0000000000000000 x4 : 0000000000000000
[    5.888002] x3 : ffff80001230b820 x2 : 00000000ffffffd0
[    5.893308] x1 : ffff8000115abd30 x0 : fbf8000080004080
[    5.898615] Call trace:
[    5.901056]  trace_event_format+0x28/0x1a0
[    5.905147]  trace_event_printf+0x50/0x98
[    5.909151]  trace_raw_output_cpu_frequency_limits+0x48/0x60
[    5.914807]  trace_event_buffer_commit+0x1bc/0x288
[    5.919592]  trace_event_raw_event_cpu_frequency_limits+0x78/0xd0
[    5.925679]  __traceiter_cpu_frequency_limits+0x30/0x48
[    5.930899]  cpufreq_set_policy+0x15c/0x288
[    5.935079]  cpufreq_online+0x6f4/0x928
[    5.938910]  cpufreq_add_dev+0x78/0x88
[    5.942654]  subsys_interface_register+0x9c/0xf0
[    5.947266]  cpufreq_register_driver+0x170/0x218
[    5.951878]  tegra186_cpufreq_probe+0x164/0x350
[    5.956404]  platform_probe+0x90/0xd8
[    5.960061]  really_probe+0x20c/0x3e8
[    5.963720]  driver_probe_device+0x54/0xb8
[    5.967812]  __device_attach_driver+0x90/0xc0
[    5.972161]  bus_for_each_drv+0x70/0xc8
[    5.975992]  __device_attach+0xec/0x150
[    5.979825]  device_initial_probe+0x10/0x18
[    5.984002]  bus_probe_device+0x94/0xa0
[    5.987833]  deferred_probe_work_func+0x80/0xb8
[    5.992359]  process_one_work+0x1f0/0x4b8
[    5.996368]  worker_thread+0x20c/0x450
[    6.000112]  kthread+0x124/0x150
[    6.003337]  ret_from_fork+0x10/0x18
[    6.006913] Code: b4000b21 aa0003f6 f9400000 aa0103fa (b9407800)
[    6.013000] ---[ end trace eae1531f47c7c14a ]---

Thanks!
Jon

-- 
nvpublic

Re: [PATCH v3 1/3] tracing: Show real address for trace event arguments

[Steven Rostedt]

On Mon, 19 Apr 2021 14:08:14 +0100
Jon Hunter <jonathanh@nvidia.com> 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

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 66a4ad93b5e9..f1ce4be7a499 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -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;
@@ -9931,7 +9935,7 @@ void __init early_trace_init(void)
 {
 	if (tracepoint_printk) {
 		tracepoint_print_iter =
-			kmalloc(sizeof(*tracepoint_print_iter), GFP_KERNEL);
+			kzalloc(sizeof(*tracepoint_print_iter), GFP_KERNEL);
 		if (MEM_FAIL(!tracepoint_print_iter,
 			     "Failed to allocate trace iterator\n"))
 			tracepoint_printk = 0;

Re: [PATCH v3 1/3] tracing: Show real address for trace event arguments

[Jon Hunter]

On 19/04/2021 19:22, Steven Rostedt wrote:
> On Mon, 19 Apr 2021 14:08:14 +0100
> Jon Hunter <jonathanh@nvidia.com> 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
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 66a4ad93b5e9..f1ce4be7a499 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -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;
> @@ -9931,7 +9935,7 @@ void __init early_trace_init(void)
>  {
>  	if (tracepoint_printk) {
>  		tracepoint_print_iter =
> -			kmalloc(sizeof(*tracepoint_print_iter), GFP_KERNEL);
> +			kzalloc(sizeof(*tracepoint_print_iter), GFP_KERNEL);
>  		if (MEM_FAIL(!tracepoint_print_iter,
>  			     "Failed to allocate trace iterator\n"))
>  			tracepoint_printk = 0;
> 


Yes that works for me thanks!

Tested-by: Jon Hunter <jonathanh@nvidia.com>

Cheers!
Jon

-- 
nvpublic