* [PATCH] tracing: Fix trace output when pointer hash is disabled
@ 2024-12-10 22:25 Steven Rostedt
2024-12-11 10:53 ` kernel test robot
0 siblings, 1 reply; 2+ messages in thread
From: Steven Rostedt @ 2024-12-10 22:25 UTC (permalink / raw)
To: LKML, Linux trace kernel; +Cc: Masami Hiramatsu, Mathieu Desnoyers
From: Steven Rostedt <rostedt@goodmis.org>
The "%p" in the trace output is by default hashes the pointer. An option
was added to disable the hashing as reading trace output is a privileged
operation (just like reading kallsyms). When hashing is disabled, the
iter->fmt temp buffer is used to add "x" to "%p" into "%px" before sending
to the svnprintf() functions.
The problem with using iter->fmt, is that the trace_check_vprintf() that
makes sure that trace events "%pX" pointers are not dereferencing freed
addresses (and prints a warning if it does) also uses the iter->fmt to
save to and use to print out for the trace file. When the hash_ptr option
is disabled, the "%px" version is added to the iter->fmt buffer, and that
then is passed to the trace_check_vprintf() function that then uses the
iter->fmt as a temp buffer. Obviously this caused bad results.
This was noticed when backporting the persistent ring buffer to 5.10 and
added this code without the option being disabled by default, so it failed
one of the selftests because the sched_wakeup was missing the "comm"
field:
cat-907 [006] dN.4. 249.722403: sched_wakeup: comm= pid=74 prio=120 target_cpu=006
Instead of showing:
<idle>-0 [004] dNs6. 49.076464: sched_wakeup: comm=sshd-session pid=896 prio=120 target_cpu=0040
To fix this, change trace_check_vprintf() to modify the iter->fmt instead
of copying to it. If the fmt passed in is not the iter->fmt, first copy
the entire fmt string to iter->fmt and then iterate the iter->fmt. When
the format needs to be processed, perform the following like actions:
save_ch = p[i];
p[i] = '\0';
trace_seq_printf(&iter->seq, p, str);
p[i] = save_ch;
Cc: stable@vger.kernel.org
Fixes: efbbdaa22bb78 ("tracing: Show real address for trace event arguments")
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
kernel/trace/trace.c | 82 ++++++++++++++++++++++++++------------------
1 file changed, 49 insertions(+), 33 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index be62f0ea1814..ceae68b7466d 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3711,8 +3711,10 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
{
long text_delta = 0;
long data_delta = 0;
- const char *p = fmt;
const char *str;
+ char *p;
+ char save_ch;
+ char *buf = NULL;
bool good;
int i, j;
@@ -3737,6 +3739,19 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
if (iter->fmt == static_fmt_buf)
goto print;
+ if (fmt != iter->fmt) {
+ int len = strlen(fmt);
+ while (iter->fmt_size < len + 1) {
+ /*
+ * If we can't expand the copy buffer,
+ * just print it.
+ */
+ if (!trace_iter_expand_format(iter))
+ goto print;
+ }
+ strscpy(iter->fmt, fmt, iter->fmt_size);
+ }
+ p = iter->fmt;
while (*p) {
bool star = false;
int len = 0;
@@ -3748,14 +3763,6 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
* as well as %p[sS] if delta is non-zero
*/
for (i = 0; p[i]; i++) {
- if (i + 1 >= iter->fmt_size) {
- /*
- * If we can't expand the copy buffer,
- * just print it.
- */
- if (!trace_iter_expand_format(iter))
- goto print;
- }
if (p[i] == '\\' && p[i+1]) {
i++;
@@ -3788,10 +3795,11 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
if (!p[i])
break;
- /* Copy up to the %s, and print that */
- strncpy(iter->fmt, p, i);
- iter->fmt[i] = '\0';
- trace_seq_vprintf(&iter->seq, iter->fmt, ap);
+ /* Print up to the %s */
+ save_ch = p[i];
+ p[i] = '\0';
+ trace_seq_vprintf(&iter->seq, p, ap);
+ p[i] = save_ch;
/* Add delta to %pS pointers */
if (p[i+1] == 'p') {
@@ -3837,6 +3845,8 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
good = trace_safe_str(iter, str, star, len);
}
+ p += i;
+
/*
* If you hit this warning, it is likely that the
* trace event in question used %s on a string that
@@ -3849,41 +3859,47 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
if (WARN_ONCE(!good, "fmt: '%s' current_buffer: '%s'",
fmt, seq_buf_str(&iter->seq.seq))) {
int ret;
+#define TEMP_BUFSIZ 1024
+
+ if (!buf) {
+ char *buf = kmalloc(TEMP_BUFSIZ, GFP_KERNEL);
+ if (!buf) {
+ /* Need buffer to read address */
+ trace_seq_printf(&iter->seq, "(0x%px)[UNSAFE-MEMORY]", str);
+ goto print;
+ }
+ }
+ if (len >= TEMP_BUFSIZ)
+ len = TEMP_BUFSIZ - 1;
/* Try to safely read the string */
if (star) {
- if (len + 1 > iter->fmt_size)
- len = iter->fmt_size - 1;
- if (len < 0)
- len = 0;
- ret = copy_from_kernel_nofault(iter->fmt, str, len);
- iter->fmt[len] = 0;
- star = false;
+ ret = copy_from_kernel_nofault(buf, str, len);
+ buf[len] = 0;
} else {
- ret = strncpy_from_kernel_nofault(iter->fmt, str,
- iter->fmt_size);
+ ret = strncpy_from_kernel_nofault(buf, str, 1024);
}
if (ret < 0)
trace_seq_printf(&iter->seq, "(0x%px)", str);
else
- trace_seq_printf(&iter->seq, "(0x%px:%s)",
- str, iter->fmt);
- str = "[UNSAFE-MEMORY]";
- strcpy(iter->fmt, "%s");
+ trace_seq_printf(&iter->seq, "(0x%px:%s)", str, buf);
+ trace_seq_puts(&iter->seq, "[UNSAFE-MEMORY]");
} else {
- strncpy(iter->fmt, p + i, j + 1);
- iter->fmt[j+1] = '\0';
+ save_ch = p[j + 1];
+ p[j + 1] = '\0';
+ if (star)
+ trace_seq_printf(&iter->seq, p, len, str);
+ else
+ trace_seq_printf(&iter->seq, p, str);
+ p[j + 1] = save_ch;
}
- if (star)
- trace_seq_printf(&iter->seq, iter->fmt, len, str);
- else
- trace_seq_printf(&iter->seq, iter->fmt, str);
- p += i + j + 1;
+ p += j + 1;
}
print:
if (*p)
trace_seq_vprintf(&iter->seq, p, ap);
+ kfree(buf);
}
const char *trace_event_format(struct trace_iterator *iter, const char *fmt)
--
2.45.2
^ permalink raw reply related [flat|nested] 2+ messages in thread
* Re: [PATCH] tracing: Fix trace output when pointer hash is disabled
2024-12-10 22:25 [PATCH] tracing: Fix trace output when pointer hash is disabled Steven Rostedt
@ 2024-12-11 10:53 ` kernel test robot
0 siblings, 0 replies; 2+ messages in thread
From: kernel test robot @ 2024-12-11 10:53 UTC (permalink / raw)
To: Steven Rostedt, LKML, Linux trace kernel
Cc: llvm, oe-kbuild-all, Masami Hiramatsu, Mathieu Desnoyers
Hi Steven,
kernel test robot noticed the following build warnings:
[auto build test WARNING on linus/master]
[also build test WARNING on v6.13-rc2 next-20241211]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]
url: https://github.com/intel-lab-lkp/linux/commits/Steven-Rostedt/tracing-Fix-trace-output-when-pointer-hash-is-disabled/20241211-062827
base: linus/master
patch link: https://lore.kernel.org/r/20241210172533.04bcd5f7%40batman.local.home
patch subject: [PATCH] tracing: Fix trace output when pointer hash is disabled
config: i386-buildonly-randconfig-003-20241211 (https://download.01.org/0day-ci/archive/20241211/202412111800.LkbDgOfH-lkp@intel.com/config)
compiler: clang version 19.1.3 (https://github.com/llvm/llvm-project ab51eccf88f5321e7c60591c5546b254b6afab99)
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20241211/202412111800.LkbDgOfH-lkp@intel.com/reproduce)
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202412111800.LkbDgOfH-lkp@intel.com/
All warnings (new ones prefixed by >>):
In file included from kernel/trace/trace.c:15:
In file included from include/linux/ring_buffer.h:5:
In file included from include/linux/mm.h:2223:
include/linux/vmstat.h:518:36: warning: arithmetic between different enumeration types ('enum node_stat_item' and 'enum lru_list') [-Wenum-enum-conversion]
518 | return node_stat_name(NR_LRU_BASE + lru) + 3; // skip "nr_"
| ~~~~~~~~~~~ ^ ~~~
>> kernel/trace/trace.c:3749:8: warning: variable 'p' is used uninitialized whenever 'if' condition is true [-Wsometimes-uninitialized]
3749 | if (!trace_iter_expand_format(iter))
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace.c:3900:7: note: uninitialized use occurs here
3900 | if (*p)
| ^
kernel/trace/trace.c:3749:4: note: remove the 'if' if its condition is always false
3749 | if (!trace_iter_expand_format(iter))
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
3750 | goto print;
| ~~~~~~~~~~
kernel/trace/trace.c:3739:6: warning: variable 'p' is used uninitialized whenever 'if' condition is true [-Wsometimes-uninitialized]
3739 | if (iter->fmt == static_fmt_buf)
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace.c:3900:7: note: uninitialized use occurs here
3900 | if (*p)
| ^
kernel/trace/trace.c:3739:2: note: remove the 'if' if its condition is always false
3739 | if (iter->fmt == static_fmt_buf)
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
3740 | goto print;
| ~~~~~~~~~~
kernel/trace/trace.c:3724:6: warning: variable 'p' is used uninitialized whenever 'if' condition is true [-Wsometimes-uninitialized]
3724 | if (static_branch_unlikely(&trace_no_verify))
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
include/linux/jump_label.h:497:40: note: expanded from macro 'static_branch_unlikely'
497 | #define static_branch_unlikely(x) \
| ^
498 | ({ \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
499 | bool branch; \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
500 | if (__builtin_types_compatible_p(typeof(*x), struct static_key_true)) \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
501 | branch = arch_static_branch_jump(&(x)->key, false); \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
502 | else if (__builtin_types_compatible_p(typeof(*x), struct static_key_false)) \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
503 | branch = arch_static_branch(&(x)->key, false); \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
504 | else \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
505 | branch = ____wrong_branch_error(); \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
506 | unlikely_notrace(branch); \
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
507 | })
| ~~
kernel/trace/trace.c:3900:7: note: uninitialized use occurs here
3900 | if (*p)
| ^
kernel/trace/trace.c:3724:2: note: remove the 'if' if its condition is always false
3724 | if (static_branch_unlikely(&trace_no_verify))
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
3725 | goto print;
| ~~~~~~~~~~
kernel/trace/trace.c:3715:9: note: initialize the variable 'p' to silence this warning
3715 | char *p;
| ^
| = NULL
4 warnings generated.
vim +3749 kernel/trace/trace.c
3696
3697 /**
3698 * trace_check_vprintf - Check dereferenced strings while writing to the seq buffer
3699 * @iter: The iterator that holds the seq buffer and the event being printed
3700 * @fmt: The format used to print the event
3701 * @ap: The va_list holding the data to print from @fmt.
3702 *
3703 * This writes the data into the @iter->seq buffer using the data from
3704 * @fmt and @ap. If the format has a %s, then the source of the string
3705 * is examined to make sure it is safe to print, otherwise it will
3706 * warn and print "[UNSAFE MEMORY]" in place of the dereferenced string
3707 * pointer.
3708 */
3709 void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
3710 va_list ap)
3711 {
3712 long text_delta = 0;
3713 long data_delta = 0;
3714 const char *str;
3715 char *p;
3716 char save_ch;
3717 char *buf = NULL;
3718 bool good;
3719 int i, j;
3720
3721 if (WARN_ON_ONCE(!fmt))
3722 return;
3723
3724 if (static_branch_unlikely(&trace_no_verify))
3725 goto print;
3726
3727 /*
3728 * When the kernel is booted with the tp_printk command line
3729 * parameter, trace events go directly through to printk().
3730 * It also is checked by this function, but it does not
3731 * have an associated trace_array (tr) for it.
3732 */
3733 if (iter->tr) {
3734 text_delta = iter->tr->text_delta;
3735 data_delta = iter->tr->data_delta;
3736 }
3737
3738 /* Don't bother checking when doing a ftrace_dump() */
3739 if (iter->fmt == static_fmt_buf)
3740 goto print;
3741
3742 if (fmt != iter->fmt) {
3743 int len = strlen(fmt);
3744 while (iter->fmt_size < len + 1) {
3745 /*
3746 * If we can't expand the copy buffer,
3747 * just print it.
3748 */
> 3749 if (!trace_iter_expand_format(iter))
3750 goto print;
3751 }
3752 strscpy(iter->fmt, fmt, iter->fmt_size);
3753 }
3754 p = iter->fmt;
3755 while (*p) {
3756 bool star = false;
3757 int len = 0;
3758
3759 j = 0;
3760
3761 /*
3762 * We only care about %s and variants
3763 * as well as %p[sS] if delta is non-zero
3764 */
3765 for (i = 0; p[i]; i++) {
3766
3767 if (p[i] == '\\' && p[i+1]) {
3768 i++;
3769 continue;
3770 }
3771 if (p[i] == '%') {
3772 /* Need to test cases like %08.*s */
3773 for (j = 1; p[i+j]; j++) {
3774 if (isdigit(p[i+j]) ||
3775 p[i+j] == '.')
3776 continue;
3777 if (p[i+j] == '*') {
3778 star = true;
3779 continue;
3780 }
3781 break;
3782 }
3783 if (p[i+j] == 's')
3784 break;
3785
3786 if (text_delta && p[i+1] == 'p' &&
3787 ((p[i+2] == 's' || p[i+2] == 'S')))
3788 break;
3789
3790 star = false;
3791 }
3792 j = 0;
3793 }
3794 /* If no %s found then just print normally */
3795 if (!p[i])
3796 break;
3797
3798 /* Print up to the %s */
3799 save_ch = p[i];
3800 p[i] = '\0';
3801 trace_seq_vprintf(&iter->seq, p, ap);
3802 p[i] = save_ch;
3803
3804 /* Add delta to %pS pointers */
3805 if (p[i+1] == 'p') {
3806 unsigned long addr;
3807 char fmt[4];
3808
3809 fmt[0] = '%';
3810 fmt[1] = 'p';
3811 fmt[2] = p[i+2]; /* Either %ps or %pS */
3812 fmt[3] = '\0';
3813
3814 addr = va_arg(ap, unsigned long);
3815 addr += text_delta;
3816 trace_seq_printf(&iter->seq, fmt, (void *)addr);
3817
3818 p += i + 3;
3819 continue;
3820 }
3821
3822 /*
3823 * If iter->seq is full, the above call no longer guarantees
3824 * that ap is in sync with fmt processing, and further calls
3825 * to va_arg() can return wrong positional arguments.
3826 *
3827 * Ensure that ap is no longer used in this case.
3828 */
3829 if (iter->seq.full) {
3830 p = "";
3831 break;
3832 }
3833
3834 if (star)
3835 len = va_arg(ap, int);
3836
3837 /* The ap now points to the string data of the %s */
3838 str = va_arg(ap, const char *);
3839
3840 good = trace_safe_str(iter, str, star, len);
3841
3842 /* Could be from the last boot */
3843 if (data_delta && !good) {
3844 str += data_delta;
3845 good = trace_safe_str(iter, str, star, len);
3846 }
3847
3848 p += i;
3849
3850 /*
3851 * If you hit this warning, it is likely that the
3852 * trace event in question used %s on a string that
3853 * was saved at the time of the event, but may not be
3854 * around when the trace is read. Use __string(),
3855 * __assign_str() and __get_str() helpers in the TRACE_EVENT()
3856 * instead. See samples/trace_events/trace-events-sample.h
3857 * for reference.
3858 */
3859 if (WARN_ONCE(!good, "fmt: '%s' current_buffer: '%s'",
3860 fmt, seq_buf_str(&iter->seq.seq))) {
3861 int ret;
3862 #define TEMP_BUFSIZ 1024
3863
3864 if (!buf) {
3865 char *buf = kmalloc(TEMP_BUFSIZ, GFP_KERNEL);
3866 if (!buf) {
3867 /* Need buffer to read address */
3868 trace_seq_printf(&iter->seq, "(0x%px)[UNSAFE-MEMORY]", str);
3869 goto print;
3870 }
3871 }
3872 if (len >= TEMP_BUFSIZ)
3873 len = TEMP_BUFSIZ - 1;
3874
3875 /* Try to safely read the string */
3876 if (star) {
3877 ret = copy_from_kernel_nofault(buf, str, len);
3878 buf[len] = 0;
3879 } else {
3880 ret = strncpy_from_kernel_nofault(buf, str, 1024);
3881 }
3882 if (ret < 0)
3883 trace_seq_printf(&iter->seq, "(0x%px)", str);
3884 else
3885 trace_seq_printf(&iter->seq, "(0x%px:%s)", str, buf);
3886 trace_seq_puts(&iter->seq, "[UNSAFE-MEMORY]");
3887 } else {
3888 save_ch = p[j + 1];
3889 p[j + 1] = '\0';
3890 if (star)
3891 trace_seq_printf(&iter->seq, p, len, str);
3892 else
3893 trace_seq_printf(&iter->seq, p, str);
3894 p[j + 1] = save_ch;
3895 }
3896
3897 p += j + 1;
3898 }
3899 print:
3900 if (*p)
3901 trace_seq_vprintf(&iter->seq, p, ap);
3902 kfree(buf);
3903 }
3904
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2024-12-11 10:54 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-12-10 22:25 [PATCH] tracing: Fix trace output when pointer hash is disabled Steven Rostedt
2024-12-11 10:53 ` kernel test robot
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).