diff --git a/src/migtd/Cargo.toml b/src/migtd/Cargo.toml index 34e9052f..80ff838f 100644 --- a/src/migtd/Cargo.toml +++ b/src/migtd/Cargo.toml @@ -23,7 +23,7 @@ chrono = { version = "0.4", default-features = false, features = ["alloc"] } crypto = { path = "../crypto" } futures-util = { version = "0.3.17", default-features = false } lazy_static = { version = "1.0", features = ["spin_no_std"] } -log = { version = "0.4.29", features = ["kv", "release_max_level_off"] } +log = { version = "0.4.29", features = ["kv"] } pci = { path="../devices/pci" } policy = {path = "../policy"} rust_std_stub = { path = "../std-support/rust-std-stub" } diff --git a/src/migtd/src/bin/migtd/main.rs b/src/migtd/src/bin/migtd/main.rs index 95a32a88..46a5d142 100644 --- a/src/migtd/src/bin/migtd/main.rs +++ b/src/migtd/src/bin/migtd/main.rs @@ -10,8 +10,6 @@ extern crate alloc; use core::future::poll_fn; use core::task::Poll; -#[cfg(feature = "vmcall-raw")] -use alloc::format; #[cfg(feature = "policy_v2")] use alloc::string::String; use alloc::vec::Vec; @@ -53,6 +51,7 @@ impl TdInfoAsBytes for tdreport::TdInfo { } } } + #[cfg(feature = "vmcall-raw")] fn dump_td_info_and_hash() { let td_report = @@ -98,13 +97,20 @@ fn main() { } pub fn runtime_main() { - // Initialize logging with level filter. The actual log level is determined by - // compile-time feature flags. - let _ = td_logger::init(LevelFilter::Trace); + #[cfg(not(feature = "vmcall-raw"))] + { + // Initialize logging with level filter. The actual log level is determined by + // compile-time feature flags. + let _ = td_logger::init(LevelFilter::Trace); + } // Create LogArea per vCPU #[cfg(feature = "vmcall-raw")] { + let result = init_vmm_logger(); + if result.is_err() { + panic!("Failed to initialize VMM logger"); + } let _ = create_logarea(); } @@ -126,7 +132,7 @@ pub fn runtime_main() { #[cfg(feature = "vmcall-raw")] { - info!("log::max_level() = {}\n", log::max_level()); + log::info!("log::max_level() = {}\n", log::max_level()); if log::max_level() >= Level::Debug { dump_td_info_and_hash(); } @@ -421,23 +427,9 @@ fn handle_pre_mig() { .map(|_| MigrationResult::Success) .unwrap_or_else(|e| e); if status == MigrationResult::Success { - entrylog( - &format!("Successfully completed key exchange\n").into_bytes(), - Level::Trace, - wfr_info.mig_info.mig_request_id, - ); - log::trace!("Successfully completed key exchange for wfr_info.mig_info.mig_request_id = {}\n", wfr_info.mig_info.mig_request_id); + log::trace!(migration_request_id = wfr_info.mig_info.mig_request_id; "Successfully completed key exchange\n"); } else { - entrylog( - &format!( - "Failure during key exchange, status code: {:x}\n", - status.clone() as u8 - ) - .into_bytes(), - Level::Error, - wfr_info.mig_info.mig_request_id, - ); - log::error!("Failure during key exchange for wfr_info.mig_info.mig_request_id = {}, status code: {:x}\n", wfr_info.mig_info.mig_request_id, status.clone() as u8); + log::error!(migration_request_id = wfr_info.mig_info.mig_request_id; "Failure during key exchange status code: {:x}\n", status.clone() as u8); } let _ = report_status( status as u8, @@ -446,18 +438,12 @@ fn handle_pre_mig() { ) .await .map_err(|e| { - log::error!( - "Failed to report status for StartMigration mig_request_id {}: {:?}\n", - wfr_info.mig_info.mig_request_id, + log::error!( migration_request_id = wfr_info.mig_info.mig_request_id; + "Failed to report status {:?}\n", e ); }); - entrylog( - &format!("ReportStatus for key exchange completed\n").into_bytes(), - Level::Trace, - wfr_info.mig_info.mig_request_id, - ); - log::trace!("ReportStatus for key exchange completed for wfr_info.mig_info.mig_request_id = {}\n", wfr_info.mig_info.mig_request_id); + log::trace!(migration_request_id = wfr_info.mig_info.mig_request_id; "ReportStatus for key exchange completed\n"); REQUESTS.lock().remove(&wfr_info.mig_info.mig_request_id); } WaitForRequestResponse::GetTdReport(wfr_info) => { @@ -470,32 +456,13 @@ fn handle_pre_mig() { .map(|_| MigrationResult::Success) .unwrap_or_else(|e| e); if status == MigrationResult::Success { - entrylog( - &format!("Successfully completed get TDREPORT\n").into_bytes(), - Level::Trace, - wfr_info.mig_request_id, - ); - log::trace!("Successfully completed get TDREPORT for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id); + log::trace!(migration_request_id = wfr_info.mig_request_id; "Successfully completed get TDREPORT\n"); } else { - entrylog( - &format!( - "Failure during get TDREPORT, status code: {:x}\n", - status.clone() as u8 - ) - .into_bytes(), - Level::Error, - wfr_info.mig_request_id, - ); - log::error!("Failure during get TDREPORT for wfr_info.mig_request_id = {}, status code: {:x}\n", wfr_info.mig_request_id, status.clone() as u8); + log::error!(migration_request_id = wfr_info.mig_request_id; "Failure during get TDREPORT status code: {:x}\n", status.clone() as u8); } let _ = report_status(status as u8, wfr_info.mig_request_id, &data).await; - entrylog( - &format!("ReportStatus for get TDREPORT completed\n").into_bytes(), - Level::Trace, - wfr_info.mig_request_id, - ); - log::trace!("ReportStatus for get TDREPORT completed for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id); + log::trace!(migration_request_id = wfr_info.mig_request_id; "ReportStatus for get TDREPORT completed.\n"); REQUESTS.lock().remove(&wfr_info.mig_request_id); } WaitForRequestResponse::EnableLogArea(wfr_info) => { @@ -507,43 +474,27 @@ fn handle_pre_mig() { .await .map(|_| MigrationResult::Success) .unwrap_or_else(|e| e); + + log::info!( migration_request_id = wfr_info.mig_request_id; + "Setting log level to {}\n", + wfr_info.log_max_level + ); + log::set_max_level(u8_to_levelfilter(wfr_info.log_max_level)); + if status == MigrationResult::Success { - entrylog( - &format!("Successfully completed Enable LogArea\n") - .into_bytes(), - Level::Trace, - wfr_info.mig_request_id, - ); - log::trace!("Successfully completed Enable LogArea for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id); + log::trace!(migration_request_id = wfr_info.mig_request_id; "Successfully completed Enable LogArea\n"); } else { - entrylog( - &format!( - "Failure during Enable LogArea, status code: {:x}\n", - status.clone() as u8 - ) - .into_bytes(), - Level::Error, - wfr_info.mig_request_id, - ); - log::error!("Failure during Enable LogArea for wfr_info.mig_request_id = {}, status code: {:x}\n", wfr_info.mig_request_id, status.clone() as u8); + log::error!(migration_request_id = wfr_info.mig_request_id; "Failure during Enable LogArea status code: {:x}\n", status.clone() as u8); } - let _ = - report_status(status as u8, wfr_info.mig_request_id, &data) + let _ = report_status(status as u8, wfr_info.mig_request_id, &data) .await .map_err(|e| { - log::error!( - "Failed to report status for Enable LogArea mig_request_id {}: {:?}\n", - wfr_info.mig_request_id, + log::error!( migration_request_id = wfr_info.mig_request_id; + "Failed to report status for Enable LogArea {:?}\n", e ); }); - entrylog( - &format!("ReportStatus for Enable LogArea completed\n") - .into_bytes(), - Level::Trace, - wfr_info.mig_request_id, - ); - log::trace!("ReportStatus for Enable LogArea completed for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id); + log::trace!(migration_request_id = wfr_info.mig_request_id; "ReportStatus for Enable LogArea completed\n"); REQUESTS.lock().remove(&wfr_info.mig_request_id); } } diff --git a/src/migtd/src/migration/logging.rs b/src/migtd/src/migration/logging.rs index 1ad14a75..dee7413e 100644 --- a/src/migtd/src/migration/logging.rs +++ b/src/migtd/src/migration/logging.rs @@ -26,6 +26,17 @@ const PAGE_SIZE: usize = 0x1_000; const TDCALL_STATUS_SUCCESS: u64 = 0; const MIGRATION_REQUEST_ID_SENTINEL: u64 = 0xFFFF_FFFF_FFFF_FFFF; +pub fn u8_to_levelfilter(value: u8) -> LevelFilter { + match value { + 1 => LevelFilter::Error, + 2 => LevelFilter::Warn, + 3 => LevelFilter::Info, + 4 => LevelFilter::Debug, + 5 => LevelFilter::Trace, + _ => LevelFilter::Info, // Handle cases where the u8 doesn't map to a valid Level + } +} + type Result = core::result::Result; struct LoggingInformation { @@ -196,19 +207,10 @@ pub async fn enable_logarea(log_max_level: u8, request_id: u64, data: &mut Vec bool { - let log_max_level = LOGGING_INFORMATION.maxloglevel.load(Ordering::SeqCst); - let log_level = loglevel_to_u8(metadata.level()); - // Enable if logging is configured and level is appropriate + let mut log_max_level = log::max_level(); + + let logarea_initialized = LOGGING_INFORMATION + .logarea_initialized + .load(Ordering::SeqCst); + if logarea_initialized { + log_max_level = + u8_to_levelfilter(LOGGING_INFORMATION.maxloglevel.load(Ordering::SeqCst)); + } + + let log_level = metadata.level(); log_level <= log_max_level } @@ -515,14 +524,22 @@ impl log::Log for VmmLoggerBackend { entrylog(&msg.into_bytes(), record.level(), mig_request_id); // Also output to debug console for development (skip in test mode to avoid issues) - #[cfg(not(test))] - if mig_request_id != MIGRATION_REQUEST_ID_SENTINEL { - td_logger::dbg_write_string(&format!( - "{} - [req_id: {}] {}\n", - record.level(), - mig_request_id, - record.args() - )); + #[cfg(all(not(test), debug_assertions))] + { + if mig_request_id != MIGRATION_REQUEST_ID_SENTINEL { + td_logger::dbg_write_string(&format!( + "{} - [req_id: {}] {}\n", + record.level(), + mig_request_id, + record.args() + )); + } else { + td_logger::dbg_write_string(&format!( + "{} - {}\n", + record.level(), + record.args() + )); + } } } } diff --git a/src/migtd/src/migration/session.rs b/src/migtd/src/migration/session.rs index 8570b594..080c4a32 100644 --- a/src/migtd/src/migration/session.rs +++ b/src/migtd/src/migration/session.rs @@ -18,8 +18,6 @@ use core::{future::poll_fn, mem::size_of, task::Poll}; #[cfg(any(feature = "vmcall-interrupt", feature = "vmcall-raw"))] use event::VMCALL_SERVICE_FLAG; use lazy_static::lazy_static; -#[cfg(feature = "vmcall-raw")] -use log::Level; use spin::Mutex; use td_payload::mm::shared::SharedMemory; use tdx_tdcall::{ @@ -32,8 +30,6 @@ use tdx_tdcall::{tdreport::TdxReport, tdreport::TD_REPORT_ADDITIONAL_DATA_SIZE}; use zerocopy::AsBytes; type Result = core::result::Result; -#[cfg(feature = "vmcall-raw")] -use super::logging::entrylog; use super::{data::*, *}; use crate::driver::ticks::with_timeout; #[cfg(not(feature = "spdm_attestation"))] @@ -63,9 +59,6 @@ struct TdxReportBuf(TdxReport); #[repr(C, align(64))] struct AdditionalDataBuf([u8; TD_REPORT_ADDITIONAL_DATA_SIZE]); -#[cfg(feature = "vmcall-raw")] -const DEFAULT_MIGREQUEST_ID: u64 = u64::MAX; - #[cfg(feature = "vmcall-raw")] const TDX_VMCALL_VMM_SUCCESS: u8 = 1; @@ -211,15 +204,6 @@ fn process_buffer(buffer: &mut [u8]) -> RequestDataBufferHeader { length: 0, }; if buffer.len() < length { - entrylog( - &format!( - "process_buffer: Buffer too small! - len = {:x}\n", - buffer.len() - ) - .into_bytes(), - Level::Debug, - DEFAULT_MIGREQUEST_ID, - ); log::debug!( "process_buffer: Buffer too small! - buffer.len = {}, length = {}\n", buffer.len(), @@ -276,7 +260,6 @@ pub async fn wait_for_request() -> Result { } let data_status_bytes = &data_status.to_le_bytes(); if data_status_bytes[0] != TDX_VMCALL_VMM_SUCCESS { - entrylog(&format!("wait_for_request: data_status byte[0] failure\n").into_bytes(), Level::Error, DEFAULT_MIGREQUEST_ID); log::error!("wait_for_request: data_status byte[0] failure\n"); return Poll::Pending; } @@ -289,11 +272,10 @@ pub async fn wait_for_request() -> Result { if data_length >= size_of::() as u32 { let slice = &data_buffer[reqbufferhdrlen..reqbufferhdrlen + data_length as usize]; let mig_request_id = u64::from_le_bytes(slice[0..8].try_into().unwrap()); - entrylog(&format!("wait_for_request: StartMigration operation incorrect data length - expected {:x} actual {:x}\n", expected_datalength, data_length).into_bytes(), Level::Debug, mig_request_id); + log::error!(migration_request_id = mig_request_id; "wait_for_request: StartMigration operation incorrect data length - expected {} actual {}\n", expected_datalength, data_length); } else { - entrylog(&format!("wait_for_request: StartMigration operation incorrect data length - expected {:x} actual {:x}\n", expected_datalength, data_length).into_bytes(), Level::Debug, DEFAULT_MIGREQUEST_ID); + log::error!("wait_for_request: StartMigration operation incorrect data length - expected {} actual {}\n", expected_datalength, data_length); } - log::debug!("wait_for_request: StartMigration operation incorrect data length - expected {} actual {}\n", expected_datalength, data_length); return Poll::Pending; } let slice = &data_buffer[reqbufferhdrlen..reqbufferhdrlen + data_length as usize]; @@ -330,11 +312,10 @@ pub async fn wait_for_request() -> Result { if data_length >= size_of::() as u32 { let slice = &data_buffer[reqbufferhdrlen..reqbufferhdrlen + data_length as usize]; let mig_request_id = u64::from_le_bytes(slice[0..8].try_into().unwrap()); - entrylog(&format!("wait_for_request: StartMigration operation incorrect data length - expected {:x} or {:x} actual {:x}\n", size_of_val(&mig_request_id), size_of::(), data_length).into_bytes(), Level::Debug, mig_request_id); + log::error!(migration_request_id = mig_request_id; "wait_for_request: StartMigration operation incorrect data length - expected {} actual {}\n", size_of::(), data_length); } else { - entrylog(&format!("wait_for_request: StartMigration operation incorrect data length - expected {:x} or {:x} actual {:x}\n", size_of_val(&mig_request_id), size_of::(), data_length).into_bytes(), Level::Debug, DEFAULT_MIGREQUEST_ID); + log::error!("wait_for_request: StartMigration operation incorrect data length - expected {} actual {}\n", size_of::(), data_length); } - log::debug!("wait_for_request: StartMigration operation incorrect data length - expected {} or {} actual {}\n", size_of_val(&mig_request_id), size_of::(), data_length); return Poll::Pending; } let slice = &data_buffer[reqbufferhdrlen..reqbufferhdrlen + data_length as usize]; @@ -366,11 +347,10 @@ pub async fn wait_for_request() -> Result { if data_length >= size_of::() as u32 { let slice = &data_buffer[reqbufferhdrlen..reqbufferhdrlen + data_length as usize]; let mig_request_id = u64::from_le_bytes(slice[0..8].try_into().unwrap()); - entrylog(&format!("wait_for_request: EnableLogArea operation incorrect data length - expected {:x} actual {:x}\n", expected_datalength, data_length).into_bytes(), Level::Debug, mig_request_id); + log::error!(migration_request_id = mig_request_id; "wait_for_request: EnableLogArea operation incorrect data length - expected {} actual {}\n", expected_datalength, data_length); } else { - entrylog(&format!("wait_for_request: EnableLogArea operation incorrect data length - expected {:x} actual {:x}\n", expected_datalength, data_length).into_bytes(), Level::Debug, DEFAULT_MIGREQUEST_ID); + log::error!("wait_for_request: EnableLogArea operation incorrect data length - expected {} actual {}\n", expected_datalength, data_length); } - log::debug!("wait_for_request: EnableLogArea operation incorrect data length - expected {} actual {}\n", expected_datalength, data_length); return Poll::Pending; } @@ -539,36 +519,21 @@ pub async fn get_tdreport( let ret = td_call(&mut args); if ret != TDCALL_STATUS_SUCCESS { - entrylog( - &format!("get_tdreport: TDG.MR.REPORT failure {:x}\n", ret).into_bytes(), - Level::Debug, - request_id, - ); data.extend_from_slice( &format!("Error: get_tdreport(): TDG.MR.REPORT failure {:x}\n", ret).into_bytes(), ); - log::error!("get_tdreport: TDG.MR.REPORT failure {:x}\n", ret); + log::error!(migration_request_id = request_id; "get_tdreport: TDG.MR.REPORT failure {:x}\n", ret); return Err(MigrationResult::TdxModuleError); } data.extend_from_slice(report_buf.0.as_bytes()); if data.len() != tdreportsize { - entrylog( - &format!( - "get_tdreport: tdreport incorrect data length - expected {:x} actual {:x}\n", - tdreportsize, - data.len() - ) - .into_bytes(), - Level::Debug, - request_id, - ); data.extend_from_slice(&format!( "Error: get_tdreport(): tdreport incorrect data length - expected {:x} actual {:x}\n", tdreportsize, data.len() ).into_bytes()); - log::error!( + log::error!( migration_request_id = request_id; "get_tdreport: tdreport incorrect data length - expected {} actual {}\n", tdreportsize, data.len() @@ -590,7 +555,7 @@ pub async fn report_status(status: u8, request_id: u64, data: &Vec) -> Resul }; let reqbufferhdrlen = size_of::(); let mut data_buffer = SharedMemory::new(1).ok_or_else(|| { - log::error!("report_status: Failed to allocate shared memory for data buffer\n"); + log::error!(migration_request_id = request_id; "report_status: Failed to allocate shared memory for data buffer\n"); MigrationResult::OutOfResource })?; @@ -601,16 +566,7 @@ pub async fn report_status(status: u8, request_id: u64, data: &Vec) -> Resul .with_error_code(status); } } else { - entrylog( - &format!( - "report_status: Invalid Migration Status code: {:x}\n", - status - ) - .into_bytes(), - Level::Error, - request_id, - ); - log::error!( + log::error!( migration_request_id = request_id; "report_status: Invalid Migration Status code: {:x}\n", status ); @@ -635,7 +591,7 @@ pub async fn report_status(status: u8, request_id: u64, data: &Vec) -> Resul event::VMCALL_SERVICE_VECTOR, ) .map_err(|e| { - log::error!( + log::error!(migration_request_id = request_id; "report_status: tdvmcall_migtd_reportstatus failure {:?}\n", e ); @@ -656,12 +612,7 @@ pub async fn report_status(status: u8, request_id: u64, data: &Vec) -> Resul reqbufferhdr = process_buffer(data_buffer); let data_status_bytes = &reqbufferhdr.datastatus.to_le_bytes(); if data_status_bytes[0] != TDX_VMCALL_VMM_SUCCESS { - log::error!("report_status: data_status byte[0] failure\n"); - entrylog( - &format!("report_status: data_status byte[0] failure\n").into_bytes(), - Level::Error, - request_id, - ); + log::error!(migration_request_id = request_id; "report_status: data_status byte[0] failure\n"); return Poll::Pending; } @@ -1175,14 +1126,13 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re )) .await .map_err(|e| { - log::error!( - "exchange_msk: pre_session_data_exchange timeout error: {:?}\n", + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: pre_session_data_exchange timeout error: {:?}\n", e ); e })? .map_err(|e| { - log::error!("exchange_msk: pre_session_data_exchange error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: pre_session_data_exchange error: {:?}\n", e); e })?; @@ -1193,7 +1143,7 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re let mut remote_information = ExchangeInformation::default(); let mut exchange_information = exchange_info(&info.mig_info, info.is_src()).map_err(|e| { - log::error!("exchange_msk: exchange_info error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: exchange_info error: {:?}\n", e); e })?; @@ -1216,10 +1166,7 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .into_bytes(), ); - log::error!( - "exchange_msk(): Failed in ratls transport. Migration ID: {}\n", - info.mig_info.mig_request_id - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk(): Failed in ratls transport.\n"); MigrationResult::SecureSessionError })?; @@ -1230,11 +1177,11 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .await .map_err(|e| { - log::error!("exchange_msk: ratls_client.write timeout error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_client.write timeout error: {:?}\n", e); e })? .map_err(|e| { - log::error!("exchange_msk: ratls_client.write error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_client.write error: {:?}\n", e); e })?; let size = with_timeout( @@ -1243,11 +1190,11 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .await .map_err(|e| { - log::error!("exchange_msk: ratls_client.read timeout error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_client.read timeout error: {:?}\n", e); e })? .map_err(|e| { - log::error!("exchange_msk: ratls_client.read error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_client.read error: {:?}\n", e); e })?; if size < size_of::() { @@ -1261,15 +1208,12 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .into_bytes(), ); - log::error!("exchange_msk(): Incorrect ExchangeInformation size Migration ID: {}. Size - Expected: {} Actual: {}\n", info.mig_info.mig_request_id, size_of::(), size); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk(): Incorrect ExchangeInformation size Migration ID: {}. Size - Expected: {} Actual: {}\n", info.mig_info.mig_request_id, size_of::(), size); return Err(MigrationResult::NetworkError); } #[cfg(all(not(feature = "virtio-serial"), not(feature = "vmcall-raw")))] ratls_client.transport_mut().shutdown().await.map_err(|e| { - log::error!( - "exchange_msk: ratls_client.transport_mut().shutdown() error: {:?}\n", - e - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_client.transport_mut().shutdown() error: {:?}\n", e); e })?; @@ -1287,11 +1231,7 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .into_bytes(), ); - log::error!( - "exchange_msk: Failed to transport in vmcall_raw_instance with Migration ID: {} errorcode: {}", - info.mig_info.mig_request_id, - e - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: Failed to transport in vmcall_raw_instance with Migration ID: {} errorcode: {}", info.mig_info.mig_request_id, e); MigrationResult::InvalidParameter })?; } else { @@ -1310,10 +1250,7 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .into_bytes(), ); - log::error!( - "exchange_msk(): Failed in ratls transport. Migration ID: {}\n", - info.mig_info.mig_request_id - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk(): Failed in ratls transport. Migration ID: {:x}\n", info.mig_info.mig_request_id); MigrationResult::SecureSessionError })?; @@ -1323,11 +1260,11 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .await .map_err(|e| { - log::error!("exchange_msk: ratls_server.write timeout error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_server.write timeout error: {:?}\n", e); e })? .map_err(|e| { - log::error!("exchange_msk: ratls_server.write error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_server.write error: {:?}\n", e); e })?; let size = with_timeout( @@ -1336,17 +1273,17 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .await .map_err(|e| { - log::error!("exchange_msk: ratls_server.read timeout error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_server.read timeout error: {:?}\n", e); e })? .map_err(|e| { - log::error!("exchange_msk: ratls_server.read error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: ratls_server.read error: {:?}\n", e); e })?; if size < size_of::() { #[cfg(feature = "vmcall-raw")] data.extend_from_slice(&format!("Error: exchange_msk(): Incorrect ExchangeInformation size Migration ID: {:x}. Size - Expected: {:x} Actual: {:x}\n", info.mig_info.mig_request_id, size_of::(), size).into_bytes()); - log::error!("exchange_msk(): Incorrect ExchangeInformation size Migration ID: {}. Size - Expected: {} Actual: {}\n", info.mig_info.mig_request_id, size_of::(), size); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk(): Incorrect ExchangeInformation size Migration ID: {}. Size - Expected: {} Actual: {}\n", info.mig_info.mig_request_id, size_of::(), size); return Err(MigrationResult::NetworkError); } #[cfg(all(not(feature = "virtio-serial"), not(feature = "vmcall-raw")))] @@ -1359,35 +1296,26 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re .await .map_err(|e| { data.extend_from_slice(&format!("Error: exchange_msk(): Failed to transport in vmcall_raw_instance with Migration ID: {:x} errorcode: {}\n", info.mig_info.mig_request_id, e).into_bytes()); - log::error!("exchange_msk: Failed to transport in vmcall_raw_instance with Migration ID: {} errorcode: {}\n", info.mig_info.mig_request_id, e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: Failed to transport in vmcall_raw_instance with Migration ID: {} errorcode: {}\n", info.mig_info.mig_request_id, e); MigrationResult::InvalidParameter })?; } let mig_ver = cal_mig_version(info.is_src(), &exchange_information, &remote_information) .map_err(|e| { - log::error!("exchange_msk: cal_mig_version error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: cal_mig_version error: {:?}\n", e); e })?; set_mig_version(&info.mig_info, mig_ver).map_err(|e| { - log::error!("exchange_msk: set_mig_version error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: set_mig_version error: {:?}\n", e); e })?; write_msk(&info.mig_info, &remote_information.key).map_err(|e| { - log::error!("exchange_msk: write_msk error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: write_msk error: {:?}\n", e); e })?; - log::info!("Set MSK and report status\n"); - #[cfg(feature = "vmcall-raw")] - { - entrylog( - &format!("Set MSK and report status\n").into_bytes(), - Level::Info, - info.mig_info.mig_request_id, - ); - log::info!("Set MSK and report status\n"); - } + log::info!(migration_request_id = info.mig_info.mig_request_id; "Set MSK and report status\n"); exchange_information.key.clear(); remote_information.key.clear(); } @@ -1397,10 +1325,7 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re const SPDM_TIMEOUT: Duration = Duration::from_secs(60); // 60 seconds if info.is_src() { let mut spdm_requester = spdm::spdm_requester(transport).map_err(|_e| { - log::error!( - "exchange_msk(): Failed in spdm_requester transport. Migration ID: {}\n", - info.mig_info.mig_request_id - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk(): Failed in spdm_requester transport. Migration ID: {}\n", info.mig_info.mig_request_id); MigrationResult::SecureSessionError })?; with_timeout( @@ -1414,23 +1339,17 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .await .map_err(|e| { - log::error!( - "exchange_msk: spdm_requester_transfer_msk timeout error: {:?}\n", - e - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: spdm_requester_transfer_msk timeout error: {:?}\n", e); e })? .map_err(|e| { - log::error!("exchange_msk: spdm_requester_transfer_msk error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: spdm_requester_transfer_msk error: {:?}\n", e); e })?; - log::info!("MSK exchange completed\n"); + log::info!(migration_request_id = info.mig_info.mig_request_id;"MSK exchange completed\n"); } else { let mut spdm_responder = spdm::spdm_responder(transport).map_err(|_e| { - log::error!( - "exchange_msk(): Failed in spdm_responder transport. Migration ID: {}\n", - info.mig_info.mig_request_id - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk(): Failed in spdm_responder transport. Migration ID: {}\n", info.mig_info.mig_request_id); MigrationResult::SecureSessionError })?; @@ -1445,17 +1364,14 @@ pub async fn exchange_msk(info: &MigrationInformation, data: &mut Vec) -> Re ) .await .map_err(|e| { - log::error!( - "exchange_msk: spdm_responder_transfer_msk timeout error: {:?}\n", - e - ); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: spdm_responder_transfer_msk timeout error: {:?}\n", e); e })? .map_err(|e| { - log::error!("exchange_msk: spdm_responder_transfer_msk error: {:?}\n", e); + log::error!(migration_request_id = info.mig_info.mig_request_id; "exchange_msk: spdm_responder_transfer_msk error: {:?}\n", e); e })?; - log::info!("MSK exchange completed\n"); + log::info!(migration_request_id = info.mig_info.mig_request_id;"MSK exchange completed\n"); } } @@ -1468,11 +1384,7 @@ pub fn exchange_info( ) -> Result { let mut exchange_info = ExchangeInformation::default(); read_msk(mig_info, &mut exchange_info.key).map_err(|e| { - log::error!( - "exchange_info: read_msk failed with error: {:?} for mig_info.binding_handle = {}\n", - e, - mig_info.binding_handle - ); + log::error!(migration_request_id = mig_info.mig_request_id; "exchange_info: read_msk failed with error: {:?} for mig_info.binding_handle = {}\n", e, mig_info.binding_handle); e })?; @@ -1483,31 +1395,18 @@ pub fn exchange_info( }; let min_version = tdcall_sys_rd(field_min) .map_err(|e| { - log::error!( - "exchange_info: tdcall_sys_rd failed with error: {:?} for field_min = {}\n", - e, - field_min - ); + log::error!(migration_request_id = mig_info.mig_request_id; "exchange_info: tdcall_sys_rd failed with error: {:?} for field_min = {}\n", e, field_min); e })? .1; let max_version = tdcall_sys_rd(field_max) .map_err(|e| { - log::error!( - "exchange_info: tdcall_sys_rd failed with error: {:?} for field_max = {}\n", - e, - field_max - ); + log::error!(migration_request_id = mig_info.mig_request_id; "exchange_info: tdcall_sys_rd failed with error: {:?} for field_max = {}\n", e, field_max); e })? .1; if min_version > u16::MAX as u64 || max_version > u16::MAX as u64 { - log::error!( - "exchange_info: Migration version out of range. is_src = {}, min_version = {}, max_version = {}\n", - is_src, - min_version, - max_version - ); + log::error!(migration_request_id = mig_info.mig_request_id; "exchange_info: Migration version out of range. is_src = {}, min_version = {}, max_version = {}\n", is_src, min_version, max_version); return Err(MigrationResult::InvalidParameter); } exchange_info.min_ver = min_version as u16; @@ -1523,7 +1422,7 @@ fn read_msk(mig_info: &MigtdMigrationInformation, msk: &mut MigrationSessionKey) TDCS_FIELD_MIG_ENC_KEY + idx as u64, &mig_info.target_td_uuid, ).map_err(|e|{ - log::error!("read_msk: tdcall_servtd_rd failed with error: {:?} for mig_info.binding_handle = {}, idx = {}\n", e, mig_info.binding_handle, idx); + log::error!(migration_request_id = mig_info.mig_request_id; "read_msk: tdcall_servtd_rd failed with error: {:?} for mig_info.binding_handle = {}, idx = {}\n", e, mig_info.binding_handle, idx); e })?; msk.fields[idx] = ret.content; @@ -1540,7 +1439,7 @@ pub fn write_msk(mig_info: &MigtdMigrationInformation, msk: &MigrationSessionKey &mig_info.target_td_uuid, ) .map_err(|e| { - log::error!("write_msk: tdcall_servtd_wr failed with error: {:?} for mig_info.binding_handle = {}, idx = {}, value = {}\n", e, mig_info.binding_handle, idx, msk.fields[idx]); + log::error!(migration_request_id = mig_info.mig_request_id; "write_msk: tdcall_servtd_wr failed with error: {:?} for mig_info.binding_handle = {}, idx = {}, value = {}\n", e, mig_info.binding_handle, idx, msk.fields[idx]); MigrationResult::TdxModuleError })?; } @@ -1619,7 +1518,7 @@ pub fn set_mig_version(mig_info: &MigtdMigrationInformation, mig_ver: u16) -> Re mig_ver as u64, &mig_info.target_td_uuid, ).map_err(|e|{ - log::error!("set_mig_version: tdcall_servtd_wr failed with error: {:?} for mig_info.binding_handle = {}, mig_ver = {}\n", e, mig_info.binding_handle, mig_ver); + log::error!(migration_request_id = mig_info.mig_request_id; "set_mig_version: tdcall_servtd_wr failed with error: {:?} for mig_info.binding_handle = {}, mig_ver = {}\n", e, mig_info.binding_handle, mig_ver); e })?; Ok(())