CVM: Audit tracing and add ALLOWED/CONFIDENTIAL where appropriate

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",
@@ -8910,6 +8917,7 @@ dependencies = [
  "chipset_legacy",
  "chipset_resources",
  "closeable_mutex",
+ "cvm_tracing",
  "firmware_pcat",
  "firmware_uefi",
  "floppy",

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"] }

openhcl/diag_server/src/diag_service.rs

@@ -546,7 +546,7 @@ impl DiagServiceHandler {
     }
 
     async fn handle_update(&self, request: &UpdateRequest) -> anyhow::Result<UpdateResponse2> {
-        tracing::info!(
+        tracing::debug!(
             path = request.path.as_str(),
             value = request.value.as_str(),
             "update request"

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<Self> {
-        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<Self> {
-        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(

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

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::<hvdef::hypercall::AcceptGpaPages>())
             / size_of::<u64>();
 
-        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::<hvdef::hypercall::ModifyVtlProtectionMask>())
             / size_of::<u64>();
 
-        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;

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,

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;
             }

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,19 +390,20 @@ 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"
                                 );
                                 ShutdownResult::Failed(0x80000001)
                             }
                         };
                         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<Vec<SavedStateUnit>> {
         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<SavedStateUnit>) -> 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,

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(),
                     ))