From 601250abbf6c4c23ab58674fbdd6d1d5f9c1a031 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 01:51:24 -0700 Subject: [PATCH 01/32] Initial commit, defined diagnostics subsystem and laid out IoPort intercepts --- vm/devices/firmware/firmware_uefi/src/lib.rs | 19 +++++++++++++++++++ .../firmware/firmware_uefi/src/service/mod.rs | 1 + 2 files changed, 20 insertions(+) diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index 13d505d0d7..e74da327eb 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -104,6 +104,7 @@ struct UefiDeviceServices { generation_id: service::generation_id::GenerationIdServices, #[inspect(mut)] time: service::time::TimeServices, + diagnostics: service::diagnostics::DiagnosticsServices, } // Begin and end range are inclusive. @@ -199,6 +200,7 @@ impl UefiDevice { generation_id_deps, ), time: service::time::TimeServices::new(time_source), + diagnostics: service::diagnostics::DiagnosticsServices::new(), }, }; Ok(uefi) @@ -252,6 +254,12 @@ impl UefiDevice { ); } } + UefiCommand::SET_EFI_DIAGNOSTICS_GPA => { + tracelimit::warn_ratelimited!("EFI diagnostics gpa set to {:#x}", data); + } + UefiCommand::PROCESS_EFI_DIAGNOSTICS => { + tracelimit::warn_ratelimited!("Recieved notification to process EFI diagnostics"); + } _ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"), } } @@ -400,6 +408,10 @@ open_enum::open_enum! { WATCHDOG_RESOLUTION = 0x28, WATCHDOG_COUNT = 0x29, + // EFI Diagnostics + SET_EFI_DIAGNOSTICS_GPA = 0x2B, + PROCESS_EFI_DIAGNOSTICS = 0x2C, + // Event Logging (Windows 8.1 MQ/M0) EVENT_LOG_FLUSH = 0x30, @@ -432,6 +444,7 @@ mod save_restore { use vmcore::save_restore::SaveRestore; mod state { + use crate::service::diagnostics::DiagnosticsServices; use crate::service::event_log::EventLogServices; use crate::service::generation_id::GenerationIdServices; use crate::service::nvram::NvramServices; @@ -457,6 +470,8 @@ mod save_restore { pub generation_id: ::SavedState, #[mesh(6)] pub time: ::SavedState, + #[mesh(7)] + pub diagnostics: ::SavedState, } } @@ -475,6 +490,7 @@ mod save_restore { uefi_watchdog, generation_id, time, + diagnostics, }, address, } = self; @@ -487,6 +503,7 @@ mod save_restore { watchdog: uefi_watchdog.save()?, generation_id: generation_id.save()?, time: time.save()?, + diagnostics: diagnostics.save()?, }) } @@ -499,6 +516,7 @@ mod save_restore { watchdog, generation_id, time, + diagnostics, } = state; self.address = address; @@ -508,6 +526,7 @@ mod save_restore { self.service.uefi_watchdog.restore(watchdog)?; self.service.generation_id.restore(generation_id)?; self.service.time.restore(time)?; + self.service.diagnostics.restore(diagnostics)?; Ok(()) } diff --git a/vm/devices/firmware/firmware_uefi/src/service/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/mod.rs index 573bcb962c..6ebb95d60f 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/mod.rs @@ -4,6 +4,7 @@ //! Various UEFI device subsystems. pub mod crypto; +pub mod diagnostics; pub mod event_log; pub mod generation_id; pub mod nvram; From 7fe0fcc9ed5e5a39a026bbda13b43c937f4b91be Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 01:51:49 -0700 Subject: [PATCH 02/32] Forgot to add diagnostics.rs itself --- .../firmware_uefi/src/service/diagnostics.rs | 72 +++++++++++++++++++ 1 file changed, 72 insertions(+) create mode 100644 vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs new file mode 100644 index 0000000000..d8a53e3b05 --- /dev/null +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -0,0 +1,72 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +//! UEFI diagnostics subsystem +//! +//! This module stores the GPA of the efi dignostics buffer. +//! When signaled, the diagnostics buffer is parsed and written to +//! trace logs. +use crate::UefiDevice; +use inspect::Inspect; +use std::fmt::Debug; +use thiserror::Error; + +#[derive(Debug, Error)] +pub enum DiagnosticsError { + #[error("invalid diagnostics address")] + InvalidAddress, +} + +#[derive(Inspect)] +pub struct DiagnosticsServices { + gpa: u32, +} + +impl DiagnosticsServices { + pub fn new() -> DiagnosticsServices { + DiagnosticsServices { gpa: 0 } + } + + pub fn reset(&mut self) { + self.gpa = 0 + } + + pub fn set_gpa(&mut self, gpa: u32) -> Result<(), DiagnosticsError> { + if gpa == 0 || gpa == u32::MAX { + return Err(DiagnosticsError::InvalidAddress); + } + self.gpa = gpa; + Ok(()) + } +} + +impl UefiDevice { + pub(crate) fn _set_diagnostics_gpa(&mut self, gpa: u32) { + if let Err(err) = self.service.diagnostics.set_gpa(gpa) { + tracelimit::error_ratelimited!( + error = &err as &dyn std::error::Error, + "Failed to set diagnostics GPA", + ); + } + } +} + +mod save_restore { + use super::*; + use vmcore::save_restore::NoSavedState; + use vmcore::save_restore::RestoreError; + use vmcore::save_restore::SaveError; + use vmcore::save_restore::SaveRestore; + + impl SaveRestore for DiagnosticsServices { + type SavedState = NoSavedState; + + fn save(&mut self) -> Result { + Ok(NoSavedState) + } + + fn restore(&mut self, NoSavedState: Self::SavedState) -> Result<(), RestoreError> { + Ok(()) + } + } +} From c6dbbae2b2143390c6ac2521b49fcd2fb04a8722 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 14:21:16 -0700 Subject: [PATCH 03/32] Defined advanced logger types and laid out logic for parsing --- vm/devices/firmware/firmware_uefi/src/lib.rs | 8 +-- .../firmware_uefi/src/service/diagnostics.rs | 39 ++++++++---- .../uefi_specs/src/hyperv/efi_diagnostics.rs | 59 +++++++++++++++++++ .../firmware/uefi_specs/src/hyperv/mod.rs | 1 + 4 files changed, 90 insertions(+), 17 deletions(-) create mode 100644 vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index e74da327eb..872e313687 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -254,12 +254,8 @@ impl UefiDevice { ); } } - UefiCommand::SET_EFI_DIAGNOSTICS_GPA => { - tracelimit::warn_ratelimited!("EFI diagnostics gpa set to {:#x}", data); - } - UefiCommand::PROCESS_EFI_DIAGNOSTICS => { - tracelimit::warn_ratelimited!("Recieved notification to process EFI diagnostics"); - } + UefiCommand::SET_EFI_DIAGNOSTICS_GPA => self.set_diagnostics_gpa(data), + UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(self.gm.clone()), _ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"), } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index d8a53e3b05..9cf12b80f4 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -7,14 +7,25 @@ //! When signaled, the diagnostics buffer is parsed and written to //! trace logs. use crate::UefiDevice; +use guestmem::GuestMemory; use inspect::Inspect; use std::fmt::Debug; use thiserror::Error; #[derive(Debug, Error)] pub enum DiagnosticsError { - #[error("invalid diagnostics address")] - InvalidAddress, + #[error("invalid diagnostics gpa")] + InvalidGpa, + #[error("invalid header signature")] + InvalidHeaderSignature, + #[error("invalid header log buffer size")] + InvalidHeaderLogBufferSize, + #[error("invalid entry signature")] + InvalidEntrySignature, + #[error("invalid entry timestamp")] + InvalidEntryTimestamp, + #[error("invalid entry message length")] + InvalidEntryMessageLength, } #[derive(Inspect)] @@ -31,23 +42,29 @@ impl DiagnosticsServices { self.gpa = 0 } - pub fn set_gpa(&mut self, gpa: u32) -> Result<(), DiagnosticsError> { + pub fn set_diagnostics_gpa(&mut self, gpa: u32) -> Result<(), DiagnosticsError> { + tracelimit::info_ratelimited!("Setting diagnostics GPA to {:#x}", gpa); if gpa == 0 || gpa == u32::MAX { - return Err(DiagnosticsError::InvalidAddress); + tracelimit::error_ratelimited!("Invalid GPA: {:#x}", gpa); + return Err(DiagnosticsError::InvalidGpa); } self.gpa = gpa; Ok(()) } + + pub fn process_diagnostics(&self, _gm: GuestMemory) -> Result<(), DiagnosticsError> { + tracelimit::info_ratelimited!("Recieved notification to process EFI diagnostics"); + Ok(()) + } } impl UefiDevice { - pub(crate) fn _set_diagnostics_gpa(&mut self, gpa: u32) { - if let Err(err) = self.service.diagnostics.set_gpa(gpa) { - tracelimit::error_ratelimited!( - error = &err as &dyn std::error::Error, - "Failed to set diagnostics GPA", - ); - } + pub(crate) fn set_diagnostics_gpa(&mut self, gpa: u32) { + let _ = self.service.diagnostics.set_diagnostics_gpa(gpa); + } + + pub(crate) fn process_diagnostics(&self, gm: GuestMemory) { + let _ = self.service.diagnostics.process_diagnostics(gm); } } diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs b/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs new file mode 100644 index 0000000000..1fecff83e8 --- /dev/null +++ b/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs @@ -0,0 +1,59 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +//! Types and constants defined for EFI diagnostics. +//! Many of these types come from the UEFI Advanced Logger +//! Package from Project Mu. + +use crate::uefi::time::EFI_TIME; + +// Parsing constants +pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB +pub const MAX_MESSAGE_LENGTH: u32 = 0x1000; // 4KB + +// Signatures for the advanced logger structures +pub const SIG_HEADER: u32 = u32::from_le_bytes(*b"ALOG"); +pub const SIG_ENTRY: u32 = u32::from_le_bytes(*b"ALM2"); + +// UEFI Advanced Logger Info Header, which is shared +// with the Advanced Logger Package in UEFI. The entries +// live right after. +#[repr(C, packed)] +#[derive(Debug, Copy, Clone)] +pub struct AdvancedLoggerInfo { + pub signature: u32, // Signature 'ALOG' + pub version: u16, // Current Version + pub reserved: [u16; 3], // Reserved for future + pub log_buffer_offset: u32, // Offset from LoggerInfo to start of log + pub reserved4: u32, + pub log_current_offset: u32, // Offset from LoggerInfo to where to store next log entry + pub discarded_size: u32, // Number of bytes of messages missed + pub log_buffer_size: u32, // Size of allocated buffer + pub in_permanent_ram: bool, // Log in permanent RAM + pub at_runtime: bool, // After ExitBootServices + pub gone_virtual: bool, // After VirtualAddressChange + pub hdw_port_initialized: bool, // HdwPort initialized + pub hdw_port_disabled: bool, // HdwPort is Disabled + pub reserved2: [bool; 3], // Reserved + pub timer_frequency: u64, // Ticks per second for log timing + pub ticks_at_time: u64, // Ticks when Time Acquired + pub time: EFI_TIME, // Uefi Time Field + pub hw_print_level: u32, // Logging level to be printed at hw port + pub reserved3: u32, // Reserved +} + +// UEFI Advanced Logger Entry, which is shared with the +// Advanced Logger Package in UEFI. The messages live +// right after. +#[repr(C, packed)] +#[derive(Debug, Copy, Clone)] +pub struct AdvancedLoggerMessageEntryV2 { + pub signature: u32, // Signature + pub major_version: u8, // Major version of advanced logger message structure + pub minor_version: u8, // Minor version of advanced logger message structure + pub debug_level: u32, // Debug Level + pub time_stamp: u64, // Time stamp + pub phase: u16, // Boot phase that produced this message entry + pub message_len: u16, // Number of bytes in Message + pub message_offset: u16, // Offset of Message from start of structure +} diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs b/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs index 2cb716e6d2..c8ff5cebc2 100644 --- a/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs +++ b/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs @@ -11,6 +11,7 @@ pub mod bios_event_log; pub mod boot_bios_log; pub mod common; pub mod crypto; +pub mod efi_diagnostics; pub mod nvram; pub mod time; From 633fdbc2ba0444cf69946220e30d07c0884acdaa Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 18:08:32 -0700 Subject: [PATCH 04/32] Now parsing the buffer but getting rate limited --- .../firmware_uefi/src/service/diagnostics.rs | 216 +++++++++++++++++- .../firmware_uefi/src/service/nvram/mod.rs | 3 + .../uefi_specs/src/hyperv/efi_diagnostics.rs | 34 +-- 3 files changed, 234 insertions(+), 19 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 9cf12b80f4..fd2307ba4f 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -11,6 +11,8 @@ use guestmem::GuestMemory; use inspect::Inspect; use std::fmt::Debug; use thiserror::Error; +use uefi_specs::hyperv::efi_diagnostics::*; +use zerocopy::FromBytes; #[derive(Debug, Error)] pub enum DiagnosticsError { @@ -26,6 +28,10 @@ pub enum DiagnosticsError { InvalidEntryTimestamp, #[error("invalid entry message length")] InvalidEntryMessageLength, + #[error("unable to read header from guest memory")] + HeaderParseError, + #[error("unable to read diagnostics buffer from guest memory")] + BufferParseError, } #[derive(Inspect)] @@ -42,18 +48,220 @@ impl DiagnosticsServices { self.gpa = 0 } - pub fn set_diagnostics_gpa(&mut self, gpa: u32) -> Result<(), DiagnosticsError> { - tracelimit::info_ratelimited!("Setting diagnostics GPA to {:#x}", gpa); + fn validate_gpa(&self, gpa: u32) -> Result<(), DiagnosticsError> { if gpa == 0 || gpa == u32::MAX { tracelimit::error_ratelimited!("Invalid GPA: {:#x}", gpa); return Err(DiagnosticsError::InvalidGpa); } + Ok(()) + } + + fn validate_header(&self, header: &AdvancedLoggerInfo) -> Result<(), DiagnosticsError> { + if header.signature != SIG_HEADER { + return Err(DiagnosticsError::InvalidHeaderSignature); + } + + if header.log_buffer_size == 0 || header.log_buffer_size > MAX_LOG_BUFFER_SIZE { + return Err(DiagnosticsError::InvalidHeaderLogBufferSize); + } + + Ok(()) + } + + fn validate_entry(&self, entry: &AdvancedLoggerMessageEntryV2) -> Result<(), DiagnosticsError> { + if entry.signature != SIG_ENTRY { + return Err(DiagnosticsError::InvalidEntrySignature); + } + + if entry.time_stamp == 0 { + return Err(DiagnosticsError::InvalidEntryTimestamp); + } + + if entry.message_len == 0 || entry.message_len > MAX_MESSAGE_LENGTH as u16 { + return Err(DiagnosticsError::InvalidEntryMessageLength); + } + + Ok(()) + } + + pub fn set_diagnostics_gpa(&mut self, gpa: u32) -> Result<(), DiagnosticsError> { + tracelimit::info_ratelimited!("Setting diagnostics GPA to {:#x}", gpa); + self.validate_gpa(gpa)?; self.gpa = gpa; Ok(()) } - pub fn process_diagnostics(&self, _gm: GuestMemory) -> Result<(), DiagnosticsError> { - tracelimit::info_ratelimited!("Recieved notification to process EFI diagnostics"); + pub fn process_diagnostics(&self, gm: GuestMemory) -> Result<(), DiagnosticsError> { + // + // Step 1: Validate GPA + // + self.validate_gpa(self.gpa)?; + + // + // Step 2: Read and validate the advanced logger header + // + let header: AdvancedLoggerInfo = gm + .read_plain(self.gpa as u64) + .map_err(|_| DiagnosticsError::HeaderParseError)?; + self.validate_header(&header)?; + let log_buffer_offset = header.log_buffer_offset; + let log_current_offset = header.log_current_offset; + tracelimit::info_ratelimited!( + "Buffer offset: {:#x}, Log Current offset: {:#x}", + log_buffer_offset, + log_current_offset + ); + + // + // Step 3: Prepare processing variables + // + + // Used for summary statistics + let mut bytes_read: usize = 0; + let mut entries_processed: usize = 0; + + // Calculate used log buffer size + let used_log_buffer_size = header + .log_current_offset + .checked_sub(header.log_buffer_offset) + .ok_or_else(|| DiagnosticsError::InvalidHeaderLogBufferSize)?; + + // Validate used log buffer size + if used_log_buffer_size == 0 + || used_log_buffer_size > header.log_buffer_size + || used_log_buffer_size > MAX_LOG_BUFFER_SIZE + { + tracelimit::error_ratelimited!( + "Invalid used log buffer size: {:#x}", + used_log_buffer_size + ); + return Err(DiagnosticsError::InvalidHeaderLogBufferSize); + } + + // Used for accumulating multiple messages + let mut accumulated_message = String::new(); + let mut debug_level = 0; + let mut time_stamp = 0; + let mut phase = 0; + let mut is_accumulating = false; + + // + // Step 4: Read the used portions of the log buffer + // + + // Calcualte start address of the log buffer + let buffer_start_addr = self + .gpa + .checked_add(header.log_buffer_offset) + .ok_or_else(|| DiagnosticsError::InvalidGpa)?; + + let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; + gm.read_at(buffer_start_addr as u64, &mut buffer_data) + .map_err(|_| DiagnosticsError::BufferParseError)?; + + // Empty buffer data should early exit + if buffer_data.is_empty() { + tracelimit::info_ratelimited!("Diagnostics buffer is empty"); + return Ok(()); + } + + // + // Step 5: Parse the log buffer + // + let mut buffer_slice = &buffer_data[..]; + while !buffer_slice.is_empty() { + // Parse and validate the entry header + let (entry, _) = AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice) + .map_err(|_| DiagnosticsError::BufferParseError)?; + self.validate_entry(&entry)?; + + // Validate message bounds + // TODO: Double check if the types are appropriate here... + let message_start = entry.message_offset as usize; + let message_end = (entry.message_offset as usize) + .checked_add(entry.message_len as usize) + .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; + if message_end as usize > buffer_slice.len() { + tracelimit::error_ratelimited!( + "Message end exceeds buffer size: {} > {}", + message_end, + buffer_slice.len() + ); + return Err(DiagnosticsError::InvalidEntryMessageLength); + } + + // Get the message + let message = String::from_utf8_lossy(&buffer_slice[message_start..message_end]); + + // + // Step 5a: Handle message accumulation + // + if !is_accumulating { + debug_level = entry.debug_level; + time_stamp = entry.time_stamp; + phase = entry.phase; + accumulated_message.clear(); + is_accumulating = true; + } + accumulated_message.push_str(&message); + + // Validate that the accumulated message is not too long + if accumulated_message.len() > MAX_MESSAGE_LENGTH as usize { + tracelimit::error_ratelimited!( + "Accumulated message length exceeds maximum: {}", + accumulated_message.len() + ); + return Err(DiagnosticsError::InvalidEntryMessageLength); + } + + // Print completed messages (ending with a newline) to the trace log + if !message.is_empty() && message.ends_with('\n') { + tracelimit::info_ratelimited!( + "EFI Diagnostics: Debug Level: {:#x}, Time Stamp: {:#x}, Phase: {:#x}, Message: {}", + debug_level, + time_stamp, + phase, + accumulated_message + ); + entries_processed += 1; + is_accumulating = false; + } + + // + // Step 5b: Move to the next entry + // + + // Calculate base offset (entry header size + message length) + let base_offset = size_of::() + .checked_add(entry.message_len as usize) + .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; + + // Add padding for 8-byte alignment + let aligned_offset = base_offset + .checked_add(7) + .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; + let next_offset = aligned_offset & !7; + + // Update overall bytes read counter + bytes_read = bytes_read + .checked_add(next_offset) + .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; + + // Advanced to the next entry with boundary checks + if next_offset >= buffer_slice.len() { + // We have reached the end of the buffer + break; + } + buffer_slice = &buffer_slice[next_offset..]; + } + + // Print summary statistics + tracelimit::info_ratelimited!( + "EFI Diagnostics: Processed {} entries, Read {} bytes", + entries_processed, + bytes_read + ); + Ok(()) } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs index a438b3af4a..519214ba2a 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs @@ -571,6 +571,9 @@ impl UefiDevice { } self.service.nvram.services.exit_boot_services(); + // When exit boot services is called, process EFI diagnostics + let _ = self.process_diagnostics(self.gm.clone()); + (EfiStatus::SUCCESS, None) } NvramCommand::DEBUG_STRING => { diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs b/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs index 1fecff83e8..f260859b68 100644 --- a/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs +++ b/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs @@ -6,6 +6,9 @@ //! Package from Project Mu. use crate::uefi::time::EFI_TIME; +use zerocopy::FromBytes; +use zerocopy::Immutable; +use zerocopy::KnownLayout; // Parsing constants pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB @@ -19,7 +22,7 @@ pub const SIG_ENTRY: u32 = u32::from_le_bytes(*b"ALM2"); // with the Advanced Logger Package in UEFI. The entries // live right after. #[repr(C, packed)] -#[derive(Debug, Copy, Clone)] +#[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] pub struct AdvancedLoggerInfo { pub signature: u32, // Signature 'ALOG' pub version: u16, // Current Version @@ -29,12 +32,12 @@ pub struct AdvancedLoggerInfo { pub log_current_offset: u32, // Offset from LoggerInfo to where to store next log entry pub discarded_size: u32, // Number of bytes of messages missed pub log_buffer_size: u32, // Size of allocated buffer - pub in_permanent_ram: bool, // Log in permanent RAM - pub at_runtime: bool, // After ExitBootServices - pub gone_virtual: bool, // After VirtualAddressChange - pub hdw_port_initialized: bool, // HdwPort initialized - pub hdw_port_disabled: bool, // HdwPort is Disabled - pub reserved2: [bool; 3], // Reserved + pub in_permanent_ram: u8, // Log in permanent RAM + pub at_runtime: u8, // After ExitBootServices + pub gone_virtual: u8, // After VirtualAddressChange + pub hdw_port_initialized: u8, // HdwPort initialized + pub hdw_port_disabled: u8, // HdwPort is Disabled + pub reserved2: [u8; 3], // Reserved pub timer_frequency: u64, // Ticks per second for log timing pub ticks_at_time: u64, // Ticks when Time Acquired pub time: EFI_TIME, // Uefi Time Field @@ -46,14 +49,15 @@ pub struct AdvancedLoggerInfo { // Advanced Logger Package in UEFI. The messages live // right after. #[repr(C, packed)] -#[derive(Debug, Copy, Clone)] +#[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] pub struct AdvancedLoggerMessageEntryV2 { - pub signature: u32, // Signature - pub major_version: u8, // Major version of advanced logger message structure - pub minor_version: u8, // Minor version of advanced logger message structure - pub debug_level: u32, // Debug Level - pub time_stamp: u64, // Time stamp - pub phase: u16, // Boot phase that produced this message entry - pub message_len: u16, // Number of bytes in Message + pub signature: u32, // Signature + pub major_version: u8, // Major version of advanced logger message structure + pub minor_version: u8, // Minor version of advanced logger message structure + pub debug_level: u32, // Debug Level + pub time_stamp: u64, // Time stamp + pub phase: u16, // Boot phase that produced this message entry + pub message_len: u16, // Number of bytes in Message pub message_offset: u16, // Offset of Message from start of structure + // Rust does not support flexible arrays, but message lives after } From d43cefd8be2ded68e60ddeda039943883d6169ec Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 19:44:11 -0700 Subject: [PATCH 05/32] Significant error handling improvements --- Cargo.lock | 1 + .../firmware_uefi/src/service/diagnostics.rs | 243 ++++++++++-------- vm/devices/firmware/uefi_specs/Cargo.toml | 1 + .../uefi_specs/src/hyperv/efi_diagnostics.rs | 63 ----- .../firmware/uefi_specs/src/hyperv/mod.rs | 2 +- 5 files changed, 143 insertions(+), 167 deletions(-) delete mode 100644 vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs diff --git a/Cargo.lock b/Cargo.lock index e2660a10a3..cc32ae5820 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7194,6 +7194,7 @@ dependencies = [ "inspect", "open_enum", "static_assertions", + "thiserror 2.0.12", "ucs2 0.0.0", "wchar", "zerocopy 0.8.23", diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index fd2307ba4f..d3d7bac111 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -11,79 +11,61 @@ use guestmem::GuestMemory; use inspect::Inspect; use std::fmt::Debug; use thiserror::Error; -use uefi_specs::hyperv::efi_diagnostics::*; +use uefi_specs::hyperv::advanced_logger::*; use zerocopy::FromBytes; +// Every parsed advanced logger entry turns into this +pub struct EfiDiagnosticsLog { + pub debug_level: u32, + pub time_stamp: u64, + pub phase: u16, + pub message: String, +} + +// For any errors that occur during processing #[derive(Debug, Error)] -pub enum DiagnosticsError { - #[error("invalid diagnostics gpa")] - InvalidGpa, - #[error("invalid header signature")] - InvalidHeaderSignature, - #[error("invalid header log buffer size")] - InvalidHeaderLogBufferSize, - #[error("invalid entry signature")] - InvalidEntrySignature, - #[error("invalid entry timestamp")] - InvalidEntryTimestamp, - #[error("invalid entry message length")] - InvalidEntryMessageLength, - #[error("unable to read header from guest memory")] - HeaderParseError, - #[error("unable to read diagnostics buffer from guest memory")] - BufferParseError, +#[error("{0}")] +pub struct DiagnosticsError(pub String); + +impl From for DiagnosticsError { + fn from(err: AdvancedLoggerInfoError) -> Self { + DiagnosticsError(err.to_string()) + } } +impl From for DiagnosticsError { + fn from(err: AdvancedLoggerEntryError) -> Self { + DiagnosticsError(err.to_string()) + } +} + +// Holds necessary state for diagnostics services #[derive(Inspect)] pub struct DiagnosticsServices { gpa: u32, + did_parse: bool, } impl DiagnosticsServices { pub fn new() -> DiagnosticsServices { - DiagnosticsServices { gpa: 0 } + DiagnosticsServices { + gpa: 0, + did_parse: false, + } } pub fn reset(&mut self) { - self.gpa = 0 + self.gpa = 0; + self.did_parse = false; } fn validate_gpa(&self, gpa: u32) -> Result<(), DiagnosticsError> { - if gpa == 0 || gpa == u32::MAX { - tracelimit::error_ratelimited!("Invalid GPA: {:#x}", gpa); - return Err(DiagnosticsError::InvalidGpa); + if gpa == u32::MAX { + return Err(DiagnosticsError(format!("Invalid GPA: {:#x}", gpa))); } Ok(()) } - fn validate_header(&self, header: &AdvancedLoggerInfo) -> Result<(), DiagnosticsError> { - if header.signature != SIG_HEADER { - return Err(DiagnosticsError::InvalidHeaderSignature); - } - - if header.log_buffer_size == 0 || header.log_buffer_size > MAX_LOG_BUFFER_SIZE { - return Err(DiagnosticsError::InvalidHeaderLogBufferSize); - } - - Ok(()) - } - - fn validate_entry(&self, entry: &AdvancedLoggerMessageEntryV2) -> Result<(), DiagnosticsError> { - if entry.signature != SIG_ENTRY { - return Err(DiagnosticsError::InvalidEntrySignature); - } - - if entry.time_stamp == 0 { - return Err(DiagnosticsError::InvalidEntryTimestamp); - } - - if entry.message_len == 0 || entry.message_len > MAX_MESSAGE_LENGTH as u16 { - return Err(DiagnosticsError::InvalidEntryMessageLength); - } - - Ok(()) - } - pub fn set_diagnostics_gpa(&mut self, gpa: u32) -> Result<(), DiagnosticsError> { tracelimit::info_ratelimited!("Setting diagnostics GPA to {:#x}", gpa); self.validate_gpa(gpa)?; @@ -91,7 +73,11 @@ impl DiagnosticsServices { Ok(()) } - pub fn process_diagnostics(&self, gm: GuestMemory) -> Result<(), DiagnosticsError> { + pub fn process_diagnostics( + &self, + gm: GuestMemory, + logs: &mut Vec, + ) -> Result<(), DiagnosticsError> { // // Step 1: Validate GPA // @@ -100,22 +86,21 @@ impl DiagnosticsServices { // // Step 2: Read and validate the advanced logger header // - let header: AdvancedLoggerInfo = gm - .read_plain(self.gpa as u64) - .map_err(|_| DiagnosticsError::HeaderParseError)?; - self.validate_header(&header)?; - let log_buffer_offset = header.log_buffer_offset; - let log_current_offset = header.log_current_offset; - tracelimit::info_ratelimited!( - "Buffer offset: {:#x}, Log Current offset: {:#x}", - log_buffer_offset, - log_current_offset - ); + let header: AdvancedLoggerInfo = gm.read_plain(self.gpa as u64).map_err(|_| { + DiagnosticsError(format!( + "Failed to read AdvancedLoggerInfo at {:#x}", + self.gpa + )) + })?; + header.validate()?; // // Step 3: Prepare processing variables // + // Force clear the logs + logs.clear(); + // Used for summary statistics let mut bytes_read: usize = 0; let mut entries_processed: usize = 0; @@ -124,18 +109,22 @@ impl DiagnosticsServices { let used_log_buffer_size = header .log_current_offset .checked_sub(header.log_buffer_offset) - .ok_or_else(|| DiagnosticsError::InvalidHeaderLogBufferSize)?; + .ok_or_else(|| { + DiagnosticsError(format!( + "Overflow: Log current offset ({:#x}) - Log buffer offset ({:#x})", + header.log_current_offset as u32, header.log_buffer_offset as u32 + )) + })?; // Validate used log buffer size if used_log_buffer_size == 0 || used_log_buffer_size > header.log_buffer_size || used_log_buffer_size > MAX_LOG_BUFFER_SIZE { - tracelimit::error_ratelimited!( + return Err(DiagnosticsError(format!( "Invalid used log buffer size: {:#x}", used_log_buffer_size - ); - return Err(DiagnosticsError::InvalidHeaderLogBufferSize); + ))); } // Used for accumulating multiple messages @@ -149,19 +138,29 @@ impl DiagnosticsServices { // Step 4: Read the used portions of the log buffer // - // Calcualte start address of the log buffer - let buffer_start_addr = self - .gpa - .checked_add(header.log_buffer_offset) - .ok_or_else(|| DiagnosticsError::InvalidGpa)?; + // Calculate start address of the log buffer + let buffer_start_addr = + self.gpa + .checked_add(header.log_buffer_offset) + .ok_or_else(|| { + DiagnosticsError(format!( + "Overflow: GPA ({:#x}) + Log buffer offset ({:#x})", + self.gpa, header.log_buffer_offset as u32 + )) + })?; let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; gm.read_at(buffer_start_addr as u64, &mut buffer_data) - .map_err(|_| DiagnosticsError::BufferParseError)?; + .map_err(|_| { + DiagnosticsError(format!( + "Failed to read log buffer at {:#x} with size {:#x}", + buffer_start_addr, used_log_buffer_size + )) + })?; // Empty buffer data should early exit if buffer_data.is_empty() { - tracelimit::info_ratelimited!("Diagnostics buffer is empty"); + tracelimit::info_ratelimited!("Diagnostics buffer is empty, ending processing"); return Ok(()); } @@ -171,23 +170,37 @@ impl DiagnosticsServices { let mut buffer_slice = &buffer_data[..]; while !buffer_slice.is_empty() { // Parse and validate the entry header - let (entry, _) = AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice) - .map_err(|_| DiagnosticsError::BufferParseError)?; - self.validate_entry(&entry)?; + let (entry, _) = + AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice).map_err(|_| { + DiagnosticsError(format!( + "Failed to read AdvancedLoggerMessageEntryV2 from buffer slice: {:?}", + buffer_slice + )) + })?; + entry.validate()?; + + // + // Step 5a: Validate message boundaries + // - // Validate message bounds - // TODO: Double check if the types are appropriate here... + // Calculate message start and end offsets let message_start = entry.message_offset as usize; - let message_end = (entry.message_offset as usize) + let message_end = message_start .checked_add(entry.message_len as usize) - .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; - if message_end as usize > buffer_slice.len() { - tracelimit::error_ratelimited!( - "Message end exceeds buffer size: {} > {}", + .ok_or_else(|| { + DiagnosticsError(format!( + "Overflow: message_start ({}) + message_length ({})", + message_start, entry.message_len as u16 + )) + })?; + + // Validate message end fits within the buffer slice + if message_end > buffer_slice.len() { + return Err(DiagnosticsError(format!( + "message_end exceeds buffer_slice: {} > {}", message_end, buffer_slice.len() - ); - return Err(DiagnosticsError::InvalidEntryMessageLength); + ))); } // Get the message @@ -207,22 +220,21 @@ impl DiagnosticsServices { // Validate that the accumulated message is not too long if accumulated_message.len() > MAX_MESSAGE_LENGTH as usize { - tracelimit::error_ratelimited!( - "Accumulated message length exceeds maximum: {}", - accumulated_message.len() - ); - return Err(DiagnosticsError::InvalidEntryMessageLength); + return Err(DiagnosticsError(format!( + "Accumulated message length exceeds maximum: {}. Max: {}", + accumulated_message.len(), + MAX_MESSAGE_LENGTH + ))); } // Print completed messages (ending with a newline) to the trace log if !message.is_empty() && message.ends_with('\n') { - tracelimit::info_ratelimited!( - "EFI Diagnostics: Debug Level: {:#x}, Time Stamp: {:#x}, Phase: {:#x}, Message: {}", + logs.push(EfiDiagnosticsLog { debug_level, time_stamp, phase, - accumulated_message - ); + message: accumulated_message.clone(), + }); entries_processed += 1; is_accumulating = false; } @@ -234,18 +246,27 @@ impl DiagnosticsServices { // Calculate base offset (entry header size + message length) let base_offset = size_of::() .checked_add(entry.message_len as usize) - .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; + .ok_or_else(|| { + DiagnosticsError(format!( + "Overflow: AdvancedLoggerMessageEntryV2 size ({}) + message length ({})", + size_of::(), + entry.message_len as u16 + )) + })?; // Add padding for 8-byte alignment - let aligned_offset = base_offset - .checked_add(7) - .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; + let aligned_offset = base_offset.checked_add(7).ok_or_else(|| { + DiagnosticsError(format!("Overflow: base_offset ({}) + 7", base_offset)) + })?; let next_offset = aligned_offset & !7; // Update overall bytes read counter - bytes_read = bytes_read - .checked_add(next_offset) - .ok_or_else(|| DiagnosticsError::InvalidEntryMessageLength)?; + bytes_read = bytes_read.checked_add(next_offset).ok_or_else(|| { + DiagnosticsError(format!( + "Overflow: bytes_read ({}) + next_offset ({})", + bytes_read, next_offset + )) + })?; // Advanced to the next entry with boundary checks if next_offset >= buffer_slice.len() { @@ -272,7 +293,23 @@ impl UefiDevice { } pub(crate) fn process_diagnostics(&self, gm: GuestMemory) { - let _ = self.service.diagnostics.process_diagnostics(gm); + let mut logs = Vec::new(); + match self.service.diagnostics.process_diagnostics(gm, &mut logs) { + Ok(_) => { + for log in logs.iter() { + tracelimit::info_ratelimited!( + "Diagnostics Log: Debug Level: {}, Timestamp: {}, Phase: {}, Message: {}", + log.debug_level, + log.time_stamp, + log.phase, + log.message + ); + } + } + Err(e) => { + tracelimit::error_ratelimited!("Diagnostics Error: {}", e); + } + } } } diff --git a/vm/devices/firmware/uefi_specs/Cargo.toml b/vm/devices/firmware/uefi_specs/Cargo.toml index 700f524cd6..72bbe2d5ec 100644 --- a/vm/devices/firmware/uefi_specs/Cargo.toml +++ b/vm/devices/firmware/uefi_specs/Cargo.toml @@ -18,6 +18,7 @@ open_enum.workspace = true ucs2.workspace = true bitfield-struct.workspace = true +thiserror.workspace = true static_assertions.workspace = true wchar.workspace = true zerocopy.workspace = true diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs b/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs deleted file mode 100644 index f260859b68..0000000000 --- a/vm/devices/firmware/uefi_specs/src/hyperv/efi_diagnostics.rs +++ /dev/null @@ -1,63 +0,0 @@ -// Copyright (c) Microsoft Corporation. -// Licensed under the MIT License. - -//! Types and constants defined for EFI diagnostics. -//! Many of these types come from the UEFI Advanced Logger -//! Package from Project Mu. - -use crate::uefi::time::EFI_TIME; -use zerocopy::FromBytes; -use zerocopy::Immutable; -use zerocopy::KnownLayout; - -// Parsing constants -pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB -pub const MAX_MESSAGE_LENGTH: u32 = 0x1000; // 4KB - -// Signatures for the advanced logger structures -pub const SIG_HEADER: u32 = u32::from_le_bytes(*b"ALOG"); -pub const SIG_ENTRY: u32 = u32::from_le_bytes(*b"ALM2"); - -// UEFI Advanced Logger Info Header, which is shared -// with the Advanced Logger Package in UEFI. The entries -// live right after. -#[repr(C, packed)] -#[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] -pub struct AdvancedLoggerInfo { - pub signature: u32, // Signature 'ALOG' - pub version: u16, // Current Version - pub reserved: [u16; 3], // Reserved for future - pub log_buffer_offset: u32, // Offset from LoggerInfo to start of log - pub reserved4: u32, - pub log_current_offset: u32, // Offset from LoggerInfo to where to store next log entry - pub discarded_size: u32, // Number of bytes of messages missed - pub log_buffer_size: u32, // Size of allocated buffer - pub in_permanent_ram: u8, // Log in permanent RAM - pub at_runtime: u8, // After ExitBootServices - pub gone_virtual: u8, // After VirtualAddressChange - pub hdw_port_initialized: u8, // HdwPort initialized - pub hdw_port_disabled: u8, // HdwPort is Disabled - pub reserved2: [u8; 3], // Reserved - pub timer_frequency: u64, // Ticks per second for log timing - pub ticks_at_time: u64, // Ticks when Time Acquired - pub time: EFI_TIME, // Uefi Time Field - pub hw_print_level: u32, // Logging level to be printed at hw port - pub reserved3: u32, // Reserved -} - -// UEFI Advanced Logger Entry, which is shared with the -// Advanced Logger Package in UEFI. The messages live -// right after. -#[repr(C, packed)] -#[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] -pub struct AdvancedLoggerMessageEntryV2 { - pub signature: u32, // Signature - pub major_version: u8, // Major version of advanced logger message structure - pub minor_version: u8, // Minor version of advanced logger message structure - pub debug_level: u32, // Debug Level - pub time_stamp: u64, // Time stamp - pub phase: u16, // Boot phase that produced this message entry - pub message_len: u16, // Number of bytes in Message - pub message_offset: u16, // Offset of Message from start of structure - // Rust does not support flexible arrays, but message lives after -} diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs b/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs index c8ff5cebc2..50bce195ce 100644 --- a/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs +++ b/vm/devices/firmware/uefi_specs/src/hyperv/mod.rs @@ -7,11 +7,11 @@ //! in any public spec. Instead, they are transcribed directly from the Hyper-V //! C/C++ sources. +pub mod advanced_logger; pub mod bios_event_log; pub mod boot_bios_log; pub mod common; pub mod crypto; -pub mod efi_diagnostics; pub mod nvram; pub mod time; From 9bc2936e52d0887004653b57ee18202e2ef9d934 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 19:44:39 -0700 Subject: [PATCH 06/32] Added advanced_logger.rs instead to clarify type ownership --- .../uefi_specs/src/hyperv/advanced_logger.rs | 133 ++++++++++++++++++ 1 file changed, 133 insertions(+) create mode 100644 vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs new file mode 100644 index 0000000000..6783465b49 --- /dev/null +++ b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs @@ -0,0 +1,133 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +//! Types and constants defined for EFI diagnostics. +//! Many of these types come from the UEFI Advanced Logger +//! Package from Project Mu. + +use crate::uefi::time::EFI_TIME; +use thiserror::Error; +use zerocopy::FromBytes; +use zerocopy::Immutable; +use zerocopy::KnownLayout; + +// Errors for validating the Advanced Logger Info structure +#[derive(Debug, Error)] +pub enum AdvancedLoggerInfoError { + #[error("Invalid header signature: {0:#x}, expected: {1:#x}")] + InvalidSignature(u32, u32), + #[error("Invalid log buffer size: {0:#x}, max: {1:#x}")] + InvalidLogBufferSize(u32, u32), +} + +// Errors for validating the Advanced Logger Entry structure +#[derive(Debug, Error)] +pub enum AdvancedLoggerEntryError { + #[error("Invalid entry signature: {0:#x}, expected: {1:#x}")] + InvalidSignature(u32, u32), + #[error("Invalid timestamp: {0:#x}")] + InvalidTimestamp(u64), + #[error("Invalid message length: {0:#x}, max: {1:#x}")] + InvalidMessageLength(u16, u16), +} + +// Advanced Logger Info validation constants +pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB +pub const SIG_HEADER: u32 = u32::from_le_bytes(*b"ALOG"); + +// Advanced Logger Entry validation constants +pub const MAX_MESSAGE_LENGTH: u16 = 0x1000; // 4KB +pub const SIG_ENTRY: u32 = u32::from_le_bytes(*b"ALM2"); + +// UEFI Advanced Logger Info Header, which is shared +// with the Advanced Logger Package in UEFI. The entries +// live right after. +#[repr(C, packed)] +#[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] +pub struct AdvancedLoggerInfo { + pub signature: u32, // Signature 'ALOG' + pub version: u16, // Current Version + pub reserved: [u16; 3], // Reserved for future + pub log_buffer_offset: u32, // Offset from LoggerInfo to start of log + pub reserved4: u32, + pub log_current_offset: u32, // Offset from LoggerInfo to where to store next log entry + pub discarded_size: u32, // Number of bytes of messages missed + pub log_buffer_size: u32, // Size of allocated buffer + pub in_permanent_ram: u8, // Log in permanent RAM + pub at_runtime: u8, // After ExitBootServices + pub gone_virtual: u8, // After VirtualAddressChange + pub hdw_port_initialized: u8, // HdwPort initialized + pub hdw_port_disabled: u8, // HdwPort is Disabled + pub reserved2: [u8; 3], // Reserved + pub timer_frequency: u64, // Ticks per second for log timing + pub ticks_at_time: u64, // Ticks when Time Acquired + pub time: EFI_TIME, // Uefi Time Field + pub hw_print_level: u32, // Logging level to be printed at hw port + pub reserved3: u32, // Reserved +} + +// UEFI Advanced Logger Entry, which is shared with the +// Advanced Logger Package in UEFI. The messages live +// right after. +#[repr(C, packed)] +#[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] +pub struct AdvancedLoggerMessageEntryV2 { + pub signature: u32, // Signature + pub major_version: u8, // Major version of advanced logger message structure + pub minor_version: u8, // Minor version of advanced logger message structure + pub debug_level: u32, // Debug Level + pub time_stamp: u64, // Time stamp + pub phase: u16, // Boot phase that produced this message entry + pub message_len: u16, // Number of bytes in Message + pub message_offset: u16, // Offset of Message from start of structure + // Rust does not support flexible arrays, but message lives after +} + +impl AdvancedLoggerInfo { + pub fn validate(&self) -> Result<(), AdvancedLoggerInfoError> { + // Check the signature + let signature = self.signature.to_le(); + if signature != SIG_HEADER { + return Err(AdvancedLoggerInfoError::InvalidSignature( + signature, SIG_HEADER, + )); + } + + // Check the log buffer size + let log_buffer_size = self.log_buffer_size; + if log_buffer_size > MAX_LOG_BUFFER_SIZE { + return Err(AdvancedLoggerInfoError::InvalidLogBufferSize( + log_buffer_size, + MAX_LOG_BUFFER_SIZE, + )); + } + Ok(()) + } +} + +impl AdvancedLoggerMessageEntryV2 { + pub fn validate(&self) -> Result<(), AdvancedLoggerEntryError> { + // Check the signature + let signature = self.signature.to_le(); + if signature != SIG_ENTRY { + return Err(AdvancedLoggerEntryError::InvalidSignature( + signature, SIG_ENTRY, + )); + } + + // Check the timestamp + if self.time_stamp == 0 { + return Err(AdvancedLoggerEntryError::InvalidTimestamp(self.time_stamp)); + } + + // Check the message length + let message_len = self.message_len; + if message_len > MAX_MESSAGE_LENGTH { + return Err(AdvancedLoggerEntryError::InvalidMessageLength( + message_len, + MAX_MESSAGE_LENGTH, + )); + } + Ok(()) + } +} From a94d854c4d90fa50c89bab8aa0444d41ee802d21 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 19:56:35 -0700 Subject: [PATCH 07/32] Moved diagnostics state to UefiDevice instead --- vm/devices/firmware/firmware_uefi/src/lib.rs | 19 ++++- .../firmware_uefi/src/service/diagnostics.rs | 69 +++++++++---------- .../firmware_uefi/src/service/nvram/mod.rs | 2 +- 3 files changed, 49 insertions(+), 41 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index 872e313687..1d57f73836 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -155,6 +155,13 @@ pub struct UefiDevice { // Volatile state #[inspect(hex)] address: u32, + + // Diagnostics state + #[inspect(mut)] + diagnostics_gpa: u32, + + #[inspect(mut)] + processed_diagnostics: bool, } impl UefiDevice { @@ -202,6 +209,8 @@ impl UefiDevice { time: service::time::TimeServices::new(time_source), diagnostics: service::diagnostics::DiagnosticsServices::new(), }, + diagnostics_gpa: 0, + processed_diagnostics: false, }; Ok(uefi) } @@ -254,8 +263,12 @@ impl UefiDevice { ); } } - UefiCommand::SET_EFI_DIAGNOSTICS_GPA => self.set_diagnostics_gpa(data), - UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(self.gm.clone()), + UefiCommand::SET_EFI_DIAGNOSTICS_GPA => { + self.diagnostics_gpa = data; + } + UefiCommand::PROCESS_EFI_DIAGNOSTICS => { + self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()) + } _ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"), } } @@ -489,6 +502,8 @@ mod save_restore { diagnostics, }, address, + diagnostics_gpa: _, + processed_diagnostics: _, } = self; Ok(state::SavedState { diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index d3d7bac111..61330c964d 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -41,56 +41,40 @@ impl From for DiagnosticsError { // Holds necessary state for diagnostics services #[derive(Inspect)] -pub struct DiagnosticsServices { - gpa: u32, - did_parse: bool, -} +pub struct DiagnosticsServices {} impl DiagnosticsServices { pub fn new() -> DiagnosticsServices { - DiagnosticsServices { - gpa: 0, - did_parse: false, - } + DiagnosticsServices {} } pub fn reset(&mut self) { - self.gpa = 0; - self.did_parse = false; + // Does nothing } fn validate_gpa(&self, gpa: u32) -> Result<(), DiagnosticsError> { - if gpa == u32::MAX { + if gpa == 0 || gpa == u32::MAX { return Err(DiagnosticsError(format!("Invalid GPA: {:#x}", gpa))); } Ok(()) } - pub fn set_diagnostics_gpa(&mut self, gpa: u32) -> Result<(), DiagnosticsError> { - tracelimit::info_ratelimited!("Setting diagnostics GPA to {:#x}", gpa); - self.validate_gpa(gpa)?; - self.gpa = gpa; - Ok(()) - } - pub fn process_diagnostics( &self, + gpa: u32, gm: GuestMemory, logs: &mut Vec, ) -> Result<(), DiagnosticsError> { // // Step 1: Validate GPA // - self.validate_gpa(self.gpa)?; + self.validate_gpa(gpa)?; // // Step 2: Read and validate the advanced logger header // - let header: AdvancedLoggerInfo = gm.read_plain(self.gpa as u64).map_err(|_| { - DiagnosticsError(format!( - "Failed to read AdvancedLoggerInfo at {:#x}", - self.gpa - )) + let header: AdvancedLoggerInfo = gm.read_plain(gpa as u64).map_err(|_| { + DiagnosticsError(format!("Failed to read AdvancedLoggerInfo at {:#x}", gpa)) })?; header.validate()?; @@ -139,15 +123,12 @@ impl DiagnosticsServices { // // Calculate start address of the log buffer - let buffer_start_addr = - self.gpa - .checked_add(header.log_buffer_offset) - .ok_or_else(|| { - DiagnosticsError(format!( - "Overflow: GPA ({:#x}) + Log buffer offset ({:#x})", - self.gpa, header.log_buffer_offset as u32 - )) - })?; + let buffer_start_addr = gpa.checked_add(header.log_buffer_offset).ok_or_else(|| { + DiagnosticsError(format!( + "Overflow: GPA ({:#x}) + Log buffer offset ({:#x})", + gpa, header.log_buffer_offset as u32 + )) + })?; let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; gm.read_at(buffer_start_addr as u64, &mut buffer_data) @@ -288,14 +269,23 @@ impl DiagnosticsServices { } impl UefiDevice { - pub(crate) fn set_diagnostics_gpa(&mut self, gpa: u32) { - let _ = self.service.diagnostics.set_diagnostics_gpa(gpa); - } + pub(crate) fn process_diagnostics(&mut self, gpa: u32, gm: GuestMemory) { + // Do not process if already done + if self.processed_diagnostics { + tracelimit::info_ratelimited!("EFI Diagnostics already processed, skipping"); + return; + } + self.processed_diagnostics = true; - pub(crate) fn process_diagnostics(&self, gm: GuestMemory) { + // Collect diagnostics logs let mut logs = Vec::new(); - match self.service.diagnostics.process_diagnostics(gm, &mut logs) { + match self + .service + .diagnostics + .process_diagnostics(gpa, gm, &mut logs) + { Ok(_) => { + // Print the logs to the trace log for log in logs.iter() { tracelimit::info_ratelimited!( "Diagnostics Log: Debug Level: {}, Timestamp: {}, Phase: {}, Message: {}", @@ -310,6 +300,9 @@ impl UefiDevice { tracelimit::error_ratelimited!("Diagnostics Error: {}", e); } } + + // Reset stored gpa + self.diagnostics_gpa = 0; } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs index 519214ba2a..8000333f70 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs @@ -572,7 +572,7 @@ impl UefiDevice { self.service.nvram.services.exit_boot_services(); // When exit boot services is called, process EFI diagnostics - let _ = self.process_diagnostics(self.gm.clone()); + let _ = self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); (EfiStatus::SUCCESS, None) } From 17ddf484430b63d9e44e03add6d80a72778d8ae4 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 20:00:15 -0700 Subject: [PATCH 08/32] Removed redundant variable useage in advanced_logger.rs validation functions --- .../firmware/uefi_specs/src/hyperv/advanced_logger.rs | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs index 6783465b49..c54a292a98 100644 --- a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs +++ b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs @@ -94,10 +94,9 @@ impl AdvancedLoggerInfo { } // Check the log buffer size - let log_buffer_size = self.log_buffer_size; - if log_buffer_size > MAX_LOG_BUFFER_SIZE { + if self.log_buffer_size > MAX_LOG_BUFFER_SIZE { return Err(AdvancedLoggerInfoError::InvalidLogBufferSize( - log_buffer_size, + self.log_buffer_size, MAX_LOG_BUFFER_SIZE, )); } @@ -121,10 +120,9 @@ impl AdvancedLoggerMessageEntryV2 { } // Check the message length - let message_len = self.message_len; - if message_len > MAX_MESSAGE_LENGTH { + if self.message_len > MAX_MESSAGE_LENGTH { return Err(AdvancedLoggerEntryError::InvalidMessageLength( - message_len, + self.message_len, MAX_MESSAGE_LENGTH, )); } From 8be249629f716282463b40458e5b9cf3e4633181 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 20:07:36 -0700 Subject: [PATCH 09/32] Modified trace prefix message --- .../firmware/firmware_uefi/src/service/diagnostics.rs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 61330c964d..ab59deb801 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -288,7 +288,7 @@ impl UefiDevice { // Print the logs to the trace log for log in logs.iter() { tracelimit::info_ratelimited!( - "Diagnostics Log: Debug Level: {}, Timestamp: {}, Phase: {}, Message: {}", + "EFI Diagnostics: Debug Level: {}, Timestamp: {}, Phase: {}, Message: {}", log.debug_level, log.time_stamp, log.phase, @@ -296,8 +296,11 @@ impl UefiDevice { ); } } - Err(e) => { - tracelimit::error_ratelimited!("Diagnostics Error: {}", e); + Err(error) => { + tracelimit::error_ratelimited!( + "EFI Diagnostics: Encountered an error during processing {}", + error + ); } } From 20c08aa32916a7910158b654cdd9f0026433d41a Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 20:20:09 -0700 Subject: [PATCH 10/32] Switched to tracing::info!() instead --- vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index ab59deb801..70631718bd 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -287,7 +287,7 @@ impl UefiDevice { Ok(_) => { // Print the logs to the trace log for log in logs.iter() { - tracelimit::info_ratelimited!( + tracing::info!( "EFI Diagnostics: Debug Level: {}, Timestamp: {}, Phase: {}, Message: {}", log.debug_level, log.time_stamp, From 288dbeac1ebad94769e6fe89bc90fb89623193f9 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 20:28:23 -0700 Subject: [PATCH 11/32] fixed error strings --- .../firmware_uefi/src/service/diagnostics.rs | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 70631718bd..3c46a95e40 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -95,7 +95,7 @@ impl DiagnosticsServices { .checked_sub(header.log_buffer_offset) .ok_or_else(|| { DiagnosticsError(format!( - "Overflow: Log current offset ({:#x}) - Log buffer offset ({:#x})", + "Overflow: log_current_offset ({:#x}) - log_buffer_offset ({:#x})", header.log_current_offset as u32, header.log_buffer_offset as u32 )) })?; @@ -106,7 +106,7 @@ impl DiagnosticsServices { || used_log_buffer_size > MAX_LOG_BUFFER_SIZE { return Err(DiagnosticsError(format!( - "Invalid used log buffer size: {:#x}", + "Invalid used_log_buffer_size: {:#x}", used_log_buffer_size ))); } @@ -125,7 +125,7 @@ impl DiagnosticsServices { // Calculate start address of the log buffer let buffer_start_addr = gpa.checked_add(header.log_buffer_offset).ok_or_else(|| { DiagnosticsError(format!( - "Overflow: GPA ({:#x}) + Log buffer offset ({:#x})", + "Overflow: gpa ({:#x}) + log_buffer_offset ({:#x})", gpa, header.log_buffer_offset as u32 )) })?; @@ -134,14 +134,14 @@ impl DiagnosticsServices { gm.read_at(buffer_start_addr as u64, &mut buffer_data) .map_err(|_| { DiagnosticsError(format!( - "Failed to read log buffer at {:#x} with size {:#x}", + "Failed to read buffer_data at {:#x} with size {:#x}", buffer_start_addr, used_log_buffer_size )) })?; // Empty buffer data should early exit if buffer_data.is_empty() { - tracelimit::info_ratelimited!("Diagnostics buffer is empty, ending processing"); + tracelimit::info_ratelimited!("buffer_data is empty, ending processing"); return Ok(()); } @@ -154,7 +154,7 @@ impl DiagnosticsServices { let (entry, _) = AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice).map_err(|_| { DiagnosticsError(format!( - "Failed to read AdvancedLoggerMessageEntryV2 from buffer slice: {:?}", + "Failed to read AdvancedLoggerMessageEntryV2 from buffer_slice: {:?}", buffer_slice )) })?; @@ -202,7 +202,7 @@ impl DiagnosticsServices { // Validate that the accumulated message is not too long if accumulated_message.len() > MAX_MESSAGE_LENGTH as usize { return Err(DiagnosticsError(format!( - "Accumulated message length exceeds maximum: {}. Max: {}", + "accumulated_message exceeds maximum length: {}. Max: {}", accumulated_message.len(), MAX_MESSAGE_LENGTH ))); @@ -229,7 +229,7 @@ impl DiagnosticsServices { .checked_add(entry.message_len as usize) .ok_or_else(|| { DiagnosticsError(format!( - "Overflow: AdvancedLoggerMessageEntryV2 size ({}) + message length ({})", + "Overflow: AdvancedLoggerMessageEntryV2 size ({}) + message_len ({})", size_of::(), entry.message_len as u16 )) From 997cd1bb7296dc90fb5824a7a6db00cae1f06bdf Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 20:36:41 -0700 Subject: [PATCH 12/32] process diagnostics when UefiDevice stops or resets --- vm/devices/firmware/firmware_uefi/src/lib.rs | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index 1d57f73836..c34fe7953e 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -277,9 +277,13 @@ impl UefiDevice { impl ChangeDeviceState for UefiDevice { fn start(&mut self) {} - async fn stop(&mut self) {} + async fn stop(&mut self) { + self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); + } async fn reset(&mut self) { + self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); + self.address = 0; self.service.nvram.reset(); From 5956808a73a9a89739220f0f995e873099f4f510 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sat, 19 Apr 2025 20:56:17 -0700 Subject: [PATCH 13/32] Remove trailing newlines characters --- vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 3c46a95e40..1aea4e44b3 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -292,7 +292,7 @@ impl UefiDevice { log.debug_level, log.time_stamp, log.phase, - log.message + log.message.trim_end_matches(&['\r', '\n'][..]) // Remove trailing newlines ); } } From adb430739a31a08118e0b0fbc39978382f14f7ad Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sun, 20 Apr 2025 13:04:05 -0700 Subject: [PATCH 14/32] clippy fixes --- .../firmware_uefi/src/service/diagnostics.rs | 7 ++++- .../uefi_specs/src/hyperv/advanced_logger.rs | 28 ++++++++----------- 2 files changed, 18 insertions(+), 17 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 1aea4e44b3..65e93bc51d 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -11,7 +11,12 @@ use guestmem::GuestMemory; use inspect::Inspect; use std::fmt::Debug; use thiserror::Error; -use uefi_specs::hyperv::advanced_logger::*; +use uefi_specs::hyperv::advanced_logger::AdvancedLoggerEntryError; +use uefi_specs::hyperv::advanced_logger::AdvancedLoggerInfo; +use uefi_specs::hyperv::advanced_logger::AdvancedLoggerInfoError; +use uefi_specs::hyperv::advanced_logger::AdvancedLoggerMessageEntryV2; +use uefi_specs::hyperv::advanced_logger::MAX_LOG_BUFFER_SIZE; +use uefi_specs::hyperv::advanced_logger::MAX_MESSAGE_LENGTH; use zerocopy::FromBytes; // Every parsed advanced logger entry turns into this diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs index c54a292a98..91946e7ed8 100644 --- a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs +++ b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs @@ -11,24 +11,24 @@ use zerocopy::FromBytes; use zerocopy::Immutable; use zerocopy::KnownLayout; -// Errors for validating the Advanced Logger Info structure +// Validation errors for the Advanced Logger Info structure #[derive(Debug, Error)] pub enum AdvancedLoggerInfoError { #[error("Invalid header signature: {0:#x}, expected: {1:#x}")] - InvalidSignature(u32, u32), + Signature(u32, u32), #[error("Invalid log buffer size: {0:#x}, max: {1:#x}")] - InvalidLogBufferSize(u32, u32), + LogBufferSize(u32, u32), } -// Errors for validating the Advanced Logger Entry structure +// Validation errors for the Advanced Logger Entry structure #[derive(Debug, Error)] pub enum AdvancedLoggerEntryError { #[error("Invalid entry signature: {0:#x}, expected: {1:#x}")] - InvalidSignature(u32, u32), + Signature(u32, u32), #[error("Invalid timestamp: {0:#x}")] - InvalidTimestamp(u64), + Timestamp(u64), #[error("Invalid message length: {0:#x}, max: {1:#x}")] - InvalidMessageLength(u16, u16), + MessageLength(u16, u16), } // Advanced Logger Info validation constants @@ -88,14 +88,12 @@ impl AdvancedLoggerInfo { // Check the signature let signature = self.signature.to_le(); if signature != SIG_HEADER { - return Err(AdvancedLoggerInfoError::InvalidSignature( - signature, SIG_HEADER, - )); + return Err(AdvancedLoggerInfoError::Signature(signature, SIG_HEADER)); } // Check the log buffer size if self.log_buffer_size > MAX_LOG_BUFFER_SIZE { - return Err(AdvancedLoggerInfoError::InvalidLogBufferSize( + return Err(AdvancedLoggerInfoError::LogBufferSize( self.log_buffer_size, MAX_LOG_BUFFER_SIZE, )); @@ -109,19 +107,17 @@ impl AdvancedLoggerMessageEntryV2 { // Check the signature let signature = self.signature.to_le(); if signature != SIG_ENTRY { - return Err(AdvancedLoggerEntryError::InvalidSignature( - signature, SIG_ENTRY, - )); + return Err(AdvancedLoggerEntryError::Signature(signature, SIG_ENTRY)); } // Check the timestamp if self.time_stamp == 0 { - return Err(AdvancedLoggerEntryError::InvalidTimestamp(self.time_stamp)); + return Err(AdvancedLoggerEntryError::Timestamp(self.time_stamp)); } // Check the message length if self.message_len > MAX_MESSAGE_LENGTH { - return Err(AdvancedLoggerEntryError::InvalidMessageLength( + return Err(AdvancedLoggerEntryError::MessageLength( self.message_len, MAX_MESSAGE_LENGTH, )); From b06ba4141ba74e5d49ece02aa834a7f47124fd50 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Sun, 20 Apr 2025 13:15:33 -0700 Subject: [PATCH 15/32] use ALIGNMENT constant, handle remaining messages --- .../firmware_uefi/src/service/diagnostics.rs | 29 +++++++++++++++---- 1 file changed, 24 insertions(+), 5 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 65e93bc51d..bcaf763270 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -10,6 +10,7 @@ use crate::UefiDevice; use guestmem::GuestMemory; use inspect::Inspect; use std::fmt::Debug; +use std::mem::size_of; use thiserror::Error; use uefi_specs::hyperv::advanced_logger::AdvancedLoggerEntryError; use uefi_specs::hyperv::advanced_logger::AdvancedLoggerInfo; @@ -19,6 +20,10 @@ use uefi_specs::hyperv::advanced_logger::MAX_LOG_BUFFER_SIZE; use uefi_specs::hyperv::advanced_logger::MAX_MESSAGE_LENGTH; use zerocopy::FromBytes; +// Constants for parsing +const ALIGNMENT: usize = 8; +const ALIGNMENT_MASK: usize = ALIGNMENT - 1; + // Every parsed advanced logger entry turns into this pub struct EfiDiagnosticsLog { pub debug_level: u32, @@ -193,7 +198,7 @@ impl DiagnosticsServices { let message = String::from_utf8_lossy(&buffer_slice[message_start..message_end]); // - // Step 5a: Handle message accumulation + // Step 5b: Handle message accumulation // if !is_accumulating { debug_level = entry.debug_level; @@ -226,7 +231,7 @@ impl DiagnosticsServices { } // - // Step 5b: Move to the next entry + // Step 5c: Move to the next entry // // Calculate base offset (entry header size + message length) @@ -241,10 +246,13 @@ impl DiagnosticsServices { })?; // Add padding for 8-byte alignment - let aligned_offset = base_offset.checked_add(7).ok_or_else(|| { - DiagnosticsError(format!("Overflow: base_offset ({}) + 7", base_offset)) + let aligned_offset = base_offset.checked_add(ALIGNMENT_MASK).ok_or_else(|| { + DiagnosticsError(format!( + "Overflow: base_offset ({}) + {}", + base_offset, ALIGNMENT_MASK + )) })?; - let next_offset = aligned_offset & !7; + let next_offset = aligned_offset & !ALIGNMENT_MASK; // Update overall bytes read counter bytes_read = bytes_read.checked_add(next_offset).ok_or_else(|| { @@ -262,6 +270,17 @@ impl DiagnosticsServices { buffer_slice = &buffer_slice[next_offset..]; } + // Process remaining messages + if is_accumulating { + logs.push(EfiDiagnosticsLog { + debug_level, + time_stamp, + phase, + message: accumulated_message.clone(), + }); + entries_processed += 1; + } + // Print summary statistics tracelimit::info_ratelimited!( "EFI Diagnostics: Processed {} entries, Read {} bytes", From 866cf0efee77a69218d4d797ffef2cd7b304a4e2 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Mon, 21 Apr 2025 00:31:49 -0700 Subject: [PATCH 16/32] More clippy fixes, move functionality from specs to service, added todo of next steps --- Cargo.lock | 1 - .../firmware_uefi/src/service/diagnostics.rs | 206 +++++++++++++----- .../firmware_uefi/src/service/nvram/mod.rs | 2 +- vm/devices/firmware/uefi_specs/Cargo.toml | 1 - .../uefi_specs/src/hyperv/advanced_logger.rs | 78 +------ 5 files changed, 160 insertions(+), 128 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index cc32ae5820..e2660a10a3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7194,7 +7194,6 @@ dependencies = [ "inspect", "open_enum", "static_assertions", - "thiserror 2.0.12", "ucs2 0.0.0", "wchar", "zerocopy 0.8.23", diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index bcaf763270..36cf68727a 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -1,55 +1,146 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. -//! UEFI diagnostics subsystem +//! UEFI diagnostics service //! -//! This module stores the GPA of the efi dignostics buffer. -//! When signaled, the diagnostics buffer is parsed and written to -//! trace logs. +//! This service handles processing of the EFI diagnostics buffer, +//! producing friendly logs for any telemetry during the UEFI boot +//! process. +//! +//! The EFI diagnostics buffer follows the specification of Project Mu's +//! Advanced Logger package, whose relevant types are defined in the Hyper-V +//! specification within the uefi_specs crate. +//! +//! TODO: +//! - Document functions +//! - Add unit tests +//! - Change ProcessingError from struct to enum to be more granular +//! on the processing errors that occur? use crate::UefiDevice; use guestmem::GuestMemory; use inspect::Inspect; use std::fmt::Debug; use std::mem::size_of; use thiserror::Error; -use uefi_specs::hyperv::advanced_logger::AdvancedLoggerEntryError; use uefi_specs::hyperv::advanced_logger::AdvancedLoggerInfo; -use uefi_specs::hyperv::advanced_logger::AdvancedLoggerInfoError; use uefi_specs::hyperv::advanced_logger::AdvancedLoggerMessageEntryV2; -use uefi_specs::hyperv::advanced_logger::MAX_LOG_BUFFER_SIZE; -use uefi_specs::hyperv::advanced_logger::MAX_MESSAGE_LENGTH; +use uefi_specs::hyperv::advanced_logger::SIG_ENTRY; +use uefi_specs::hyperv::advanced_logger::SIG_HEADER; use zerocopy::FromBytes; +// // Constants for parsing +// const ALIGNMENT: usize = 8; const ALIGNMENT_MASK: usize = ALIGNMENT - 1; +pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB +pub const MAX_MESSAGE_LENGTH: u16 = 0x1000; // 4KB -// Every parsed advanced logger entry turns into this +// +// Represents a processed log entry from the EFI diagnostics buffer +// +#[derive(Debug, Clone)] pub struct EfiDiagnosticsLog { - pub debug_level: u32, - pub time_stamp: u64, - pub phase: u16, - pub message: String, + pub debug_level: u32, // The debug level of the log entry + pub time_stamp: u64, // Timestamp of when the log entry was created + pub phase: u16, // The boot phase that produced this log entry + pub message: String, // The log message itself +} + +// +// Error types for the advanced logger spec types +// +#[derive(Debug, Error)] +pub enum AdvancedLoggerInfoError { + #[error("Invalid header signature: {0:#x}, expected: {1:#x}")] + Signature(u32, u32), + #[error("Invalid log buffer size: {0:#x}, max: {1:#x}")] + LogBufferSize(u32, u32), +} + +#[derive(Debug, Error)] +pub enum AdvancedLoggerEntryError { + #[error("Invalid entry signature: {0:#x}, expected: {1:#x}")] + Signature(u32, u32), + #[error("Invalid timestamp: {0:#x}")] + Timestamp(u64), + #[error("Invalid message length: {0:#x}, max: {1:#x}")] + MessageLength(u16, u16), +} + +// +// Validation extension trait for the advanced logger spec types +// +pub trait Validateable { + type Error; + fn validate(&self) -> Result<(), Self::Error>; +} + +impl Validateable for AdvancedLoggerInfo { + type Error = AdvancedLoggerInfoError; + + fn validate(&self) -> Result<(), Self::Error> { + let signature = self.signature.to_le(); + if signature != SIG_HEADER { + return Err(AdvancedLoggerInfoError::Signature(signature, SIG_HEADER)); + } + + if self.log_buffer_size > MAX_LOG_BUFFER_SIZE { + return Err(AdvancedLoggerInfoError::LogBufferSize( + self.log_buffer_size, + MAX_LOG_BUFFER_SIZE, + )); + } + Ok(()) + } } -// For any errors that occur during processing +impl Validateable for AdvancedLoggerMessageEntryV2 { + type Error = AdvancedLoggerEntryError; + + fn validate(&self) -> Result<(), Self::Error> { + let signature = self.signature.to_le(); + if signature != SIG_ENTRY { + return Err(AdvancedLoggerEntryError::Signature(signature, SIG_ENTRY)); + } + + if self.time_stamp == 0 { + return Err(AdvancedLoggerEntryError::Timestamp(self.time_stamp)); + } + + if self.message_len > MAX_MESSAGE_LENGTH { + return Err(AdvancedLoggerEntryError::MessageLength( + self.message_len, + MAX_MESSAGE_LENGTH, + )); + } + Ok(()) + } +} + +// +// Generic error raised when processing the +// efi diagnostics buffer +// #[derive(Debug, Error)] #[error("{0}")] -pub struct DiagnosticsError(pub String); +pub struct ProcessingError(pub String); -impl From for DiagnosticsError { +impl From for ProcessingError { fn from(err: AdvancedLoggerInfoError) -> Self { - DiagnosticsError(err.to_string()) + ProcessingError(err.to_string()) } } -impl From for DiagnosticsError { +impl From for ProcessingError { fn from(err: AdvancedLoggerEntryError) -> Self { - DiagnosticsError(err.to_string()) + ProcessingError(err.to_string()) } } -// Holds necessary state for diagnostics services +// +// Define the state and functinality of this service +// #[derive(Inspect)] pub struct DiagnosticsServices {} @@ -62,9 +153,9 @@ impl DiagnosticsServices { // Does nothing } - fn validate_gpa(&self, gpa: u32) -> Result<(), DiagnosticsError> { + fn validate_gpa(&self, gpa: u32) -> Result<(), ProcessingError> { if gpa == 0 || gpa == u32::MAX { - return Err(DiagnosticsError(format!("Invalid GPA: {:#x}", gpa))); + return Err(ProcessingError(format!("Invalid GPA: {:#x}", gpa))); } Ok(()) } @@ -74,7 +165,7 @@ impl DiagnosticsServices { gpa: u32, gm: GuestMemory, logs: &mut Vec, - ) -> Result<(), DiagnosticsError> { + ) -> Result<(), ProcessingError> { // // Step 1: Validate GPA // @@ -84,7 +175,7 @@ impl DiagnosticsServices { // Step 2: Read and validate the advanced logger header // let header: AdvancedLoggerInfo = gm.read_plain(gpa as u64).map_err(|_| { - DiagnosticsError(format!("Failed to read AdvancedLoggerInfo at {:#x}", gpa)) + ProcessingError(format!("Failed to read AdvancedLoggerInfo at {:#x}", gpa)) })?; header.validate()?; @@ -99,14 +190,17 @@ impl DiagnosticsServices { let mut bytes_read: usize = 0; let mut entries_processed: usize = 0; - // Calculate used log buffer size - let used_log_buffer_size = header - .log_current_offset - .checked_sub(header.log_buffer_offset) + // Copy packed fields to local variables to avoid unaligned access + let log_current_offset = header.log_current_offset; + let log_buffer_offset = header.log_buffer_offset; + + // Calculate used log buffer size using the local variables + let used_log_buffer_size = log_current_offset + .checked_sub(log_buffer_offset) .ok_or_else(|| { - DiagnosticsError(format!( + ProcessingError(format!( "Overflow: log_current_offset ({:#x}) - log_buffer_offset ({:#x})", - header.log_current_offset as u32, header.log_buffer_offset as u32 + log_current_offset, log_buffer_offset )) })?; @@ -115,14 +209,14 @@ impl DiagnosticsServices { || used_log_buffer_size > header.log_buffer_size || used_log_buffer_size > MAX_LOG_BUFFER_SIZE { - return Err(DiagnosticsError(format!( + return Err(ProcessingError(format!( "Invalid used_log_buffer_size: {:#x}", used_log_buffer_size ))); } // Used for accumulating multiple messages - let mut accumulated_message = String::new(); + let mut accumulated_message = String::with_capacity(MAX_MESSAGE_LENGTH as usize); let mut debug_level = 0; let mut time_stamp = 0; let mut phase = 0; @@ -133,17 +227,17 @@ impl DiagnosticsServices { // // Calculate start address of the log buffer - let buffer_start_addr = gpa.checked_add(header.log_buffer_offset).ok_or_else(|| { - DiagnosticsError(format!( + let buffer_start_addr = gpa.checked_add(log_buffer_offset).ok_or_else(|| { + ProcessingError(format!( "Overflow: gpa ({:#x}) + log_buffer_offset ({:#x})", - gpa, header.log_buffer_offset as u32 + gpa, log_buffer_offset )) })?; let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; gm.read_at(buffer_start_addr as u64, &mut buffer_data) .map_err(|_| { - DiagnosticsError(format!( + ProcessingError(format!( "Failed to read buffer_data at {:#x} with size {:#x}", buffer_start_addr, used_log_buffer_size )) @@ -163,7 +257,7 @@ impl DiagnosticsServices { // Parse and validate the entry header let (entry, _) = AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice).map_err(|_| { - DiagnosticsError(format!( + ProcessingError(format!( "Failed to read AdvancedLoggerMessageEntryV2 from buffer_slice: {:?}", buffer_slice )) @@ -174,20 +268,24 @@ impl DiagnosticsServices { // Step 5a: Validate message boundaries // + // Copy packed fields to local variables to avoid unaligned access + let message_offset = entry.message_offset; + let message_len = entry.message_len; + // Calculate message start and end offsets - let message_start = entry.message_offset as usize; + let message_start = message_offset as usize; let message_end = message_start - .checked_add(entry.message_len as usize) + .checked_add(message_len as usize) .ok_or_else(|| { - DiagnosticsError(format!( + ProcessingError(format!( "Overflow: message_start ({}) + message_length ({})", - message_start, entry.message_len as u16 + message_start, message_len )) })?; // Validate message end fits within the buffer slice if message_end > buffer_slice.len() { - return Err(DiagnosticsError(format!( + return Err(ProcessingError(format!( "message_end exceeds buffer_slice: {} > {}", message_end, buffer_slice.len() @@ -211,20 +309,22 @@ impl DiagnosticsServices { // Validate that the accumulated message is not too long if accumulated_message.len() > MAX_MESSAGE_LENGTH as usize { - return Err(DiagnosticsError(format!( + return Err(ProcessingError(format!( "accumulated_message exceeds maximum length: {}. Max: {}", accumulated_message.len(), MAX_MESSAGE_LENGTH ))); } - // Print completed messages (ending with a newline) to the trace log + // Completed messages (ending with '\n') become log entries if !message.is_empty() && message.ends_with('\n') { logs.push(EfiDiagnosticsLog { debug_level, time_stamp, phase, - message: accumulated_message.clone(), + message: std::mem::take(&mut accumulated_message) + .trim_end_matches(&['\r', '\n'][..]) + .to_string(), }); entries_processed += 1; is_accumulating = false; @@ -236,18 +336,18 @@ impl DiagnosticsServices { // Calculate base offset (entry header size + message length) let base_offset = size_of::() - .checked_add(entry.message_len as usize) + .checked_add(message_len as usize) .ok_or_else(|| { - DiagnosticsError(format!( + ProcessingError(format!( "Overflow: AdvancedLoggerMessageEntryV2 size ({}) + message_len ({})", size_of::(), - entry.message_len as u16 + message_len )) })?; // Add padding for 8-byte alignment let aligned_offset = base_offset.checked_add(ALIGNMENT_MASK).ok_or_else(|| { - DiagnosticsError(format!( + ProcessingError(format!( "Overflow: base_offset ({}) + {}", base_offset, ALIGNMENT_MASK )) @@ -256,7 +356,7 @@ impl DiagnosticsServices { // Update overall bytes read counter bytes_read = bytes_read.checked_add(next_offset).ok_or_else(|| { - DiagnosticsError(format!( + ProcessingError(format!( "Overflow: bytes_read ({}) + next_offset ({})", bytes_read, next_offset )) @@ -276,7 +376,9 @@ impl DiagnosticsServices { debug_level, time_stamp, phase, - message: accumulated_message.clone(), + message: std::mem::take(&mut accumulated_message) + .trim_end_matches(&['\r', '\n'][..]) + .to_string(), }); entries_processed += 1; } @@ -316,7 +418,7 @@ impl UefiDevice { log.debug_level, log.time_stamp, log.phase, - log.message.trim_end_matches(&['\r', '\n'][..]) // Remove trailing newlines + log.message ); } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs index 8000333f70..9bf76369dd 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs @@ -572,7 +572,7 @@ impl UefiDevice { self.service.nvram.services.exit_boot_services(); // When exit boot services is called, process EFI diagnostics - let _ = self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); + self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); (EfiStatus::SUCCESS, None) } diff --git a/vm/devices/firmware/uefi_specs/Cargo.toml b/vm/devices/firmware/uefi_specs/Cargo.toml index 72bbe2d5ec..700f524cd6 100644 --- a/vm/devices/firmware/uefi_specs/Cargo.toml +++ b/vm/devices/firmware/uefi_specs/Cargo.toml @@ -18,7 +18,6 @@ open_enum.workspace = true ucs2.workspace = true bitfield-struct.workspace = true -thiserror.workspace = true static_assertions.workspace = true wchar.workspace = true zerocopy.workspace = true diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs index 91946e7ed8..660462a0ca 100644 --- a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs +++ b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs @@ -1,42 +1,17 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. -//! Types and constants defined for EFI diagnostics. -//! Many of these types come from the UEFI Advanced Logger -//! Package from Project Mu. - +//! Types and constants defined by Project Mu's Advanced Logger package, +//! used in the Hyper-V UEFI firmware. use crate::uefi::time::EFI_TIME; -use thiserror::Error; use zerocopy::FromBytes; use zerocopy::Immutable; use zerocopy::KnownLayout; -// Validation errors for the Advanced Logger Info structure -#[derive(Debug, Error)] -pub enum AdvancedLoggerInfoError { - #[error("Invalid header signature: {0:#x}, expected: {1:#x}")] - Signature(u32, u32), - #[error("Invalid log buffer size: {0:#x}, max: {1:#x}")] - LogBufferSize(u32, u32), -} - -// Validation errors for the Advanced Logger Entry structure -#[derive(Debug, Error)] -pub enum AdvancedLoggerEntryError { - #[error("Invalid entry signature: {0:#x}, expected: {1:#x}")] - Signature(u32, u32), - #[error("Invalid timestamp: {0:#x}")] - Timestamp(u64), - #[error("Invalid message length: {0:#x}, max: {1:#x}")] - MessageLength(u16, u16), -} - -// Advanced Logger Info validation constants -pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB +// Advanced Logger Info signature pub const SIG_HEADER: u32 = u32::from_le_bytes(*b"ALOG"); -// Advanced Logger Entry validation constants -pub const MAX_MESSAGE_LENGTH: u16 = 0x1000; // 4KB +// Advanced Logger Entry signature pub const SIG_ENTRY: u32 = u32::from_le_bytes(*b"ALM2"); // UEFI Advanced Logger Info Header, which is shared @@ -80,48 +55,5 @@ pub struct AdvancedLoggerMessageEntryV2 { pub phase: u16, // Boot phase that produced this message entry pub message_len: u16, // Number of bytes in Message pub message_offset: u16, // Offset of Message from start of structure - // Rust does not support flexible arrays, but message lives after -} - -impl AdvancedLoggerInfo { - pub fn validate(&self) -> Result<(), AdvancedLoggerInfoError> { - // Check the signature - let signature = self.signature.to_le(); - if signature != SIG_HEADER { - return Err(AdvancedLoggerInfoError::Signature(signature, SIG_HEADER)); - } - - // Check the log buffer size - if self.log_buffer_size > MAX_LOG_BUFFER_SIZE { - return Err(AdvancedLoggerInfoError::LogBufferSize( - self.log_buffer_size, - MAX_LOG_BUFFER_SIZE, - )); - } - Ok(()) - } -} - -impl AdvancedLoggerMessageEntryV2 { - pub fn validate(&self) -> Result<(), AdvancedLoggerEntryError> { - // Check the signature - let signature = self.signature.to_le(); - if signature != SIG_ENTRY { - return Err(AdvancedLoggerEntryError::Signature(signature, SIG_ENTRY)); - } - - // Check the timestamp - if self.time_stamp == 0 { - return Err(AdvancedLoggerEntryError::Timestamp(self.time_stamp)); - } - - // Check the message length - if self.message_len > MAX_MESSAGE_LENGTH { - return Err(AdvancedLoggerEntryError::MessageLength( - self.message_len, - MAX_MESSAGE_LENGTH, - )); - } - Ok(()) - } + // Rust prevents C flexible array members, but "message_text: [u8; _]" would be here } From 042d407998c098df498d61fa57bba0582f775f47 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Mon, 21 Apr 2025 14:16:21 -0700 Subject: [PATCH 17/32] Invalid UTF8 gives error, improve tracing::info!() when logging logs --- .../firmware_uefi/src/service/diagnostics.rs | 22 ++++++++++++------- 1 file changed, 14 insertions(+), 8 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 36cf68727a..48f0e1398d 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -293,7 +293,14 @@ impl DiagnosticsServices { } // Get the message - let message = String::from_utf8_lossy(&buffer_slice[message_start..message_end]); + let message = std::str::from_utf8(&buffer_slice[message_start..message_end]) + .map_err(|error| { + ProcessingError(format!( + "Invalid UTF-8 in message at offset {}: {}", + message_start, error + )) + })? + .to_string(); // // Step 5b: Handle message accumulation @@ -403,7 +410,7 @@ impl UefiDevice { } self.processed_diagnostics = true; - // Collect diagnostics logs + // Collect diagnostics logs and send to tracing let mut logs = Vec::new(); match self .service @@ -411,14 +418,13 @@ impl UefiDevice { .process_diagnostics(gpa, gm, &mut logs) { Ok(_) => { - // Print the logs to the trace log for log in logs.iter() { tracing::info!( - "EFI Diagnostics: Debug Level: {}, Timestamp: {}, Phase: {}, Message: {}", - log.debug_level, - log.time_stamp, - log.phase, - log.message + debug_level = log.debug_level, + timestamp = log.time_stamp, + phase = log.phase, + description = %log.message, + "EFI Diagnostics:" ); } } From af9299addd901fa973cefae51239eeefd5d20e98 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Mon, 21 Apr 2025 16:45:36 -0700 Subject: [PATCH 18/32] Improved error handling v2 --- .../firmware_uefi/src/service/diagnostics.rs | 135 +++++++++--------- 1 file changed, 67 insertions(+), 68 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 48f0e1398d..41d15921a7 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -12,12 +12,13 @@ //! specification within the uefi_specs crate. //! //! TODO: +//! - Move state from UefiDevice to diagnostics service +//! - Introduce a block_processing flag, who gets set after EBS //! - Document functions //! - Add unit tests -//! - Change ProcessingError from struct to enum to be more granular -//! on the processing errors that occur? use crate::UefiDevice; use guestmem::GuestMemory; +use guestmem::GuestMemoryError; use inspect::Inspect; use std::fmt::Debug; use std::mem::size_of; @@ -48,7 +49,7 @@ pub struct EfiDiagnosticsLog { } // -// Error types for the advanced logger spec types +// Validation error types for the advanced logger spec types // #[derive(Debug, Error)] pub enum AdvancedLoggerInfoError { @@ -59,7 +60,7 @@ pub enum AdvancedLoggerInfoError { } #[derive(Debug, Error)] -pub enum AdvancedLoggerEntryError { +pub enum AdvancedLoggerMessageEntryV2Error { #[error("Invalid entry signature: {0:#x}, expected: {1:#x}")] Signature(u32, u32), #[error("Invalid timestamp: {0:#x}")] @@ -96,20 +97,24 @@ impl Validateable for AdvancedLoggerInfo { } impl Validateable for AdvancedLoggerMessageEntryV2 { - type Error = AdvancedLoggerEntryError; + type Error = AdvancedLoggerMessageEntryV2Error; fn validate(&self) -> Result<(), Self::Error> { let signature = self.signature.to_le(); if signature != SIG_ENTRY { - return Err(AdvancedLoggerEntryError::Signature(signature, SIG_ENTRY)); + return Err(AdvancedLoggerMessageEntryV2Error::Signature( + signature, SIG_ENTRY, + )); } if self.time_stamp == 0 { - return Err(AdvancedLoggerEntryError::Timestamp(self.time_stamp)); + return Err(AdvancedLoggerMessageEntryV2Error::Timestamp( + self.time_stamp, + )); } if self.message_len > MAX_MESSAGE_LENGTH { - return Err(AdvancedLoggerEntryError::MessageLength( + return Err(AdvancedLoggerMessageEntryV2Error::MessageLength( self.message_len, MAX_MESSAGE_LENGTH, )); @@ -118,24 +123,33 @@ impl Validateable for AdvancedLoggerMessageEntryV2 { } } -// -// Generic error raised when processing the -// efi diagnostics buffer -// +/// Errors that occur during processing +/// TODO: Add more specific error types #[derive(Debug, Error)] -#[error("{0}")] -pub struct ProcessingError(pub String); +pub enum DiagnosticsError { + #[error("Bad GPA value: {0:#x}")] + BadGpa(u32), -impl From for ProcessingError { - fn from(err: AdvancedLoggerInfoError) -> Self { - ProcessingError(err.to_string()) - } -} + #[error("Failed to read from guest memory: {0}")] + GuestMemoryRead(#[from] GuestMemoryError), -impl From for ProcessingError { - fn from(err: AdvancedLoggerEntryError) -> Self { - ProcessingError(err.to_string()) - } + #[error("Invalid UTF-8 in message: {0}")] + Utf8Error(#[from] std::str::Utf8Error), + + #[error("Encountered arithmetic overflow: {0}")] + Overflow(String), + + #[error("Faild to validate AdvancedLoggerInfo: {0}")] + HeaderValidation(#[from] AdvancedLoggerInfoError), + + #[error("Failed to validate AdvancedLoggerMessageEntryV2: {0}")] + EntryValidation(#[from] AdvancedLoggerMessageEntryV2Error), + + #[error("Failed to read buffer data: {0}")] + BoundsError(#[from] std::io::Error), + + #[error("General error: {0}")] + GeneralError(String), } // @@ -153,9 +167,9 @@ impl DiagnosticsServices { // Does nothing } - fn validate_gpa(&self, gpa: u32) -> Result<(), ProcessingError> { + fn validate_gpa(&self, gpa: u32) -> Result<(), DiagnosticsError> { if gpa == 0 || gpa == u32::MAX { - return Err(ProcessingError(format!("Invalid GPA: {:#x}", gpa))); + return Err(DiagnosticsError::BadGpa(gpa)); } Ok(()) } @@ -165,7 +179,7 @@ impl DiagnosticsServices { gpa: u32, gm: GuestMemory, logs: &mut Vec, - ) -> Result<(), ProcessingError> { + ) -> Result<(), DiagnosticsError> { // // Step 1: Validate GPA // @@ -174,9 +188,7 @@ impl DiagnosticsServices { // // Step 2: Read and validate the advanced logger header // - let header: AdvancedLoggerInfo = gm.read_plain(gpa as u64).map_err(|_| { - ProcessingError(format!("Failed to read AdvancedLoggerInfo at {:#x}", gpa)) - })?; + let header: AdvancedLoggerInfo = gm.read_plain(gpa as u64)?; header.validate()?; // @@ -198,8 +210,8 @@ impl DiagnosticsServices { let used_log_buffer_size = log_current_offset .checked_sub(log_buffer_offset) .ok_or_else(|| { - ProcessingError(format!( - "Overflow: log_current_offset ({:#x}) - log_buffer_offset ({:#x})", + DiagnosticsError::Overflow(format!( + "log_current_offset ({:#x}) - log_buffer_offset ({:#x})", log_current_offset, log_buffer_offset )) })?; @@ -209,9 +221,9 @@ impl DiagnosticsServices { || used_log_buffer_size > header.log_buffer_size || used_log_buffer_size > MAX_LOG_BUFFER_SIZE { - return Err(ProcessingError(format!( - "Invalid used_log_buffer_size: {:#x}", - used_log_buffer_size + return Err(DiagnosticsError::GeneralError(format!( + "Invalid used log buffer size: {:#x}, max: {:#x}", + used_log_buffer_size, MAX_LOG_BUFFER_SIZE ))); } @@ -228,20 +240,14 @@ impl DiagnosticsServices { // Calculate start address of the log buffer let buffer_start_addr = gpa.checked_add(log_buffer_offset).ok_or_else(|| { - ProcessingError(format!( - "Overflow: gpa ({:#x}) + log_buffer_offset ({:#x})", + DiagnosticsError::Overflow(format!( + "gpa ({:#x}) + log_buffer_offset ({:#x})", gpa, log_buffer_offset )) })?; let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; - gm.read_at(buffer_start_addr as u64, &mut buffer_data) - .map_err(|_| { - ProcessingError(format!( - "Failed to read buffer_data at {:#x} with size {:#x}", - buffer_start_addr, used_log_buffer_size - )) - })?; + gm.read_at(buffer_start_addr as u64, &mut buffer_data)?; // Empty buffer data should early exit if buffer_data.is_empty() { @@ -256,10 +262,10 @@ impl DiagnosticsServices { while !buffer_slice.is_empty() { // Parse and validate the entry header let (entry, _) = - AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice).map_err(|_| { - ProcessingError(format!( - "Failed to read AdvancedLoggerMessageEntryV2 from buffer_slice: {:?}", - buffer_slice + AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice).map_err(|error| { + DiagnosticsError::GeneralError(format!( + "Failed to parse entry from buffer_slice: {}", + error )) })?; entry.validate()?; @@ -277,30 +283,23 @@ impl DiagnosticsServices { let message_end = message_start .checked_add(message_len as usize) .ok_or_else(|| { - ProcessingError(format!( - "Overflow: message_start ({}) + message_length ({})", + DiagnosticsError::Overflow(format!( + "message_start ({}) + message_len ({})", message_start, message_len )) })?; // Validate message end fits within the buffer slice if message_end > buffer_slice.len() { - return Err(ProcessingError(format!( - "message_end exceeds buffer_slice: {} > {}", + return Err(DiagnosticsError::GeneralError(format!( + "message_end ({}) exceeds buffer slice length ({})", message_end, buffer_slice.len() ))); } // Get the message - let message = std::str::from_utf8(&buffer_slice[message_start..message_end]) - .map_err(|error| { - ProcessingError(format!( - "Invalid UTF-8 in message at offset {}: {}", - message_start, error - )) - })? - .to_string(); + let message = std::str::from_utf8(&buffer_slice[message_start..message_end])?; // // Step 5b: Handle message accumulation @@ -312,12 +311,12 @@ impl DiagnosticsServices { accumulated_message.clear(); is_accumulating = true; } - accumulated_message.push_str(&message); + accumulated_message.push_str(message); // Validate that the accumulated message is not too long if accumulated_message.len() > MAX_MESSAGE_LENGTH as usize { - return Err(ProcessingError(format!( - "accumulated_message exceeds maximum length: {}. Max: {}", + return Err(DiagnosticsError::GeneralError(format!( + "Accumulated message length ({}) exceeds max length ({})", accumulated_message.len(), MAX_MESSAGE_LENGTH ))); @@ -345,8 +344,8 @@ impl DiagnosticsServices { let base_offset = size_of::() .checked_add(message_len as usize) .ok_or_else(|| { - ProcessingError(format!( - "Overflow: AdvancedLoggerMessageEntryV2 size ({}) + message_len ({})", + DiagnosticsError::Overflow(format!( + "size_of:: ({}) + message_len ({})", size_of::(), message_len )) @@ -354,8 +353,8 @@ impl DiagnosticsServices { // Add padding for 8-byte alignment let aligned_offset = base_offset.checked_add(ALIGNMENT_MASK).ok_or_else(|| { - ProcessingError(format!( - "Overflow: base_offset ({}) + {}", + DiagnosticsError::Overflow(format!( + "base_offset ({}) + ALIGNMENT_MASK ({})", base_offset, ALIGNMENT_MASK )) })?; @@ -363,8 +362,8 @@ impl DiagnosticsServices { // Update overall bytes read counter bytes_read = bytes_read.checked_add(next_offset).ok_or_else(|| { - ProcessingError(format!( - "Overflow: bytes_read ({}) + next_offset ({})", + DiagnosticsError::Overflow(format!( + "bytes_read ({}) + next_offset ({})", bytes_read, next_offset )) })?; From 8cdc11ab6fea4d27d176ebf350330474b8a75873 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Mon, 21 Apr 2025 16:49:14 -0700 Subject: [PATCH 19/32] changes tracelimit error when a diagnostics error occurs --- vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 41d15921a7..135516478c 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -429,8 +429,8 @@ impl UefiDevice { } Err(error) => { tracelimit::error_ratelimited!( - "EFI Diagnostics: Encountered an error during processing {}", - error + error = &error as &dyn std::error::Error, + "EFI Diagnostics: Failed to process diagnostics buffer" ); } } From 7910dc9be8ba6b84bc4d91442e02f144071e8a99 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Mon, 21 Apr 2025 17:27:06 -0700 Subject: [PATCH 20/32] Moved diagnostics state to service, changed to ebs_complete flag --- vm/devices/firmware/firmware_uefi/src/lib.rs | 25 +---- .../firmware_uefi/src/service/diagnostics.rs | 103 ++++++++++++------ .../firmware_uefi/src/service/nvram/mod.rs | 6 +- 3 files changed, 74 insertions(+), 60 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index c34fe7953e..e77e554f3d 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -155,13 +155,6 @@ pub struct UefiDevice { // Volatile state #[inspect(hex)] address: u32, - - // Diagnostics state - #[inspect(mut)] - diagnostics_gpa: u32, - - #[inspect(mut)] - processed_diagnostics: bool, } impl UefiDevice { @@ -209,8 +202,6 @@ impl UefiDevice { time: service::time::TimeServices::new(time_source), diagnostics: service::diagnostics::DiagnosticsServices::new(), }, - diagnostics_gpa: 0, - processed_diagnostics: false, }; Ok(uefi) } @@ -263,12 +254,8 @@ impl UefiDevice { ); } } - UefiCommand::SET_EFI_DIAGNOSTICS_GPA => { - self.diagnostics_gpa = data; - } - UefiCommand::PROCESS_EFI_DIAGNOSTICS => { - self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()) - } + UefiCommand::SET_EFI_DIAGNOSTICS_GPA => self.service.diagnostics.set_gpa(data), + UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(self.gm.clone()), _ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"), } } @@ -277,13 +264,9 @@ impl UefiDevice { impl ChangeDeviceState for UefiDevice { fn start(&mut self) {} - async fn stop(&mut self) { - self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); - } + async fn stop(&mut self) {} async fn reset(&mut self) { - self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); - self.address = 0; self.service.nvram.reset(); @@ -506,8 +489,6 @@ mod save_restore { diagnostics, }, address, - diagnostics_gpa: _, - processed_diagnostics: _, } = self; Ok(state::SavedState { diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 135516478c..77b07a73ff 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -12,9 +12,7 @@ //! specification within the uefi_specs crate. //! //! TODO: -//! - Move state from UefiDevice to diagnostics service -//! - Introduce a block_processing flag, who gets set after EBS -//! - Document functions +//! - Add more doc comments //! - Add unit tests use crate::UefiDevice; use guestmem::GuestMemory; @@ -139,7 +137,7 @@ pub enum DiagnosticsError { #[error("Encountered arithmetic overflow: {0}")] Overflow(String), - #[error("Faild to validate AdvancedLoggerInfo: {0}")] + #[error("Failed to validate AdvancedLoggerInfo: {0}")] HeaderValidation(#[from] AdvancedLoggerInfoError), #[error("Failed to validate AdvancedLoggerMessageEntryV2: {0}")] @@ -152,38 +150,65 @@ pub enum DiagnosticsError { GeneralError(String), } -// -// Define the state and functinality of this service -// +/// Definition of the diagnostics services state #[derive(Inspect)] -pub struct DiagnosticsServices {} +pub struct DiagnosticsServices { + gpa: Option, // The guest physical address of the diagnostics buffer + ebs_complete: bool, // Flag indicating if ExitBootServices has been reached +} impl DiagnosticsServices { + /// Create a new instance of the diagnostics services pub fn new() -> DiagnosticsServices { - DiagnosticsServices {} + DiagnosticsServices { + gpa: None, + ebs_complete: false, + } } + /// Reset the diagnostics services state pub fn reset(&mut self) { - // Does nothing + self.gpa = None; + self.ebs_complete = false; } - fn validate_gpa(&self, gpa: u32) -> Result<(), DiagnosticsError> { - if gpa == 0 || gpa == u32::MAX { - return Err(DiagnosticsError::BadGpa(gpa)); + /// Set the GPA of the diagnostics buffer + pub fn set_gpa(&mut self, gpa: u32) { + self.gpa = match gpa { + 0 => None, + _ => Some(gpa), } - Ok(()) } + /// Mark the Exit Boot Services (EBS) event complete + pub fn set_ebs_complete(&mut self) { + self.ebs_complete = true; + } + + /// Process the diagnostics buffer into friendly logs pub fn process_diagnostics( &self, - gpa: u32, gm: GuestMemory, logs: &mut Vec, ) -> Result<(), DiagnosticsError> { + // Do not proceed if we have encountered ExitBootServices + if self.ebs_complete { + tracelimit::warn_ratelimited!("Diagnostics: EBS complete, skipping processing"); + return Ok(()); + } + // // Step 1: Validate GPA // - self.validate_gpa(gpa)?; + let gpa = match self.gpa { + Some(gpa) if gpa != 0 && gpa != u32::MAX => gpa, + Some(invalid_gpa) => return Err(DiagnosticsError::BadGpa(invalid_gpa)), + None => { + return Err(DiagnosticsError::GeneralError( + "No diagnostics GPA set".to_string(), + )); + } + }; // // Step 2: Read and validate the advanced logger header @@ -401,21 +426,11 @@ impl DiagnosticsServices { } impl UefiDevice { - pub(crate) fn process_diagnostics(&mut self, gpa: u32, gm: GuestMemory) { - // Do not process if already done - if self.processed_diagnostics { - tracelimit::info_ratelimited!("EFI Diagnostics already processed, skipping"); - return; - } - self.processed_diagnostics = true; - + /// Process the diagnostics buffer and log the entries to tracing + pub(crate) fn process_diagnostics(&mut self, gm: GuestMemory) { // Collect diagnostics logs and send to tracing let mut logs = Vec::new(); - match self - .service - .diagnostics - .process_diagnostics(gpa, gm, &mut logs) - { + match self.service.diagnostics.process_diagnostics(gm, &mut logs) { Ok(_) => { for log in logs.iter() { tracing::info!( @@ -434,27 +449,43 @@ impl UefiDevice { ); } } - - // Reset stored gpa - self.diagnostics_gpa = 0; } } mod save_restore { use super::*; - use vmcore::save_restore::NoSavedState; use vmcore::save_restore::RestoreError; use vmcore::save_restore::SaveError; use vmcore::save_restore::SaveRestore; + mod state { + use mesh::payload::Protobuf; + use vmcore::save_restore::SavedStateRoot; + + #[derive(Protobuf, SavedStateRoot)] + #[mesh(package = "firmware.uefi.diagnostics")] + pub struct SavedState { + #[mesh(1)] + pub gpa: Option, + #[mesh(2)] + pub ebs_complete: bool, + } + } + impl SaveRestore for DiagnosticsServices { - type SavedState = NoSavedState; + type SavedState = state::SavedState; fn save(&mut self) -> Result { - Ok(NoSavedState) + Ok(state::SavedState { + gpa: self.gpa, + ebs_complete: self.ebs_complete, + }) } - fn restore(&mut self, NoSavedState: Self::SavedState) -> Result<(), RestoreError> { + fn restore(&mut self, state: Self::SavedState) -> Result<(), RestoreError> { + let state::SavedState { gpa, ebs_complete } = state; + self.gpa = gpa; + self.ebs_complete = ebs_complete; Ok(()) } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs index 9bf76369dd..8bde6b9765 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs @@ -571,8 +571,10 @@ impl UefiDevice { } self.service.nvram.services.exit_boot_services(); - // When exit boot services is called, process EFI diagnostics - self.process_diagnostics(self.diagnostics_gpa, self.gm.clone()); + // Process efi diagnostics and set the ebs complete flag + // to prevent double processing. + self.process_diagnostics(self.gm.clone()); + self.service.diagnostics.set_ebs_complete(); (EfiStatus::SUCCESS, None) } From 79db679c965625171c72870a687f6d9cce40a2f8 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Tue, 22 Apr 2025 16:54:37 -0700 Subject: [PATCH 21/32] Publicize runtime state and use that instead of ebs_complete --- vm/devices/firmware/firmware_uefi/src/lib.rs | 2 +- .../firmware_uefi/src/service/diagnostics.rs | 40 ++++++------------- .../firmware_uefi/src/service/nvram/mod.rs | 8 +--- .../src/service/nvram/spec_services/mod.rs | 10 ++--- 4 files changed, 20 insertions(+), 40 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index e77e554f3d..a7b0be204b 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -255,7 +255,7 @@ impl UefiDevice { } } UefiCommand::SET_EFI_DIAGNOSTICS_GPA => self.service.diagnostics.set_gpa(data), - UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(self.gm.clone()), + UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(&self.gm), _ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"), } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 77b07a73ff..339357f1e2 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -153,23 +153,18 @@ pub enum DiagnosticsError { /// Definition of the diagnostics services state #[derive(Inspect)] pub struct DiagnosticsServices { - gpa: Option, // The guest physical address of the diagnostics buffer - ebs_complete: bool, // Flag indicating if ExitBootServices has been reached + gpa: Option, // The guest physical address of the diagnostics buffer } impl DiagnosticsServices { /// Create a new instance of the diagnostics services pub fn new() -> DiagnosticsServices { - DiagnosticsServices { - gpa: None, - ebs_complete: false, - } + DiagnosticsServices { gpa: None } } /// Reset the diagnostics services state pub fn reset(&mut self) { self.gpa = None; - self.ebs_complete = false; } /// Set the GPA of the diagnostics buffer @@ -180,23 +175,12 @@ impl DiagnosticsServices { } } - /// Mark the Exit Boot Services (EBS) event complete - pub fn set_ebs_complete(&mut self) { - self.ebs_complete = true; - } - /// Process the diagnostics buffer into friendly logs pub fn process_diagnostics( &self, - gm: GuestMemory, + gm: &GuestMemory, logs: &mut Vec, ) -> Result<(), DiagnosticsError> { - // Do not proceed if we have encountered ExitBootServices - if self.ebs_complete { - tracelimit::warn_ratelimited!("Diagnostics: EBS complete, skipping processing"); - return Ok(()); - } - // // Step 1: Validate GPA // @@ -427,7 +411,13 @@ impl DiagnosticsServices { impl UefiDevice { /// Process the diagnostics buffer and log the entries to tracing - pub(crate) fn process_diagnostics(&mut self, gm: GuestMemory) { + pub(crate) fn process_diagnostics(&self, gm: &GuestMemory) { + // Do not proceed if we have encountered ExitBootServices + if self.service.nvram.services.runtime_state.is_runtime() { + tracelimit::warn_ratelimited!("EFI Diagnostics: EBS complete, skipping processing"); + return; + } + // Collect diagnostics logs and send to tracing let mut logs = Vec::new(); match self.service.diagnostics.process_diagnostics(gm, &mut logs) { @@ -467,8 +457,6 @@ mod save_restore { pub struct SavedState { #[mesh(1)] pub gpa: Option, - #[mesh(2)] - pub ebs_complete: bool, } } @@ -476,16 +464,12 @@ mod save_restore { type SavedState = state::SavedState; fn save(&mut self) -> Result { - Ok(state::SavedState { - gpa: self.gpa, - ebs_complete: self.ebs_complete, - }) + Ok(state::SavedState { gpa: self.gpa }) } fn restore(&mut self, state: Self::SavedState) -> Result<(), RestoreError> { - let state::SavedState { gpa, ebs_complete } = state; + let state::SavedState { gpa } = state; self.gpa = gpa; - self.ebs_complete = ebs_complete; Ok(()) } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs index 8bde6b9765..3c3886c414 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs @@ -67,7 +67,7 @@ pub struct NvramServices { // Sub-emulators #[inspect(flatten)] - services: NvramSpecServices>, + pub services: NvramSpecServices>, } impl NvramServices { @@ -569,13 +569,9 @@ impl UefiDevice { vsm.revoke_guest_vsm() } } + self.process_diagnostics(&self.gm); self.service.nvram.services.exit_boot_services(); - // Process efi diagnostics and set the ebs complete flag - // to prevent double processing. - self.process_diagnostics(self.gm.clone()); - self.service.diagnostics.set_ebs_complete(); - (EfiStatus::SUCCESS, None) } NvramCommand::DEBUG_STRING => { diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs index ac2459c7b2..7b2c14c354 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs @@ -180,7 +180,7 @@ where } #[derive(Clone, Copy, Debug, Protobuf, Inspect)] -enum RuntimeState { +pub enum RuntimeState { /// Implementation-specific state, whereby certain read-only and /// authenticated variable checks are bypassed. /// @@ -194,15 +194,15 @@ enum RuntimeState { } impl RuntimeState { - fn is_pre_boot(&self) -> bool { + pub fn is_pre_boot(&self) -> bool { matches!(&self, RuntimeState::PreBoot) } - fn is_boot(&self) -> bool { + pub fn is_boot(&self) -> bool { matches!(&self, RuntimeState::Boot) } - fn is_runtime(&self) -> bool { + pub fn is_runtime(&self) -> bool { matches!(&self, RuntimeState::Runtime) } } @@ -226,7 +226,7 @@ impl RuntimeState { #[derive(Debug, Inspect)] pub struct NvramSpecServices { storage: S, - runtime_state: RuntimeState, + pub runtime_state: RuntimeState, } impl NvramSpecServices { From 5132b02eef71d6b3bfa16d3770a9c295608b6da8 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Tue, 22 Apr 2025 16:59:34 -0700 Subject: [PATCH 22/32] Fixed Validator spelling --- .../firmware/firmware_uefi/src/service/diagnostics.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 339357f1e2..43e96591fb 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -70,12 +70,12 @@ pub enum AdvancedLoggerMessageEntryV2Error { // // Validation extension trait for the advanced logger spec types // -pub trait Validateable { +pub trait Validator { type Error; fn validate(&self) -> Result<(), Self::Error>; } -impl Validateable for AdvancedLoggerInfo { +impl Validator for AdvancedLoggerInfo { type Error = AdvancedLoggerInfoError; fn validate(&self) -> Result<(), Self::Error> { @@ -94,7 +94,7 @@ impl Validateable for AdvancedLoggerInfo { } } -impl Validateable for AdvancedLoggerMessageEntryV2 { +impl Validator for AdvancedLoggerMessageEntryV2 { type Error = AdvancedLoggerMessageEntryV2Error; fn validate(&self) -> Result<(), Self::Error> { From 8a6b62aa7e133389dd10b1899c12cd241981dd62 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Wed, 23 Apr 2025 15:50:56 -0700 Subject: [PATCH 23/32] Update mu_msvm version --- flowey/flowey_lib_hvlite/src/_jobs/cfg_versions.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/flowey/flowey_lib_hvlite/src/_jobs/cfg_versions.rs b/flowey/flowey_lib_hvlite/src/_jobs/cfg_versions.rs index ffacf3e58e..cbacce0ed2 100644 --- a/flowey/flowey_lib_hvlite/src/_jobs/cfg_versions.rs +++ b/flowey/flowey_lib_hvlite/src/_jobs/cfg_versions.rs @@ -23,7 +23,7 @@ pub const MDBOOK: &str = "0.4.40"; pub const MDBOOK_ADMONISH: &str = "1.18.0"; pub const MDBOOK_MERMAID: &str = "0.14.0"; pub const RUSTUP_TOOLCHAIN: &str = "1.86.0"; -pub const MU_MSVM: &str = "24.0.4"; +pub const MU_MSVM: &str = "25.0.1"; pub const NEXTEST: &str = "0.9.74"; pub const NODEJS: &str = "18.x"; pub const OPENHCL_KERNEL_DEV_VERSION: &str = "6.6.63.2"; From cac77ad19cfa270a61a22819ebc485c078245a4e Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Thu, 24 Apr 2025 14:43:06 -0700 Subject: [PATCH 24/32] Changed message to description, clarified units for timestamp, use anon function for tracing --- .../firmware_uefi/src/service/diagnostics.rs | 55 +++++++++---------- 1 file changed, 26 insertions(+), 29 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 43e96591fb..82db7b5cea 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -40,10 +40,10 @@ pub const MAX_MESSAGE_LENGTH: u16 = 0x1000; // 4KB // #[derive(Debug, Clone)] pub struct EfiDiagnosticsLog { - pub debug_level: u32, // The debug level of the log entry - pub time_stamp: u64, // Timestamp of when the log entry was created - pub phase: u16, // The boot phase that produced this log entry - pub message: String, // The log message itself + pub debug_level: u32, // The debug level of the log entry + pub time_stamp: u64, // Timestamp of when the log entry was created + pub phase: u16, // The boot phase that produced this log entry + pub description: String, // The log message itself } // @@ -176,11 +176,14 @@ impl DiagnosticsServices { } /// Process the diagnostics buffer into friendly logs - pub fn process_diagnostics( + pub fn process_diagnostics( &self, gm: &GuestMemory, - logs: &mut Vec, - ) -> Result<(), DiagnosticsError> { + mut log_handler: F, + ) -> Result<(), DiagnosticsError> + where + F: FnMut(EfiDiagnosticsLog), + { // // Step 1: Validate GPA // @@ -204,9 +207,6 @@ impl DiagnosticsServices { // Step 3: Prepare processing variables // - // Force clear the logs - logs.clear(); - // Used for summary statistics let mut bytes_read: usize = 0; let mut entries_processed: usize = 0; @@ -331,13 +331,13 @@ impl DiagnosticsServices { ))); } - // Completed messages (ending with '\n') become log entries + // Handle completed messages (ending with '\n') if !message.is_empty() && message.ends_with('\n') { - logs.push(EfiDiagnosticsLog { + log_handler(EfiDiagnosticsLog { debug_level, time_stamp, phase, - message: std::mem::take(&mut accumulated_message) + description: std::mem::take(&mut accumulated_message) .trim_end_matches(&['\r', '\n'][..]) .to_string(), }); @@ -387,11 +387,11 @@ impl DiagnosticsServices { // Process remaining messages if is_accumulating { - logs.push(EfiDiagnosticsLog { + log_handler(EfiDiagnosticsLog { debug_level, time_stamp, phase, - message: std::mem::take(&mut accumulated_message) + description: std::mem::take(&mut accumulated_message) .trim_end_matches(&['\r', '\n'][..]) .to_string(), }); @@ -418,20 +418,17 @@ impl UefiDevice { return; } - // Collect diagnostics logs and send to tracing - let mut logs = Vec::new(); - match self.service.diagnostics.process_diagnostics(gm, &mut logs) { - Ok(_) => { - for log in logs.iter() { - tracing::info!( - debug_level = log.debug_level, - timestamp = log.time_stamp, - phase = log.phase, - description = %log.message, - "EFI Diagnostics:" - ); - } - } + // Process diagnostics logs and send each directly to tracing + match self.service.diagnostics.process_diagnostics(gm, |log| { + tracing::info!( + debug_level = log.debug_level, + time_stamp_ticks = log.time_stamp, + phase = log.phase, + description = %log.description, + "EFI Diagnostics:" + ); + }) { + Ok(_) => {} Err(error) => { tracelimit::error_ratelimited!( error = &error as &dyn std::error::Error, From bc1bb381c822fa69481e8e008bafdea0966689eb Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Thu, 24 Apr 2025 16:17:27 -0700 Subject: [PATCH 25/32] Separate entry processing to its own function, clarify doc comments, improve errors v3 w/ anyhow --- Cargo.lock | 1 + vm/devices/firmware/firmware_uefi/Cargo.toml | 1 + .../firmware_uefi/src/service/diagnostics.rs | 412 +++++++++--------- 3 files changed, 197 insertions(+), 217 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index afc1a7559c..50610ddd64 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1687,6 +1687,7 @@ dependencies = [ name = "firmware_uefi" version = "0.0.0" dependencies = [ + "anyhow", "async-trait", "bitfield-struct 0.10.1", "chipset_device", diff --git a/vm/devices/firmware/firmware_uefi/Cargo.toml b/vm/devices/firmware/firmware_uefi/Cargo.toml index dca17b1d6d..337956a046 100644 --- a/vm/devices/firmware/firmware_uefi/Cargo.toml +++ b/vm/devices/firmware/firmware_uefi/Cargo.toml @@ -40,6 +40,7 @@ open_enum.workspace = true pal_async.workspace = true ucs2.workspace = true +anyhow.workspace = true async-trait.workspace = true bitfield-struct.workspace = true der = { workspace = true, features = ["derive", "alloc", "oid"], optional = true } diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 82db7b5cea..896dc443ed 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -12,9 +12,9 @@ //! specification within the uefi_specs crate. //! //! TODO: -//! - Add more doc comments //! - Add unit tests use crate::UefiDevice; +use anyhow::anyhow; use guestmem::GuestMemory; use guestmem::GuestMemoryError; use inspect::Inspect; @@ -27,17 +27,13 @@ use uefi_specs::hyperv::advanced_logger::SIG_ENTRY; use uefi_specs::hyperv::advanced_logger::SIG_HEADER; use zerocopy::FromBytes; -// -// Constants for parsing -// -const ALIGNMENT: usize = 8; -const ALIGNMENT_MASK: usize = ALIGNMENT - 1; +// Constants for processing the efi diagnostics buffer +const ALIGNMENT: usize = 8; // 8-byte alignment +const ALIGNMENT_MASK: usize = ALIGNMENT - 1; // Mask for alignment pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB pub const MAX_MESSAGE_LENGTH: u16 = 0x1000; // 4KB -// -// Represents a processed log entry from the EFI diagnostics buffer -// +/// Represents a processed log entry from the EFI diagnostics buffer #[derive(Debug, Clone)] pub struct EfiDiagnosticsLog { pub debug_level: u32, // The debug level of the log entry @@ -46,108 +42,151 @@ pub struct EfiDiagnosticsLog { pub description: String, // The log message itself } -// -// Validation error types for the advanced logger spec types -// +/// Errors that occur when parsing entries #[derive(Debug, Error)] -pub enum AdvancedLoggerInfoError { - #[error("Invalid header signature: {0:#x}, expected: {1:#x}")] - Signature(u32, u32), - #[error("Invalid log buffer size: {0:#x}, max: {1:#x}")] - LogBufferSize(u32, u32), -} +pub enum EntryParseError { + #[error("Expected: {0:#x}, got: {1:#x}")] + SignatureMismatch(u32, u32), -#[derive(Debug, Error)] -pub enum AdvancedLoggerMessageEntryV2Error { - #[error("Invalid entry signature: {0:#x}, expected: {1:#x}")] - Signature(u32, u32), - #[error("Invalid timestamp: {0:#x}")] + #[error("Expected non-zero timestamp, got: {0:#x}")] Timestamp(u64), - #[error("Invalid message length: {0:#x}, max: {1:#x}")] + + #[error("Expected message length < {0:#x}, got: {1:#x}")] MessageLength(u16, u16), -} -// -// Validation extension trait for the advanced logger spec types -// -pub trait Validator { - type Error; - fn validate(&self) -> Result<(), Self::Error>; + #[error("Failed to read from buffer slice")] + SliceRead, + + #[error("Encountered arithmetic overflow: {0}")] + Overflow(#[from] anyhow::Error), + + #[error("Failed to read UTF-8 string: {0}")] + Utf8Error(#[from] std::str::Utf8Error), + + #[error("message_end ({0:#x}) exceeds buffer slice length ({1:#x})")] + BadMessageEnd(usize, usize), } -impl Validator for AdvancedLoggerInfo { - type Error = AdvancedLoggerInfoError; +/// Represents a single parsed entry from the EFI diagnostics buffer +struct EntryData<'a> { + debug_level: u32, // The debug level of the log entry + time_stamp: u64, // Timestamp of when the log entry was created + phase: u16, // The boot phase that produced this log entry + message: &'a str, // The log message itself + entry_size: usize, // Size of the entry in bytes (including alignment) +} - fn validate(&self) -> Result<(), Self::Error> { - let signature = self.signature.to_le(); - if signature != SIG_HEADER { - return Err(AdvancedLoggerInfoError::Signature(signature, SIG_HEADER)); - } +/// Parse a single entry from a buffer slice +fn parse_entry(buffer_slice: &[u8]) -> Result, EntryParseError> { + // Try to parse an entry from the buffer slice + let (entry, _) = AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice) + .map_err(|_| EntryParseError::SliceRead)?; - if self.log_buffer_size > MAX_LOG_BUFFER_SIZE { - return Err(AdvancedLoggerInfoError::LogBufferSize( - self.log_buffer_size, - MAX_LOG_BUFFER_SIZE, - )); - } - Ok(()) + // Validate the entry signature + let signature = entry.signature.to_le(); + if signature != SIG_ENTRY { + return Err(EntryParseError::SignatureMismatch(SIG_ENTRY, signature)); } -} -impl Validator for AdvancedLoggerMessageEntryV2 { - type Error = AdvancedLoggerMessageEntryV2Error; + // Validate the entry timestamp + if entry.time_stamp == 0 { + return Err(EntryParseError::Timestamp(entry.time_stamp)); + } - fn validate(&self) -> Result<(), Self::Error> { - let signature = self.signature.to_le(); - if signature != SIG_ENTRY { - return Err(AdvancedLoggerMessageEntryV2Error::Signature( - signature, SIG_ENTRY, - )); - } + // Validate the message length + if entry.message_len > MAX_MESSAGE_LENGTH { + return Err(EntryParseError::MessageLength( + MAX_MESSAGE_LENGTH, + entry.message_len, + )); + } - if self.time_stamp == 0 { - return Err(AdvancedLoggerMessageEntryV2Error::Timestamp( - self.time_stamp, - )); - } + // Copy packed fields to local variables to avoid unaligned access + let message_offset = entry.message_offset; + let message_len = entry.message_len; + + // Calculate message start and end offsets + let message_start = message_offset as usize; + let message_end = message_start + .checked_add(message_len as usize) + .ok_or_else(|| { + EntryParseError::Overflow(anyhow!( + "message_start ({}) + message_len ({})", + message_start, + message_len + )) + })?; - if self.message_len > MAX_MESSAGE_LENGTH { - return Err(AdvancedLoggerMessageEntryV2Error::MessageLength( - self.message_len, - MAX_MESSAGE_LENGTH, - )); - } - Ok(()) + // Validate message end fits within the buffer slice + if message_end > buffer_slice.len() { + return Err(EntryParseError::BadMessageEnd( + message_end, + buffer_slice.len(), + )); } + + // Get the message + let message = std::str::from_utf8(&buffer_slice[message_start..message_end])?; + + // Calculate base offset (entry header size + message length) + let base_offset = size_of::() + .checked_add(message_len as usize) + .ok_or_else(|| { + EntryParseError::Overflow(anyhow!( + "size_of:: ({}) + message_len ({})", + size_of::(), + message_len + )) + })?; + + // Add padding for 8-byte alignment + let aligned_offset = base_offset.checked_add(ALIGNMENT_MASK).ok_or_else(|| { + EntryParseError::Overflow(anyhow!( + "base_offset ({}) + ALIGNMENT_MASK ({})", + base_offset, + ALIGNMENT_MASK + )) + })?; + let entry_size = aligned_offset & !ALIGNMENT_MASK; + + Ok(EntryData { + debug_level: entry.debug_level, + time_stamp: entry.time_stamp, + phase: entry.phase, + message, + entry_size, + }) } /// Errors that occur during processing -/// TODO: Add more specific error types #[derive(Debug, Error)] pub enum DiagnosticsError { + #[error("Failed to parse entry: {0}")] + EntryParse(#[from] EntryParseError), + + #[error("Expected: {0:#x}, got: {1:#x}")] + HeaderSignatureMismatch(u32, u32), + + #[error("Expected log buffer size < {0:#x}, got: {1:#x}")] + HeaderBufferSize(u32, u32), + #[error("Bad GPA value: {0:#x}")] BadGpa(u32), + #[error("No GPA set")] + NoGpa, + #[error("Failed to read from guest memory: {0}")] GuestMemoryRead(#[from] GuestMemoryError), - #[error("Invalid UTF-8 in message: {0}")] - Utf8Error(#[from] std::str::Utf8Error), - #[error("Encountered arithmetic overflow: {0}")] - Overflow(String), + Overflow(#[from] anyhow::Error), - #[error("Failed to validate AdvancedLoggerInfo: {0}")] - HeaderValidation(#[from] AdvancedLoggerInfoError), + #[error("Expected used log buffer size < {0:#x}, got: {1:#x}")] + BadUsedBufferSize(u32, u32), - #[error("Failed to validate AdvancedLoggerMessageEntryV2: {0}")] - EntryValidation(#[from] AdvancedLoggerMessageEntryV2Error), - - #[error("Failed to read buffer data: {0}")] - BoundsError(#[from] std::io::Error), - - #[error("General error: {0}")] - GeneralError(String), + #[error("Expected accumulated message length < {0:#x}, got: {1:#x}")] + BadAccumulatedMessageLength(u16, u16), } /// Definition of the diagnostics services state @@ -175,7 +214,7 @@ impl DiagnosticsServices { } } - /// Process the diagnostics buffer into friendly logs + /// Process the diagnostics buffer pub fn process_diagnostics( &self, gm: &GuestMemory, @@ -190,38 +229,48 @@ impl DiagnosticsServices { let gpa = match self.gpa { Some(gpa) if gpa != 0 && gpa != u32::MAX => gpa, Some(invalid_gpa) => return Err(DiagnosticsError::BadGpa(invalid_gpa)), - None => { - return Err(DiagnosticsError::GeneralError( - "No diagnostics GPA set".to_string(), - )); - } + None => return Err(DiagnosticsError::NoGpa), }; // - // Step 2: Read and validate the advanced logger header + // Step 2: Get the advanced logger info header // + + // Read the header from the guest memory let header: AdvancedLoggerInfo = gm.read_plain(gpa as u64)?; - header.validate()?; + + // Validate the header signature + let signature = header.signature.to_le(); + if signature != SIG_HEADER { + return Err(DiagnosticsError::HeaderSignatureMismatch( + SIG_HEADER, signature, + )); + } + + // Validate the log buffer size + if header.log_buffer_size > MAX_LOG_BUFFER_SIZE { + return Err(DiagnosticsError::HeaderBufferSize( + MAX_LOG_BUFFER_SIZE, + header.log_buffer_size, + )); + } // - // Step 3: Prepare processing variables + // Step 3: Read the rest of the used log buffer // - // Used for summary statistics - let mut bytes_read: usize = 0; - let mut entries_processed: usize = 0; - // Copy packed fields to local variables to avoid unaligned access let log_current_offset = header.log_current_offset; let log_buffer_offset = header.log_buffer_offset; - // Calculate used log buffer size using the local variables + // Calculate used log buffer size let used_log_buffer_size = log_current_offset .checked_sub(log_buffer_offset) .ok_or_else(|| { - DiagnosticsError::Overflow(format!( + DiagnosticsError::Overflow(anyhow!( "log_current_offset ({:#x}) - log_buffer_offset ({:#x})", - log_current_offset, log_buffer_offset + log_current_offset, + log_buffer_offset )) })?; @@ -230,89 +279,53 @@ impl DiagnosticsServices { || used_log_buffer_size > header.log_buffer_size || used_log_buffer_size > MAX_LOG_BUFFER_SIZE { - return Err(DiagnosticsError::GeneralError(format!( - "Invalid used log buffer size: {:#x}, max: {:#x}", - used_log_buffer_size, MAX_LOG_BUFFER_SIZE - ))); + return Err(DiagnosticsError::BadUsedBufferSize( + MAX_LOG_BUFFER_SIZE, + used_log_buffer_size, + )); } - // Used for accumulating multiple messages - let mut accumulated_message = String::with_capacity(MAX_MESSAGE_LENGTH as usize); - let mut debug_level = 0; - let mut time_stamp = 0; - let mut phase = 0; - let mut is_accumulating = false; - - // - // Step 4: Read the used portions of the log buffer - // - // Calculate start address of the log buffer let buffer_start_addr = gpa.checked_add(log_buffer_offset).ok_or_else(|| { - DiagnosticsError::Overflow(format!( + DiagnosticsError::Overflow(anyhow!( "gpa ({:#x}) + log_buffer_offset ({:#x})", - gpa, log_buffer_offset + gpa, + log_buffer_offset )) })?; + // Now read the used log buffer into a vector let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; gm.read_at(buffer_start_addr as u64, &mut buffer_data)?; - - // Empty buffer data should early exit if buffer_data.is_empty() { tracelimit::info_ratelimited!("buffer_data is empty, ending processing"); return Ok(()); } // - // Step 5: Parse the log buffer + // Step 4: Parse the log buffer // + + // Maintain a slice of the buffer that needs to be processed let mut buffer_slice = &buffer_data[..]; - while !buffer_slice.is_empty() { - // Parse and validate the entry header - let (entry, _) = - AdvancedLoggerMessageEntryV2::read_from_prefix(buffer_slice).map_err(|error| { - DiagnosticsError::GeneralError(format!( - "Failed to parse entry from buffer_slice: {}", - error - )) - })?; - entry.validate()?; - - // - // Step 5a: Validate message boundaries - // - - // Copy packed fields to local variables to avoid unaligned access - let message_offset = entry.message_offset; - let message_len = entry.message_len; - - // Calculate message start and end offsets - let message_start = message_offset as usize; - let message_end = message_start - .checked_add(message_len as usize) - .ok_or_else(|| { - DiagnosticsError::Overflow(format!( - "message_start ({}) + message_len ({})", - message_start, message_len - )) - })?; - - // Validate message end fits within the buffer slice - if message_end > buffer_slice.len() { - return Err(DiagnosticsError::GeneralError(format!( - "message_end ({}) exceeds buffer slice length ({})", - message_end, - buffer_slice.len() - ))); - } - // Get the message - let message = std::str::from_utf8(&buffer_slice[message_start..message_end])?; + // Message accumulation state + let mut accumulated_message = String::with_capacity(MAX_MESSAGE_LENGTH as usize); + let mut debug_level = 0; + let mut time_stamp = 0; + let mut phase = 0; + let mut is_accumulating = false; - // - // Step 5b: Handle message accumulation - // + // Used for tracking what has been processed + let mut bytes_read: usize = 0; + let mut entries_processed: usize = 0; + + // Process the buffer slice until all entries are processed + while !buffer_slice.is_empty() { + // Parse the current etnry + let entry = parse_entry(buffer_slice)?; + + // Handle message accumulation if !is_accumulating { debug_level = entry.debug_level; time_stamp = entry.time_stamp; @@ -320,19 +333,20 @@ impl DiagnosticsServices { accumulated_message.clear(); is_accumulating = true; } - accumulated_message.push_str(message); - // Validate that the accumulated message is not too long + // Append the message + accumulated_message.push_str(entry.message); + + // Check message length if accumulated_message.len() > MAX_MESSAGE_LENGTH as usize { - return Err(DiagnosticsError::GeneralError(format!( - "Accumulated message length ({}) exceeds max length ({})", - accumulated_message.len(), - MAX_MESSAGE_LENGTH - ))); + return Err(DiagnosticsError::BadAccumulatedMessageLength( + MAX_MESSAGE_LENGTH, + accumulated_message.len() as u16, + )); } // Handle completed messages (ending with '\n') - if !message.is_empty() && message.ends_with('\n') { + if !entry.message.is_empty() && entry.message.ends_with('\n') { log_handler(EfiDiagnosticsLog { debug_level, time_stamp, @@ -345,57 +359,21 @@ impl DiagnosticsServices { is_accumulating = false; } - // - // Step 5c: Move to the next entry - // - - // Calculate base offset (entry header size + message length) - let base_offset = size_of::() - .checked_add(message_len as usize) - .ok_or_else(|| { - DiagnosticsError::Overflow(format!( - "size_of:: ({}) + message_len ({})", - size_of::(), - message_len - )) - })?; - - // Add padding for 8-byte alignment - let aligned_offset = base_offset.checked_add(ALIGNMENT_MASK).ok_or_else(|| { - DiagnosticsError::Overflow(format!( - "base_offset ({}) + ALIGNMENT_MASK ({})", - base_offset, ALIGNMENT_MASK + // Update bytes read and move to the next entry + bytes_read = bytes_read.checked_add(entry.entry_size).ok_or_else(|| { + DiagnosticsError::Overflow(anyhow!( + "bytes_read ({}) + entry_size ({})", + bytes_read, + entry.entry_size )) })?; - let next_offset = aligned_offset & !ALIGNMENT_MASK; - // Update overall bytes read counter - bytes_read = bytes_read.checked_add(next_offset).ok_or_else(|| { - DiagnosticsError::Overflow(format!( - "bytes_read ({}) + next_offset ({})", - bytes_read, next_offset - )) - })?; - - // Advanced to the next entry with boundary checks - if next_offset >= buffer_slice.len() { - // We have reached the end of the buffer - break; + // Advance the buffer to the next entry + if entry.entry_size >= buffer_slice.len() { + break; // End of buffer + } else { + buffer_slice = &buffer_slice[entry.entry_size..]; } - buffer_slice = &buffer_slice[next_offset..]; - } - - // Process remaining messages - if is_accumulating { - log_handler(EfiDiagnosticsLog { - debug_level, - time_stamp, - phase, - description: std::mem::take(&mut accumulated_message) - .trim_end_matches(&['\r', '\n'][..]) - .to_string(), - }); - entries_processed += 1; } // Print summary statistics @@ -412,7 +390,7 @@ impl DiagnosticsServices { impl UefiDevice { /// Process the diagnostics buffer and log the entries to tracing pub(crate) fn process_diagnostics(&self, gm: &GuestMemory) { - // Do not proceed if we have encountered ExitBootServices + // Do not proceed if we hit ExitBootServices if self.service.nvram.services.runtime_state.is_runtime() { tracelimit::warn_ratelimited!("EFI Diagnostics: EBS complete, skipping processing"); return; From d218bd54928bb2ca9a850d0982dadd785b7a7d4a Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Thu, 24 Apr 2025 17:25:10 -0700 Subject: [PATCH 26/32] Add no-boot test for efi diagnostics for openhcl_uefi_x64 only --- vmm_tests/vmm_tests/tests/tests/multiarch.rs | 29 ++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/vmm_tests/vmm_tests/tests/tests/multiarch.rs b/vmm_tests/vmm_tests/tests/tests/multiarch.rs index 7d7994ca0f..593f97f7e5 100644 --- a/vmm_tests/vmm_tests/tests/tests/multiarch.rs +++ b/vmm_tests/vmm_tests/tests/tests/multiarch.rs @@ -4,6 +4,7 @@ //! Integration tests that run on more than one architecture. use anyhow::Context; +use futures::StreamExt; use get_resources::ged::FirmwareEvent; use hyperv_ic_resources::kvp::KvpRpc; use jiff::SignedDuration; @@ -62,6 +63,34 @@ async fn boot(config: Box) -> anyhow::Result<()> { Ok(()) } +/// Test EFI diagnostics with no boot devices on OpenVMM. +/// TODO: +/// - kmsg support in Hyper-V +/// - openhcl_uefi_aarch64 support +/// - uefi_x64 + uefi_aarch64 trace searching support +#[openvmm_test(openhcl_uefi_x64(none))] +async fn efi_diagnostics_no_boot(config: PetriVmConfigOpenVmm) -> anyhow::Result<()> { + let mut vm = config.run_without_agent().await?; + vm.wait_for_successful_boot_event().await?; + + // Expected no-boot message. + const NO_BOOT_MSG: &str = "[Bds] Unable to boot!"; + + // Search kmsg for the expected message. + let mut kmsg = vm.kmsg().await?; + while let Some(data) = kmsg.next().await { + let data = data.context("reading kmsg")?; + let msg = kmsg::KmsgParsedEntry::new(&data)?; + let raw = msg.message.as_raw(); + if raw.contains(NO_BOOT_MSG) { + assert_eq!(vm.wait_for_teardown().await?, HaltReason::PowerOff); + return Ok(()); + } + } + + anyhow::bail!("Did not find expected message in kmsg"); +} + /// Test the KVP IC. /// /// Windows-only right now, because the Linux images do not include the KVP IC From 4f6872f9aa1608e71d1169c20ae9e3da031e5db5 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Tue, 29 Apr 2025 17:03:42 -0700 Subject: [PATCH 27/32] Rename to ticks and message instead, process remaining messages, early exit if used_log_buffer_size is 0 --- .../firmware_uefi/src/service/diagnostics.rs | 44 +++++++++++++------ 1 file changed, 30 insertions(+), 14 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 896dc443ed..4419360bfb 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -36,10 +36,10 @@ pub const MAX_MESSAGE_LENGTH: u16 = 0x1000; // 4KB /// Represents a processed log entry from the EFI diagnostics buffer #[derive(Debug, Clone)] pub struct EfiDiagnosticsLog { - pub debug_level: u32, // The debug level of the log entry - pub time_stamp: u64, // Timestamp of when the log entry was created - pub phase: u16, // The boot phase that produced this log entry - pub description: String, // The log message itself + pub debug_level: u32, // The debug level of the log entry + pub ticks: u64, // Hypervisor reference ticks elapsed from UEFI + pub phase: u16, // The boot phase that produced this log entry + pub message: String, // The log message itself } /// Errors that occur when parsing entries @@ -274,9 +274,16 @@ impl DiagnosticsServices { )) })?; + // If used log buffer size is zero, return early + if used_log_buffer_size == 0 { + tracelimit::info_ratelimited!( + "EFI Diagnostics: Used log buffer size is zero, ending processing" + ); + return Ok(()); + } + // Validate used log buffer size - if used_log_buffer_size == 0 - || used_log_buffer_size > header.log_buffer_size + if used_log_buffer_size > header.log_buffer_size || used_log_buffer_size > MAX_LOG_BUFFER_SIZE { return Err(DiagnosticsError::BadUsedBufferSize( @@ -297,10 +304,6 @@ impl DiagnosticsServices { // Now read the used log buffer into a vector let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; gm.read_at(buffer_start_addr as u64, &mut buffer_data)?; - if buffer_data.is_empty() { - tracelimit::info_ratelimited!("buffer_data is empty, ending processing"); - return Ok(()); - } // // Step 4: Parse the log buffer @@ -349,9 +352,9 @@ impl DiagnosticsServices { if !entry.message.is_empty() && entry.message.ends_with('\n') { log_handler(EfiDiagnosticsLog { debug_level, - time_stamp, + ticks: time_stamp, phase, - description: std::mem::take(&mut accumulated_message) + message: std::mem::take(&mut accumulated_message) .trim_end_matches(&['\r', '\n'][..]) .to_string(), }); @@ -376,6 +379,19 @@ impl DiagnosticsServices { } } + // Process any remaining accumulated message + if is_accumulating && !accumulated_message.is_empty() { + log_handler(EfiDiagnosticsLog { + debug_level, + ticks: time_stamp, + phase, + message: std::mem::take(&mut accumulated_message) + .trim_end_matches(&['\r', '\n'][..]) + .to_string(), + }); + entries_processed += 1; + } + // Print summary statistics tracelimit::info_ratelimited!( "EFI Diagnostics: Processed {} entries, Read {} bytes", @@ -400,9 +416,9 @@ impl UefiDevice { match self.service.diagnostics.process_diagnostics(gm, |log| { tracing::info!( debug_level = log.debug_level, - time_stamp_ticks = log.time_stamp, + ticks = log.ticks, phase = log.phase, - description = %log.description, + message = %log.message, "EFI Diagnostics:" ); }) { From 35fe96c7a2506119262dc78c4fb873afb7e8c8a1 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Tue, 29 Apr 2025 18:41:57 -0700 Subject: [PATCH 28/32] restore nvram spec_services module to undo pub, plumb new flush flag instead --- vm/devices/firmware/firmware_uefi/src/lib.rs | 2 +- .../firmware_uefi/src/service/diagnostics.rs | 28 +++++++++++++------ .../firmware_uefi/src/service/nvram/mod.rs | 2 +- .../src/service/nvram/spec_services/mod.rs | 10 +++---- 4 files changed, 27 insertions(+), 15 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/lib.rs b/vm/devices/firmware/firmware_uefi/src/lib.rs index a7b0be204b..e77e554f3d 100644 --- a/vm/devices/firmware/firmware_uefi/src/lib.rs +++ b/vm/devices/firmware/firmware_uefi/src/lib.rs @@ -255,7 +255,7 @@ impl UefiDevice { } } UefiCommand::SET_EFI_DIAGNOSTICS_GPA => self.service.diagnostics.set_gpa(data), - UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(&self.gm), + UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(self.gm.clone()), _ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"), } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 4419360bfb..69fa9d4d59 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -193,17 +193,22 @@ pub enum DiagnosticsError { #[derive(Inspect)] pub struct DiagnosticsServices { gpa: Option, // The guest physical address of the diagnostics buffer + did_flush: bool, // Flag to indicate if we have already processed the buffer } impl DiagnosticsServices { /// Create a new instance of the diagnostics services pub fn new() -> DiagnosticsServices { - DiagnosticsServices { gpa: None } + DiagnosticsServices { + gpa: None, + did_flush: false, + } } /// Reset the diagnostics services state pub fn reset(&mut self) { self.gpa = None; + self.did_flush = false; } /// Set the GPA of the diagnostics buffer @@ -405,15 +410,16 @@ impl DiagnosticsServices { impl UefiDevice { /// Process the diagnostics buffer and log the entries to tracing - pub(crate) fn process_diagnostics(&self, gm: &GuestMemory) { - // Do not proceed if we hit ExitBootServices - if self.service.nvram.services.runtime_state.is_runtime() { - tracelimit::warn_ratelimited!("EFI Diagnostics: EBS complete, skipping processing"); + pub(crate) fn process_diagnostics(&mut self, gm: GuestMemory) { + // Do not proceed if we have already processed before + if self.service.diagnostics.did_flush { + tracelimit::warn_ratelimited!("EFI Diagnostics: Already processed, skipping"); return; } + self.service.diagnostics.did_flush = true; // Process diagnostics logs and send each directly to tracing - match self.service.diagnostics.process_diagnostics(gm, |log| { + match self.service.diagnostics.process_diagnostics(&gm, |log| { tracing::info!( debug_level = log.debug_level, ticks = log.ticks, @@ -448,6 +454,8 @@ mod save_restore { pub struct SavedState { #[mesh(1)] pub gpa: Option, + #[mesh(2)] + pub did_flush: bool, } } @@ -455,12 +463,16 @@ mod save_restore { type SavedState = state::SavedState; fn save(&mut self) -> Result { - Ok(state::SavedState { gpa: self.gpa }) + Ok(state::SavedState { + gpa: self.gpa, + did_flush: self.did_flush, + }) } fn restore(&mut self, state: Self::SavedState) -> Result<(), RestoreError> { - let state::SavedState { gpa } = state; + let state::SavedState { gpa, did_flush } = state; self.gpa = gpa; + self.did_flush = did_flush; Ok(()) } } diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs index 3c3886c414..b057c4e338 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs @@ -569,7 +569,7 @@ impl UefiDevice { vsm.revoke_guest_vsm() } } - self.process_diagnostics(&self.gm); + self.process_diagnostics(self.gm.clone()); self.service.nvram.services.exit_boot_services(); (EfiStatus::SUCCESS, None) diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs index 7b2c14c354..ac2459c7b2 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/spec_services/mod.rs @@ -180,7 +180,7 @@ where } #[derive(Clone, Copy, Debug, Protobuf, Inspect)] -pub enum RuntimeState { +enum RuntimeState { /// Implementation-specific state, whereby certain read-only and /// authenticated variable checks are bypassed. /// @@ -194,15 +194,15 @@ pub enum RuntimeState { } impl RuntimeState { - pub fn is_pre_boot(&self) -> bool { + fn is_pre_boot(&self) -> bool { matches!(&self, RuntimeState::PreBoot) } - pub fn is_boot(&self) -> bool { + fn is_boot(&self) -> bool { matches!(&self, RuntimeState::Boot) } - pub fn is_runtime(&self) -> bool { + fn is_runtime(&self) -> bool { matches!(&self, RuntimeState::Runtime) } } @@ -226,7 +226,7 @@ impl RuntimeState { #[derive(Debug, Inspect)] pub struct NvramSpecServices { storage: S, - pub runtime_state: RuntimeState, + runtime_state: RuntimeState, } impl NvramSpecServices { From 25183007279d894991c1cf0dc82767eff7e14aee Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Tue, 29 Apr 2025 18:50:23 -0700 Subject: [PATCH 29/32] Unpub nvram subservice --- vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs index b057c4e338..18ef3b1a01 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/nvram/mod.rs @@ -67,7 +67,7 @@ pub struct NvramServices { // Sub-emulators #[inspect(flatten)] - pub services: NvramSpecServices>, + services: NvramSpecServices>, } impl NvramServices { From d8ac1a32703ca8601025204225ebe830170329b0 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Wed, 30 Apr 2025 14:57:41 -0700 Subject: [PATCH 30/32] Fixed test --- vmm_tests/vmm_tests/tests/tests/multiarch.rs | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/vmm_tests/vmm_tests/tests/tests/multiarch.rs b/vmm_tests/vmm_tests/tests/tests/multiarch.rs index 7d7db85a2b..5074eb1407 100644 --- a/vmm_tests/vmm_tests/tests/tests/multiarch.rs +++ b/vmm_tests/vmm_tests/tests/tests/multiarch.rs @@ -92,24 +92,36 @@ async fn boot_reset_expected(config: PetriVmConfigOpenVmm) -> anyhow::Result<()> #[openvmm_test(openhcl_uefi_x64(none))] async fn efi_diagnostics_no_boot(config: PetriVmConfigOpenVmm) -> anyhow::Result<()> { let mut vm = config.run_without_agent().await?; + + // Boot the VM vm.wait_for_successful_boot_event().await?; // Expected no-boot message. const NO_BOOT_MSG: &str = "[Bds] Unable to boot!"; - // Search kmsg for the expected message. + // Get kmsg before waiting for teardown let mut kmsg = vm.kmsg().await?; + + // Search for the message + let mut found_message = false; while let Some(data) = kmsg.next().await { let data = data.context("reading kmsg")?; let msg = kmsg::KmsgParsedEntry::new(&data)?; let raw = msg.message.as_raw(); if raw.contains(NO_BOOT_MSG) { - assert_eq!(vm.wait_for_teardown().await?, HaltReason::PowerOff); - return Ok(()); + found_message = true; + break; } } - anyhow::bail!("Did not find expected message in kmsg"); + // Now wait for VM to shut down + assert_eq!(vm.wait_for_teardown().await?, HaltReason::PowerOff); + + if found_message { + return Ok(()); + } + + anyhow::bail!("did not find expected message in kmsg"); } /// Test the KVP IC. From 153f8b19ebb3e7973e63db055dca9ca042e3f256 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Wed, 30 Apr 2025 15:24:23 -0700 Subject: [PATCH 31/32] Fix test using frontpage to prevent halting --- vmm_tests/vmm_tests/tests/tests/multiarch.rs | 19 +++++-------------- 1 file changed, 5 insertions(+), 14 deletions(-) diff --git a/vmm_tests/vmm_tests/tests/tests/multiarch.rs b/vmm_tests/vmm_tests/tests/tests/multiarch.rs index 5074eb1407..8c273ee32b 100644 --- a/vmm_tests/vmm_tests/tests/tests/multiarch.rs +++ b/vmm_tests/vmm_tests/tests/tests/multiarch.rs @@ -91,37 +91,28 @@ async fn boot_reset_expected(config: PetriVmConfigOpenVmm) -> anyhow::Result<()> /// - uefi_x64 + uefi_aarch64 trace searching support #[openvmm_test(openhcl_uefi_x64(none))] async fn efi_diagnostics_no_boot(config: PetriVmConfigOpenVmm) -> anyhow::Result<()> { - let mut vm = config.run_without_agent().await?; + let mut vm = config.with_uefi_frontpage(true).run_without_agent().await?; - // Boot the VM + // Boot the VM first vm.wait_for_successful_boot_event().await?; // Expected no-boot message. const NO_BOOT_MSG: &str = "[Bds] Unable to boot!"; - // Get kmsg before waiting for teardown + // Get kmsg stream let mut kmsg = vm.kmsg().await?; // Search for the message - let mut found_message = false; while let Some(data) = kmsg.next().await { let data = data.context("reading kmsg")?; let msg = kmsg::KmsgParsedEntry::new(&data)?; let raw = msg.message.as_raw(); if raw.contains(NO_BOOT_MSG) { - found_message = true; - break; + return Ok(()); } } - // Now wait for VM to shut down - assert_eq!(vm.wait_for_teardown().await?, HaltReason::PowerOff); - - if found_message { - return Ok(()); - } - - anyhow::bail!("did not find expected message in kmsg"); + anyhow::bail!("Did not find expected message in kmsg"); } /// Test the KVP IC. From 8fb909f18d29e1c5b3cd40c20342da6a268cfff6 Mon Sep 17 00:00:00 2001 From: maheeraeron Date: Fri, 2 May 2025 11:03:12 -0700 Subject: [PATCH 32/32] Add and require doc comments --- .../firmware_uefi/src/service/diagnostics.rs | 87 ++++++++------- .../uefi_specs/src/hyperv/advanced_logger.rs | 100 ++++++++++++------ 2 files changed, 107 insertions(+), 80 deletions(-) diff --git a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs index 69fa9d4d59..dc53ab137e 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs @@ -10,9 +10,9 @@ //! The EFI diagnostics buffer follows the specification of Project Mu's //! Advanced Logger package, whose relevant types are defined in the Hyper-V //! specification within the uefi_specs crate. -//! -//! TODO: -//! - Add unit tests + +#![warn(missing_docs)] + use crate::UefiDevice; use anyhow::anyhow; use guestmem::GuestMemory; @@ -27,53 +27,63 @@ use uefi_specs::hyperv::advanced_logger::SIG_ENTRY; use uefi_specs::hyperv::advanced_logger::SIG_HEADER; use zerocopy::FromBytes; -// Constants for processing the efi diagnostics buffer -const ALIGNMENT: usize = 8; // 8-byte alignment -const ALIGNMENT_MASK: usize = ALIGNMENT - 1; // Mask for alignment +/// 8-byte alignment for every entry +const ALIGNMENT: usize = 8; + +/// Alignment mask for the entry +const ALIGNMENT_MASK: usize = ALIGNMENT - 1; + +/// Maximum allowed size of the log buffer pub const MAX_LOG_BUFFER_SIZE: u32 = 0x400000; // 4MB + +/// Maximum allowed size of a single message pub const MAX_MESSAGE_LENGTH: u16 = 0x1000; // 4KB /// Represents a processed log entry from the EFI diagnostics buffer #[derive(Debug, Clone)] pub struct EfiDiagnosticsLog { - pub debug_level: u32, // The debug level of the log entry - pub ticks: u64, // Hypervisor reference ticks elapsed from UEFI - pub phase: u16, // The boot phase that produced this log entry - pub message: String, // The log message itself + /// The debug level of the log entry + pub debug_level: u32, + /// Hypervisor reference ticks elapsed from UEFI + pub ticks: u64, + /// The boot phase that produced this log entry + pub phase: u16, + /// The log message itself + pub message: String, } /// Errors that occur when parsing entries #[derive(Debug, Error)] +#[allow(missing_docs)] pub enum EntryParseError { #[error("Expected: {0:#x}, got: {1:#x}")] SignatureMismatch(u32, u32), - #[error("Expected non-zero timestamp, got: {0:#x}")] Timestamp(u64), - #[error("Expected message length < {0:#x}, got: {1:#x}")] MessageLength(u16, u16), - #[error("Failed to read from buffer slice")] SliceRead, - #[error("Encountered arithmetic overflow: {0}")] Overflow(#[from] anyhow::Error), - #[error("Failed to read UTF-8 string: {0}")] Utf8Error(#[from] std::str::Utf8Error), - #[error("message_end ({0:#x}) exceeds buffer slice length ({1:#x})")] BadMessageEnd(usize, usize), } /// Represents a single parsed entry from the EFI diagnostics buffer struct EntryData<'a> { - debug_level: u32, // The debug level of the log entry - time_stamp: u64, // Timestamp of when the log entry was created - phase: u16, // The boot phase that produced this log entry - message: &'a str, // The log message itself - entry_size: usize, // Size of the entry in bytes (including alignment) + /// The debug level of the log entry + debug_level: u32, + /// Timestamp of when the log entry was created + time_stamp: u64, + /// The boot phase that produced this log entry + phase: u16, + /// The log message itself + message: &'a str, + /// The size of the entry in bytes (including alignment) + entry_size: usize, } /// Parse a single entry from a buffer slice @@ -160,31 +170,24 @@ fn parse_entry(buffer_slice: &[u8]) -> Result, EntryParseError> { /// Errors that occur during processing #[derive(Debug, Error)] +#[allow(missing_docs)] pub enum DiagnosticsError { #[error("Failed to parse entry: {0}")] EntryParse(#[from] EntryParseError), - #[error("Expected: {0:#x}, got: {1:#x}")] HeaderSignatureMismatch(u32, u32), - #[error("Expected log buffer size < {0:#x}, got: {1:#x}")] HeaderBufferSize(u32, u32), - #[error("Bad GPA value: {0:#x}")] BadGpa(u32), - #[error("No GPA set")] NoGpa, - #[error("Failed to read from guest memory: {0}")] GuestMemoryRead(#[from] GuestMemoryError), - #[error("Encountered arithmetic overflow: {0}")] Overflow(#[from] anyhow::Error), - #[error("Expected used log buffer size < {0:#x}, got: {1:#x}")] BadUsedBufferSize(u32, u32), - #[error("Expected accumulated message length < {0:#x}, got: {1:#x}")] BadAccumulatedMessageLength(u16, u16), } @@ -192,8 +195,10 @@ pub enum DiagnosticsError { /// Definition of the diagnostics services state #[derive(Inspect)] pub struct DiagnosticsServices { - gpa: Option, // The guest physical address of the diagnostics buffer - did_flush: bool, // Flag to indicate if we have already processed the buffer + /// The guest physical address of the diagnostics buffer + gpa: Option, + /// Flag to indicate if we have already processed the buffer + did_process: bool, } impl DiagnosticsServices { @@ -201,14 +206,14 @@ impl DiagnosticsServices { pub fn new() -> DiagnosticsServices { DiagnosticsServices { gpa: None, - did_flush: false, + did_process: false, } } /// Reset the diagnostics services state pub fn reset(&mut self) { self.gpa = None; - self.did_flush = false; + self.did_process = false; } /// Set the GPA of the diagnostics buffer @@ -228,18 +233,14 @@ impl DiagnosticsServices { where F: FnMut(EfiDiagnosticsLog), { - // // Step 1: Validate GPA - // let gpa = match self.gpa { Some(gpa) if gpa != 0 && gpa != u32::MAX => gpa, Some(invalid_gpa) => return Err(DiagnosticsError::BadGpa(invalid_gpa)), None => return Err(DiagnosticsError::NoGpa), }; - // // Step 2: Get the advanced logger info header - // // Read the header from the guest memory let header: AdvancedLoggerInfo = gm.read_plain(gpa as u64)?; @@ -260,9 +261,7 @@ impl DiagnosticsServices { )); } - // // Step 3: Read the rest of the used log buffer - // // Copy packed fields to local variables to avoid unaligned access let log_current_offset = header.log_current_offset; @@ -310,9 +309,7 @@ impl DiagnosticsServices { let mut buffer_data = vec![0u8; used_log_buffer_size as usize]; gm.read_at(buffer_start_addr as u64, &mut buffer_data)?; - // // Step 4: Parse the log buffer - // // Maintain a slice of the buffer that needs to be processed let mut buffer_slice = &buffer_data[..]; @@ -412,11 +409,11 @@ impl UefiDevice { /// Process the diagnostics buffer and log the entries to tracing pub(crate) fn process_diagnostics(&mut self, gm: GuestMemory) { // Do not proceed if we have already processed before - if self.service.diagnostics.did_flush { + if self.service.diagnostics.did_process { tracelimit::warn_ratelimited!("EFI Diagnostics: Already processed, skipping"); return; } - self.service.diagnostics.did_flush = true; + self.service.diagnostics.did_process = true; // Process diagnostics logs and send each directly to tracing match self.service.diagnostics.process_diagnostics(&gm, |log| { @@ -465,14 +462,14 @@ mod save_restore { fn save(&mut self) -> Result { Ok(state::SavedState { gpa: self.gpa, - did_flush: self.did_flush, + did_flush: self.did_process, }) } fn restore(&mut self, state: Self::SavedState) -> Result<(), RestoreError> { let state::SavedState { gpa, did_flush } = state; self.gpa = gpa; - self.did_flush = did_flush; + self.did_process = did_flush; Ok(()) } } diff --git a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs index 660462a0ca..7317eb416b 100644 --- a/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs +++ b/vm/devices/firmware/uefi_specs/src/hyperv/advanced_logger.rs @@ -3,57 +3,87 @@ //! Types and constants defined by Project Mu's Advanced Logger package, //! used in the Hyper-V UEFI firmware. + +#![warn(missing_docs)] + use crate::uefi::time::EFI_TIME; use zerocopy::FromBytes; use zerocopy::Immutable; use zerocopy::KnownLayout; -// Advanced Logger Info signature +/// Advanced Logger Info signature pub const SIG_HEADER: u32 = u32::from_le_bytes(*b"ALOG"); -// Advanced Logger Entry signature +/// Advanced Logger Entry signature pub const SIG_ENTRY: u32 = u32::from_le_bytes(*b"ALM2"); -// UEFI Advanced Logger Info Header, which is shared -// with the Advanced Logger Package in UEFI. The entries -// live right after. +/// UEFI Advanced Logger Info Header, which is shared +/// with the Advanced Logger Package in UEFI. The entries +/// live right after. #[repr(C, packed)] #[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] pub struct AdvancedLoggerInfo { - pub signature: u32, // Signature 'ALOG' - pub version: u16, // Current Version - pub reserved: [u16; 3], // Reserved for future - pub log_buffer_offset: u32, // Offset from LoggerInfo to start of log + /// Signature 'ALOG' + pub signature: u32, + /// Current Version + pub version: u16, + /// Reserved for future + pub reserved: [u16; 3], + /// Offset from LoggerInfo to start of log + pub log_buffer_offset: u32, + /// Reserved field pub reserved4: u32, - pub log_current_offset: u32, // Offset from LoggerInfo to where to store next log entry - pub discarded_size: u32, // Number of bytes of messages missed - pub log_buffer_size: u32, // Size of allocated buffer - pub in_permanent_ram: u8, // Log in permanent RAM - pub at_runtime: u8, // After ExitBootServices - pub gone_virtual: u8, // After VirtualAddressChange - pub hdw_port_initialized: u8, // HdwPort initialized - pub hdw_port_disabled: u8, // HdwPort is Disabled - pub reserved2: [u8; 3], // Reserved - pub timer_frequency: u64, // Ticks per second for log timing - pub ticks_at_time: u64, // Ticks when Time Acquired - pub time: EFI_TIME, // Uefi Time Field - pub hw_print_level: u32, // Logging level to be printed at hw port - pub reserved3: u32, // Reserved + /// Offset from LoggerInfo to where to store next log entry + pub log_current_offset: u32, + /// Number of bytes of messages missed + pub discarded_size: u32, + /// Size of allocated buffer + pub log_buffer_size: u32, + /// Log in permanent RAM + pub in_permanent_ram: u8, + /// After ExitBootServices + pub at_runtime: u8, + /// After VirtualAddressChange + pub gone_virtual: u8, + /// HdwPort initialized + pub hdw_port_initialized: u8, + /// HdwPort is Disabled + pub hdw_port_disabled: u8, + /// Reserved field + pub reserved2: [u8; 3], + /// Ticks per second for log timing + pub timer_frequency: u64, + /// Ticks when Time Acquired + pub ticks_at_time: u64, + /// Uefi Time Field + pub time: EFI_TIME, + /// Logging level to be printed at hw port + pub hw_print_level: u32, + /// Reserved field + pub reserved3: u32, } -// UEFI Advanced Logger Entry, which is shared with the -// Advanced Logger Package in UEFI. The messages live -// right after. +/// UEFI Advanced Logger Entry, which is shared with the +/// Advanced Logger Package in UEFI. The messages live +/// right after. #[repr(C, packed)] #[derive(Debug, Copy, Clone, FromBytes, Immutable, KnownLayout)] pub struct AdvancedLoggerMessageEntryV2 { - pub signature: u32, // Signature - pub major_version: u8, // Major version of advanced logger message structure - pub minor_version: u8, // Minor version of advanced logger message structure - pub debug_level: u32, // Debug Level - pub time_stamp: u64, // Time stamp - pub phase: u16, // Boot phase that produced this message entry - pub message_len: u16, // Number of bytes in Message - pub message_offset: u16, // Offset of Message from start of structure - // Rust prevents C flexible array members, but "message_text: [u8; _]" would be here + /// Signature 'ALM2' + pub signature: u32, + /// Major version of the advanced logger message structure. + pub major_version: u8, + /// Minor version of the advanced logger message structure. + pub minor_version: u8, + /// Debug level + pub debug_level: u32, + /// Time stamp + pub time_stamp: u64, + /// Boot phase that produced this message entry + pub phase: u16, + /// Number of bytes in the Message + pub message_len: u16, + /// Offset of the message from the start of the structure. + pub message_offset: u16, + // Rust prevents C flexible array members, but "message_text: [u8; _]" would be here }