From d5b2816092641f9dde4d703bd9b4c7381783eee3 Mon Sep 17 00:00:00 2001 From: Steven Malis Date: Fri, 23 May 2025 17:24:50 -0400 Subject: [PATCH 1/8] CVM: Audit tracing and add ALLOWED/CONFIDENTIAL where appropriate --- Cargo.lock | 7 ++ openhcl/diag_server/Cargo.toml | 1 + openhcl/diag_server/src/diag_service.rs | 2 +- openhcl/diag_server/src/lib.rs | 9 +- openhcl/hcl/Cargo.toml | 1 + openhcl/hcl/src/ioctl.rs | 5 +- openhcl/hcl/src/ioctl/deferred.rs | 2 + openhcl/profiler_worker/src/lib.rs | 9 +- openhcl/underhill_core/src/dispatch/mod.rs | 41 ++++--- .../src/dispatch/pci_shutdown.rs | 2 + .../src/dispatch/vtl2_settings_worker.rs | 36 ++++-- .../underhill_core/src/emuplat/firmware.rs | 2 + .../underhill_core/src/emuplat/local_clock.rs | 15 ++- .../underhill_core/src/emuplat/watchdog.rs | 3 + openhcl/underhill_core/src/get_tracing.rs | 2 + .../src/get_tracing/kmsg_stream.rs | 2 + openhcl/underhill_core/src/inspect_proc.rs | 3 +- openhcl/underhill_core/src/lib.rs | 23 ++-- openhcl/underhill_core/src/livedump.rs | 2 +- openhcl/underhill_core/src/loader/mod.rs | 9 +- .../underhill_core/src/loader/vtl0_config.rs | 2 +- openhcl/underhill_core/src/vp.rs | 5 +- openhcl/underhill_core/src/worker.rs | 114 +++++++++++------- openhcl/underhill_mem/Cargo.toml | 1 + openhcl/underhill_mem/src/init.rs | 19 +-- openhcl/underhill_mem/src/lib.rs | 2 + openhcl/underhill_mem/src/registrar.rs | 5 +- openhcl/underhill_threadpool/Cargo.toml | 1 + openhcl/underhill_threadpool/src/lib.rs | 2 + openhcl/virt_mshv_vtl/src/cvm_cpuid/mod.rs | 2 + openhcl/virt_mshv_vtl/src/cvm_cpuid/tdx.rs | 3 + openhcl/virt_mshv_vtl/src/lib.rs | 10 +- .../src/processor/hardware_cvm/apic.rs | 3 +- .../src/processor/hardware_cvm/mod.rs | 27 +++-- openhcl/virt_mshv_vtl/src/processor/mod.rs | 17 ++- .../virt_mshv_vtl/src/processor/snp/mod.rs | 25 +++- .../virt_mshv_vtl/src/processor/tdx/mod.rs | 108 +++++++++++++---- .../firmware_uefi/src/service/time.rs | 4 +- .../hcl_compat_uefi_nvram_storage/Cargo.toml | 1 + .../hcl_compat_uefi_nvram_storage/src/lib.rs | 14 ++- .../src/process_loop.rs | 6 +- vm/devices/tpm/Cargo.toml | 1 + vm/devices/tpm/src/lib.rs | 49 +++++--- vm/devices/tpm/src/tpm_helper.rs | 11 +- vmm_core/Cargo.toml | 1 + vmm_core/src/partition_unit/vp_set.rs | 5 + 46 files changed, 442 insertions(+), 172 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b450c3e16b..52dcd9d0c2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1071,6 +1071,7 @@ dependencies = [ "anyhow", "azure_profiler_proto", "build_rs_guest_arch", + "cvm_tracing", "diag_proto", "fs-err", "futures", @@ -2758,6 +2759,7 @@ dependencies = [ "bitfield-struct 0.10.1", "bitvec", "build_rs_guest_arch", + "cvm_tracing", "fs-err", "getrandom 0.3.2", "hv1_structs", @@ -2787,6 +2789,7 @@ version = "0.0.0" dependencies = [ "anyhow", "async-trait", + "cvm_tracing", "guid", "inspect", "open_enum", @@ -7055,6 +7058,7 @@ dependencies = [ "bitfield-struct 0.10.1", "chipset_device", "chipset_device_resources", + "cvm_tracing", "getrandom 0.3.2", "guestmem", "inspect", @@ -7605,6 +7609,7 @@ version = "0.0.0" dependencies = [ "anyhow", "build_rs_guest_arch", + "cvm_tracing", "futures", "guestmem", "hcl", @@ -7628,6 +7633,7 @@ dependencies = [ name = "underhill_threadpool" version = "0.0.0" dependencies = [ + "cvm_tracing", "fs-err", "inspect", "loan_cell", @@ -8798,6 +8804,7 @@ dependencies = [ "build_rs_guest_arch", "cache_topology", "chipset", + "cvm_tracing", "futures", "futures-concurrency", "guestmem", diff --git a/openhcl/diag_server/Cargo.toml b/openhcl/diag_server/Cargo.toml index cfefcdb616..ddca83783e 100644 --- a/openhcl/diag_server/Cargo.toml +++ b/openhcl/diag_server/Cargo.toml @@ -10,6 +10,7 @@ rust-version.workspace = true diag_proto.workspace = true azure_profiler_proto.workspace = true +cvm_tracing.workspace = true inspect_proto.workspace = true inspect = { workspace = true, features = ["defer"] } mesh = { workspace = true, features = ["socket2"] } diff --git a/openhcl/diag_server/src/diag_service.rs b/openhcl/diag_server/src/diag_service.rs index 2792ec6582..2d96f41455 100644 --- a/openhcl/diag_server/src/diag_service.rs +++ b/openhcl/diag_server/src/diag_service.rs @@ -546,7 +546,7 @@ impl DiagServiceHandler { } async fn handle_update(&self, request: &UpdateRequest) -> anyhow::Result { - tracing::info!( + tracing::debug!( path = request.path.as_str(), value = request.value.as_str(), "update request" diff --git a/openhcl/diag_server/src/lib.rs b/openhcl/diag_server/src/lib.rs index fe9540fb50..d34c9bb9bc 100644 --- a/openhcl/diag_server/src/lib.rs +++ b/openhcl/diag_server/src/lib.rs @@ -12,6 +12,7 @@ pub use diag_service::DiagRequest; pub use diag_service::StartParams; use anyhow::Context; +use cvm_tracing::CVM_ALLOWED; use futures::AsyncWriteExt; use futures::FutureExt; use mesh::CancelReason; @@ -48,11 +49,11 @@ pub struct DiagServer { impl DiagServer { /// Creates a server over VmSockets and starts listening. pub fn new_vsock(control_address: VmAddress, data_address: VmAddress) -> anyhow::Result { - tracing::info!(?control_address, "control starting"); + tracing::info!(CVM_ALLOWED, ?control_address, "control starting"); let control_listener = VmListener::bind(control_address).context("failed to bind socket")?; - tracing::info!(?data_address, "data starting"); + tracing::info!(CVM_ALLOWED, ?data_address, "data starting"); let data_listener = VmListener::bind(data_address).context("failed to bind socket")?; Ok(Self::new_generic( @@ -63,11 +64,11 @@ impl DiagServer { /// Creates a server over Unix sockets and starts listening. pub fn new_unix(control_address: &Path, data_address: &Path) -> anyhow::Result { - tracing::info!(?control_address, "control starting"); + tracing::info!(CVM_ALLOWED, ?control_address, "control starting"); let control_listener = UnixListener::bind(control_address).context("failed to bind socket")?; - tracing::info!(?data_address, "data starting"); + tracing::info!(CVM_ALLOWED, ?data_address, "data starting"); let data_listener = UnixListener::bind(data_address).context("failed to bind socket")?; Ok(Self::new_generic( diff --git a/openhcl/hcl/Cargo.toml b/openhcl/hcl/Cargo.toml index c8ff9553b9..f06fc76276 100644 --- a/openhcl/hcl/Cargo.toml +++ b/openhcl/hcl/Cargo.toml @@ -7,6 +7,7 @@ edition.workspace = true rust-version.workspace = true [target.'cfg(target_os = "linux")'.dependencies] +cvm_tracing.workspace = true hv1_structs.workspace = true hvdef.workspace = true pal.workspace = true diff --git a/openhcl/hcl/src/ioctl.rs b/openhcl/hcl/src/ioctl.rs index 337164a808..dc8c89e630 100644 --- a/openhcl/hcl/src/ioctl.rs +++ b/openhcl/hcl/src/ioctl.rs @@ -24,6 +24,7 @@ use crate::protocol::MSHV_APIC_PAGE_OFFSET; use crate::protocol::hcl_intr_offload_flags; use crate::protocol::hcl_run; use bitvec::vec::BitVec; +use cvm_tracing::CVM_ALLOWED; use deferred::RegisteredDeferredActions; use deferred::push_deferred_action; use deferred::register_deferred_actions; @@ -924,7 +925,7 @@ impl MshvHvcall { - size_of::()) / size_of::(); - let span = tracing::span!(tracing::Level::INFO, "accept_pages", ?range); + let span = tracing::info_span!("accept_pages", CVM_ALLOWED, ?range); let _enter = span.enter(); let mut current_page = range.start() / HV_PAGE_SIZE; @@ -1343,7 +1344,7 @@ impl MshvHvcall { - size_of::()) / size_of::(); - let span = tracing::span!(tracing::Level::INFO, "modify_vtl_protection_mask", ?range); + let span = tracing::info_span!("modify_vtl_protection_mask", CVM_ALLOWED, ?range); let _enter = span.enter(); let start = range.start() / HV_PAGE_SIZE; diff --git a/openhcl/hcl/src/ioctl/deferred.rs b/openhcl/hcl/src/ioctl/deferred.rs index ea7846235f..8922676b6d 100644 --- a/openhcl/hcl/src/ioctl/deferred.rs +++ b/openhcl/hcl/src/ioctl/deferred.rs @@ -6,6 +6,7 @@ use super::Hcl; use crate::protocol; use crate::protocol::hcl_run; +use cvm_tracing::CVM_ALLOWED; use std::cell::Cell; use std::cell::UnsafeCell; use std::marker::PhantomData; @@ -129,6 +130,7 @@ impl DeferredAction { DeferredAction::SignalEvent { vp, sint, flag } => { if let Err(err) = hcl.hvcall_signal_event_direct(vp, sint, flag) { tracelimit::warn_ratelimited!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, vp, sint, diff --git a/openhcl/profiler_worker/src/lib.rs b/openhcl/profiler_worker/src/lib.rs index 44db998e49..6a325fbbb0 100644 --- a/openhcl/profiler_worker/src/lib.rs +++ b/openhcl/profiler_worker/src/lib.rs @@ -153,7 +153,10 @@ pub async fn profile(request: ProfilerRequest, driver: &impl Driver) -> anyhow:: let free_mem_mb = match get_free_mem_mb() { Ok(m) => m, Err(e) => { - tracing::error!("Error when getting memory {}", e.to_string()); + tracing::error!( + e = e.as_ref() as &dyn std::error::Error, + "Error when getting memory" + ); 0 } }; @@ -203,8 +206,8 @@ pub async fn profile(request: ProfilerRequest, driver: &impl Driver) -> anyhow:: Err(e) => { process_success = false; tracing::error!( - "Running profiler binary failed with error {}", - e.to_string() + e = &e as &dyn std::error::Error, + "Running profiler binary failed", ); break; } diff --git a/openhcl/underhill_core/src/dispatch/mod.rs b/openhcl/underhill_core/src/dispatch/mod.rs index 3a36ff3208..7a8b984a60 100644 --- a/openhcl/underhill_core/src/dispatch/mod.rs +++ b/openhcl/underhill_core/src/dispatch/mod.rs @@ -21,6 +21,7 @@ use crate::worker::FirmwareType; use crate::worker::NetworkSettingsError; use anyhow::Context; use async_trait::async_trait; +use cvm_tracing::CVM_ALLOWED; use futures::FutureExt; use futures::StreamExt; use futures_concurrency::future::Join; @@ -279,7 +280,7 @@ impl LoadedVm { } } } - .instrument(tracing::info_span!("restart")) + .instrument(tracing::info_span!("restart", CVM_ALLOWED)) .await; if let Some((rpc, servicing_state)) = state { @@ -373,6 +374,7 @@ impl LoadedVm { } Err(err) => { tracing::error!( + CVM_ALLOWED, error = err.as_ref() as &dyn std::error::Error, "failed to notify host of servicing result" ); @@ -388,11 +390,12 @@ impl LoadedVm { } let (_, send_guest) = self.shutdown_relay.as_mut().expect("active shutdown_relay"); - tracing::info!(params = ?msg, "Relaying shutdown message"); + tracing::info!(CVM_ALLOWED, params = ?msg, "Relaying shutdown message"); let result = match send_guest.call(ShutdownRpc::Shutdown, msg).await { Ok(result) => result, Err(err) => { tracing::error!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "Failed to relay shutdown notification to guest" ); @@ -400,7 +403,7 @@ impl LoadedVm { } }; if !matches!(result, ShutdownResult::Ok) { - tracing::warn!(?result, "Shutdown request failed"); + tracing::warn!(CVM_ALLOWED, ?result, "Shutdown request failed"); self.handle_hibernate_request(true).await; } result @@ -464,6 +467,7 @@ impl LoadedVm { } Err(err) => { tracing::error!( + CVM_ALLOWED, error = err.as_ref() as &dyn std::error::Error, "error while handling servicing" ); @@ -517,7 +521,7 @@ impl LoadedVm { if let Some(network_settings) = self.network_settings.as_mut() { network_settings .unload_for_servicing() - .instrument(tracing::info_span!("shutdown_mana")) + .instrument(tracing::info_span!("shutdown_mana",CVM_ALLOWED)) .await; } }; @@ -527,7 +531,7 @@ impl LoadedVm { if let Some(nvme_manager) = self.nvme_manager.take() { nvme_manager .shutdown(nvme_keepalive) - .instrument(tracing::info_span!("shutdown_nvme_vfio", %correlation_id, %nvme_keepalive)) + .instrument(tracing::info_span!("shutdown_nvme_vfio",CVM_ALLOWED, %correlation_id, %nvme_keepalive)) .await; } }; @@ -536,7 +540,7 @@ impl LoadedVm { // restart. let shutdown_pci = async { pci_shutdown::shutdown_pci_devices() - .instrument(tracing::info_span!("shutdown_pci_devices")) + .instrument(tracing::info_span!("shutdown_pci_devices",CVM_ALLOWED)) .await }; @@ -545,7 +549,7 @@ impl LoadedVm { Ok(state) } - .instrument(tracing::info_span!("servicing_save_vtl2", %correlation_id)) + .instrument(tracing::info_span!("servicing_save_vtl2",CVM_ALLOWED, %correlation_id)) .await; let mut state = match r { @@ -593,12 +597,18 @@ impl LoadedVm { if !rollback { network_settings .prepare_for_hibernate(rollback) - .instrument(tracing::info_span!("prepare_for_guest_hibernate")) + .instrument(tracing::info_span!( + "prepare_for_guest_hibernate", + CVM_ALLOWED + )) .await; } else { network_settings .prepare_for_hibernate(rollback) - .instrument(tracing::info_span!("rollback_prepare_for_guest_hibernate")) + .instrument(tracing::info_span!( + "rollback_prepare_for_guest_hibernate", + CVM_ALLOWED + )) .await; }; } @@ -611,7 +621,7 @@ impl LoadedVm { let reference_time = ReferenceTime::new(self.partition.reference_time()); if let Some(stopped) = self.last_state_unit_stop { let blackout_time = reference_time.since(stopped); - tracing::info!( + tracing::info!(CVM_ALLOWED, correlation_id = %correlation_id.unwrap_or(Guid::ZERO), blackout_time_ms = blackout_time.map(|t| t.as_millis() as u64), blackout_time = blackout_time @@ -623,6 +633,7 @@ impl LoadedVm { // Assume we started at reference time 0. let boot_time = reference_time.since(ReferenceTime::new(0)); tracing::info!( + CVM_ALLOWED, boot_time_ms = boot_time.map(|t| t.as_millis() as u64), boot_time = boot_time .map_or_else(|| "unknown".to_string(), |t| format!("{:?}", t)) @@ -636,7 +647,7 @@ impl LoadedVm { async fn stop(&mut self) -> bool { if self.state_units.is_running() { self.last_state_unit_stop = Some(ReferenceTime::new(self.partition.reference_time())); - tracing::info!("stopping VM"); + tracing::info!(CVM_ALLOWED, "stopping VM"); self.state_units.stop().await; true } else { @@ -672,7 +683,7 @@ impl LoadedVm { // was enabled. let nvme_state = if let Some(n) = &self.nvme_manager { n.save(vf_keepalive_flag) - .instrument(tracing::info_span!("nvme_manager_save")) + .instrument(tracing::info_span!("nvme_manager_save", CVM_ALLOWED)) .await .map(|s| NvmeSavedState { nvme_state: s }) } else { @@ -725,19 +736,19 @@ impl LoadedVm { Ok(state) } - #[instrument(skip(self))] + #[instrument(skip(self), fields(CVM_ALLOWED))] async fn save_units(&mut self) -> anyhow::Result> { Ok(self.state_units.save().await?) } - #[instrument(skip(self, saved_state))] + #[instrument(skip(self, saved_state), fields(CVM_ALLOWED))] pub async fn restore_units(&mut self, saved_state: Vec) -> anyhow::Result<()> { self.state_units.restore(saved_state).await?; Ok(()) } fn notify_of_vtl_crash(&self, vtl_crash: VtlCrash) { - tracelimit::info_ratelimited!("Notifying the host of the guest system crash"); + tracelimit::info_ratelimited!(CVM_ALLOWED, "Notifying the host of the guest system crash"); let VtlCrash { vp_index, diff --git a/openhcl/underhill_core/src/dispatch/pci_shutdown.rs b/openhcl/underhill_core/src/dispatch/pci_shutdown.rs index 71dc914c9f..bff354ed6f 100644 --- a/openhcl/underhill_core/src/dispatch/pci_shutdown.rs +++ b/openhcl/underhill_core/src/dispatch/pci_shutdown.rs @@ -2,6 +2,7 @@ // Licensed under the MIT License. use blocking::unblock; +use cvm_tracing::CVM_ALLOWED; use fs_err::PathExt; use futures::future::try_join_all; use std::os::unix::prelude::*; @@ -47,6 +48,7 @@ pub async fn shutdown_pci_devices() -> Result<(), ShutdownError> { unblock(move || fs_err::write(driver_link.join("unbind"), pci_id.as_bytes())) .instrument(tracing::info_span!( "unbind_pci_device", + CVM_ALLOWED, driver = driver_name.as_ref(), pci_id = pci_id_str.as_str(), )) diff --git a/openhcl/underhill_core/src/dispatch/vtl2_settings_worker.rs b/openhcl/underhill_core/src/dispatch/vtl2_settings_worker.rs index 4eb2b66391..df03e53bdd 100644 --- a/openhcl/underhill_core/src/dispatch/vtl2_settings_worker.rs +++ b/openhcl/underhill_core/src/dispatch/vtl2_settings_worker.rs @@ -7,6 +7,7 @@ use super::LoadedVm; use crate::nvme_manager::NvmeDiskConfig; use crate::worker::NicConfig; use anyhow::Context; +use cvm_tracing::CVM_ALLOWED; use disk_backend::Disk; use disk_backend::resolve::ResolveDiskParameters; use disk_backend_resources::AutoFormattedDiskHandle; @@ -303,7 +304,7 @@ impl Vtl2SettingsWorker { let new_settings = vtl2_settings.dynamic; - tracing::info!("Received VTL2 settings {:?}", new_settings); + tracing::info!(CVM_ALLOWED, ?new_settings, "Received VTL2 settings"); let mut todos: Vec = Vec::new(); @@ -332,14 +333,18 @@ impl Vtl2SettingsWorker { .await { Err(e) => { - tracing::error!("Error acquiring VTL2 configuration resources: {:?}", e); + tracing::error!( + CVM_ALLOWED, + ?e, + "Error acquiring VTL2 configuration resources" + ); errors.push(e); } Ok(()) => { // NOTHING BEYOND CAN FAIL // We assume recover action for commit is to re-create the VM if let Err(e) = self.commit_configuration_changes(to_commits).await { - tracing::error!("Error commit VTL2 configuration changes: {:?}", e); + tracing::error!(CVM_ALLOWED, ?e, "Error commit VTL2 configuration changes"); errors.push(e); } } @@ -350,7 +355,7 @@ impl Vtl2SettingsWorker { return Err(errors); } - tracing::info!("VTL2 settings modified"); + tracing::info!(CVM_ALLOWED, "VTL2 settings modified"); self.old_settings = new_settings; Ok(()) } @@ -952,7 +957,7 @@ struct StorageContext<'a> { use_nvme_vfio: bool, } -#[instrument(skip_all)] +#[instrument(skip_all, fields(CVM_ALLOWED))] async fn make_disk_type_from_physical_device( ctx: &mut CancelContext, storage_context: &StorageContext<'_>, @@ -1016,7 +1021,7 @@ async fn make_disk_type_from_physical_device( } } }) - .instrument(tracing::info_span!("get_devname")) + .instrument(tracing::info_span!("get_devname", CVM_ALLOWED)) .await??; Ok(devname) } @@ -1042,7 +1047,7 @@ async fn make_disk_type_from_physical_device( devname.as_ref(), "bdi".as_ref(), ])) - .instrument(tracing::info_span!("wait_for_bdi")), + .instrument(tracing::info_span!("wait_for_bdi", CVM_ALLOWED)), ) .await??; Ok(()) @@ -1278,7 +1283,7 @@ async fn make_disk_type( Ok(disk_type) => Some(disk_type), Err(err_info) => match err_info.code() { Vtl2SettingsErrorCode::StorageCannotOpenVtl2Device => { - tracing::warn!("Check if ISO is present on drive: {:?}", err_info); + tracing::warn!(CVM_ALLOWED, ?err_info, "Check if ISO is present on drive"); None } _ => Err(err_info)?, @@ -1311,7 +1316,7 @@ async fn make_nvme_disk_config( }) } -#[instrument(skip_all)] +#[instrument(skip_all, fields(CVM_ALLOWED))] async fn make_ide_controller_config( ctx: &mut CancelContext, storage_context: &StorageContext<'_>, @@ -1353,7 +1358,7 @@ async fn make_ide_controller_config( } } -#[instrument(skip_all)] +#[instrument(skip_all, fields(CVM_ALLOWED))] async fn make_scsi_controller_config( ctx: &mut CancelContext, storage_context: &StorageContext<'_>, @@ -1392,7 +1397,7 @@ async fn make_scsi_controller_config( }) } -#[instrument(skip_all)] +#[instrument(skip_all, fields(CVM_ALLOWED))] async fn make_nvme_controller_config( ctx: &mut CancelContext, storage_context: &StorageContext<'_>, @@ -1495,11 +1500,16 @@ async fn check_block_sysfs_ready(devname: &str) -> bool { match blocking::unblock(move || fs_err::File::open(Path::new("/dev").join(dev_clone))).await { Ok(_) => true, Err(err) if err.raw_os_error() == Some(libc::ENXIO) => { - tracing::info!(devname, "block device not ready, waiting for uevent"); + tracing::info!( + CVM_ALLOWED, + devname, + "block device not ready, waiting for uevent" + ); false } Err(err) => { tracing::warn!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, devname, "block device failed to open during scan" @@ -1779,7 +1789,7 @@ impl InitialControllers { let vtl2_settings = dps.general.vtl2_settings.as_ref(); - tracing::info!("Initial VTL2 settings {:?}", vtl2_settings); + tracing::info!(CVM_ALLOWED, ?vtl2_settings, "Initial VTL2 settings"); let fixed = vtl2_settings.map_or_else(Default::default, |s| s.fixed.clone()); let dynamic = vtl2_settings.map(|s| &s.dynamic); diff --git a/openhcl/underhill_core/src/emuplat/firmware.rs b/openhcl/underhill_core/src/emuplat/firmware.rs index 0e9140efcd..6ba06c687e 100644 --- a/openhcl/underhill_core/src/emuplat/firmware.rs +++ b/openhcl/underhill_core/src/emuplat/firmware.rs @@ -1,6 +1,7 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +use cvm_tracing::CVM_ALLOWED; #[cfg(guest_arch = "x86_64")] use firmware_pcat::PcatEvent; #[cfg(guest_arch = "x86_64")] @@ -62,6 +63,7 @@ impl firmware_uefi::platform::nvram::VsmConfig for UnderhillVsmConfig { if let Some(partition) = self.partition.upgrade() { if let Err(err) = partition.revoke_guest_vsm() { tracing::warn!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "failed to revoke guest vsm" ); diff --git a/openhcl/underhill_core/src/emuplat/local_clock.rs b/openhcl/underhill_core/src/emuplat/local_clock.rs index 8969b2c220..db4c1e024f 100644 --- a/openhcl/underhill_core/src/emuplat/local_clock.rs +++ b/openhcl/underhill_core/src/emuplat/local_clock.rs @@ -2,6 +2,7 @@ // Licensed under the MIT License. use self::host_time::HostSystemTimeAccess; +use cvm_tracing::CVM_ALLOWED; use inspect::Inspect; use local_clock::LocalClock; use local_clock::LocalClockDelta; @@ -80,7 +81,11 @@ impl UnderhillLocalClock { // stores UTC. let skew = this.host_time.now().offset(); let skew = time::Duration::seconds(skew.whole_seconds().into()); - tracing::info!(?skew, "no saved skew found: defaulting to host local time"); + tracing::info!( + CVM_ALLOWED, + ?skew, + "no saved skew found: defaulting to host local time" + ); skew.into() } } @@ -92,7 +97,10 @@ impl UnderhillLocalClock { let neg_two_days = LocalClockDelta::from_millis(-MILLIS_IN_TWO_DAYS); if this.offset_from_host_time < neg_two_days { this.offset_from_host_time = neg_two_days; - tracing::warn!("Guest time was more than two days in the past."); + tracing::warn!( + CVM_ALLOWED, + "Guest time was more than two days in the past." + ); } Ok(this) @@ -112,7 +120,7 @@ async fn fetch_skew_from_store( raw_skew_100ns / NANOS_100_IN_SECOND, (raw_skew_100ns % NANOS_100_IN_SECOND) as i32, ); - tracing::info!(?skew, "restored existing RTC skew"); + tracing::info!(CVM_ALLOWED, ?skew, "restored existing RTC skew"); Ok(Some(skew.into())) } @@ -134,6 +142,7 @@ impl LocalClock for UnderhillLocalClock { let res = pal_async::local::block_on(self.store.persist(raw_skew.to_le_bytes().into())); if let Err(err) = res { tracing::error!( + CVM_ALLOWED, err = &err as &dyn std::error::Error, "failed to persist RTC skew" ); diff --git a/openhcl/underhill_core/src/emuplat/watchdog.rs b/openhcl/underhill_core/src/emuplat/watchdog.rs index 2f620e8241..e198c69614 100644 --- a/openhcl/underhill_core/src/emuplat/watchdog.rs +++ b/openhcl/underhill_core/src/emuplat/watchdog.rs @@ -1,6 +1,7 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +use cvm_tracing::CVM_ALLOWED; use vmcore::non_volatile_store::NonVolatileStore; use watchdog_core::platform::WatchdogPlatform; use watchdog_vmgs_format::WatchdogVmgsFormatStore; @@ -39,6 +40,7 @@ impl WatchdogPlatform for UnderhillWatchdog { let res = self.store.set_boot_failure().await; if let Err(e) = res { tracing::error!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "error persisting watchdog status" ); @@ -61,6 +63,7 @@ impl WatchdogPlatform for UnderhillWatchdog { Ok(status) => status, Err(e) => { tracing::error!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "error reading watchdog status" ); diff --git a/openhcl/underhill_core/src/get_tracing.rs b/openhcl/underhill_core/src/get_tracing.rs index ef6bd757c4..87d5982043 100644 --- a/openhcl/underhill_core/src/get_tracing.rs +++ b/openhcl/underhill_core/src/get_tracing.rs @@ -25,6 +25,7 @@ mod kmsg_stream; mod kmsg_writer; use anyhow::Context; +use cvm_tracing::CVM_ALLOWED; use futures::FutureExt; use futures::StreamExt; use futures_concurrency::stream::Merge; @@ -80,6 +81,7 @@ pub fn init_tracing_backend(driver: impl 'static + SpawnDriver) -> anyhow::Resul .and_then(|dev| vmbus_user_channel::message_pipe(&driver, dev)) .map_err(|err| { tracing::error!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "failed to open the vmbus tracing channel" ); diff --git a/openhcl/underhill_core/src/get_tracing/kmsg_stream.rs b/openhcl/underhill_core/src/get_tracing/kmsg_stream.rs index 49c48fcf33..5df04ba4f3 100644 --- a/openhcl/underhill_core/src/get_tracing/kmsg_stream.rs +++ b/openhcl/underhill_core/src/get_tracing/kmsg_stream.rs @@ -5,6 +5,7 @@ //! send to the host. use super::json_common::KmsgMessage; +use cvm_tracing::CVM_ALLOWED; use futures::AsyncRead; use futures::Stream; use get_helpers::build_tracelogging_notification_buffer; @@ -161,6 +162,7 @@ impl Stream for KmsgStream { } Err(err) => { tracing::error!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "failed to read from /dev/kmsg" ); diff --git a/openhcl/underhill_core/src/inspect_proc.rs b/openhcl/underhill_core/src/inspect_proc.rs index 1b8aee956f..20fb6df5b6 100644 --- a/openhcl/underhill_core/src/inspect_proc.rs +++ b/openhcl/underhill_core/src/inspect_proc.rs @@ -2,6 +2,7 @@ // Licensed under the MIT License. use anyhow::Context; +use cvm_tracing::CVM_ALLOWED; use inspect::Request; use inspect::Response; use inspect::SensitivityLevel; @@ -209,7 +210,7 @@ pub async fn periodic_telemetry_task(driver: VmTaskDriver) { let results = inspection.results(); let json = results.json(); // The below message needs to be valid JSON for ease of processing - tracing::info!("{{\"periodic_memory_status\":{}}}", json); + tracing::info!(CVM_ALLOWED, "{{\"periodic_memory_status\":{}}}", json); // Wait a day before logging again timer.sleep(Duration::from_secs(60 * 60 * 24)).await; } diff --git a/openhcl/underhill_core/src/lib.rs b/openhcl/underhill_core/src/lib.rs index 0579b2add1..e03205b2e8 100644 --- a/openhcl/underhill_core/src/lib.rs +++ b/openhcl/underhill_core/src/lib.rs @@ -206,7 +206,11 @@ async fn do_main(driver: DefaultDriver, mut tracing: TracingBackend) -> anyhow:: let r = run_control(driver, &mesh, opt, &mut tracing).await; if let Err(err) = &r { - tracing::error!(error = err.as_ref() as &dyn std::error::Error, "VM failure"); + tracing::error!( + CVM_ALLOWED, + error = err.as_ref() as &dyn std::error::Error, + "VM failure" + ); } // Wait a few seconds for child processes to terminate and tracing to finish. @@ -238,6 +242,7 @@ fn log_boot_times() -> anyhow::Result<()> { sidecar_end, } = BootTimes::new().context("failed to parse boot times")?; tracing::info!( + CVM_ALLOWED, start, end, sidecar_start, @@ -706,10 +711,10 @@ async fn run_control( Event::Worker(event) => match event { WorkerEvent::Started => { if let Some(response) = restart_rpc.take() { - tracing::info!("restart complete"); + tracing::info!(CVM_ALLOWED, "restart complete"); response.complete(Ok(())); } else { - tracing::info!("vm worker started"); + tracing::info!(CVM_ALLOWED, "vm worker started"); } state = ControlState::Started; } @@ -720,7 +725,11 @@ async fn run_control( return Err(anyhow::Error::from(err)).context("vm worker failed"); } WorkerEvent::RestartFailed(err) => { - tracing::error!(error = &err as &dyn std::error::Error, "restart failed"); + tracing::error!( + CVM_ALLOWED, + error = &err as &dyn std::error::Error, + "restart failed" + ); restart_rpc.take().unwrap().complete(Err(err)); state = ControlState::Started; } @@ -728,7 +737,7 @@ async fn run_control( Event::Control(req) => match req { ControlRequest::FlushLogs(rpc) => { rpc.handle(async |mut ctx| { - tracing::info!("flushing logs"); + tracing::info!(CVM_ALLOWED, "flushing logs"); ctx.until_cancelled(tracing.flush()).await?; Ok(()) }) @@ -742,7 +751,7 @@ async fn run_control( } async fn signal_vtl0_started(driver: &DefaultDriver) -> anyhow::Result<()> { - tracing::info!("signaling vtl0 started early"); + tracing::info!(CVM_ALLOWED, "signaling vtl0 started early"); let (client, task) = guest_emulation_transport::spawn_get_worker(driver.clone()) .await .context("failed to spawn GET")?; @@ -750,7 +759,7 @@ async fn signal_vtl0_started(driver: &DefaultDriver) -> anyhow::Result<()> { // Disconnect the GET so that it can be reused. drop(client); task.await.unwrap(); - tracing::info!("signaled vtl0 start"); + tracing::info!(CVM_ALLOWED, "signaled vtl0 start"); Ok(()) } diff --git a/openhcl/underhill_core/src/livedump.rs b/openhcl/underhill_core/src/livedump.rs index 15f941f57c..955b056782 100644 --- a/openhcl/underhill_core/src/livedump.rs +++ b/openhcl/underhill_core/src/livedump.rs @@ -6,7 +6,7 @@ use std::process::Stdio; pub(crate) async fn livedump() { // If a livedump fails we don't want to panic, just log the error. match livedump_core().await { - Err(e) => tracing::error!(?e, "livedump failed"), + Err(e) => tracing::error!(e = e.as_ref() as &dyn std::error::Error, "livedump failed"), Ok(()) => tracing::info!("livedump succeeded"), } } diff --git a/openhcl/underhill_core/src/loader/mod.rs b/openhcl/underhill_core/src/loader/mod.rs index fdbd708507..71614d94e5 100644 --- a/openhcl/underhill_core/src/loader/mod.rs +++ b/openhcl/underhill_core/src/loader/mod.rs @@ -6,6 +6,7 @@ use self::vtl2_config::RuntimeParameters; use crate::loader::vtl0_config::LinuxInfo; use crate::worker::FirmwareType; +use cvm_tracing::CVM_ALLOWED; use guest_emulation_transport::api::platform_settings::DevicePlatformSettings; use guest_emulation_transport::api::platform_settings::General; use guestmem::GuestMemory; @@ -114,11 +115,11 @@ pub fn load( ) -> Result { let context = match load_kind { LoadKind::None => { - tracing::info!("loading nothing into VTL0"); + tracing::info!(CVM_ALLOWED, "loading nothing into VTL0"); VpContext::Vbs(Vec::new()) } LoadKind::Uefi => { - tracing::info!("loading UEFI into VTL0"); + tracing::info!(CVM_ALLOWED, "loading UEFI into VTL0"); // UEFI image is already loaded into guest memory, so only the // dynamic config needs to be written. let uefi_info = vtl0_info.supports_uefi.as_ref().ok_or(Error::UefiSupport)?; @@ -152,7 +153,7 @@ pub fn load( } #[cfg(guest_arch = "x86_64")] LoadKind::Linux => { - tracing::info!("loading Linux into VTL0"); + tracing::info!(CVM_ALLOWED, "loading Linux into VTL0"); let LinuxInfo { kernel_range, @@ -190,7 +191,7 @@ pub fn load( })? } LoadKind::Pcat => { - tracing::info!("loading pcat into VTL0"); + tracing::info!(CVM_ALLOWED, "loading pcat into VTL0"); if !vtl0_info.supports_pcat { return Err(Error::PcatSupport); diff --git a/openhcl/underhill_core/src/loader/vtl0_config.rs b/openhcl/underhill_core/src/loader/vtl0_config.rs index fff60acb39..3daff7cf7e 100644 --- a/openhcl/underhill_core/src/loader/vtl0_config.rs +++ b/openhcl/underhill_core/src/loader/vtl0_config.rs @@ -68,7 +68,7 @@ pub struct MeasuredVtl0Info { impl MeasuredVtl0Info { /// Read measured VTL0 load information from guest memory. - #[instrument(skip_all)] + #[instrument(skip_all, fields(CVM_ALLOWED))] pub fn read_from_memory(gm: &GuestMemory) -> Result { // Read the measured config, noting which pages the config was stored // in. These pages will need to be zeroed out afterwards (the memory diff --git a/openhcl/underhill_core/src/vp.rs b/openhcl/underhill_core/src/vp.rs index 8f25cf8571..04bb91e44c 100644 --- a/openhcl/underhill_core/src/vp.rs +++ b/openhcl/underhill_core/src/vp.rs @@ -4,6 +4,7 @@ //! Code to spawn VP tasks and run VPs. use anyhow::Context; +use cvm_tracing::CVM_ALLOWED; use futures::future::try_join_all; use pal_async::task::Spawn; use pal_async::task::SpawnLocal; @@ -228,7 +229,7 @@ impl VpSpawner { None }; - tracing::info!(cpu = self.cpu, "onlining sidecar VP"); + tracing::info!(CVM_ALLOWED, cpu = self.cpu, "onlining sidecar VP"); online_cpu(self.cpu).await; // Respawn the VP on the new thread. @@ -255,7 +256,7 @@ async fn online_cpu(cpu: u32) { .name(format!("online-{cpu}")) .spawn(move || { send.send({ - let _span = tracing::info_span!("online_cpu", cpu).entered(); + let _span = tracing::info_span!("online_cpu", CVM_ALLOWED, cpu).entered(); underhill_threadpool::set_cpu_online(cpu) }) }) diff --git a/openhcl/underhill_core/src/worker.rs b/openhcl/underhill_core/src/worker.rs index 742544efc1..b0ccef3c1c 100644 --- a/openhcl/underhill_core/src/worker.rs +++ b/openhcl/underhill_core/src/worker.rs @@ -58,6 +58,7 @@ use anyhow::Context; use async_trait::async_trait; use chipset_device::ChipsetDevice; use closeable_mutex::CloseableMutex; +use cvm_tracing::CVM_ALLOWED; use debug_ptr::DebugPtr; use disk_backend::Disk; use disk_blockdevice::BlockDeviceResolver; @@ -342,6 +343,7 @@ impl Worker for UnderhillVmWorker { if let Err(err) = &result { tracing::error!( + CVM_ALLOWED, error = err.as_ref() as &dyn std::error::Error, "failed to start VM" ); @@ -395,7 +397,7 @@ impl Worker for UnderhillVmWorker { self.vm_rpc, worker_rpc, )); - tracing::info!("terminating worker"); + tracing::info!(CVM_ALLOWED, "terminating worker"); self.get_thread.join().unwrap(); if let Some(state) = state { let params = UnderhillWorkerParameters { @@ -412,7 +414,7 @@ impl Worker for UnderhillVmWorker { control_send: state.control_send, }; - tracing::info!("sending worker restart state"); + tracing::info!(CVM_ALLOWED, "sending worker restart state"); state.restart_rpc.complete(Ok(RestartState { params, servicing_state: state.servicing_state, @@ -423,7 +425,7 @@ impl Worker for UnderhillVmWorker { } impl UnderhillVmWorker { - #[instrument(name = "init", skip_all)] + #[instrument(name = "init", skip_all, fields(CVM_ALLOWED))] async fn new_or_restart( get_infra: GuestEmulationTransportInfra, params: UnderhillWorkerParameters, @@ -441,7 +443,7 @@ impl UnderhillVmWorker { // re-fetching them (but then how would we know we need to get the // servicing state from the host? Classic catch-22.) let dps = read_device_platform_settings(&get_client) - .instrument(tracing::info_span!("init/dps")) + .instrument(tracing::info_span!("init/dps", CVM_ALLOWED)) .await?; // Build the thread pool now that we know the IO ring size to use. @@ -484,11 +486,14 @@ impl UnderhillVmWorker { future::pending::<()>().await; } - tracing::info!("VTL2 restart, getting servicing state from the host"); + tracing::info!( + CVM_ALLOWED, + "VTL2 restart, getting servicing state from the host" + ); let saved_state_buf = get_client .get_saved_state_from_host() - .instrument(tracing::info_span!("init/get_saved_state")) + .instrument(tracing::info_span!("init/get_saved_state", CVM_ALLOWED)) .await .context("Failed to get saved state from host")?; @@ -498,6 +503,7 @@ impl UnderhillVmWorker { ); tracing::info!( + CVM_ALLOWED, saved_state_len = saved_state_buf.len(), "received servicing state from host" ); @@ -534,6 +540,7 @@ impl UnderhillVmWorker { ) .instrument(tracing::info_span!( "init/new_underhill_vm", + CVM_ALLOWED, correlation_id = correlation_id.map(tracing::field::display) )) .await?; @@ -546,6 +553,7 @@ impl UnderhillVmWorker { .restore_units(unit_state) .instrument(tracing::info_span!( "init/restore", + CVM_ALLOWED, correlation_id = correlation_id.map(tracing::field::display) )) .await; @@ -606,7 +614,7 @@ async fn read_device_platform_settings( // TODO: figure out if we really need to trace this. These are too long for // the Underhill trace buffer. - tracing::info!("device platform settings {:?}", dps); + tracing::debug!("device platform settings {:?}", dps); Ok(dps) } @@ -678,8 +686,9 @@ impl UhVmNetworkSettings { for instance_id in instance_ids { if !nic_channels.iter().any(|(id, _)| *id == instance_id) { - tracing::error!( - "No vmbus channel found that matches VF Manager instance_id: {instance_id}" + tracing::error!(CVM_ALLOWED, + %instance_id, + "No vmbus channel found that matches VF Manager instance_id" ); } } @@ -691,7 +700,7 @@ impl UhVmNetworkSettings { let nic = channel.remove().await.revoke().await; nic.shutdown() } - .instrument(tracing::info_span!("nic_shutdown", %instance_id)) + .instrument(tracing::info_span!("nic_shutdown",CVM_ALLOWED, %instance_id)) .await })) .await; @@ -700,7 +709,9 @@ impl UhVmNetworkSettings { async |(instance_id, mut manager)| { manager .complete(keep_vf_alive) - .instrument(tracing::info_span!("vf_manager_shutdown", %instance_id)) + .instrument( + tracing::info_span!("vf_manager_shutdown",CVM_ALLOWED, %instance_id), + ) .await }, )); @@ -947,6 +958,7 @@ impl LoadedVmNetworkSettings for UhVmNetworkSettings { .collect::>>(); if let Err(err) = result { tracing::error!( + CVM_ALLOWED, error = err.as_ref() as &dyn std::error::Error, rollback, "Failed preparing accelerated network devices for hibernate" @@ -1051,6 +1063,7 @@ fn build_vtl0_memory_layout( .context("invalid complete memory layout")?; tracing::info!( + CVM_ALLOWED, vtl0_ram = vtl0_memory_layout .ram() .iter() @@ -1061,6 +1074,7 @@ fn build_vtl0_memory_layout( ); tracing::info!( + CVM_ALLOWED, vtl0_mmio = vtl0_memory_layout .mmio() .iter() @@ -1161,7 +1175,7 @@ async fn new_underhill_vm( if let Ok(kernel_boot_time) = std::env::var("KERNEL_BOOT_TIME") { if let Ok(kernel_boot_time_ns) = kernel_boot_time.parse::() { - tracing::info!(kernel_boot_time_ns, "kernel boot time"); + tracing::info!(CVM_ALLOWED, kernel_boot_time_ns, "kernel boot time"); } } @@ -1171,8 +1185,13 @@ async fn new_underhill_vm( // Log information about VTL2 memory let memory_allocation_mode = runtime_params.parsed_openhcl_boot().memory_allocation_mode; - tracing::info!(?memory_allocation_mode, "memory allocation mode"); tracing::info!( + CVM_ALLOWED, + ?memory_allocation_mode, + "memory allocation mode" + ); + tracing::info!( + CVM_ALLOWED, vtl2_ram = runtime_params .vtl2_memory_map() .iter() @@ -1205,9 +1224,9 @@ async fn new_underhill_vm( servicing_state.flush_logs_result { if let Some(error) = error { - tracing::error!(duration_us, error, "flush logs result") + tracing::error!(CVM_ALLOWED, duration_us, error, "flush logs result") } else { - tracing::info!(duration_us, "flush logs result") + tracing::info!(CVM_ALLOWED, duration_us, "flush logs result") } } @@ -1370,7 +1389,7 @@ async fn new_underhill_vm( } None => { let disk = disk_get_vmgs::GetVmgsDisk::new(get_client.clone()) - .instrument(tracing::info_span!("vmgs_get_storage")) + .instrument(tracing::info_span!("vmgs_get_storage", CVM_ALLOWED)) .await .context("failed to get VMGS client")?; @@ -1383,9 +1402,9 @@ async fn new_underhill_vm( dps.general.guest_state_lifetime, GuestStateLifetime::Reprovision ) { - tracing::info!("formatting vmgs file on request"); + tracing::info!(CVM_ALLOWED, "formatting vmgs file on request"); Vmgs::format_new(disk, Some(logger)) - .instrument(tracing::info_span!("vmgs_format")) + .instrument(tracing::info_span!("vmgs_format", CVM_ALLOWED)) .await .context("failed to format vmgs")? } else { @@ -1398,7 +1417,7 @@ async fn new_underhill_vm( GuestStateLifetime::ReprovisionOnFailure ), ) - .instrument(tracing::info_span!("vmgs_open")) + .instrument(tracing::info_span!("vmgs_open", CVM_ALLOWED)) .await .context("failed to open vmgs")? }; @@ -1417,12 +1436,16 @@ async fn new_underhill_vm( // or some other kernel changes. If possible, would be good to not // require 5 level paging and just further extend valid bits. if alias_map <= 1 << 48 { - tracing::info!(alias_map, "enabling alias map"); + tracing::info!(CVM_ALLOWED, alias_map, "enabling alias map"); true } else { // BUGBUG: This needs to be fixed, but allow it with just an error // log for now. - tracing::error!(alias_map, "alias map bit larger than supported"); + tracing::error!( + CVM_ALLOWED, + alias_map, + "alias map bit larger than supported" + ); false } }); @@ -1595,7 +1618,7 @@ async fn new_underhill_vm( // VBS not supported yet, fall back to the host type. // Raise an error message instead of aborting so that // we do not block VBS bringup. - tracing::error!("VBS attestation not supported yet"); + tracing::error!(CVM_ALLOWED, "VBS attestation not supported yet"); // TODO VBS: Support VBS attestation AttestationType::Host } @@ -1641,7 +1664,10 @@ async fn new_underhill_vm( suppress_attestation, early_init_driver, ) - .instrument(tracing::info_span!("initialize_platform_security")) + .instrument(tracing::info_span!( + "initialize_platform_security", + CVM_ALLOWED + )) .await .context("failed to initialize platform security")? } @@ -1669,7 +1695,7 @@ async fn new_underhill_vm( let config = MeasuredVtl0Info::read_from_memory(gm.vtl0()) .context("failed to read measured vtl0 info")?; let load_kind = if let Some(kind) = env_cfg.force_load_vtl0_image { - tracing::info!(kind, "overriding dps load type"); + tracing::info!(CVM_ALLOWED, kind, "overriding dps load type"); match kind.as_str() { "pcat" => LoadKind::Pcat, "uefi" => LoadKind::Uefi, @@ -1753,7 +1779,7 @@ async fn new_underhill_vm( let (partition, vps) = proto_partition .build(late_params) - .instrument(tracing::info_span!("new_uh_partition")) + .instrument(tracing::info_span!("new_uh_partition", CVM_ALLOWED)) .await .context("failed to create partition")?; @@ -1772,14 +1798,14 @@ async fn new_underhill_vm( is_restoring, default_io_queue_depth, ) - .instrument(tracing::info_span!("new_initial_controllers")) + .instrument(tracing::info_span!("new_initial_controllers", CVM_ALLOWED)) .await .context("failed to merge configuration")?; // TODO MCR: support closed-source configuration logic for MCR device if env_cfg.mcr { use crate::dispatch::vtl2_settings_worker::UhVpciDeviceConfig; - tracing::info!("Instantiating The MCR Device"); + tracing::info!(CVM_ALLOWED, "Instantiating The MCR Device"); const MCR_INSTANCE_ID: Guid = guid::guid!("07effd8f-7501-426c-a947-d8345f39113d"); let res = UhVpciDeviceConfig { @@ -1791,7 +1817,7 @@ async fn new_underhill_vm( }; controllers.vpci_devices.push(res); } else { - tracing::info!("Not Instantiating The MCR Device"); + tracing::info!(CVM_ALLOWED, "Not Instantiating The MCR Device"); } let (halt_vps, halt_request_recv) = Halt::new(); @@ -2004,7 +2030,7 @@ async fn new_underhill_vm( match res { Ok(vars) => vars, Err(e) => { - tracing::error!("Failed to load custom UEFI vars"); + tracing::error!(CVM_ALLOWED, "Failed to load custom UEFI vars"); get_client .event_log_fatal(EventLogId::BOOT_FAILURE_SECURE_BOOT_FAILED) .await; @@ -2097,7 +2123,10 @@ async fn new_underhill_vm( if dps.general.processor_idle_enabled { // TODO: Will likely address along with battery task above - tracing::warn!("processor idle emulator unsupported for underhill"); + tracing::warn!( + CVM_ALLOWED, + "processor idle emulator unsupported for underhill" + ); } let mut input_distributor = InputDistributor::new(remote_console_cfg.input); @@ -2550,7 +2579,7 @@ async fn new_underhill_vm( .with_trace_unknown_mmio(!use_mmio_hypercalls) .with_fallback_mmio_device(fallback_mmio_device) .build(&driver_source, &state_units, &resolver) - .instrument(tracing::info_span!("base_chipset_build")) + .instrument(tracing::info_span!("base_chipset_build", CVM_ALLOWED)) .await .context("failed to create devices")?; @@ -2612,7 +2641,7 @@ async fn new_underhill_vm( let enable_mnf = env_cfg .vmbus_enable_mnf .unwrap_or(!controllers.mana.is_empty()); - tracing::info!(enable_mnf, "Underhill MNF enabled?"); + tracing::info!(CVM_ALLOWED, enable_mnf, "Underhill MNF enabled?"); let max_version = env_cfg .vmbus_max_version @@ -2716,7 +2745,7 @@ async fn new_underhill_vm( // Storage let mut ide_accel_devices = Vec::new(); { - let _span = tracing::info_span!("scsi_controller_map").entered(); + let _span = tracing::info_span!("scsi_controller_map", CVM_ALLOWED).entered(); for (path, scsi_disk) in storvsp_ide_disks { let io_queue_depth = ide_io_queue_depth.unwrap_or(default_io_queue_depth); @@ -2799,7 +2828,7 @@ async fn new_underhill_vm( }; let mut netvsp_state = Vec::with_capacity(controllers.mana.len()); if !controllers.mana.is_empty() { - let _span = tracing::info_span!("network_settings").entered(); + let _span = tracing::info_span!("network_settings", CVM_ALLOWED).entered(); for nic_config in controllers.mana.into_iter() { let save_state = uh_network_settings .add_network( @@ -2964,7 +2993,7 @@ async fn new_underhill_vm( isolation.is_isolated(), env_cfg.disable_uefi_frontpage, ) - .instrument(tracing::info_span!("load_firmware")) + .instrument(tracing::info_span!("load_firmware", CVM_ALLOWED)) .await?; } @@ -3181,7 +3210,7 @@ async fn halt_task( HaltReason::Reset => HaltRequest::Reset, HaltReason::Hibernate => HaltRequest::Hibernate, HaltReason::TripleFault { vp, registers } => { - tracing::info!(vp, "triple fault"); + tracing::info!(CVM_ALLOWED, vp, "triple fault"); let reg_state = build_vp_state(registers.as_deref()); HaltRequest::TripleFault { vp, @@ -3203,15 +3232,15 @@ async fn halt_task( } } HaltReason::DebugBreak { vp } => { - tracing::info!(vp, "debug break"); + tracing::info!(CVM_ALLOWED, vp, "debug break"); HaltRequest::None } HaltReason::SingleStep { vp } => { - tracing::info!(vp, "single step"); + tracing::info!(CVM_ALLOWED, vp, "single step"); HaltRequest::None } HaltReason::HwBreakpoint { vp, .. } => { - tracing::info!(vp, "hardware breakpoint"); + tracing::info!(CVM_ALLOWED, vp, "hardware breakpoint"); HaltRequest::None } }; @@ -3222,7 +3251,7 @@ async fn halt_task( HaltRequest::None => {} // For guest requested halts, log the error and do not forward to the host. _ => { - tracing::info!(?halt_request, "guest halted"); + tracing::info!(CVM_ALLOWED, ?halt_request, "guest halted"); } } } else { @@ -3302,7 +3331,7 @@ async fn load_firmware( let registers = initial_regs(®isters, caps, &processor_topology.vp_arch(VpIndex::BSP)); partition_unit .set_initial_regs(Vtl::Vtl0, registers) - .instrument(tracing::info_span!("set_initial_regs")) + .instrument(tracing::info_span!("set_initial_regs", CVM_ALLOWED)) .await .context("failed to set initial registers")?; @@ -3328,6 +3357,7 @@ impl chipset::pm::PmTimerAssist for UnderhillPmTimerAssist { if let Some(partition) = self.partition.upgrade() { if let Err(err) = partition.set_pm_timer_assist(port) { tracing::warn!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, ?port, "failed to set PM timer assist" @@ -3361,6 +3391,7 @@ impl chipset_device::mmio::MmioIntercept for FallbackMmioDevice { if self.is_allowed(addr, data.len()) { if let Err(err) = self.mshv_hvcall.mmio_read(addr, data) { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "failed host MMIO read" ); @@ -3374,6 +3405,7 @@ impl chipset_device::mmio::MmioIntercept for FallbackMmioDevice { if self.is_allowed(addr, data.len()) { if let Err(err) = self.mshv_hvcall.mmio_write(addr, data) { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "failed host MMIO write" ); diff --git a/openhcl/underhill_mem/Cargo.toml b/openhcl/underhill_mem/Cargo.toml index e84deaf5ab..f459b4bd21 100644 --- a/openhcl/underhill_mem/Cargo.toml +++ b/openhcl/underhill_mem/Cargo.toml @@ -18,6 +18,7 @@ virt_mshv_vtl.workspace = true vm_topology.workspace = true x86defs.workspace = true +cvm_tracing.workspace = true inspect.workspace = true pal_async.workspace = true sparse_mmap.workspace = true diff --git a/openhcl/underhill_mem/src/init.rs b/openhcl/underhill_mem/src/init.rs index 849ae203f1..683ff295ba 100644 --- a/openhcl/underhill_mem/src/init.rs +++ b/openhcl/underhill_mem/src/init.rs @@ -7,6 +7,7 @@ use crate::HardwareIsolatedMemoryProtector; use crate::MemoryAcceptor; use crate::mapping::GuestMemoryMapping; use anyhow::Context; +use cvm_tracing::CVM_ALLOWED; use futures::future::try_join_all; use guestmem::GuestMemory; use hcl::ioctl::MshvHvcall; @@ -111,7 +112,7 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { tracing::debug!("Applying VTL2 protections"); apply_vtl2_protections(boot_init.tp, boot_init.vtl2_memory) - .instrument(tracing::info_span!("apply_vtl2_protections")) + .instrument(tracing::info_span!("apply_vtl2_protections", CVM_ALLOWED)) .await?; } else { // Prepare VTL0 memory for mapping. @@ -209,7 +210,7 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { // kernel-registered RAM. tracing::debug!("Building VTL0 memory map"); let vtl0_mapping = Arc::new({ - let _span = tracing::info_span!("map_vtl0_memory").entered(); + let _span = tracing::info_span!("map_vtl0_memory", CVM_ALLOWED).entered(); GuestMemoryMapping::builder(0) .dma_base_address(None) // prohibit direct DMA attempts until TDISP is supported .use_bitmap(Some(true)) @@ -282,7 +283,7 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { // bounce buffering. tracing::debug!("Building shared memory map"); let shared_mapping = Arc::new({ - let _span = tracing::info_span!("map_shared_memory").entered(); + let _span = tracing::info_span!("map_shared_memory", CVM_ALLOWED).entered(); GuestMemoryMapping::builder(shared_offset) .shared(true) .use_bitmap(Some(false)) @@ -325,7 +326,8 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { // applied because the lower VTLs are not running yet. // // TODO: perform lazily - let _span = tracing::info_span!("zeroing lower vtl memory for SNP").entered(); + let _span = + tracing::info_span!("zeroing lower vtl memory for SNP", CVM_ALLOWED).entered(); tracing::debug!("zeroing lower vtl memory for SNP"); for range in validated_ranges { @@ -370,7 +372,7 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { } else { tracing::debug!("Creating VTL0 guest memory"); let vtl0_mapping = { - let _span = tracing::info_span!("map_vtl0_memory").entered(); + let _span = tracing::info_span!("map_vtl0_memory", CVM_ALLOWED).entered(); let base_address = params.vtl0_alias_map_bit.unwrap_or(0); Arc::new( GuestMemoryMapping::builder(base_address) @@ -399,6 +401,7 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { // On ARM, the alias map is not exposed: see // underhill_core::init::vtl0_alias_map_bit. tracing::warn!( + CVM_ALLOWED, "cannot safely support VTL 1 without using the alias map; Guest VSM not supported" ); None @@ -406,7 +409,7 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { } else { tracing::debug!("Creating VTL 1 memory map"); - let _span = tracing::info_span!("map_vtl1_memory").entered(); + let _span = tracing::info_span!("map_vtl1_memory", CVM_ALLOWED).entered(); let vtl1_mapping = GuestMemoryMapping::builder(0) .for_kernel_access(true) .dma_base_address(Some(0)) @@ -420,10 +423,10 @@ pub async fn init(params: &Init<'_>) -> anyhow::Result { }; let vtl1_gm = if let Some(vtl1_mapping) = &vtl1_mapping { - tracing::info!("VTL 1 memory map created"); + tracing::info!(CVM_ALLOWED, "VTL 1 memory map created"); Some(GuestMemory::new("vtl1", vtl1_mapping.clone())) } else { - tracing::info!("Skipping VTL 1 memory map creation"); + tracing::info!(CVM_ALLOWED, "Skipping VTL 1 memory map creation"); None }; diff --git a/openhcl/underhill_mem/src/lib.rs b/openhcl/underhill_mem/src/lib.rs index 8a41d8eb11..9d6809657a 100644 --- a/openhcl/underhill_mem/src/lib.rs +++ b/openhcl/underhill_mem/src/lib.rs @@ -14,6 +14,7 @@ pub use init::Init; pub use init::MemoryMappings; pub use init::init; +use cvm_tracing::CVM_ALLOWED; use guestmem::PAGE_SIZE; use guestmem::ranges::PagedRange; use hcl::GuestVtl; @@ -71,6 +72,7 @@ impl RegisterMemory for MshvVtlWithPolicy { // TODO: remove this once the kernel driver tracks registration Err(err) if self.ignore_registration_failure => { tracing::warn!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "registration failure, could be expected" ); diff --git a/openhcl/underhill_mem/src/registrar.rs b/openhcl/underhill_mem/src/registrar.rs index 7592680b5c..c1bb4daff0 100644 --- a/openhcl/underhill_mem/src/registrar.rs +++ b/openhcl/underhill_mem/src/registrar.rs @@ -19,6 +19,7 @@ //! initial registration for a chunk small. We track whether a given chunk has //! been registered via a small bitmap. +use cvm_tracing::CVM_ALLOWED; use inspect::Inspect; use memory_range::MemoryRange; use memory_range::overlapping_ranges; @@ -167,9 +168,9 @@ impl MemoryRegistrar { self.registration_offset + range.start() ..self.registration_offset + range.end(), ); - tracing::info!(%range, "registering memory"); + tracing::info!(CVM_ALLOWED, %range, "registering memory"); if let Err(err) = self.register.register_range(range) { - tracing::error!( + tracing::error!(CVM_ALLOWED, %range, registration_offset = self.registration_offset, error = &err as &dyn std::error::Error, diff --git a/openhcl/underhill_threadpool/Cargo.toml b/openhcl/underhill_threadpool/Cargo.toml index 4007541822..a196af6474 100644 --- a/openhcl/underhill_threadpool/Cargo.toml +++ b/openhcl/underhill_threadpool/Cargo.toml @@ -7,6 +7,7 @@ edition.workspace = true rust-version.workspace = true [target.'cfg(target_os = "linux")'.dependencies] +cvm_tracing.workspace = true inspect = { workspace = true, features = ["std"] } loan_cell.workspace = true pal.workspace = true diff --git a/openhcl/underhill_threadpool/src/lib.rs b/openhcl/underhill_threadpool/src/lib.rs index c38b5e7f86..8caa3c3671 100644 --- a/openhcl/underhill_threadpool/src/lib.rs +++ b/openhcl/underhill_threadpool/src/lib.rs @@ -10,6 +10,7 @@ #![forbid(unsafe_code)] +use cvm_tracing::CVM_ALLOWED; use inspect::Inspect; use loan_cell::LoanCell; use pal::unix::affinity::CpuSet; @@ -163,6 +164,7 @@ impl ThreadpoolBuilder { // because the thread will probably get allocated with the wrong node, // but it's recoverable. tracing::warn!( + CVM_ALLOWED, cpu, error = &err as &dyn std::error::Error, "could not set package affinity for thread pool thread" diff --git a/openhcl/virt_mshv_vtl/src/cvm_cpuid/mod.rs b/openhcl/virt_mshv_vtl/src/cvm_cpuid/mod.rs index bfc1c90af9..fa1ebb84eb 100644 --- a/openhcl/virt_mshv_vtl/src/cvm_cpuid/mod.rs +++ b/openhcl/virt_mshv_vtl/src/cvm_cpuid/mod.rs @@ -7,6 +7,7 @@ use self::tdx::TdxCpuidInitializer; use core::arch::x86_64::CpuidResult; +use cvm_tracing::CVM_ALLOWED; use masking::CpuidResultMask; use snp::SnpCpuidInitializer; use std::collections::BTreeMap; @@ -285,6 +286,7 @@ impl CpuidResults { if skipped { tracing::warn!( + CVM_ALLOWED, "cpuid result for leaf {} subleaf {} specified multiple times, ignoring duplicate with eax {}, ebx {}, ecx {}, edx {}", leaf.0, subleaf, diff --git a/openhcl/virt_mshv_vtl/src/cvm_cpuid/tdx.rs b/openhcl/virt_mshv_vtl/src/cvm_cpuid/tdx.rs index d870b1d311..ae37d026ff 100644 --- a/openhcl/virt_mshv_vtl/src/cvm_cpuid/tdx.rs +++ b/openhcl/virt_mshv_vtl/src/cvm_cpuid/tdx.rs @@ -12,6 +12,7 @@ use super::CpuidSubtable; use super::ParsedCpuidEntry; use super::TopologyError; use core::arch::x86_64::CpuidResult; +use cvm_tracing::CVM_ALLOWED; use vm_topology::processor::ProcessorTopology; use vm_topology::processor::x86::X86Topology; use x86defs::cpuid; @@ -230,6 +231,7 @@ impl CpuidArchInitializer for TdxCpuidInitializer<'_> { || (extended_topology_ecx_0.level_type() != super::CPUID_LEAF_B_LEVEL_TYPE_SMT) { tracing::error!( + CVM_ALLOWED, "Incorrect values received: {:?}. Level Number should represent sub-leaf 0, while Level Type should represent domain type 1 for logical processor.", extended_topology_ecx_0 ); @@ -244,6 +246,7 @@ impl CpuidArchInitializer for TdxCpuidInitializer<'_> { || (extended_topology_ecx_1.level_type() != super::CPUID_LEAF_B_LEVEL_TYPE_CORE) { tracing::error!( + CVM_ALLOWED, "Incorrect values received: {:?}. Level Number should represent sub-leaf 1, while Level Type should represent domain type 2 for Core.", extended_topology_ecx_1 ); diff --git a/openhcl/virt_mshv_vtl/src/lib.rs b/openhcl/virt_mshv_vtl/src/lib.rs index d2fb4539e0..49809f0a87 100644 --- a/openhcl/virt_mshv_vtl/src/lib.rs +++ b/openhcl/virt_mshv_vtl/src/lib.rs @@ -45,6 +45,7 @@ use anyhow::Context as AnyhowContext; use bitfield_struct::bitfield; use bitvec::boxed::BitBox; use bitvec::vec::BitVec; +use cvm_tracing::CVM_ALLOWED; use guestmem::GuestMemory; use hcl::GuestVtl; use hcl::ioctl::Hcl; @@ -970,6 +971,7 @@ impl virt::Synic for UhPartition { let vtl = GuestVtl::try_from(vtl).expect("higher vtl not configured"); let Some(vp) = self.inner.vp(vp_index) else { tracelimit::warn_ratelimited!( + CVM_ALLOWED, vp = vp_index.index(), "invalid vp target for post_message" ); @@ -1260,6 +1262,7 @@ impl UhPartitionInner { vtl, ) { tracelimit::warn_ratelimited!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, address = request.address, data = request.data, @@ -1877,7 +1880,7 @@ impl UhProtoPartition<'_> { .rmp_query(); if !rmp_query { - tracing::info!("rmp query not supported, cannot enable vsm"); + tracing::info!(CVM_ALLOWED, "rmp query not supported, cannot enable vsm"); return Ok(false); } } @@ -2155,7 +2158,10 @@ impl UhPartitionInner { // Probably a build that doesn't support range wrapping yet. // Don't try again. SKIP_RANGE.store(true, Ordering::Relaxed); - tracing::warn!("old hypervisor build; using slow path for intercept ranges"); + tracing::warn!( + CVM_ALLOWED, + "old hypervisor build; using slow path for intercept ranges" + ); } Err(err) => { panic!("io port range registration failure: {err:?}"); diff --git a/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/apic.rs b/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/apic.rs index 54baf8ff75..13975e0c27 100644 --- a/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/apic.rs +++ b/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/apic.rs @@ -6,6 +6,7 @@ use super::UhRunVpError; use crate::UhProcessor; use crate::processor::HardwareIsolatedBacking; +use cvm_tracing::CVM_ALLOWED; use hcl::GuestVtl; use virt::Processor; use virt::vp::MpState; @@ -27,7 +28,7 @@ pub(crate) trait ApicBacking<'b, B: HardwareIsolatedBacking> { fn handle_interrupt(&mut self, vtl: GuestVtl, vector: u8) -> Result<(), UhRunVpError>; fn handle_extint(&mut self, vtl: GuestVtl) -> Result<(), UhRunVpError> { - tracelimit::warn_ratelimited!(?vtl, "extint not supported"); + tracelimit::warn_ratelimited!(CVM_ALLOWED, ?vtl, "extint not supported"); Ok(()) } } diff --git a/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/mod.rs b/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/mod.rs index 367ad69b15..76b2f2092c 100644 --- a/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/hardware_cvm/mod.rs @@ -19,6 +19,7 @@ use crate::WakeReason; use crate::processor::HardwareIsolatedBacking; use crate::processor::UhHypercallHandler; use crate::validate_vtl_gpa_flags; +use cvm_tracing::CVM_ALLOWED; use guestmem::GuestMemory; use hv1_emulator::RequestInterrupt; use hv1_hypercall::HvRepResult; @@ -410,6 +411,7 @@ impl UhHypercallHandler<'_, '_, T, B> { } _ => { tracing::error!( + CVM_ALLOWED, ?name, "guest invoked getvpregister with unsupported register" ); @@ -636,7 +638,8 @@ impl UhHypercallHandler<'_, '_, T, B> { } _ => { tracing::error!( - ?reg, + CVM_ALLOWED, + reg = ?reg.name, "guest invoked SetVpRegisters with unsupported register", ); Err(HvError::InvalidParameter) @@ -967,13 +970,17 @@ impl hv1_hypercall::VtlCall for UhHypercallHandle // Only allowed from VTL 0 if self.intercepted_vtl != GuestVtl::Vtl0 { tracelimit::warn_ratelimited!( + CVM_ALLOWED, "vtl call not allowed from vtl {:?}", self.intercepted_vtl ); false } else if self.vp.backing.cvm_state().vtl1.is_none() { // VTL 1 must be active on the vp - tracelimit::warn_ratelimited!("vtl call not allowed because vtl 1 is not enabled"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + "vtl call not allowed because vtl 1 is not enabled" + ); false } else { true @@ -993,6 +1000,7 @@ impl hv1_hypercall::VtlReturn for UhHypercallHand fn is_vtl_return_allowed(&self) -> bool { if self.intercepted_vtl != GuestVtl::Vtl1 { tracelimit::warn_ratelimited!( + CVM_ALLOWED, "vtl return not allowed from vtl {:?}", self.intercepted_vtl ); @@ -1252,7 +1260,7 @@ impl hv1_hypercall::EnablePartitionVtl tracing::debug!("Successfully granted vtl 1 access to lower vtl memory"); - tracing::info!("Enabled vtl 1 on the partition"); + tracing::info!(CVM_ALLOWED, "Enabled vtl 1 on the partition"); Ok(()) } @@ -2307,6 +2315,7 @@ impl UhProcessor<'_, B> { // same instruction again, providing another opportunity to // deliver the intercept. tracelimit::warn_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, ?vtl, ?message, @@ -2435,25 +2444,29 @@ pub(crate) fn validate_xsetbv_exit(input: XsetbvExitInput) -> Option { } = input; if rcx != 0 { - tracelimit::warn_ratelimited!(rcx, "xsetbv exit: rcx is not set to 0"); + tracelimit::warn_ratelimited!(CVM_ALLOWED, rcx, "xsetbv exit: rcx is not set to 0"); return None; } if cpl != 0 { - tracelimit::warn_ratelimited!(cpl, "xsetbv exit: invalid cpl"); + tracelimit::warn_ratelimited!(CVM_ALLOWED, cpl, "xsetbv exit: invalid cpl"); return None; } let osxsave_flag = cr4 & x86defs::X64_CR4_OSXSAVE; if osxsave_flag == 0 { - tracelimit::warn_ratelimited!(cr4, "xsetbv exit: cr4 osxsave not set"); + tracelimit::warn_ratelimited!(CVM_ALLOWED, cr4, "xsetbv exit: cr4 osxsave not set"); return None; } let xfem = (rdx << 32) | (rax & 0xffffffff); if (xfem & x86defs::xsave::XFEATURE_X87) == 0 { - tracelimit::warn_ratelimited!(xfem, "xsetbv exit: xfem legacy x87 bit not set"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + xfem, + "xsetbv exit: xfem legacy x87 bit not set" + ); return None; } diff --git a/openhcl/virt_mshv_vtl/src/processor/mod.rs b/openhcl/virt_mshv_vtl/src/processor/mod.rs index 9404349ff5..a1b978b7c9 100644 --- a/openhcl/virt_mshv_vtl/src/processor/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/mod.rs @@ -42,6 +42,7 @@ use super::UhVpInner; use crate::ExitActivity; use crate::GuestVtl; use crate::WakeReason; +use cvm_tracing::CVM_ALLOWED; use guestmem::GuestMemory; use hcl::ioctl::Hcl; use hcl::ioctl::ProcessorRunner; @@ -563,7 +564,8 @@ impl UhVpInner { pub fn set_sidecar_exit_reason(&self, reason: SidecarExitReason) { self.sidecar_exit_reason.lock().get_or_insert_with(|| { - tracing::info!(?reason, "sidecar exit"); + tracing::info!(CVM_ALLOWED, "sidecar exit"); + tracing::info!(CVM_CONFIDENTIAL, ?reason); reason }); } @@ -1044,7 +1046,11 @@ impl<'a, T: Backing> UhProcessor<'a, T> { control: hvdef::GuestCrashCtl::from(value), parameters: self.crash_reg, }; - tracelimit::warn_ratelimited!(?crash, "Guest has reported system crash"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + ?crash, + "Guest has reported system crash" + ); if crash.control.crash_message() { let message_gpa = crash.parameters[3]; @@ -1060,7 +1066,11 @@ impl<'a, T: Backing> UhProcessor<'a, T> { ); } Err(e) => { - tracelimit::warn_ratelimited!(?e, "Failed to read crash message"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + ?e, + "Failed to read crash message" + ); } } } @@ -1181,6 +1191,7 @@ impl<'a, T: Backing> UhProcessor<'a, T> { fn signal_mnf(dev: &impl CpuIo, connection_id: u32) { if let Err(err) = dev.signal_synic_event(Vtl::Vtl0, connection_id, 0) { tracelimit::warn_ratelimited!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, connection_id, "failed to signal mnf" diff --git a/openhcl/virt_mshv_vtl/src/processor/snp/mod.rs b/openhcl/virt_mshv_vtl/src/processor/snp/mod.rs index 76772580cf..2848bb03e8 100644 --- a/openhcl/virt_mshv_vtl/src/processor/snp/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/snp/mod.rs @@ -26,6 +26,8 @@ use crate::WakeReason; use crate::devmsr; use crate::processor::UhHypercallHandler; use crate::processor::UhProcessor; +use cvm_tracing::CVM_ALLOWED; +use cvm_tracing::CVM_CONFIDENTIAL; use hcl::vmsa::VmsaWrapper; use hv1_emulator::hv::ProcessorVtlHv; use hv1_emulator::synic::ProcessorSynic; @@ -677,7 +679,13 @@ fn init_vmsa(vmsa: &mut VmsaWrapper<'_, &mut SevVmsa>, vtl: GuestVtl, vtom: Opti vmsa.set_efer(x86defs::X64_EFER_SVME); let sev_features = vmsa.sev_features(); - tracing::info!(?vtl, ?sev_status, ?sev_features, "VMSA features"); + tracing::info!( + CVM_ALLOWED, + ?vtl, + ?sev_status, + ?sev_features, + "VMSA features" + ); } struct SnpApicClient<'a, T> { @@ -925,6 +933,7 @@ impl UhProcessor<'_, SnpBacked> { // TODO SNP: Should allow arbitrary page to be used for GHCB if ghcb_pfn != ghcb_overlay { tracelimit::warn_ratelimited!( + CVM_ALLOWED, vmgexit_pfn = ghcb_pfn, overlay_pfn = ghcb_overlay, "ghcb page used for vmgexit does not match overlay page" @@ -1139,7 +1148,10 @@ impl UhProcessor<'_, SnpBacked> { // // TODO SNP: consider emulating the instruction. if !mov_crx_drx.mov_crx() { - tracelimit::warn_ratelimited!("Intercepted crx access, instruction is not mov crx"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + "Intercepted crx access, instruction is not mov crx" + ); return; } @@ -1177,7 +1189,7 @@ impl UhProcessor<'_, SnpBacked> { let halt = self.backing.cvm.lapics[next_vtl].activity != MpState::Running || tlb_halt; if halt && next_vtl == GuestVtl::Vtl1 && !tlb_halt { - tracelimit::warn_ratelimited!("halting VTL 1, which might halt the guest"); + tracelimit::warn_ratelimited!(CVM_ALLOWED, "halting VTL 1, which might halt the guest"); } self.runner.set_halted(halt); @@ -1551,6 +1563,7 @@ impl UhProcessor<'_, SnpBacked> { _ => { tracing::error!( + CVM_CONFIDENTIAL, "SEV exit code {sev_error_code:x?} sev features {:x?} v_intr_control {:x?} event inject {:x?} \ vmpl {:x?} cpl {:x?} exit_info1 {:x?} exit_info2 {:x?} exit_int_info {:x?} virtual_tom {:x?} \ efer {:x?} cr4 {:x?} cr3 {:x?} cr0 {:x?} rflag {:x?} rip {:x?} next rip {:x?}", @@ -1599,7 +1612,11 @@ impl UhProcessor<'_, SnpBacked> { // TODO SNP: Figure out why we are getting these. } message_type => { - tracelimit::error_ratelimited!(?message_type, "unknown synthetic exit"); + tracelimit::error_ratelimited!( + CVM_ALLOWED, + ?message_type, + "unknown synthetic exit" + ); } } } diff --git a/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs b/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs index fc02f60e3d..27206f2dbf 100644 --- a/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs @@ -23,6 +23,8 @@ use crate::UhPartitionInner; use crate::UhPartitionNewParams; use crate::UhProcessor; use crate::WakeReason; +use cvm_tracing::CVM_ALLOWED; +use cvm_tracing::CVM_CONFIDENTIAL; use hcl::ioctl::ProcessorRunner; use hcl::ioctl::tdx::Tdx; use hcl::ioctl::tdx::TdxPrivateRegs; @@ -1082,7 +1084,7 @@ impl BackingPrivate for TdxBacked { scan_irr: bool, ) -> Result<(), UhRunVpError> { if !this.try_poll_apic(vtl, scan_irr)? { - tracing::info!("disabling APIC offload due to auto EOI"); + tracing::info!(CVM_ALLOWED, "disabling APIC offload due to auto EOI"); let page = this.runner.tdx_apic_page_mut(vtl); let (irr, isr) = pull_apic_offload(page); @@ -1104,7 +1106,7 @@ impl BackingPrivate for TdxBacked { if let Some(synic) = &mut this.backing.untrusted_synic { synic.request_sint_readiness(sints); } else { - tracelimit::error_ratelimited!("untrusted synic is not configured"); + tracelimit::error_ratelimited!(CVM_ALLOWED, "untrusted synic is not configured"); } } @@ -1568,6 +1570,7 @@ impl UhProcessor<'_, TdxBacked> { (false, true) => MpState::Idle, (true, true) => { tracelimit::warn_ratelimited!( + CVM_ALLOWED, "Kernel indicates VP is both halted and idle!" ); activity @@ -1818,7 +1821,7 @@ impl UhProcessor<'_, TdxBacked> { let value = match result { Ok(v) => Some(v), Err(MsrError::Unknown) => { - tracelimit::warn_ratelimited!(msr, "unknown tdx vm msr read"); + tracelimit::warn_ratelimited!(CVM_ALLOWED, msr, "unknown tdx vm msr read"); Some(0) } Err(MsrError::InvalidAccess) => None, @@ -1870,7 +1873,12 @@ impl UhProcessor<'_, TdxBacked> { let inject_gp = match result { Ok(()) => false, Err(MsrError::Unknown) => { - tracelimit::warn_ratelimited!(msr, value, "unknown tdx vm msr write"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + msr, + "unknown tdx vm msr write" + ); + tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value); false } Err(MsrError::InvalidAccess) => true, @@ -1961,7 +1969,12 @@ impl UhProcessor<'_, TdxBacked> { self.update_execution_mode(intercepted_vtl); self.advance_to_next_instruction(intercepted_vtl); } else { - tracelimit::warn_ratelimited!(?cr, value, "failed to write cr"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + ?cr, + value, + "failed to write cr" + ); self.inject_gpf(intercepted_vtl); } } @@ -2157,10 +2170,10 @@ impl UhProcessor<'_, TdxBacked> { /// Trace processor state for debugging purposes. fn trace_processor_state(&self, vtl: GuestVtl) { let raw_exit = self.runner.tdx_vp_enter_exit_info(); - tracing::error!(?raw_exit, "raw tdx vp enter exit info"); + tracing::error!(CVM_CONFIDENTIAL, ?raw_exit, "raw tdx vp enter exit info"); let gprs = self.runner.tdx_enter_guest_gps(); - tracing::error!(?gprs, "guest gpr list"); + tracing::error!(CVM_CONFIDENTIAL, ?gprs, "guest gpr list"); let TdxPrivateRegs { rflags, @@ -2178,6 +2191,7 @@ impl UhProcessor<'_, TdxBacked> { vp_entry_flags, } = self.backing.vtls[vtl].private_regs; tracing::error!( + CVM_CONFIDENTIAL, rflags, rip, rsp, @@ -2201,7 +2215,13 @@ impl UhProcessor<'_, TdxBacked> { let cr0_guest_host_mask: u64 = self .runner .read_vmcs64(vtl, VmcsField::VMX_VMCS_CR0_GUEST_HOST_MASK); - tracing::error!(physical_cr0, shadow_cr0, cr0_guest_host_mask, "cr0 values"); + tracing::error!( + CVM_CONFIDENTIAL, + physical_cr0, + shadow_cr0, + cr0_guest_host_mask, + "cr0 values" + ); let physical_cr4 = self.runner.read_vmcs64(vtl, VmcsField::VMX_VMCS_GUEST_CR4); let shadow_cr4 = self @@ -2210,18 +2230,24 @@ impl UhProcessor<'_, TdxBacked> { let cr4_guest_host_mask = self .runner .read_vmcs64(vtl, VmcsField::VMX_VMCS_CR4_GUEST_HOST_MASK); - tracing::error!(physical_cr4, shadow_cr4, cr4_guest_host_mask, "cr4 values"); + tracing::error!( + CVM_CONFIDENTIAL, + physical_cr4, + shadow_cr4, + cr4_guest_host_mask, + "cr4 values" + ); let cr3 = self.runner.read_vmcs64(vtl, VmcsField::VMX_VMCS_GUEST_CR3); - tracing::error!(cr3, "cr3"); + tracing::error!(CVM_CONFIDENTIAL, cr3, "cr3"); let cached_efer = self.backing.vtls[vtl].efer; let vmcs_efer = self.runner.read_vmcs64(vtl, VmcsField::VMX_VMCS_GUEST_EFER); let entry_controls = self .runner .read_vmcs32(vtl, VmcsField::VMX_VMCS_ENTRY_CONTROLS); - tracing::error!(cached_efer, vmcs_efer, "efer"); - tracing::error!(entry_controls, "entry controls"); + tracing::error!(CVM_CONFIDENTIAL, cached_efer, vmcs_efer, "efer"); + tracing::error!(CVM_CONFIDENTIAL, entry_controls, "entry controls"); let cs = self.read_segment(vtl, TdxSegmentReg::Cs); let ds = self.read_segment(vtl, TdxSegmentReg::Ds); @@ -2232,12 +2258,23 @@ impl UhProcessor<'_, TdxBacked> { let tr = self.read_segment(vtl, TdxSegmentReg::Tr); let ldtr = self.read_segment(vtl, TdxSegmentReg::Ldtr); - tracing::error!(?cs, ?ds, ?es, ?fs, ?gs, ?ss, ?tr, ?ldtr, "segment values"); + tracing::error!( + CVM_CONFIDENTIAL, + ?cs, + ?ds, + ?es, + ?fs, + ?gs, + ?ss, + ?tr, + ?ldtr, + "segment values" + ); let exception_bitmap = self .runner .read_vmcs32(vtl, VmcsField::VMX_VMCS_EXCEPTION_BITMAP); - tracing::error!(exception_bitmap, "exception bitmap"); + tracing::error!(CVM_CONFIDENTIAL, exception_bitmap, "exception bitmap"); let cached_processor_controls = self.backing.vtls[vtl].processor_controls; let vmcs_processor_controls = ProcessorControls::from( @@ -2249,6 +2286,7 @@ impl UhProcessor<'_, TdxBacked> { .read_vmcs32(vtl, VmcsField::VMX_VMCS_SECONDARY_PROCESSOR_CONTROLS), ); tracing::error!( + CVM_CONFIDENTIAL, ?cached_processor_controls, ?vmcs_processor_controls, ?vmcs_secondary_processor_controls, @@ -2256,14 +2294,19 @@ impl UhProcessor<'_, TdxBacked> { ); if cached_processor_controls != vmcs_processor_controls { - tracing::error!("BUGBUG: processor controls mismatch"); + tracing::error!(CVM_ALLOWED, "BUGBUG: processor controls mismatch"); } let cached_tpr_threshold = self.backing.vtls[vtl].tpr_threshold; let vmcs_tpr_threshold = self .runner .read_vmcs32(vtl, VmcsField::VMX_VMCS_TPR_THRESHOLD); - tracing::error!(cached_tpr_threshold, vmcs_tpr_threshold, "tpr threshold"); + tracing::error!( + CVM_CONFIDENTIAL, + cached_tpr_threshold, + vmcs_tpr_threshold, + "tpr threshold" + ); let cached_eoi_exit_bitmap = self.backing.eoi_exit_bitmap; let vmcs_eoi_exit_bitmap = { @@ -2279,6 +2322,7 @@ impl UhProcessor<'_, TdxBacked> { .collect::>() }; tracing::error!( + CVM_CONFIDENTIAL, ?cached_eoi_exit_bitmap, ?vmcs_eoi_exit_bitmap, "eoi exit bitmap" @@ -2293,6 +2337,7 @@ impl UhProcessor<'_, TdxBacked> { .runner .read_vmcs32(vtl, VmcsField::VMX_VMCS_ENTRY_EXCEPTION_ERROR_CODE); tracing::error!( + CVM_CONFIDENTIAL, ?cached_interrupt_information, cached_interruption_set, vmcs_interrupt_information, @@ -2303,7 +2348,11 @@ impl UhProcessor<'_, TdxBacked> { let guest_interruptibility = self .runner .read_vmcs32(vtl, VmcsField::VMX_VMCS_GUEST_INTERRUPTIBILITY); - tracing::error!(guest_interruptibility, "guest interruptibility"); + tracing::error!( + CVM_CONFIDENTIAL, + guest_interruptibility, + "guest interruptibility" + ); let vmcs_sysenter_cs = self .runner @@ -2315,6 +2364,7 @@ impl UhProcessor<'_, TdxBacked> { .runner .read_vmcs64(vtl, VmcsField::VMX_VMCS_GUEST_SYSENTER_EIP_MSR); tracing::error!( + CVM_CONFIDENTIAL, vmcs_sysenter_cs, vmcs_sysenter_esp, vmcs_sysenter_eip, @@ -2322,7 +2372,7 @@ impl UhProcessor<'_, TdxBacked> { ); let vmcs_pat = self.runner.read_vmcs64(vtl, VmcsField::VMX_VMCS_GUEST_PAT); - tracing::error!(vmcs_pat, "guest PAT"); + tracing::error!(CVM_CONFIDENTIAL, vmcs_pat, "guest PAT"); } fn handle_vm_enter_failed( @@ -2335,7 +2385,7 @@ impl UhProcessor<'_, TdxBacked> { VmxExitBasic::BAD_GUEST_STATE => { // Log system register state for debugging why we were // unable to enter the guest. This is a VMM bug. - tracing::error!("VP.ENTER failed with bad guest state"); + tracing::error!(CVM_ALLOWED, "VP.ENTER failed with bad guest state"); self.trace_processor_state(vtl); // TODO: panic instead? @@ -2420,7 +2470,11 @@ impl UhProcessor<'_, TdxBacked> { .probe_gpa_readable(gpa) .is_ok() { - tracelimit::warn_ratelimited!(gpa, "possible spurious EPT violation, ignoring"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + gpa, + "possible spurious EPT violation, ignoring" + ); } else { // TODO: It would be better to show what exact bitmap check // failed, but that requires some refactoring of how the @@ -2434,6 +2488,7 @@ impl UhProcessor<'_, TdxBacked> { // should have already been checked to be valid memory // described to the guest or not. tracelimit::warn_ratelimited!( + CVM_ALLOWED, gpa, is_shared, ?ept_info, @@ -2456,6 +2511,7 @@ impl UhProcessor<'_, TdxBacked> { // // For now, log that the guest did this. tracelimit::warn_ratelimited!( + CVM_ALLOWED, gpa, is_shared, ?ept_info, @@ -2494,11 +2550,12 @@ impl UhProcessor<'_, TdxBacked> { } Err(err) => { tracelimit::warn_ratelimited!( + CVM_ALLOWED, msr, - value, ?err, "failed tdvmcall msr write" ); + tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value); TdVmCallR10Result::OPERAND_INVALID } } @@ -2512,13 +2569,19 @@ impl UhProcessor<'_, TdxBacked> { TdVmCallR10Result::SUCCESS } Err(err) => { - tracelimit::warn_ratelimited!(msr, ?err, "failed tdvmcall msr read"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + msr, + ?err, + "failed tdvmcall msr read" + ); TdVmCallR10Result::OPERAND_INVALID } } } subfunction => { tracelimit::warn_ratelimited!( + CVM_ALLOWED, ?subfunction, "architectural vmcall not supported" ); @@ -2594,6 +2657,7 @@ impl UhProcessor<'_, TdxBacked> { value.into(), ) { tracelimit::warn_ratelimited!( + CVM_ALLOWED, error = &err as &dyn std::error::Error, "failed to set sint register" ); diff --git a/vm/devices/firmware/firmware_uefi/src/service/time.rs b/vm/devices/firmware/firmware_uefi/src/service/time.rs index 2cdd0f818b..ac4e34632e 100644 --- a/vm/devices/firmware/firmware_uefi/src/service/time.rs +++ b/vm/devices/firmware/firmware_uefi/src/service/time.rs @@ -147,7 +147,7 @@ impl UefiDevice { time, }, Err(e) => { - tracing::error!("get_time: {}", e); + tracing::debug!("get_time: {}", e); VmEfiTime { status: EfiStatus::DEVICE_ERROR.into(), time: Default::default(), @@ -166,7 +166,7 @@ impl UefiDevice { let status = match self.service.time.set_time(vm_time.time) { Ok(_) => EfiStatus::SUCCESS, Err(e) => { - tracing::error!("set_time: {}", e); + tracing::debug!("set_time: {}", e); match e { TimeServiceError::InvalidArg => EfiStatus::INVALID_PARAMETER, _ => EfiStatus::DEVICE_ERROR, diff --git a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/Cargo.toml b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/Cargo.toml index a1021c44a0..31f3e4814d 100644 --- a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/Cargo.toml +++ b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/Cargo.toml @@ -14,6 +14,7 @@ inspect = ["dep:inspect", "uefi_nvram_storage/inspect"] [dependencies] uefi_nvram_storage.workspace = true +cvm_tracing.workspace = true guid.workspace = true inspect = { workspace = true, optional = true } open_enum.workspace = true diff --git a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs index 76dec7ce18..9dd13ea387 100644 --- a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs +++ b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs @@ -18,6 +18,8 @@ pub mod storage_backend; +use cvm_tracing::CVM_ALLOWED; +use cvm_tracing::CVM_CONFIDENTIAL; use guid::Guid; use std::fmt::Debug; use storage_backend::StorageBackend; @@ -133,10 +135,8 @@ impl HclCompatNvram { async fn lazy_load_from_storage(&mut self) -> Result<(), NvramStorageError> { let res = self.lazy_load_from_storage_inner().await; if let Err(e) = &res { - tracing::error!( - error = e as &dyn std::error::Error, - "storage contains corrupt nvram state" - ) + tracing::error!(CVM_ALLOWED, "storage contains corrupt nvram state"); + tracing::error!(CVM_CONFIDENTIAL, error = e as &dyn std::error::Error); } res } @@ -251,7 +251,11 @@ impl HclCompatNvram { var.push(0); ucs2::Ucs2LeVec::from_vec_with_nul(var) }; - tracing::warn!(?var, "skipping corrupt nvram var (missing null term)"); + tracing::warn!( + CVM_ALLOWED, + "skipping corrupt nvram var (missing null term)" + ); + tracing::warn!(CVM_CONFIDENTIAL, ?var); continue; } else { return Err(NvramStorageError::Load(e.into())); diff --git a/vm/devices/get/guest_emulation_transport/src/process_loop.rs b/vm/devices/get/guest_emulation_transport/src/process_loop.rs index fd6cba1a19..a441e2fcd6 100644 --- a/vm/devices/get/guest_emulation_transport/src/process_loop.rs +++ b/vm/devices/get/guest_emulation_transport/src/process_loop.rs @@ -764,7 +764,7 @@ impl ProcessLoop { .map_err(|_| FatalError::InvalidResponse)?; if version_accepted { - tracing::info!("[GET] version negotiated: {:?}", protocol); + tracing::info!(?protocol, "[GET] version negotiated"); return Ok(protocol); } @@ -1297,8 +1297,8 @@ impl ProcessLoop { } invalid_notification => { tracing::error!( - "[HOST GET] ignoring invalid guest notification: {:?}", - invalid_notification + ?invalid_notification, + "[HOST GET] ignoring invalid guest notification", ); } } diff --git a/vm/devices/tpm/Cargo.toml b/vm/devices/tpm/Cargo.toml index e0c26a5770..95f0cacb01 100644 --- a/vm/devices/tpm/Cargo.toml +++ b/vm/devices/tpm/Cargo.toml @@ -17,6 +17,7 @@ tpm_resources.workspace = true chipset_device.workspace = true chipset_device_resources.workspace = true +cvm_tracing.workspace = true guestmem.workspace = true vmcore.workspace = true vm_resource.workspace = true diff --git a/vm/devices/tpm/src/lib.rs b/vm/devices/tpm/src/lib.rs index 1eeda9087f..5276e85546 100644 --- a/vm/devices/tpm/src/lib.rs +++ b/vm/devices/tpm/src/lib.rs @@ -27,6 +27,8 @@ use chipset_device::io::IoResult; use chipset_device::mmio::MmioIntercept; use chipset_device::pio::PortIoIntercept; use chipset_device::poll_device::PollDevice; +use cvm_tracing::CVM_ALLOWED; +use cvm_tracing::CVM_CONFIDENTIAL; use guestmem::GuestMemory; use inspect::Inspect; use inspect::InspectMut; @@ -559,10 +561,8 @@ impl Tpm { .initialize_guest_secret_key(&guest_secret_key) { // Failures are non-fatal as the feature is not necessary for booting. - tracing::error!( - error = &e as &dyn std::error::Error, - "Failed to initialize guest secret key" - ); + tracing::error!(CVM_ALLOWED, "Failed to initialize guest secret key"); + tracing::error!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error); } } @@ -591,7 +591,10 @@ impl Tpm { let io_command = match self.current_io_command { Some(cmd) => cmd, None => { - tracelimit::warn_ratelimited!("Invalid tpm IO data port read (no command set)"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + "Invalid tpm IO data port read (no command set)" + ); return IoResult::Ok; } }; @@ -607,7 +610,11 @@ impl Tpm { io_port_interface::TcgProtocol::Tcg2 as u32 } _ => { - tracelimit::warn_ratelimited!(?io_command, "Invalid tpm IO data read"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + ?io_command, + "Invalid tpm IO data read" + ); return IoResult::Ok; } } @@ -642,6 +649,7 @@ impl Tpm { Some(cmd) => cmd, None => { tracelimit::warn_ratelimited!( + CVM_ALLOWED, "Invalid tpm IO data port write (no command set)" ); return IoResult::Ok; @@ -671,7 +679,11 @@ impl Tpm { self.ppi_state.tpm_capability_hash_alg_bitmap = val; } other => { - tracelimit::warn_ratelimited!(?other, "unimplemented TpmIoCommand"); + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + ?other, + "unimplemented TpmIoCommand" + ); update_ppi = false; } }; @@ -683,9 +695,10 @@ impl Tpm { ); if let Err(e) = res { tracing::warn!( - error = &e as &dyn std::error::Error, + CVM_ALLOWED, "could not persist ppi state to non-volatile store" ); + tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error); } } }; @@ -713,7 +726,7 @@ impl Tpm { self.ppi_state.ppi_set_operation_arg3_integer2, )?, other => { - tracelimit::warn_ratelimited!(?other, "unknown pending PPI operation"); + tracelimit::warn_ratelimited!(CVM_ALLOWED, ?other, "unknown pending PPI operation"); 0 } }; @@ -735,6 +748,7 @@ impl Tpm { Err(error) => { if let TpmCommandError::TpmCommandFailed { response_code } = error { tracelimit::error_ratelimited!( + CVM_ALLOWED, err = &error as &dyn std::error::Error, "tpm PcrAllocateCmd failed" ); @@ -770,7 +784,7 @@ impl Tpm { self.tpm_engine_helper .initialize_tpm_engine() .map_err(TpmErrorKind::InitializeTpmEngine)?; - tracelimit::info_ratelimited!("tpm reset after sending PcrAllocateCmd"); + tracelimit::info_ratelimited!(CVM_ALLOWED, "tpm reset after sending PcrAllocateCmd"); } Ok(response_code) @@ -884,6 +898,7 @@ impl Tpm { } Ok(_data) => { tracelimit::warn_ratelimited!( + CVM_ALLOWED, "The requested TPM AK cert is empty - now: {:?}", now.duration_since(std::time::UNIX_EPOCH), ); @@ -898,6 +913,7 @@ impl Tpm { } Err(error) => { tracelimit::warn_ratelimited!( + CVM_ALLOWED, error, "Failed to request new TPM AK cert - now: {:?}", now.duration_since(std::time::UNIX_EPOCH), @@ -917,6 +933,7 @@ impl Tpm { &response, ) { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "Failed write new TPM AK cert to NV index" ); @@ -980,6 +997,7 @@ impl Tpm { Ok(ak_cert_request) => { if let Err(e) = self.renew_attestation_report(&ak_cert_request) { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "Error while renewing the attestation report on NvRead" ); @@ -987,6 +1005,7 @@ impl Tpm { } Err(e) => { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "Error while creating ak cert request for renewing the attestation report" ); @@ -1008,6 +1027,7 @@ impl Tpm { if renew_cert_needed { if let Err(e) = self.renew_ak_cert() { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "Error while renewing AK cert on NvRead" ); @@ -1201,6 +1221,7 @@ impl MmioIntercept for Tpm { if let Err(e) = res { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "Failed to read TPM command from guest memory" ); @@ -1232,6 +1253,7 @@ impl MmioIntercept for Tpm { &mut self.tpm_engine_helper.reply_buffer, ) { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "Error while executing TPM command" ); @@ -1253,6 +1275,7 @@ impl MmioIntercept for Tpm { if let Err(e) = res { tracelimit::error_ratelimited!( + CVM_ALLOWED, error = &e as &dyn std::error::Error, "Failed to write TPM reply into guest memory" ); @@ -1267,10 +1290,8 @@ impl MmioIntercept for Tpm { let res = pal_async::local::block_on(self.flush_pending_nvram()); if let Err(e) = res { - tracing::warn!( - error = &e as &dyn std::error::Error, - "could not commit nvram to non-volatile store" - ); + tracing::warn!(CVM_ALLOWED, "could not commit nvram to non-volatile store"); + tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error); }; IoResult::Ok diff --git a/vm/devices/tpm/src/tpm_helper.rs b/vm/devices/tpm/src/tpm_helper.rs index 1291234b09..9bd2d72522 100644 --- a/vm/devices/tpm/src/tpm_helper.rs +++ b/vm/devices/tpm/src/tpm_helper.rs @@ -40,6 +40,7 @@ use crate::tpm20proto::protocol::TpmtPublic; use crate::tpm20proto::protocol::TpmtRsaScheme; use crate::tpm20proto::protocol::TpmtSymDefObject; use crate::tpm20proto::protocol::common::CmdAuth; +use cvm_tracing::CVM_ALLOWED; use inspect::InspectMut; use ms_tpm_20_ref::MsTpm20RefPlatform; use thiserror::Error; @@ -212,6 +213,7 @@ impl TpmEngineHelper { if let Err(error) = self.clear_control(TPM20_RH_PLATFORM, false) { if let TpmCommandError::TpmCommandFailed { response_code } = error { tracelimit::error_ratelimited!( + CVM_ALLOWED, err = &error as &dyn std::error::Error, "tpm ClearControlCmd failed" ); @@ -236,6 +238,7 @@ impl TpmEngineHelper { Err(error) => { if let TpmCommandError::TpmCommandFailed { response_code } = error { tracelimit::error_ratelimited!( + CVM_ALLOWED, err = &error as &dyn std::error::Error, "tpm ClearCmd failed" ); @@ -343,6 +346,7 @@ impl TpmEngineHelper { // Guest might cause the command to fail (e.g., taking the ownership of a hierarchy). // Making this failure as non-fatal. tracelimit::error_ratelimited!( + CVM_ALLOWED, err = &error as &dyn std::error::Error, "tpm CreatePrimaryCmd failed" ); @@ -369,7 +373,10 @@ impl TpmEngineHelper { if res.out_public.size.get() == 0 { // Guest might cause the command to fail (e.g., taking the ownership of a hierarchy). // Making this failure as non-fatal. - tracelimit::error_ratelimited!("No public data in CreatePrimaryCmd response"); + tracelimit::error_ratelimited!( + CVM_ALLOWED, + "No public data in CreatePrimaryCmd response" + ); return Ok(TpmRsa2kPublic { modulus: [0u8; RSA_2K_MODULUS_SIZE], @@ -396,6 +403,7 @@ impl TpmEngineHelper { // Guest might cause the command to fail (e.g., taking the ownership of a hierarchy). // Making this failure as non-fatal. tracelimit::error_ratelimited!( + CVM_ALLOWED, err = &error as &dyn std::error::Error, "tpm FlushContextCmd failed" ); @@ -428,6 +436,7 @@ impl TpmEngineHelper { // Guest might cause the command to fail (e.g., taking the ownership of a hierarchy). // Making this failure as non-fatal. tracelimit::error_ratelimited!( + CVM_ALLOWED, err = &error as &dyn std::error::Error, "tpm EvictControlCmd failed" ); diff --git a/vmm_core/Cargo.toml b/vmm_core/Cargo.toml index e598003d38..df680a2eef 100644 --- a/vmm_core/Cargo.toml +++ b/vmm_core/Cargo.toml @@ -19,6 +19,7 @@ vmm_core_defs.workspace = true aarch64defs.workspace = true acpi_spec = { workspace = true, features = ["std"] } acpi.workspace = true +cvm_tracing.workspace = true hcl_compat_uefi_nvram_storage.workspace = true hvdef.workspace = true memory_range = { workspace = true, features = ["inspect"] } diff --git a/vmm_core/src/partition_unit/vp_set.rs b/vmm_core/src/partition_unit/vp_set.rs index 666cb16c9b..84f8b7eebb 100644 --- a/vmm_core/src/partition_unit/vp_set.rs +++ b/vmm_core/src/partition_unit/vp_set.rs @@ -293,6 +293,8 @@ where guest_memory: Option<&GuestMemory>, registers: Option<&virt::x86::vp::Registers>, ) { + use cvm_tracing::CVM_CONFIDENTIAL; + #[cfg(not(feature = "gdb"))] let _ = (guest_memory, vtl); @@ -337,6 +339,7 @@ where efer, } = *registers; tracing::error!( + CVM_CONFIDENTIAL, vp = self.vp_index.index(), ?vtl, rax, @@ -360,6 +363,7 @@ where "triple fault register state", ); tracing::error!( + CVM_CONFIDENTIAL, ?vtl, vp = self.vp_index.index(), ?cs, @@ -387,6 +391,7 @@ where vp_state::next_instruction(guest_memory, self, vtl, registers) { tracing::error!( + CVM_CONFIDENTIAL, instruction = instr.to_string(), ?bytes, "faulting instruction" From e7e096157be3c50293b6c7db42e884d5a685e0a0 Mon Sep 17 00:00:00 2001 From: Steven Malis Date: Fri, 23 May 2025 17:42:06 -0400 Subject: [PATCH 2/8] Fix arm --- openhcl/virt_mshv_vtl/src/processor/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/openhcl/virt_mshv_vtl/src/processor/mod.rs b/openhcl/virt_mshv_vtl/src/processor/mod.rs index a1b978b7c9..882f64ca42 100644 --- a/openhcl/virt_mshv_vtl/src/processor/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/mod.rs @@ -18,7 +18,6 @@ cfg_if::cfg_if! { use crate::VtlCrash; use bitvec::prelude::BitArray; use bitvec::prelude::Lsb0; - use cvm_tracing::CVM_CONFIDENTIAL; use hv1_emulator::synic::ProcessorSynic; use hvdef::HvRegisterCrInterceptControl; use hvdef::HvX64RegisterName; @@ -43,6 +42,7 @@ use crate::ExitActivity; use crate::GuestVtl; use crate::WakeReason; use cvm_tracing::CVM_ALLOWED; +use cvm_tracing::CVM_CONFIDENTIAL; use guestmem::GuestMemory; use hcl::ioctl::Hcl; use hcl::ioctl::ProcessorRunner; From cd6b3ae34620219a7910111c099569e24efa8e50 Mon Sep 17 00:00:00 2001 From: Steven Malis <137308034+smalis-msft@users.noreply.github.com> Date: Tue, 27 May 2025 15:57:35 -0400 Subject: [PATCH 3/8] Spacing --- openhcl/underhill_core/src/dispatch/mod.rs | 8 ++++---- openhcl/underhill_core/src/worker.rs | 4 ++-- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/openhcl/underhill_core/src/dispatch/mod.rs b/openhcl/underhill_core/src/dispatch/mod.rs index 7a8b984a60..b0d5f432d0 100644 --- a/openhcl/underhill_core/src/dispatch/mod.rs +++ b/openhcl/underhill_core/src/dispatch/mod.rs @@ -521,7 +521,7 @@ impl LoadedVm { if let Some(network_settings) = self.network_settings.as_mut() { network_settings .unload_for_servicing() - .instrument(tracing::info_span!("shutdown_mana",CVM_ALLOWED)) + .instrument(tracing::info_span!("shutdown_mana", CVM_ALLOWED)) .await; } }; @@ -531,7 +531,7 @@ impl LoadedVm { if let Some(nvme_manager) = self.nvme_manager.take() { nvme_manager .shutdown(nvme_keepalive) - .instrument(tracing::info_span!("shutdown_nvme_vfio",CVM_ALLOWED, %correlation_id, %nvme_keepalive)) + .instrument(tracing::info_span!("shutdown_nvme_vfio", CVM_ALLOWED, %correlation_id, %nvme_keepalive)) .await; } }; @@ -540,7 +540,7 @@ impl LoadedVm { // restart. let shutdown_pci = async { pci_shutdown::shutdown_pci_devices() - .instrument(tracing::info_span!("shutdown_pci_devices",CVM_ALLOWED)) + .instrument(tracing::info_span!("shutdown_pci_devices", CVM_ALLOWED)) .await }; @@ -549,7 +549,7 @@ impl LoadedVm { Ok(state) } - .instrument(tracing::info_span!("servicing_save_vtl2",CVM_ALLOWED, %correlation_id)) + .instrument(tracing::info_span!("servicing_save_vtl2", CVM_ALLOWED, %correlation_id)) .await; let mut state = match r { diff --git a/openhcl/underhill_core/src/worker.rs b/openhcl/underhill_core/src/worker.rs index b0ccef3c1c..a95fba04d8 100644 --- a/openhcl/underhill_core/src/worker.rs +++ b/openhcl/underhill_core/src/worker.rs @@ -700,7 +700,7 @@ impl UhVmNetworkSettings { let nic = channel.remove().await.revoke().await; nic.shutdown() } - .instrument(tracing::info_span!("nic_shutdown",CVM_ALLOWED, %instance_id)) + .instrument(tracing::info_span!("nic_shutdown", CVM_ALLOWED, %instance_id)) .await })) .await; @@ -710,7 +710,7 @@ impl UhVmNetworkSettings { manager .complete(keep_vf_alive) .instrument( - tracing::info_span!("vf_manager_shutdown",CVM_ALLOWED, %instance_id), + tracing::info_span!("vf_manager_shutdown", CVM_ALLOWED, %instance_id), ) .await }, From 45e38f083709bab212947be53c49fbc1f4c4c06a Mon Sep 17 00:00:00 2001 From: Steven Malis Date: Fri, 30 May 2025 13:03:44 -0400 Subject: [PATCH 4/8] No point in filtering this --- openhcl/underhill_core/src/worker.rs | 13 ++++--------- 1 file changed, 4 insertions(+), 9 deletions(-) diff --git a/openhcl/underhill_core/src/worker.rs b/openhcl/underhill_core/src/worker.rs index a95fba04d8..f6862dd7d3 100644 --- a/openhcl/underhill_core/src/worker.rs +++ b/openhcl/underhill_core/src/worker.rs @@ -348,17 +348,12 @@ impl Worker for UnderhillVmWorker { "failed to start VM" ); - // An error could potentially contain sensitive information, so don't send it on CVMs. - let error_msg = if underhill_confidentiality::confidential_filtering_enabled() { - String::new() - } else { - // Format error as raw string because the error is anyhow::Error - format!("{:#}", err) - }; - // Note that this probably will not return, since the host // should terminate the VM in this case. - get_client.complete_start_vtl0(Some(error_msg)).await; + // Format error as raw string because the error is anyhow::Error + get_client + .complete_start_vtl0(Some(format!("{:#}", err))) + .await; } else { get_client.complete_start_vtl0(None).await; } From de31c76d9035527e7304640355143d46b2e5848a Mon Sep 17 00:00:00 2001 From: Steven Malis <137308034+smalis-msft@users.noreply.github.com> Date: Fri, 30 May 2025 15:46:37 -0400 Subject: [PATCH 5/8] Add message for split tracings --- openhcl/virt_mshv_vtl/src/processor/mod.rs | 2 +- openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs | 4 ++-- .../firmware/hcl_compat_uefi_nvram_storage/src/lib.rs | 4 ++-- vm/devices/tpm/src/lib.rs | 6 +++--- 4 files changed, 8 insertions(+), 8 deletions(-) diff --git a/openhcl/virt_mshv_vtl/src/processor/mod.rs b/openhcl/virt_mshv_vtl/src/processor/mod.rs index 882f64ca42..f1bb0504d0 100644 --- a/openhcl/virt_mshv_vtl/src/processor/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/mod.rs @@ -565,7 +565,7 @@ impl UhVpInner { pub fn set_sidecar_exit_reason(&self, reason: SidecarExitReason) { self.sidecar_exit_reason.lock().get_or_insert_with(|| { tracing::info!(CVM_ALLOWED, "sidecar exit"); - tracing::info!(CVM_CONFIDENTIAL, ?reason); + tracing::info!(CVM_CONFIDENTIAL, ?reason, "sidecar exit"); reason }); } diff --git a/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs b/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs index 27206f2dbf..c650a02f97 100644 --- a/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs @@ -1878,7 +1878,7 @@ impl UhProcessor<'_, TdxBacked> { msr, "unknown tdx vm msr write" ); - tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value); + tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value, "unknown tdx vm msr write"); false } Err(MsrError::InvalidAccess) => true, @@ -2555,7 +2555,7 @@ impl UhProcessor<'_, TdxBacked> { ?err, "failed tdvmcall msr write" ); - tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value); + tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value, "failed tdvmcall msr write"); TdVmCallR10Result::OPERAND_INVALID } } diff --git a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs index 9dd13ea387..0fca514d9e 100644 --- a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs +++ b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs @@ -136,7 +136,7 @@ impl HclCompatNvram { let res = self.lazy_load_from_storage_inner().await; if let Err(e) = &res { tracing::error!(CVM_ALLOWED, "storage contains corrupt nvram state"); - tracing::error!(CVM_CONFIDENTIAL, error = e as &dyn std::error::Error); + tracing::error!(CVM_CONFIDENTIAL, error = e as &dyn std::error::Error, "storage contains corrupt nvram state"); } res } @@ -255,7 +255,7 @@ impl HclCompatNvram { CVM_ALLOWED, "skipping corrupt nvram var (missing null term)" ); - tracing::warn!(CVM_CONFIDENTIAL, ?var); + tracing::warn!(CVM_CONFIDENTIAL, ?var, "skipping corrupt nvram var (missing null term)"); continue; } else { return Err(NvramStorageError::Load(e.into())); diff --git a/vm/devices/tpm/src/lib.rs b/vm/devices/tpm/src/lib.rs index 5276e85546..0fd98a69b5 100644 --- a/vm/devices/tpm/src/lib.rs +++ b/vm/devices/tpm/src/lib.rs @@ -562,7 +562,7 @@ impl Tpm { { // Failures are non-fatal as the feature is not necessary for booting. tracing::error!(CVM_ALLOWED, "Failed to initialize guest secret key"); - tracing::error!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error); + tracing::error!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error, "Failed to initialize guest secret key"); } } @@ -698,7 +698,7 @@ impl Tpm { CVM_ALLOWED, "could not persist ppi state to non-volatile store" ); - tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error); + tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error, "could not persist ppi state to non-volatile store"); } } }; @@ -1291,7 +1291,7 @@ impl MmioIntercept for Tpm { let res = pal_async::local::block_on(self.flush_pending_nvram()); if let Err(e) = res { tracing::warn!(CVM_ALLOWED, "could not commit nvram to non-volatile store"); - tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error); + tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error, "could not commit nvram to non-volatile store"); }; IoResult::Ok From 0f6a746d9f7a8680d4dc63d4f66a45dbe3087d69 Mon Sep 17 00:00:00 2001 From: Steven Malis Date: Fri, 30 May 2025 16:04:17 -0400 Subject: [PATCH 6/8] Do some chipset ones too --- Cargo.lock | 1 + vmm_core/vmotherboard/Cargo.toml | 1 + vmm_core/vmotherboard/src/base_chipset.rs | 8 +++--- vmm_core/vmotherboard/src/chipset/mod.rs | 31 +++++++++++++++-------- 4 files changed, 28 insertions(+), 13 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 52dcd9d0c2..9eb098e709 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -8917,6 +8917,7 @@ dependencies = [ "chipset_legacy", "chipset_resources", "closeable_mutex", + "cvm_tracing", "firmware_pcat", "firmware_uefi", "floppy", diff --git a/vmm_core/vmotherboard/Cargo.toml b/vmm_core/vmotherboard/Cargo.toml index f01b8570e5..6b5f6c7cae 100644 --- a/vmm_core/vmotherboard/Cargo.toml +++ b/vmm_core/vmotherboard/Cargo.toml @@ -46,6 +46,7 @@ watchdog_core.workspace = true address_filter.workspace = true arc_cyclic_builder.workspace = true closeable_mutex.workspace = true +cvm_tracing.workspace = true inspect_counters.workspace = true inspect.workspace = true local_clock.workspace = true diff --git a/vmm_core/vmotherboard/src/base_chipset.rs b/vmm_core/vmotherboard/src/base_chipset.rs index f8faeea01a..c21214cc91 100644 --- a/vmm_core/vmotherboard/src/base_chipset.rs +++ b/vmm_core/vmotherboard/src/base_chipset.rs @@ -17,6 +17,7 @@ use chipset_device_resources::GPE0_LINE_SET; use chipset_device_resources::IRQ_LINE_SET; use chipset_device_resources::ResolveChipsetDeviceHandleParams; use closeable_mutex::CloseableMutex; +use cvm_tracing::CVM_ALLOWED; use firmware_uefi::UefiCommandSet; use framebuffer::Framebuffer; use framebuffer::FramebufferDevice; @@ -320,8 +321,9 @@ impl<'a> BaseChipsetBuilder<'a> { Box::new(move || power.on_power_event(PowerEvent::Reset)) }; - let set_a20_signal = - Box::new(move |active| tracing::info!(?active, "setting stubbed A20 signal")); + let set_a20_signal = Box::new(move |active| { + tracing::info!(CVM_ALLOWED, active, "setting stubbed A20 signal") + }); builder .arc_mutex_device("piix4-pci-isa-bridge") @@ -516,7 +518,7 @@ impl<'a> BaseChipsetBuilder<'a> { let pm_action = || { let power = foundation.power_event_handler.clone(); move |action: pm::PowerAction| { - tracing::info!(?action, "guest initiated"); + tracing::info!(CVM_ALLOWED, ?action, "guest initiated"); let req = match action { pm::PowerAction::PowerOff => PowerEvent::PowerOff, pm::PowerAction::Hibernate => PowerEvent::Hibernate, diff --git a/vmm_core/vmotherboard/src/chipset/mod.rs b/vmm_core/vmotherboard/src/chipset/mod.rs index 56bc07b79e..b372eb9203 100644 --- a/vmm_core/vmotherboard/src/chipset/mod.rs +++ b/vmm_core/vmotherboard/src/chipset/mod.rs @@ -18,6 +18,8 @@ use chipset_device::ChipsetDevice; use chipset_device::io::IoError; use chipset_device::io::IoResult; use closeable_mutex::CloseableMutex; +use cvm_tracing::CVM_ALLOWED; +use cvm_tracing::CVM_CONFIDENTIAL; use inspect::Inspect; use std::future::poll_fn; use std::sync::Arc; @@ -104,6 +106,7 @@ impl Chipset { // Fill data with !0 to indicate an error to the guest. bytes.fill(!0); tracelimit::warn_ratelimited!( + CVM_ALLOWED, device = &*lookup.dev_name, address, len, @@ -112,15 +115,22 @@ impl Chipset { "device io read error" ); } - IoType::Write(bytes) => tracelimit::warn_ratelimited!( - device = &*lookup.dev_name, - address, - len, - ?kind, - error, - ?bytes, - "device io write error" - ), + IoType::Write(bytes) => { + tracelimit::warn_ratelimited!( + CVM_ALLOWED, + device = &*lookup.dev_name, + address, + len, + ?kind, + error, + "device io write error" + ); + tracelimit::warn_ratelimited!( + CVM_CONFIDENTIAL, + ?bytes, + "device io write error" + ); + } } Ok(()) } @@ -147,7 +157,8 @@ impl Chipset { } } Err(err) => { - tracing::error!( + tracelimit::error_ratelimited!( + CVM_ALLOWED, device = &*lookup.dev_name, ?kind, address, From 53b5f1a9803495ac36ba61a7671bcbbb77fa7f0e Mon Sep 17 00:00:00 2001 From: Steven Malis <137308034+smalis-msft@users.noreply.github.com> Date: Fri, 30 May 2025 16:09:54 -0400 Subject: [PATCH 7/8] confidentialify chipset --- vmm_core/vmotherboard/src/chipset/mod.rs | 17 +++++------------ 1 file changed, 5 insertions(+), 12 deletions(-) diff --git a/vmm_core/vmotherboard/src/chipset/mod.rs b/vmm_core/vmotherboard/src/chipset/mod.rs index b372eb9203..9e1bdc0324 100644 --- a/vmm_core/vmotherboard/src/chipset/mod.rs +++ b/vmm_core/vmotherboard/src/chipset/mod.rs @@ -18,7 +18,6 @@ use chipset_device::ChipsetDevice; use chipset_device::io::IoError; use chipset_device::io::IoResult; use closeable_mutex::CloseableMutex; -use cvm_tracing::CVM_ALLOWED; use cvm_tracing::CVM_CONFIDENTIAL; use inspect::Inspect; use std::future::poll_fn; @@ -106,7 +105,7 @@ impl Chipset { // Fill data with !0 to indicate an error to the guest. bytes.fill(!0); tracelimit::warn_ratelimited!( - CVM_ALLOWED, + CVM_CONFIDENTIAL, device = &*lookup.dev_name, address, len, @@ -115,22 +114,16 @@ impl Chipset { "device io read error" ); } - IoType::Write(bytes) => { - tracelimit::warn_ratelimited!( - CVM_ALLOWED, + IoType::Write(bytes) => tracelimit::warn_ratelimited!( + CVM_CONFIDENTIAL, device = &*lookup.dev_name, address, len, ?kind, error, - "device io write error" - ); - tracelimit::warn_ratelimited!( - CVM_CONFIDENTIAL, ?bytes, "device io write error" - ); - } + ), } Ok(()) } @@ -158,7 +151,7 @@ impl Chipset { } Err(err) => { tracelimit::error_ratelimited!( - CVM_ALLOWED, + CVM_CONFIDENTIAL, device = &*lookup.dev_name, ?kind, address, From 767ea2f776870b099208566373962dddc2d79b50 Mon Sep 17 00:00:00 2001 From: Steven Malis Date: Fri, 30 May 2025 16:27:10 -0400 Subject: [PATCH 8/8] Fmt --- openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs | 12 ++++++++++-- .../hcl_compat_uefi_nvram_storage/src/lib.rs | 12 ++++++++++-- vm/devices/tpm/src/lib.rs | 18 +++++++++++++++--- vmm_core/vmotherboard/src/chipset/mod.rs | 18 +++++++++--------- 4 files changed, 44 insertions(+), 16 deletions(-) diff --git a/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs b/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs index c650a02f97..e166a7fe96 100644 --- a/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs +++ b/openhcl/virt_mshv_vtl/src/processor/tdx/mod.rs @@ -1878,7 +1878,11 @@ impl UhProcessor<'_, TdxBacked> { msr, "unknown tdx vm msr write" ); - tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value, "unknown tdx vm msr write"); + tracelimit::warn_ratelimited!( + CVM_CONFIDENTIAL, + value, + "unknown tdx vm msr write" + ); false } Err(MsrError::InvalidAccess) => true, @@ -2555,7 +2559,11 @@ impl UhProcessor<'_, TdxBacked> { ?err, "failed tdvmcall msr write" ); - tracelimit::warn_ratelimited!(CVM_CONFIDENTIAL, value, "failed tdvmcall msr write"); + tracelimit::warn_ratelimited!( + CVM_CONFIDENTIAL, + value, + "failed tdvmcall msr write" + ); TdVmCallR10Result::OPERAND_INVALID } } diff --git a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs index 0fca514d9e..a4db5ba2b2 100644 --- a/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs +++ b/vm/devices/firmware/hcl_compat_uefi_nvram_storage/src/lib.rs @@ -136,7 +136,11 @@ impl HclCompatNvram { let res = self.lazy_load_from_storage_inner().await; if let Err(e) = &res { tracing::error!(CVM_ALLOWED, "storage contains corrupt nvram state"); - tracing::error!(CVM_CONFIDENTIAL, error = e as &dyn std::error::Error, "storage contains corrupt nvram state"); + tracing::error!( + CVM_CONFIDENTIAL, + error = e as &dyn std::error::Error, + "storage contains corrupt nvram state" + ); } res } @@ -255,7 +259,11 @@ impl HclCompatNvram { CVM_ALLOWED, "skipping corrupt nvram var (missing null term)" ); - tracing::warn!(CVM_CONFIDENTIAL, ?var, "skipping corrupt nvram var (missing null term)"); + tracing::warn!( + CVM_CONFIDENTIAL, + ?var, + "skipping corrupt nvram var (missing null term)" + ); continue; } else { return Err(NvramStorageError::Load(e.into())); diff --git a/vm/devices/tpm/src/lib.rs b/vm/devices/tpm/src/lib.rs index 0fd98a69b5..294e6fdd2e 100644 --- a/vm/devices/tpm/src/lib.rs +++ b/vm/devices/tpm/src/lib.rs @@ -562,7 +562,11 @@ impl Tpm { { // Failures are non-fatal as the feature is not necessary for booting. tracing::error!(CVM_ALLOWED, "Failed to initialize guest secret key"); - tracing::error!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error, "Failed to initialize guest secret key"); + tracing::error!( + CVM_CONFIDENTIAL, + error = &e as &dyn std::error::Error, + "Failed to initialize guest secret key" + ); } } @@ -698,7 +702,11 @@ impl Tpm { CVM_ALLOWED, "could not persist ppi state to non-volatile store" ); - tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error, "could not persist ppi state to non-volatile store"); + tracing::warn!( + CVM_CONFIDENTIAL, + error = &e as &dyn std::error::Error, + "could not persist ppi state to non-volatile store" + ); } } }; @@ -1291,7 +1299,11 @@ impl MmioIntercept for Tpm { let res = pal_async::local::block_on(self.flush_pending_nvram()); if let Err(e) = res { tracing::warn!(CVM_ALLOWED, "could not commit nvram to non-volatile store"); - tracing::warn!(CVM_CONFIDENTIAL, error = &e as &dyn std::error::Error, "could not commit nvram to non-volatile store"); + tracing::warn!( + CVM_CONFIDENTIAL, + error = &e as &dyn std::error::Error, + "could not commit nvram to non-volatile store" + ); }; IoResult::Ok diff --git a/vmm_core/vmotherboard/src/chipset/mod.rs b/vmm_core/vmotherboard/src/chipset/mod.rs index 9e1bdc0324..8f91206958 100644 --- a/vmm_core/vmotherboard/src/chipset/mod.rs +++ b/vmm_core/vmotherboard/src/chipset/mod.rs @@ -115,15 +115,15 @@ impl Chipset { ); } IoType::Write(bytes) => tracelimit::warn_ratelimited!( - CVM_CONFIDENTIAL, - device = &*lookup.dev_name, - address, - len, - ?kind, - error, - ?bytes, - "device io write error" - ), + CVM_CONFIDENTIAL, + device = &*lookup.dev_name, + address, + len, + ?kind, + error, + ?bytes, + "device io write error" + ), } Ok(()) }