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

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

[Masami Hiramatsu]

Hi,

Here is the 2nd series of the real address printing in trace log.
Here is the 1st version, I've changed the implementation according
to Steve's comment.

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

This version has 3 patches, replacing %p to %px online, update trace_event.h
description and add an option to switch hashed ptr and real value on
trace log. Those are all new patches.

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   |    3 ++
 include/trace/trace_events.h   |   31 ++++++++++++++-------
 kernel/trace/trace.c           |   60 +++++++++++++++++++++++++++++++++++++++-
 kernel/trace/trace.h           |    3 ++
 kernel/trace/trace_output.c    |   12 +++++++-
 6 files changed, 103 insertions(+), 12 deletions(-)

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

[RFC PATCH v2 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>
---
 include/linux/trace_events.h |    3 ++
 include/trace/trace_events.h |    2 +-
 kernel/trace/trace.c         |   56 +++++++++++++++++++++++++++++++++++++++++-
 kernel/trace/trace.h         |    2 ++
 kernel/trace/trace_output.c  |   12 ++++++++-
 5 files changed, 72 insertions(+), 3 deletions(-)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 5c6943354049..3c474a3f64f2 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -55,6 +55,7 @@ struct trace_event;
 
 int trace_raw_output_prep(struct trace_iterator *iter,
 			  struct trace_event *event);
+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 +88,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..1ebcc83b1e23 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3515,6 +3515,47 @@ __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];
+
+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;
+retry:
+	p = fmt;
+	new_fmt = q = iter->fmt;
+	while (*p) {
+		if (unlikely(q - new_fmt + 3 > iter->fmt_size)) {
+			/* expand format buffer if needed */
+			if (iter->fmt == static_fmt_buf)
+				return fmt;
+
+			iter->fmt_size = iter->fmt_size ? iter->fmt_size * 2
+							: STATIC_FMT_BUF_SIZE;
+			kfree(iter->fmt);
+			iter->fmt = kmalloc(iter->fmt_size, GFP_KERNEL);
+			goto retry;
+		}
+		*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 +4346,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 +4507,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 +9338,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);
 }

[RFC PATCH v2 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

[RFC PATCH v2 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           |    4 ++++
 kernel/trace/trace.h           |    1 +
 3 files changed, 11 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 1ebcc83b1e23..414c40a579be 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3525,6 +3525,10 @@ 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;
+
 retry:
 	p = fmt;
 	new_fmt = q = iter->fmt;
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: [RFC PATCH v2 1/3] tracing: Show real address for trace event arguments

[Steven Rostedt]

On Thu, 15 Oct 2020 18:00:08 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> +#define STATIC_FMT_BUF_SIZE	128
> +static char static_fmt_buf[STATIC_FMT_BUF_SIZE];
> +
> +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;
> +retry:
> +	p = fmt;
> +	new_fmt = q = iter->fmt;
> +	while (*p) {
> +		if (unlikely(q - new_fmt + 3 > iter->fmt_size)) {
> +			/* expand format buffer if needed */
> +			if (iter->fmt == static_fmt_buf)
> +				return fmt;
> +
> +			iter->fmt_size = iter->fmt_size ? iter->fmt_size * 2
> +							: STATIC_FMT_BUF_SIZE;

Doubling may be too much, as fmt strings are not going to grow
exponentially.

> +			kfree(iter->fmt);
> +			iter->fmt = kmalloc(iter->fmt_size, GFP_KERNEL);

Need to test the return value of kmalloc. But I would use realloc instead,
and continue:

			char *tmp_fmt;
			unsigned int tmp_size;

			tmp_size = iter->fmt_size + STATIC_FMT_BUF_SIZE;

			tmp_fmt = krealloc(iter->fmt, tmp_size, GFP_KERNEL);
			if (!tmp_fmt)
				return fmt;

			q += tmp_fmt - new_fmt;
			new_fmt = iter->fmt = tmp_fmt;
			iter->fmt_size = tmp_size;

> +			goto retry;

Then you don't even need the retry, and just continue processing.

Also, if it fails to allocate, you still have the iter->fmt and fmt_size
intact and correct.

-- Steve

> +		}
> +		*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;
> +}
> +

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

[Masami Hiramatsu]

On Thu, 15 Oct 2020 09:09:55 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Thu, 15 Oct 2020 18:00:08 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > +#define STATIC_FMT_BUF_SIZE	128
> > +static char static_fmt_buf[STATIC_FMT_BUF_SIZE];
> > +
> > +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;
> > +retry:
> > +	p = fmt;
> > +	new_fmt = q = iter->fmt;
> > +	while (*p) {
> > +		if (unlikely(q - new_fmt + 3 > iter->fmt_size)) {
> > +			/* expand format buffer if needed */
> > +			if (iter->fmt == static_fmt_buf)
> > +				return fmt;
> > +
> > +			iter->fmt_size = iter->fmt_size ? iter->fmt_size * 2
> > +							: STATIC_FMT_BUF_SIZE;
> 
> Doubling may be too much, as fmt strings are not going to grow
> exponentially.

OK, then I just make it "+= STATIC_FMT_BUF_SIZE".

Actually, as far as I can see, the format string should be shorter than
128 bytes. If we see it is longer than that, it will be 2 lines in event
definition. And 128 + 128 = 256, which will be longer than 3 lines in 80
columns wide terminal. I guess no one want to write it. :)

> 
> > +			kfree(iter->fmt);
> > +			iter->fmt = kmalloc(iter->fmt_size, GFP_KERNEL);
> 
> Need to test the return value of kmalloc. But I would use realloc instead,
> and continue:

Good catch!

> 
> 			char *tmp_fmt;
> 			unsigned int tmp_size;
> 
> 			tmp_size = iter->fmt_size + STATIC_FMT_BUF_SIZE;
> 
> 			tmp_fmt = krealloc(iter->fmt, tmp_size, GFP_KERNEL);
> 			if (!tmp_fmt)
> 				return fmt;
> 
> 			q += tmp_fmt - new_fmt;
> 			new_fmt = iter->fmt = tmp_fmt;
> 			iter->fmt_size = tmp_size;
> 
> > +			goto retry;
> 
> Then you don't even need the retry, and just continue processing.
> 
> Also, if it fails to allocate, you still have the iter->fmt and fmt_size
> intact and correct.

OK, let me update it.

Thank you,

> 
> -- Steve
> 
> > +		}
> > +		*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;
> > +}
> > +


-- 
Masami Hiramatsu <mhiramat@kernel.org>