Skip to content

fix(migtd): apply log level settings to spdmlib #1052

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

Draft
sgrams wants to merge 1 commit into
base: main
Choose a base branch
from
+104 −91
Draft

fix(migtd): apply log level settings to spdmlib #1052

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/src/bin/migtd/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -102,7 +102,7 @@ pub fn runtime_main() {
{
// Initialize logging with level filter. The actual log level is determined by
// compile-time feature flags.
let _ = td_logger::init(log::LevelFilter::Trace);
let _ = td_logger::init(log::LevelFilter::Info);
}

// Create LogArea per vCPU
Expand Down
66 changes: 45 additions & 21 deletions src/migtd/src/migration/logging.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -275,6 +275,7 @@ pub async fn enable_logarea(log_max_level: u8, request_id: u64, data: &mut Vec<u
}

if let Some(_log_level) = u8_to_loglevel(log_max_level) {
let log_max_level = log_max_level.min(loglevel_to_u8(Level::Info));
LOGGING_INFORMATION
.maxloglevel
.store(log_max_level, Ordering::SeqCst);
Expand Down Expand Up @@ -361,6 +362,9 @@ pub async fn enable_logarea(log_max_level: u8, request_id: u64, data: &mut Vec<u
}

pub fn entrylog(msg: &Vec<u8>, loglevel: Level, request_id: u64) {
if loglevel > Level::Info {
return;
}
let logarea_initialized: bool = LOGGING_INFORMATION
.logarea_initialized
.load(Ordering::SeqCst);
Expand Down Expand Up @@ -642,24 +646,13 @@ impl log::Log for VmmLoggerBackend {
log_max_level =
u8_to_levelfilter(LOGGING_INFORMATION.maxloglevel.load(Ordering::SeqCst));
} else if provisional_logs_enabled {
// Provisional records are captured into private buffers and copied into
// the VMM-readable shared area when EnableLogArea succeeds. In release
// images cap the provisional level at Info as well, so sensitive
// Debug/Trace material cannot reach the shared area through this path.
#[cfg(debug_assertions)]
{
log_max_level = LevelFilter::Trace;
}
#[cfg(not(debug_assertions))]
{
log_max_level = LevelFilter::Info;
}
log_max_level = LevelFilter::Info;
} else {
log_max_level = log::max_level();
}

let log_level = metadata.level();
log_level <= log_max_level
log_level <= log_max_level.min(LevelFilter::Info)
}

fn log(&self, record: &Record) {
Expand Down Expand Up @@ -706,7 +699,7 @@ static VM_LOGGER_BACKEND: VmmLoggerBackend = VmmLoggerBackend;

/// Initialize the VMM logger as the global logger
pub fn init_vmm_logger() -> core::result::Result<(), SetLoggerError> {
log::set_logger(&VM_LOGGER_BACKEND).map(|()| log::set_max_level(LevelFilter::Trace))
log::set_logger(&VM_LOGGER_BACKEND).map(|()| log::set_max_level(LevelFilter::Info))
}

#[cfg(test)]
Expand Down Expand Up @@ -752,6 +745,14 @@ mod test {
assert!(provisional_logs_enabled);
assert!(!logarea_initialized);

for level in [Level::Info, Level::Debug, Level::Trace] {
let metadata = Metadata::builder().level(level).build();
assert_eq!(
log::Log::enabled(&VM_LOGGER_BACKEND, &metadata),
level == Level::Info
);
}

// Test utility functions
assert_eq!(loglevel_to_u8(Level::Error), 1);
assert_eq!(loglevel_to_u8(Level::Info), 3);
Expand Down Expand Up @@ -805,6 +806,15 @@ mod test {
.load(Ordering::SeqCst);
assert!(!provisional_logs_enabled);
assert!(logarea_initialized);
assert_eq!(log::max_level(), LevelFilter::Info);
assert_eq!(LOGGING_INFORMATION.maxloglevel.load(Ordering::SeqCst), 3);
for level in [Level::Info, Level::Debug, Level::Trace] {
let metadata = Metadata::builder().level(level).build();
assert_eq!(
log::Log::enabled(&VM_LOGGER_BACKEND, &metadata),
level == Level::Info
);
}

let mut logareavector = LOGAREAPTR.lock();
let data_buffer = logareavector[0];
Expand Down Expand Up @@ -849,9 +859,16 @@ mod test {
assert!(result.is_ok());

// Add a log entry
for level in [Level::Debug, Level::Trace] {
entrylog(&b"Suppressed provisional log\n".to_vec(), level, u64::MAX);
}
assert_eq!(
LOGGING_INFORMATION.logentry_id.load(Ordering::SeqCst),
initial_entry_id
);
entrylog(
&"Test provisional log\n".to_string().into_bytes(),
Level::Trace,
Level::Info,
u64::MAX,
);

Expand Down Expand Up @@ -888,7 +905,7 @@ mod test {

assert_eq!(log_entry_id, 1);
assert_eq!(mig_request_id, u64::MAX);
assert_eq!(loglevel, loglevel_to_u8(Level::Trace));
assert_eq!(loglevel, loglevel_to_u8(Level::Info));
assert_eq!(length, "Test provisional log\n".len() as u32);

logareavector.clear();
Expand Down Expand Up @@ -938,9 +955,16 @@ mod test {
assert!(result.is_ok());

// Add a log entry
for level in [Level::Debug, Level::Trace] {
entrylog(&b"Suppressed shared log\n".to_vec(), level, u64::MAX);
}
assert_eq!(
LOGGING_INFORMATION.logentry_id.load(Ordering::SeqCst),
initial_entry_id
);
entrylog(
&"Test message\n".to_string().into_bytes(),
Level::Trace,
Level::Info,
u64::MAX,
);

Expand Down Expand Up @@ -977,7 +1001,7 @@ mod test {

assert_eq!(log_entry_id, 1);
assert_eq!(mig_request_id, u64::MAX);
assert_eq!(loglevel, loglevel_to_u8(Level::Trace));
assert_eq!(loglevel, loglevel_to_u8(Level::Info));
assert_eq!(length, "Test message\n".len() as u32);

logareavector.clear();
Expand Down Expand Up @@ -1025,7 +1049,7 @@ mod test {
let provisional_msg = "Test provisional log\n";
entrylog(
&provisional_msg.to_string().into_bytes(),
Level::Trace,
Level::Info,
u64::MAX,
);
assert_eq!(LOGGING_INFORMATION.logentry_id.load(Ordering::SeqCst), 1);
Expand Down Expand Up @@ -1053,7 +1077,7 @@ mod test {

assert_eq!(entry_log_entry_id, 1);
assert_eq!(entry_mig_request_id, u64::MAX);
assert_eq!(entry_loglevel, loglevel_to_u8(Level::Trace));
assert_eq!(entry_loglevel, loglevel_to_u8(Level::Info));
assert_eq!(entry_length, provisional_msg.len() as u32);
}

Expand Down Expand Up @@ -1096,7 +1120,7 @@ mod test {

assert_eq!(first_entry_log_entry_id, 1);
assert_eq!(first_entry_mig_request_id, u64::MAX);
assert_eq!(first_entry_loglevel, loglevel_to_u8(Level::Trace));
assert_eq!(first_entry_loglevel, loglevel_to_u8(Level::Info));
assert_eq!(first_entry_length, provisional_msg.len() as u32);
assert_eq!(
core::str::from_utf8(&data_buffer[first_msg_start..first_msg_end]).unwrap(),
Expand Down
127 changes: 58 additions & 69 deletions xtask/src/build.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,7 @@ pub(crate) struct BuildArgs {
/// Path of the configuration file for td-shim image layout
#[clap(long)]
image_layout: Option<PathBuf>,
/// Log level control in migtd, default value is `off` for release and `info` for debug
/// Log level for MigTD and dependencies, capped at `info`; defaults to `off` for release and `info` for debug
#[clap(short, long)]
log_level: Option<LogLevel>,
/// MMIO space layout configuration for migtd
Expand Down Expand Up @@ -121,9 +121,7 @@ impl LogLevel {
LogLevel::Off => "log/max_level_off",
LogLevel::Error => "log/max_level_error",
LogLevel::Warn => "log/max_level_warn",
LogLevel::Info => "log/max_level_info",
LogLevel::Debug => "log/max_level_debug",
LogLevel::Trace => "log/max_level_trace",
LogLevel::Info | LogLevel::Debug | LogLevel::Trace => "log/max_level_info",
}
}

Expand All @@ -132,9 +130,7 @@ impl LogLevel {
LogLevel::Off => "log/release_max_level_off",
LogLevel::Error => "log/release_max_level_error",
LogLevel::Warn => "log/release_max_level_warn",
LogLevel::Info => "log/release_max_level_info",
LogLevel::Debug => "log/release_max_level_debug",
LogLevel::Trace => "log/release_max_level_trace",
LogLevel::Info | LogLevel::Debug | LogLevel::Trace => "log/release_max_level_info",
}
}
}
Expand Down Expand Up @@ -464,70 +460,10 @@ impl BuildArgs {
features.push_str(",");
if self.debug {
println!("Building debug MigTD");
match self.log_level {
Some(loglevel) => match loglevel {
LogLevel::Off => {
println!("Building debug MigTD found loglevel=Off), overriding to Info");
features.push_str(LogLevel::Info.debug_feature());
}
LogLevel::Error => {
println!("Building debug MigTD found loglevel=Error");
features.push_str(loglevel.debug_feature());
}
LogLevel::Warn => {
println!("Building debug MigTD found loglevel=Warn");
features.push_str(loglevel.debug_feature());
}
LogLevel::Info => {
println!("Building debug MigTD found loglevel=Info");
features.push_str(loglevel.debug_feature());
}
LogLevel::Debug => {
println!("Building debug MigTD found loglevel=Debug");
features.push_str(loglevel.debug_feature());
}
LogLevel::Trace => {
println!("Building debug MigTD found loglevel=Trace");
features.push_str(loglevel.debug_feature());
}
},
_ => {
println!("Building debug MigTD found None(loglevel)");
}
}
features.push_str(self.log_level.unwrap_or(LogLevel::Info).debug_feature());
} else {
println!("Building release MigTD");
match self.log_level {
Some(loglevel) => match loglevel {
LogLevel::Off => {
println!("Building release MigTD found loglevel=Off), overriding to Info");
features.push_str(LogLevel::Info.release_feature());
}
LogLevel::Error => {
println!("Building release MigTD found loglevel=Error");
features.push_str(loglevel.release_feature());
}
LogLevel::Warn => {
println!("Building release MigTD found loglevel=Warn");
features.push_str(loglevel.release_feature());
}
LogLevel::Info => {
println!("Building release MigTD found loglevel=Info");
features.push_str(loglevel.release_feature());
}
LogLevel::Debug => {
println!("Building release MigTD found loglevel=Debug");
features.push_str(loglevel.release_feature());
}
LogLevel::Trace => {
println!("Building release MigTD found loglevel=Trace");
features.push_str(loglevel.release_feature());
}
},
_ => {
println!("Building release MigTD found None(loglevel)");
}
}
features.push_str(self.log_level.unwrap_or(LogLevel::Off).release_feature());
}

features
Expand Down Expand Up @@ -612,3 +548,56 @@ impl BuildArgs {
fs::canonicalize(path).map_err(|e| e.into())
}
}

#[cfg(test)]
mod tests {
use super::BuildArgs;
use clap::Parser;

#[derive(Parser)]
struct TestArgs {
#[clap(flatten)]
build: BuildArgs,
}

#[test]
fn log_level_features() {
for debug in [false, true] {
for level in [
None,
Some("off"),
Some("error"),
Some("warn"),
Some("info"),
Some("debug"),
Some("trace"),
] {
let mut args = vec!["test"];
if debug {
args.push("--debug");
}
if let Some(level) = level {
args.extend(["--log-level", level]);
}
let build = TestArgs::parse_from(args).build;
let prefix = if debug {
"max_level"
} else {
"release_max_level"
};
let expected_level = level.unwrap_or(if debug { "info" } else { "off" });
let expected_level = match expected_level {
"debug" | "trace" => "info",
level => level,
};
let expected = format!("log/{prefix}_{expected_level}");
let features = build.features();
let log_features: Vec<_> = features
.split(',')
.filter(|feature| feature.starts_with("log/"))
.collect();
assert_eq!(log_features, vec![expected.as_str()]);
}
}
}
}
Loading