Skip to content

Commit 7a536e1

Browse files
maheeraeronmaheeraeron
authored
firmware_uefi: EfiDiagnostics change to tracelimit with custom period and limit (#1706)
1 parent f24168c commit 7a536e1

File tree

3 files changed

+207
-20
lines changed

3 files changed

+207
-20
lines changed

‎support/tracelimit/src/lib.rs

Lines changed: 168 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -38,12 +38,12 @@ pub fn disable_rate_limiting(disabled: bool) {
3838

3939
#[doc(hidden)]
4040
pub struct RateLimiter {
41-
period_ms: u32,
42-
events_per_period: u32,
4341
state: Mutex<RateLimiterState>,
4442
}
4543

4644
struct RateLimiterState {
45+
period_ms: u32,
46+
events_per_period: u32,
4747
start: Option<Instant>,
4848
events: u32,
4949
missed: u64,
@@ -59,9 +59,9 @@ impl RateLimiter {
5959

6060
pub const fn new(period_ms: u32, events_per_period: u32) -> Self {
6161
Self {
62-
period_ms,
63-
events_per_period,
6462
state: Mutex::new(RateLimiterState {
63+
period_ms,
64+
events_per_period,
6565
start: None,
6666
events: 0,
6767
missed: 0,
@@ -74,31 +74,110 @@ impl RateLimiter {
7474
/// `missed_events` is `Some(n)` if there were any missed events or if this
7575
/// event is the last one before rate limiting kicks in.
7676
pub fn event(&self) -> Result<Option<u64>, RateLimited> {
77+
self.event_with_config(None, None)
78+
}
79+
80+
/// Returns `Ok(missed_events)` if this event should be logged.
81+
/// Optionally reconfigures the rate limiter if new parameters are provided.
82+
///
83+
/// `missed_events` is `Some(n)` if there were any missed events or if this
84+
/// event is the last one before rate limiting kicks in.
85+
pub fn event_with_config(
86+
&self,
87+
period_ms: Option<u32>,
88+
events_per_period: Option<u32>,
89+
) -> Result<Option<u64>, RateLimited> {
7790
if DISABLE_RATE_LIMITING.load(Ordering::Relaxed) {
7891
return Ok(None);
7992
}
93+
8094
let mut state = self.state.try_lock().ok_or(RateLimited)?;
95+
96+
// Reconfigure if new parameters are provided
97+
let mut reset_state = false;
98+
if let Some(new_period) = period_ms {
99+
if state.period_ms != new_period {
100+
state.period_ms = new_period;
101+
reset_state = true;
102+
}
103+
}
104+
if let Some(new_events_per_period) = events_per_period {
105+
if state.events_per_period != new_events_per_period {
106+
state.events_per_period = new_events_per_period;
107+
reset_state = true;
108+
}
109+
}
110+
111+
// Reset state when parameters change
112+
if reset_state {
113+
state.start = None;
114+
state.events = 0;
115+
state.missed = 0;
116+
}
117+
81118
let now = Instant::now();
119+
let period_ms = state.period_ms;
82120
let start = state.start.get_or_insert(now);
83121
let elapsed = now.duration_since(*start);
84-
if elapsed.as_millis() > self.period_ms as u128 {
122+
if elapsed.as_millis() > period_ms as u128 {
85123
*start = now;
86124
state.events = 0;
87125
}
88-
if state.events >= self.events_per_period {
126+
if state.events >= state.events_per_period {
89127
state.missed += 1;
90128
return Err(RateLimited);
91129
}
92130
state.events += 1;
93131
let missed = std::mem::take(&mut state.missed);
94-
let missed = (missed != 0 || state.events == self.events_per_period).then_some(missed);
132+
let missed = (missed != 0 || state.events == state.events_per_period).then_some(missed);
95133
Ok(missed)
96134
}
97135
}
98136

99137
/// As [`tracing::error!`], but rate limited.
138+
///
139+
/// Can be called with optional parameters to customize rate limiting:
140+
/// - `period: <ms>` - rate limiting period in milliseconds
141+
/// - `limit: <count>` - maximum events per period
142+
///
143+
/// Examples:
144+
/// ```
145+
/// use tracelimit::error_ratelimited;
146+
/// error_ratelimited!("simple message");
147+
/// error_ratelimited!(period: 1000, limit: 5, "custom rate limit");
148+
/// error_ratelimited!(period: 10000, "custom period only");
149+
/// error_ratelimited!(limit: 50, "custom limit only");
150+
/// ```
100151
#[macro_export]
101152
macro_rules! error_ratelimited {
153+
// With both period and limit
154+
(period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {
155+
{
156+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
157+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), Some($limit)) {
158+
$crate::tracing::error!(dropped_ratelimited = missed_events, $($rest)*);
159+
}
160+
}
161+
};
162+
// With period only
163+
(period: $period:expr, $($rest:tt)*) => {
164+
{
165+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
166+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), None) {
167+
$crate::tracing::error!(dropped_ratelimited = missed_events, $($rest)*);
168+
}
169+
}
170+
};
171+
// With limit only
172+
(limit: $limit:expr, $($rest:tt)*) => {
173+
{
174+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
175+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(None, Some($limit)) {
176+
$crate::tracing::error!(dropped_ratelimited = missed_events, $($rest)*);
177+
}
178+
}
179+
};
180+
// Default case (no custom parameters)
102181
($($rest:tt)*) => {
103182
{
104183
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
@@ -110,8 +189,49 @@ macro_rules! error_ratelimited {
110189
}
111190

112191
/// As [`tracing::warn!`], but rate limited.
192+
///
193+
/// Can be called with optional parameters to customize rate limiting:
194+
/// - `period: <ms>` - rate limiting period in milliseconds
195+
/// - `limit: <count>` - maximum events per period
196+
///
197+
/// Examples:
198+
/// ```
199+
/// use tracelimit::warn_ratelimited;
200+
/// warn_ratelimited!("simple message");
201+
/// warn_ratelimited!(period: 1000, limit: 5, "custom rate limit");
202+
/// warn_ratelimited!(period: 10000, "custom period only");
203+
/// warn_ratelimited!(limit: 50, "custom limit only");
204+
/// ```
113205
#[macro_export]
114206
macro_rules! warn_ratelimited {
207+
// With both period and limit
208+
(period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {
209+
{
210+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
211+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), Some($limit)) {
212+
$crate::tracing::warn!(dropped_ratelimited = missed_events, $($rest)*);
213+
}
214+
}
215+
};
216+
// With period only
217+
(period: $period:expr, $($rest:tt)*) => {
218+
{
219+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
220+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), None) {
221+
$crate::tracing::warn!(dropped_ratelimited = missed_events, $($rest)*);
222+
}
223+
}
224+
};
225+
// With limit only
226+
(limit: $limit:expr, $($rest:tt)*) => {
227+
{
228+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
229+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(None, Some($limit)) {
230+
$crate::tracing::warn!(dropped_ratelimited = missed_events, $($rest)*);
231+
}
232+
}
233+
};
234+
// Default case (no custom parameters)
115235
($($rest:tt)*) => {
116236
{
117237
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
@@ -123,8 +243,49 @@ macro_rules! warn_ratelimited {
123243
}
124244

125245
/// As [`tracing::info!`], but rate limited.
246+
///
247+
/// Can be called with optional parameters to customize rate limiting:
248+
/// - `period: <ms>` - rate limiting period in milliseconds
249+
/// - `limit: <count>` - maximum events per period
250+
///
251+
/// Examples:
252+
/// ```
253+
/// use tracelimit::info_ratelimited;
254+
/// info_ratelimited!("simple message");
255+
/// info_ratelimited!(period: 1000, limit: 5, "custom rate limit");
256+
/// info_ratelimited!(period: 10000, "custom period only");
257+
/// info_ratelimited!(limit: 50, "custom limit only");
258+
/// ```
126259
#[macro_export]
127260
macro_rules! info_ratelimited {
261+
// With both period and limit
262+
(period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {
263+
{
264+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
265+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), Some($limit)) {
266+
$crate::tracing::info!(dropped_ratelimited = missed_events, $($rest)*);
267+
}
268+
}
269+
};
270+
// With period only
271+
(period: $period:expr, $($rest:tt)*) => {
272+
{
273+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
274+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), None) {
275+
$crate::tracing::info!(dropped_ratelimited = missed_events, $($rest)*);
276+
}
277+
}
278+
};
279+
// With limit only
280+
(limit: $limit:expr, $($rest:tt)*) => {
281+
{
282+
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
283+
if let Ok(missed_events) = RATE_LIMITER.event_with_config(None, Some($limit)) {
284+
$crate::tracing::info!(dropped_ratelimited = missed_events, $($rest)*);
285+
}
286+
}
287+
};
288+
// Default case (no custom parameters)
128289
($($rest:tt)*) => {
129290
{
130291
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();

‎vm/devices/firmware/firmware_uefi/src/lib.rs

Lines changed: 11 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,7 @@ use local_clock::InspectableLocalClock;
7070
use pal_async::local::block_on;
7171
use platform::logger::UefiLogger;
7272
use platform::nvram::VsmConfig;
73+
use service::diagnostics::DEFAULT_LOGS_PER_PERIOD;
7374
use std::convert::TryInto;
7475
use std::ops::RangeInclusive;
7576
use std::task::Context;
@@ -269,13 +270,17 @@ impl UefiDevice {
269270
tracelimit::info_ratelimited!(?addr, data, "set gpa for diagnostics");
270271
self.service.diagnostics.set_gpa(data)
271272
}
272-
UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(false, "guest"),
273+
UefiCommand::PROCESS_EFI_DIAGNOSTICS => {
274+
self.process_diagnostics(false, DEFAULT_LOGS_PER_PERIOD, "guest")
275+
}
273276
_ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"),
274277
}
275278
}
276279

277280
fn inspect_extra(&mut self, _resp: &mut inspect::Response<'_>) {
278-
self.process_diagnostics(true, "inspect_extra");
281+
// This is the only place where we allow reprocessing diagnostics,
282+
// since this will be driven by the user themselves.
283+
self.process_diagnostics(true, DEFAULT_LOGS_PER_PERIOD, "inspect_extra");
279284
}
280285
}
281286

@@ -317,8 +322,10 @@ impl PollDevice for UefiDevice {
317322

318323
// Poll watchdog timeout events
319324
if let Poll::Ready(Ok(())) = self.watchdog_recv.poll_recv(cx) {
320-
tracing::info!("watchdog timeout received");
321-
self.process_diagnostics(true, "watchdog timeout");
325+
// NOTE: Do not allow reprocessing diagnostics here.
326+
// UEFI programs the watchdog's configuration, so we should assume that
327+
// this path could trigger multiple times.
328+
self.process_diagnostics(false, DEFAULT_LOGS_PER_PERIOD, "watchdog timeout");
322329
}
323330
}
324331
}

‎vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs

Lines changed: 28 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,9 @@ use uefi_specs::hyperv::debug_level::DEBUG_FLAG_NAMES;
3232
use uefi_specs::hyperv::debug_level::DEBUG_WARN;
3333
use zerocopy::FromBytes;
3434

35+
/// Default number of EfiDiagnosticsLogs emitted per period
36+
pub const DEFAULT_LOGS_PER_PERIOD: u32 = 150;
37+
3538
/// 8-byte alignment for every entry
3639
const ALIGNMENT: usize = 8;
3740

@@ -103,26 +106,29 @@ fn phase_to_string(phase: u16) -> &'static str {
103106
}
104107

105108
/// Defines how we want EfiDiagnosticsLog entries to be handled.
106-
pub fn handle_efi_diagnostics_log<'a>(log: EfiDiagnosticsLog<'a>) {
109+
pub fn handle_efi_diagnostics_log(log: EfiDiagnosticsLog<'_>, limit: u32) {
107110
let debug_level_str = debug_level_to_string(log.debug_level);
108111
let phase_str = phase_to_string(log.phase);
109112

110113
match log.debug_level {
111-
DEBUG_WARN => tracing::warn!(
114+
DEBUG_WARN => tracelimit::warn_ratelimited!(
115+
limit: limit,
112116
debug_level = %debug_level_str,
113117
ticks = log.ticks,
114118
phase = %phase_str,
115119
log_message = log.message,
116120
"EFI log entry"
117121
),
118-
DEBUG_ERROR => tracing::error!(
122+
DEBUG_ERROR => tracelimit::error_ratelimited!(
123+
limit: limit,
119124
debug_level = %debug_level_str,
120125
ticks = log.ticks,
121126
phase = %phase_str,
122127
log_message = log.message,
123128
"EFI log entry"
124129
),
125-
_ => tracing::info!(
130+
_ => tracelimit::info_ratelimited!(
131+
limit: limit,
126132
debug_level = %debug_level_str,
127133
ticks = log.ticks,
128134
phase = %phase_str,
@@ -283,11 +289,13 @@ impl DiagnosticsServices {
283289
///
284290
/// # Arguments
285291
/// * `allow_reprocess` - If true, allows processing even if already processed for guest
292+
/// * `triggered_by` - String to indicate who triggered the diagnostics processing
286293
/// * `gm` - Guest memory to read diagnostics from
287294
/// * `log_handler` - Function to handle each parsed log entry
288295
fn process_diagnostics<F>(
289296
&mut self,
290297
allow_reprocess: bool,
298+
triggered_by: &str,
291299
gm: &GuestMemory,
292300
mut log_handler: F,
293301
) -> Result<(), DiagnosticsError>
@@ -450,7 +458,12 @@ impl DiagnosticsServices {
450458
}
451459

452460
// Print summary statistics
453-
tracelimit::info_ratelimited!(entries_processed, bytes_read, "processed EFI log entries");
461+
tracelimit::info_ratelimited!(
462+
triggered_by,
463+
entries_processed,
464+
bytes_read,
465+
"processed EFI log entries"
466+
);
454467

455468
Ok(())
456469
}
@@ -461,16 +474,22 @@ impl UefiDevice {
461474
///
462475
/// # Arguments
463476
/// * `allow_reprocess` - If true, allows processing even if already processed for guest
464-
/// * `context` - String to indicate who triggered the diagnostics processing
465-
pub(crate) fn process_diagnostics(&mut self, allow_reprocess: bool, context: &str) {
477+
/// * `triggered_by` - String to indicate who triggered the diagnostics processing
478+
pub(crate) fn process_diagnostics(
479+
&mut self,
480+
allow_reprocess: bool,
481+
limit: u32,
482+
triggered_by: &str,
483+
) {
466484
if let Err(error) = self.service.diagnostics.process_diagnostics(
467485
allow_reprocess,
486+
triggered_by,
468487
&self.gm,
469-
handle_efi_diagnostics_log,
488+
|log| handle_efi_diagnostics_log(log, limit),
470489
) {
471490
tracelimit::error_ratelimited!(
472491
error = &error as &dyn std::error::Error,
473-
context,
492+
triggered_by,
474493
"failed to process diagnostics buffer"
475494
);
476495
}

0 commit comments

Comments
 (0)