[PATCH] tracing: Don't log an error for the speculative field variable lookup

[PATCH] tracing: Don't log an error for the speculative field variable lookup

[Donggeun Yoo]

A hist trigger that installs and works leaves two errors behind:

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > \
      events/sched/sched_waking/trigger
  # echo 'my_synth u64 lat; int prio' > synthetic_events
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
      onmatch(sched.sched_waking).my_synth($wakeup_lat,prio)' > \
      events/sched/sched_switch/trigger
  # cat error_log
  hist:sched:sched_switch: error: Couldn't find field
  hist:sched:sched_switch: error: Couldn't parse field variable

prio is a sched_waking field, so the trigger installs and my_synth
fires.

trace_action_create_field_var() tries the target event first -- "First
try to create a field var on the target event", as its own comment says
-- and falls back to the onmatch() event, which is how a parameter taken
from the matched event resolves. The failed first attempt logs through
hist_err() and nothing clears it.

Silence hist_err() while that attempt runs. A name on neither event
still reports, from the fallback, and the write still fails.

Fixes: c282a386a397 ("tracing: Add 'onmatch' hist trigger action support")
Reported-by: Steven Rostedt <rostedt@goodmis.org>
Closes: https://lore.kernel.org/linux-trace-kernel/20260913122523.30f487d9@robin/
Signed-off-by: Donggeun Yoo <donggeunyoo.kernel@gmail.com>
Assisted-by: Claude:claude-fable-5
---

x86_64 under QEMU, CONFIG_KASAN=y, 4 CPUs, base 2f0c1cf72f46.  A histogram
on sched_waking keyed on pid, an onmatch() target on sched_switch keyed on
next_pid, my_synth($wakeup_lat,ARG).

  ARG         where it lives      unpatched          patched
  next_prio   target event        rc=0, 0 errors     rc=0, 0 errors
  prio        match event only    rc=0, 2 errors     rc=0, 0 errors
  nosuchfld   neither             rc=1, 4 errors     rc=1, 2 errors

 kernel/trace/trace_events_hist.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 963e0d6b61fd..4676dc6d9146 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -806,9 +806,12 @@ static void last_cmd_set(struct trace_event_file *file, char *str)
 		snprintf(last_cmd_loc, MAX_FILTER_STR_VAL, HIST_PREFIX "%s:%s", system, name);
 }
 
+/* Set while a field lookup may fail silently; the parse path is serialized. */
+static bool hist_err_silent;
+
 static void hist_err(struct trace_array *tr, u8 err_type, u16 err_pos)
 {
-	if (!last_cmd)
+	if (!last_cmd || hist_err_silent)
 		return;
 
 	tracing_log_err(tr, last_cmd_loc, last_cmd, err_text,
@@ -4003,7 +4006,9 @@ trace_action_create_field_var(struct hist_trigger_data *hist_data,
 	 * unqualified fields on the target event, or if qualified,
 	 * target fields that have qualified names matching the target.
 	 */
+	hist_err_silent = true;
 	field_var = create_target_field_var(hist_data, system, event, var);
+	hist_err_silent = false;
 
 	if (field_var && !IS_ERR(field_var)) {
 		save_field_var(hist_data, field_var);
-- 
2.53.0

Re: [PATCH] tracing: Don't log an error for the speculative field variable lookup

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 1 potential issue(s) to consider:

Pre-existing issues:
- [High] Memory leak of VAR_REF hist_field objects when a variable is referenced 3 or more times.
--

commit de921069f4d7b51b3167c82eacf22c1d74694b83
Author: Donggeun Yoo <donggeunyoo.kernel@gmail.com>

tracing: Don't log an error for the speculative field variable lookup

This commit prevents a spurious error log during speculative field variable
lookups in trace events. It silences hist_err() while initially attempting
to create a field variable on the target event, avoiding persistent errors
for fallback matches.

Closes: https://lore.kernel.org/linux-trace-kernel/20260913122523.30f487d9@robin/

> diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
> index 963e0d6b61fdf..4676dc6d91465 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -806,9 +806,12 @@ static void last_cmd_set(struct trace_event_file *file, char *str)
>  		snprintf(last_cmd_loc, MAX_FILTER_STR_VAL, HIST_PREFIX "%s:%s", system, name);
>  }
>  
> +/* Set while a field lookup may fail silently; the parse path is serialized. */
> +static bool hist_err_silent;
> +
>  static void hist_err(struct trace_array *tr, u8 err_type, u16 err_pos)
>  {
> -	if (!last_cmd)
> +	if (!last_cmd || hist_err_silent)
>  		return;
>  
>  	tracing_log_err(tr, last_cmd_loc, last_cmd, err_text,

[ ... ]

[Severity: High]
This isn't a bug introduced by this patch, but while reviewing
trace_events_hist.c, I noticed a potential memory leak of var_ref
hist_field objects when a variable is referenced 3 or more times.

Looking at how variables are referenced:

kernel/trace/trace_events_hist.c:create_var_ref() {
    ...
	for (i = 0; i < hist_data->n_var_refs; i++) {
		ref_field = hist_data->var_refs[i];
		if (ref_field->var.idx == var_field->var.idx &&
		    ref_field->var.hist_data == var_field->hist_data) {
			get_hist_field(ref_field);
			return ref_field;
		}
	}
    ...
}

This increments the reference count for each additional use of the variable.

During trigger destruction, the teardown logic iterates over the unique
var_ref objects in the hist_data->var_refs array and calls
__destroy_hist_field() exactly once for each. However, looking at the
refcount check:

kernel/trace/trace_events_hist.c:__destroy_hist_field() {
	if (--hist_field->ref > 1)
		return;

	kfree(hist_field->var.name);
    ...
}

If a variable is referenced 3 or more times, its ref count becomes >= 3.
Since the single teardown call only decrements the ref count by 1 (leaving
it >= 2), the condition > 1 evaluates to true, and the function returns
early without freeing the structure. 

Does this permanently leak the var_ref object and its dynamically allocated
strings, since __destroy_hist_field() is never called again for that object?

Could this allow a privileged user to reliably exhaust kernel memory by
creating and destroying a tracefs histogram trigger that references the same
variable 3 or more times (e.g., using a variable multiple times in a
synthetic event or an arithmetic expression)?

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20260913203156.941433-1-donggeunyoo.kernel@gmail.com?part=1