Re: [PATCH v3 1/3] tracing: Show real address for trace event arguments
On 19/04/2021 19:22, Steven Rostedt wrote:
> On Mon, 19 Apr 2021 14:08:14 +0100
> Jon Hunter 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
Cheers!
Jon
--
nvpublic
Re: [PATCH v3 1/3] tracing: Show real address for trace event arguments
On Mon, 19 Apr 2021 14:08:14 +0100
Jon Hunter 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
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
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
fbf8800040f8
[5.739215] Mem abort info:
[5.742004] ESR = 0x9604
[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 = 0x0004
[5.763244] CM = 0, WnR = 0
[5.766205] [fbf8800040f8] address between user and kernel
address ranges
[5.773332] Internal error: Oops: 9604 [#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: 6085 (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 : 80001230b760
[5.819014] x29: 80001230b760 x28: 800011e99c10
[5.824324] x27: 82d9ce18 x26: 8000115abd30
[5.829630] x25: x24: 800011f3e040
[5.834937] x23: 800050c8 x22: 80004000
[5.840242] x21: 800012276e38 x20: 80004000
[5.845549] x19: 800011e99948 x18:
[5.850854] x17: 0007 x16: 0001
[5.856161] x15: 800011e99948 x14: 82d15688
[5.861468] x13: 82d15687 x12: 0018
[5.866774] x11: 0101010101010101 x10: 7f7f7f7f7f7f7f7f
[5.872082] x9 : 0090 x8 : 0095
[5.877389] x7 : 0014 x6 : 800050de
[5.882695] x5 : x4 :
[5.888002] x3 : 80001230b820 x2 : ffd0
[5.893308] x1 : 8000115abd30 x0 : fbf880004080
[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 f940 aa0103fa (b9407800)
[6.013000] ---[ end trace eae1531f47c7c14a ]---
Thanks!
Jon
--
nvpublic
[PATCH v3 1/3] tracing: Show real address for trace event arguments
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
---
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 inttemp_size;
+ char*fmt; /* modified format holder */
+ unsigned intfmt_size;
/* trace_seq for __print_flags() and __print_symbolic() etc. */
struct trace_seqtmp_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_SIZE128
+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 =
