Skip to content

Enable unified logging for Rust logging and memory logging for vmcall-raw. #678

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
agokarn wants to merge 1 commit into
base: main
Choose a base branch
from
+125 −258
Open

Enable unified logging for Rust logging and memory logging for vmcall-raw. #678

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion src/migtd/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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" }
Expand Down
115 changes: 33 additions & 82 deletions src/migtd/src/bin/migtd/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -53,6 +51,7 @@ impl TdInfoAsBytes for tdreport::TdInfo {
}
}
}

#[cfg(feature = "vmcall-raw")]
fn dump_td_info_and_hash() {
let td_report =
Expand Down Expand Up @@ -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();
}

Expand All @@ -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();
}
Expand Down Expand Up @@ -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,
Expand All @@ -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) => {
Expand All @@ -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) => {
Expand All @@ -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);
}
}
Expand Down
67 changes: 42 additions & 25 deletions src/migtd/src/migration/logging.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Contributor

@jyao1 jyao1 Dec 23, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, 0 will match Info?

}
}

type Result<T> = core::result::Result<T, MigrationResult>;

struct LoggingInformation {
Expand Down Expand Up @@ -196,19 +207,10 @@ pub async fn enable_logarea(log_max_level: u8, request_id: u64, data: &mut Vec<u
data.extend_from_slice(&PAGE_SIZE.to_le_bytes());
}

log::info!(
log::info!( migration_request_id = request_id;
"enable_logarea: Logging has been enabled with MaxLevel: {}\n",
log_max_level
);
entrylog(
&format!(
"enable_logarea: Logging has been enabled with MaxLevel: {}\n",
log_max_level
)
.into_bytes(),
Level::Info,
request_id,
);
}
#[cfg(test)]
{
Expand Down Expand Up @@ -236,10 +238,9 @@ pub async fn enable_logarea(log_max_level: u8, request_id: u64, data: &mut Vec<u
}
Ok(())
} else {
entrylog(
&format!("enable_logarea: Invalid MaxLogLevel: {:x}\n", log_max_level).into_bytes(),
Level::Error,
request_id,
log::error!( migration_request_id = request_id;
"enable_logarea: Logging has been enabled with MaxLevel: {}\n",
log_max_level
);
data.extend_from_slice(
&format!(
Expand Down Expand Up @@ -492,10 +493,18 @@ pub struct VmmLoggerBackend;

impl log::Log for VmmLoggerBackend {
fn enabled(&self, metadata: &Metadata) -> 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
}

Expand All @@ -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()
));
}
}
}
}
Expand Down
Loading
Loading