diff --git a/openhcl/ohcldiag-dev/src/main.rs b/openhcl/ohcldiag-dev/src/main.rs index b7537d5b5d..111007e2eb 100644 --- a/openhcl/ohcldiag-dev/src/main.rs +++ b/openhcl/ohcldiag-dev/src/main.rs @@ -294,6 +294,22 @@ enum Command { #[clap(short)] output: Option, }, + /// Processes EFI diagnostics from guest memory and outputs the logs. + /// + /// The log level filter controls which UEFI log entries are emitted. + /// The buffer already contains all log levels; this filter selects + /// which ones to display. + EfiDiagnostics { + /// The log level filter to apply. + /// + /// Accepted values: "default" (errors+warnings), "info" (errors+warnings+info), + /// "full" (all levels). + log_level: EfiDiagnosticsLogLevel, + /// The output destination. + /// + /// Accepted values: "stdout", "tracing". + output: EfiDiagnosticsOutput, + }, } #[derive(Debug, Clone, Args)] @@ -361,6 +377,43 @@ enum CrashType { UhPanic, } +#[derive(Clone, clap::ValueEnum)] +enum EfiDiagnosticsLogLevel { + /// Errors and warnings only + Default, + /// Errors, warnings, and info + Info, + /// All log levels + Full, +} + +impl EfiDiagnosticsLogLevel { + fn as_inspect_value(&self) -> &'static str { + match self { + EfiDiagnosticsLogLevel::Default => "default", + EfiDiagnosticsLogLevel::Info => "info", + EfiDiagnosticsLogLevel::Full => "full", + } + } +} + +#[derive(Clone, clap::ValueEnum)] +enum EfiDiagnosticsOutput { + /// Emit to stdout + Stdout, + /// Emit to tracing + Tracing, +} + +impl EfiDiagnosticsOutput { + fn as_inspect_value(&self) -> &'static str { + match self { + EfiDiagnosticsOutput::Stdout => "stdout", + EfiDiagnosticsOutput::Tracing => "tracing", + } + } +} + #[derive(Debug, Error)] #[error("bad environment variable, expected VAR=value")] struct BadEnvString; @@ -510,7 +563,10 @@ pub fn main() -> anyhow::Result<()> { }; let value = client.update(path, update).await?; - println!("{value}"); + match value.kind { + inspect::ValueKind::String(s) => println!("{s}"), + _ => println!("{value}"), + } } else { let timeout = if timeout == 0 { None @@ -568,7 +624,10 @@ pub fn main() -> anyhow::Result<()> { ); let client = new_client(driver.clone(), &vm)?; let value = client.update(path, value).await?; - println!("{value}"); + match value.kind { + inspect::ValueKind::String(s) => println!("{s}"), + _ => println!("{value}"), + } } Command::Start { env, unset, args } => { let client = new_client(driver.clone(), &vm)?; @@ -901,6 +960,22 @@ pub fn main() -> anyhow::Result<()> { let mut file = create_or_stderr(&output)?; file.write_all(&client.memory_profile_trace(pid).await?)?; } + Command::EfiDiagnostics { log_level, output } => { + let client = new_client(driver.clone(), &vm)?; + let arg = format!( + "{},{}", + log_level.as_inspect_value(), + output.as_inspect_value() + ); + let value = client + .update("vm/uefi/process_diagnostics", &arg) + .await + .context("failed to process EFI diagnostics")?; + match value.kind { + inspect::ValueKind::String(s) => print!("{s}"), + _ => print!("{value}"), + } + } } Ok(()) }) diff --git a/openvmm/openvmm_entry/src/lib.rs b/openvmm/openvmm_entry/src/lib.rs index 6bdd9f9138..899d92bd2e 100644 --- a/openvmm/openvmm_entry/src/lib.rs +++ b/openvmm/openvmm_entry/src/lib.rs @@ -3256,7 +3256,10 @@ async fn run_control(driver: &DefaultDriver, mesh: &VmmMesh, opt: Options) -> an } .await; match value { - Ok(node) => println!("{:#}", node), + Ok(node) => match &node.kind { + inspect::ValueKind::String(s) => println!("{s}"), + _ => println!("{:#}", node), + }, Err(err) => println!("error: {:#}", err), } } else { diff --git a/vm/devices/firmware/firmware_uefi/fuzz/fuzz_diagnostics.rs b/vm/devices/firmware/firmware_uefi/fuzz/fuzz_diagnostics.rs index 5890b1304c..c270da2af4 100644 --- a/vm/devices/firmware/firmware_uefi/fuzz/fuzz_diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/fuzz/fuzz_diagnostics.rs @@ -47,7 +47,7 @@ fn do_fuzz(input: DiagnosticsInput) { // Set GPA to point somewhere in our fuzzed buffer diagnostics.set_gpa(buffer_gpa); - let _ = diagnostics.process_diagnostics(input.allow_reprocess, &gm, |_log| { + let _ = diagnostics.process_diagnostics(input.allow_reprocess, &gm, None, |_log| { // Log handler - just discard logs during fuzzing }); } diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index aa4c6571b0..78e5135487 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -73,6 +73,7 @@ use pal_async::local::block_on; use platform::logger::UefiLogger; use platform::nvram::VsmConfig; use service::diagnostics::DEFAULT_LOGS_PER_PERIOD; +use service::diagnostics::WATCHDOG_LOGS_PER_PERIOD; use std::convert::TryInto; use std::ops::RangeInclusive; use std::task::Context; @@ -276,7 +277,13 @@ impl UefiDevice { self.service.diagnostics.set_gpa(data) } UefiCommand::PROCESS_EFI_DIAGNOSTICS => { - self.process_diagnostics(false, Some(DEFAULT_LOGS_PER_PERIOD)) + let _ = self.process_diagnostics( + false, + service::diagnostics::DiagnosticsEmitter::Tracing { + limit: Some(DEFAULT_LOGS_PER_PERIOD), + }, + None, + ); } _ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"), } @@ -284,20 +291,54 @@ impl UefiDevice { /// Extra inspection fields for the UEFI device. fn inspect_extra(&mut self, resp: &mut inspect::Response<'_>) { + const USAGE: &str = + "Use: inspect -u , vm/uefi/process_diagnostics"; + resp.field_mut_with("process_diagnostics", |v| { - // NOTE: Today, the inspect source code will fail if we invoke like below - // `inspect -u vm/uefi/process_diagnostics`. This is true, even for other - // mutable paths in the inspect graph. - if v.is_some() { - self.process_diagnostics(true, None); - Result::<_, std::convert::Infallible>::Ok( - "attempted to process diagnostics through inspect".to_string(), - ) - } else { - Result::<_, std::convert::Infallible>::Ok( - "Use: inspect -u 1 vm/uefi/process_diagnostics".to_string(), - ) - } + let output = (|| { + let value = v?; + let (level_str, dest_str) = value.split_once(',').unwrap_or((value, "stdout")); + + let log_level_override = match level_str { + "default" => Some(LogLevel::make_default()), + "info" => Some(LogLevel::make_info()), + "full" => Some(LogLevel::make_full()), + _ => return None, + }; + + Some(match dest_str { + "stdout" => match self.process_diagnostics( + true, + service::diagnostics::DiagnosticsEmitter::String, + log_level_override, + ) { + Ok(Some(output)) if output.is_empty() => { + "(no diagnostics entries found)".to_string() + } + Ok(Some(output)) => output, + Ok(None) => unreachable!("String emitter should return output"), + Err(error) => format!("error processing diagnostics: {error}"), + }, + "tracing" => { + match self.process_diagnostics( + true, + service::diagnostics::DiagnosticsEmitter::Tracing { limit: None }, + log_level_override, + ) { + Ok(_) => format!( + "processed diagnostics via tracing \ + (log_level_override: {level_str})" + ), + Err(error) => { + format!("error processing diagnostics: {error}") + } + } + } + _ => return None, + }) + })(); + + Result::<_, std::convert::Infallible>::Ok(output.unwrap_or_else(|| USAGE.to_string())) }); } } @@ -343,7 +384,15 @@ impl PollDevice for UefiDevice { // NOTE: Do not allow reprocessing diagnostics here. // UEFI programs the watchdog's configuration, so we should assume that // this path could trigger multiple times. - self.process_diagnostics(false, Some(DEFAULT_LOGS_PER_PERIOD)); + // + // Here, we emit diagnostics to tracing with INFO level and no limit + let _ = self.process_diagnostics( + false, + service::diagnostics::DiagnosticsEmitter::Tracing { + limit: Some(WATCHDOG_LOGS_PER_PERIOD), + }, + Some(LogLevel::make_info()), + ); } } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics/mod.rs index 9f16beac39..5e8b17bb15 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics/mod.rs @@ -34,6 +34,9 @@ mod processor; /// Default number of EfiDiagnosticsLogs emitted per period pub const DEFAULT_LOGS_PER_PERIOD: u32 = 150; +/// Number of EfiDiagnosticsLogs emitted per period for watchdog timeouts +pub const WATCHDOG_LOGS_PER_PERIOD: u32 = 2000; + /// Emit a diagnostic log entry with rate limiting. /// /// # Arguments @@ -185,11 +188,13 @@ impl DiagnosticsServices { /// # Arguments /// * `allow_reprocess` - If true, allows processing even if already processed for guest /// * `gm` - Guest memory to read diagnostics from + /// * `log_level_override` - If provided, overrides the configured log level for this processing run /// * `log_handler` - Function to handle each parsed log entry pub fn process_diagnostics( &mut self, allow_reprocess: bool, gm: &GuestMemory, + log_level_override: Option, log_handler: F, ) -> Result<(), ProcessingError> where @@ -204,34 +209,77 @@ impl DiagnosticsServices { // Mark as processed first to prevent guest spam (even on failure) self.processed = true; + // Use the override log level if provided, otherwise fall back to configured level + let effective_log_level = log_level_override.unwrap_or(self.log_level); + // Delegate to the processor module - processor::process_diagnostics_internal(self.gpa, gm, self.log_level, log_handler) + processor::process_diagnostics_internal(self.gpa, gm, effective_log_level, log_handler) } } +/// The output destination for diagnostics. +pub(crate) enum DiagnosticsEmitter { + /// Emit to tracing + Tracing { limit: Option }, + /// Emit to a string + String, +} + impl UefiDevice { /// Processes UEFI diagnostics from guest memory. /// - /// When a limit is provided, traces are rate-limited to avoid spam. - /// When no limit is provided, traces are unrestricted. - /// /// # Arguments /// * `allow_reprocess` - If true, allows processing even if already processed for guest - /// * `limit` - Maximum number of logs to process per period, or `None` for no limit - pub(crate) fn process_diagnostics(&mut self, allow_reprocess: bool, limit: Option) { - if let Err(error) = - self.service - .diagnostics - .process_diagnostics(allow_reprocess, &self.gm, |log| match limit { - Some(limit) => emit_log_ratelimited(log, limit), - None => emit_log_unrestricted(log), - }) - { - tracelimit::error_ratelimited!( - error = &error as &dyn std::error::Error, - "failed to process diagnostics buffer" - ); + /// * `emitter` - The destination for the diagnostics output + /// * `log_level_override` - If provided, overrides the configured log level filter for this run + pub(crate) fn process_diagnostics( + &mut self, + allow_reprocess: bool, + emitter: DiagnosticsEmitter, + log_level_override: Option, + ) -> Result, ProcessingError> { + use std::fmt::Write; + let mut output = match emitter { + DiagnosticsEmitter::String => Some(String::new()), + DiagnosticsEmitter::Tracing { .. } => None, + }; + + if let Err(error) = self.service.diagnostics.process_diagnostics( + allow_reprocess, + &self.gm, + log_level_override, + |log| { + if let Some(out) = &mut output { + let _ = writeln!( + out, + "({} ticks) [{}] [{}]: {}", + log.ticks(), + log.debug_level_str(), + log.phase_str(), + log.message_trimmed(), + ); + } else if let DiagnosticsEmitter::Tracing { limit } = emitter { + match limit { + Some(limit) => emit_log_ratelimited(log, limit), + None => emit_log_unrestricted(log), + } + } + }, + ) { + match emitter { + DiagnosticsEmitter::Tracing { .. } => { + tracelimit::error_ratelimited!( + error = &error as &dyn std::error::Error, + "failed to process diagnostics buffer" + ); + // For tracing, we swallow the error after logging it, consistent with previous behavior + return Ok(None); + } + DiagnosticsEmitter::String => return Err(error), + } } + + Ok(output) } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics/processor.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics/processor.rs index e888aeb211..01979c62af 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics/processor.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics/processor.rs @@ -113,9 +113,7 @@ where gm.read_at(buffer_start_gpa.as_u64(), &mut buffer_data)?; // Process the buffer - LogProcessor::process_buffer(&buffer_data, log_level, log_handler)?; - - Ok(()) + LogProcessor::process_buffer(&buffer_data, log_level, log_handler) } /// Internal processor for log entries with suppression tracking @@ -126,6 +124,8 @@ struct LogProcessor { suppressed_logs: BTreeMap<&'static str, u32>, /// Number of entries processed entries_processed: usize, + /// Number of entries emitted (passed level/suppression filters) + entries_emitted: usize, /// Number of bytes read from buffer bytes_read: usize, } @@ -136,6 +136,7 @@ impl LogProcessor { accumulator: LogAccumulator::new(), suppressed_logs: BTreeMap::new(), entries_processed: 0, + entries_emitted: 0, bytes_read: 0, } } @@ -158,6 +159,7 @@ impl LogProcessor { } tracelimit::info_ratelimited!( entries_processed = self.entries_processed, + entries_emitted = self.entries_emitted, bytes_read = self.bytes_read, "processed EFI log entries" ); @@ -194,6 +196,7 @@ impl LogProcessor { if let Some(complete_log) = processor.accumulator.take() { processor.entries_processed += 1; if processor.should_emit(&complete_log, log_level) { + processor.entries_emitted += 1; log_handler(&complete_log); } } @@ -202,6 +205,7 @@ impl LogProcessor { if let Some(final_log) = processor.accumulator.clear() { processor.entries_processed += 1; if processor.should_emit(&final_log, log_level) { + processor.entries_emitted += 1; log_handler(&final_log); } }