tracing: Fix hist trigger timestamps for buffered events
Impact
In the Linux kernel, the following vulnerability has been resolved:
Source excerpt · LinuxAffected packages
Affected products
Vendor version evidence. Product records are separate from automatic dependency matching.
Linux · Linux
Other versions: unaffected
| Version / range | Source status |
|---|---|
| b94bc80df64823e676b506f8de7dcf6a688d681e to before 09c7cce2e59e6b3b1807520bcb1980c561f15d1e | affected |
| b94bc80df64823e676b506f8de7dcf6a688d681e to before 89e90b16aadd6e66bd0323bc8dfc76a62e756b57 | affected |
| b94bc80df64823e676b506f8de7dcf6a688d681e to before 9414ca3b99e5a7f1f3bf51c2a01b383e1b355dd0 | affected |
Linux · Linux
Other versions: affected
| Version / range | Source status |
|---|---|
| 5.13 | affected |
| 0 to before 5.13 | unaffected |
| 6.18.59 through 6.18.* (inclusive) | unaffected |
| 7.2.13 through 7.2.* (inclusive) | unaffected |
| 7.3 through * (inclusive) | unaffected |
Original source description
In the Linux kernel, the following vulnerability has been resolved:
tracing: Fix hist trigger timestamps for buffered events
Syzkaller triggered a WARN_ON_ONCE(!nest) warning:
WARNING: kernel/trace/ring_buffer.c:821 at ring_buffer_event_time_stamp Call trace: ring_buffer_event_time_stamp hist_field_timestamp hist_fn_call event_hist_trigger event_triggers_call __event_trigger_test_discard trace_event_buffer_commit do_trace_event_raw_event_sched_switch trace_event_raw_event_sched_switch
The warning is probabilistically reproducible and is related to syzkaller executing the following commands:
echo 'prev_pid == 999999' > events/sched/sched_switch/filter echo 'hist:keys=common_timestamp' > events/sched/sched_switch/trigger
The specific triggering process is as follows:
CPU 0 CPU 1
(context switching) (echo 'hist:keys=common_timestamp' >
events/sched/sched_switch/trigger)
do_trace_event_raw_event_##call
trace_event_buffer_lock_reserve
if (!tr->no_filter_buffering_ref &&
trace_file->flags & EVENT_FILE_FL_FILTERED)
return entry; // return directly
event_hist_trigger_parse
hist_register_trigger
tracing_set_filter_buffering(file->tr, true);
tr->no_filter_buffering_ref++;
__trace_buffer_lock_reserve
rb_start_commit
local_inc(&cpu_buffer->committing); // skipped and not executed
trace_event_buffer_commit
__event_trigger_test_discard
event_triggers_call
event_hist_trigger
hist_fn_call
hist_field_timestamp
ring_buffer_event_time_stamp
nest = local_read(&cpu_buffer->committing);
WARN_ON_ONCE(!nest) // trigger warning
The root cause is that when an event file has a filter attached and the hist trigger has not yet been attached, trace_event_buffer_lock_reserve() writes the event into the per-CPU trace_buffered_event temp buffer instead of reserving it in the ring buffer, so cpu_buffer->committing is not incremented. When the event is later processed at commit time by a hist trigger, hist_field_timestamp() -> ring_buffer_event_time_stamp() sees a zero committing count, triggering WARN_ON_ONCE(!nest).
tracing_event_time_stamp() was added by commit d8279bfc5e959 ("tracing: Add tracing_event_time_stamp() API") for exactly this case: if the event is the per-CPU trace_buffered_event, it returns the current ring buffer timestamp. But it never gained a caller. Use it in hist_field_timestamp(), so that a hist trigger that races onto a buffered event records the current time, which is only marginally later than when the event was recorded, instead of warning and recording a bogus timestamp.