Skip to content

Commit 2d70988

Browse files
agokarnjyao1
agokarn
authored and
jyao1
committed
Enable unified logging.
 modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs modified: src/migtd/src/ratls/server_client.rs Add init_vmm_logger modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs modified: src/migtd/src/ratls/server_client.rs Fix incorrect log format. Remove unneccesary changes. modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs Bug fixes modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs release_max_level_off not needed anymore. modified: src/migtd/Cargo.toml modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs Address PR comments. modified: sh_script/Azure/Makefile modified: src/migtd/Cargo.toml modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs Fix formatting. modified: sh_script/Azure/Makefile modified: src/migtd/Cargo.toml modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs Fix formatting. modified: sh_script/Azure/Makefile modified: src/migtd/Cargo.toml modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs Revert spdm-rs submodule to base branch version Fix merge. modified: sh_script/Azure/Makefile modified: src/migtd/Cargo.toml modified: src/migtd/src/bin/migtd/main.rs modified: src/migtd/src/migration/logging.rs modified: src/migtd/src/migration/session.rs
1 parent 1f732f9 commit 2d70988

File tree

5 files changed

+109
-251
lines changed

5 files changed

+109
-251
lines changed

‎sh_script/Azure/Makefile‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -65,7 +65,7 @@ generate-hash:
6565

6666
build-igvm:
6767
cd ../../ && cargo image --no-default-features --features $(IGVM_FEATURES_GET_QUOTE) --log-level $(LOG_LEVEL) \
68-
--image-format igvm --output $(IGVM_FILE)
68+
--image-format igvm --output $(IGVM_FILE) --debug
6969

7070
build-igvm-all: pre-build build-igvm generate-hash
7171

‎src/migtd/Cargo.toml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ chrono = { version = "0.4", default-features = false, features = ["alloc"] }
2323
crypto = { path = "../crypto" }
2424
futures-util = { version = "0.3.17", default-features = false }
2525
lazy_static = { version = "1.0", features = ["spin_no_std"] }
26-
log = { version = "0.4.29", features = ["kv", "release_max_level_off"] }
26+
log = { version = "0.4.29", features = ["kv"] }
2727
pci = { path="../devices/pci" }
2828
policy = {path = "../policy"}
2929
rust_std_stub = { path = "../std-support/rust-std-stub" }

‎src/migtd/src/bin/migtd/main.rs‎

Lines changed: 33 additions & 82 deletions
Original file line numberDiff line numberDiff line change
@@ -10,8 +10,6 @@ extern crate alloc;
1010
use core::future::poll_fn;
1111
use core::task::Poll;
1212

13-
#[cfg(feature = "vmcall-raw")]
14-
use alloc::format;
1513
#[cfg(feature = "policy_v2")]
1614
use alloc::string::String;
1715
use alloc::vec::Vec;
@@ -53,6 +51,7 @@ impl TdInfoAsBytes for tdreport::TdInfo {
5351
}
5452
}
5553
}
54+
5655
#[cfg(feature = "vmcall-raw")]
5756
fn dump_td_info_and_hash() {
5857
let td_report =
@@ -98,13 +97,20 @@ fn main() {
9897
}
9998

10099
pub fn runtime_main() {
101-
// Initialize logging with level filter. The actual log level is determined by
102-
// compile-time feature flags.
103-
let _ = td_logger::init(LevelFilter::Trace);
100+
#[cfg(not(feature = "vmcall-raw"))]
101+
{
102+
// Initialize logging with level filter. The actual log level is determined by
103+
// compile-time feature flags.
104+
let _ = td_logger::init(LevelFilter::Trace);
105+
}
104106

105107
// Create LogArea per vCPU
106108
#[cfg(feature = "vmcall-raw")]
107109
{
110+
let result = init_vmm_logger();
111+
if result.is_err() {
112+
panic!("Failed to initialize VMM logger");
113+
}
108114
let _ = create_logarea();
109115
}
110116

@@ -126,7 +132,7 @@ pub fn runtime_main() {
126132

127133
#[cfg(feature = "vmcall-raw")]
128134
{
129-
info!("log::max_level() = {}\n", log::max_level());
135+
log::info!("log::max_level() = {}\n", log::max_level());
130136
if log::max_level() >= Level::Debug {
131137
dump_td_info_and_hash();
132138
}
@@ -421,23 +427,9 @@ fn handle_pre_mig() {
421427
.map(|_| MigrationResult::Success)
422428
.unwrap_or_else(|e| e);
423429
if status == MigrationResult::Success {
424-
entrylog(
425-
&format!("Successfully completed key exchange\n").into_bytes(),
426-
Level::Trace,
427-
wfr_info.mig_info.mig_request_id,
428-
);
429-
log::trace!("Successfully completed key exchange for wfr_info.mig_info.mig_request_id = {}\n", wfr_info.mig_info.mig_request_id);
430+
log::trace!(migration_request_id = wfr_info.mig_info.mig_request_id; "Successfully completed key exchange\n");
430431
} else {
431-
entrylog(
432-
&format!(
433-
"Failure during key exchange, status code: {:x}\n",
434-
status.clone() as u8
435-
)
436-
.into_bytes(),
437-
Level::Error,
438-
wfr_info.mig_info.mig_request_id,
439-
);
440-
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);
432+
log::error!(migration_request_id = wfr_info.mig_info.mig_request_id; "Failure during key exchange status code: {:x}\n", status.clone() as u8);
441433
}
442434
let _ = report_status(
443435
status as u8,
@@ -446,18 +438,12 @@ fn handle_pre_mig() {
446438
)
447439
.await
448440
.map_err(|e| {
449-
log::error!(
450-
"Failed to report status for StartMigration mig_request_id {}: {:?}\n",
451-
wfr_info.mig_info.mig_request_id,
441+
log::error!( migration_request_id = wfr_info.mig_info.mig_request_id;
442+
"Failed to report status {:?}\n",
452443
e
453444
);
454445
});
455-
entrylog(
456-
&format!("ReportStatus for key exchange completed\n").into_bytes(),
457-
Level::Trace,
458-
wfr_info.mig_info.mig_request_id,
459-
);
460-
log::trace!("ReportStatus for key exchange completed for wfr_info.mig_info.mig_request_id = {}\n", wfr_info.mig_info.mig_request_id);
446+
log::trace!(migration_request_id = wfr_info.mig_info.mig_request_id; "ReportStatus for key exchange completed\n");
461447
REQUESTS.lock().remove(&wfr_info.mig_info.mig_request_id);
462448
}
463449
WaitForRequestResponse::GetTdReport(wfr_info) => {
@@ -470,32 +456,13 @@ fn handle_pre_mig() {
470456
.map(|_| MigrationResult::Success)
471457
.unwrap_or_else(|e| e);
472458
if status == MigrationResult::Success {
473-
entrylog(
474-
&format!("Successfully completed get TDREPORT\n").into_bytes(),
475-
Level::Trace,
476-
wfr_info.mig_request_id,
477-
);
478-
log::trace!("Successfully completed get TDREPORT for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id);
459+
log::trace!(migration_request_id = wfr_info.mig_request_id; "Successfully completed get TDREPORT\n");
479460
} else {
480-
entrylog(
481-
&format!(
482-
"Failure during get TDREPORT, status code: {:x}\n",
483-
status.clone() as u8
484-
)
485-
.into_bytes(),
486-
Level::Error,
487-
wfr_info.mig_request_id,
488-
);
489-
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);
461+
log::error!(migration_request_id = wfr_info.mig_request_id; "Failure during get TDREPORT status code: {:x}\n", status.clone() as u8);
490462
}
491463
let _ =
492464
report_status(status as u8, wfr_info.mig_request_id, &data).await;
493-
entrylog(
494-
&format!("ReportStatus for get TDREPORT completed\n").into_bytes(),
495-
Level::Trace,
496-
wfr_info.mig_request_id,
497-
);
498-
log::trace!("ReportStatus for get TDREPORT completed for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id);
465+
log::trace!(migration_request_id = wfr_info.mig_request_id; "ReportStatus for get TDREPORT completed.\n");
499466
REQUESTS.lock().remove(&wfr_info.mig_request_id);
500467
}
501468
WaitForRequestResponse::EnableLogArea(wfr_info) => {
@@ -507,43 +474,27 @@ fn handle_pre_mig() {
507474
.await
508475
.map(|_| MigrationResult::Success)
509476
.unwrap_or_else(|e| e);
477+
478+
log::info!( migration_request_id = wfr_info.mig_request_id;
479+
"Setting log level to {}\n",
480+
wfr_info.log_max_level
481+
);
482+
log::set_max_level(u8_to_levelfilter(wfr_info.log_max_level));
483+
510484
if status == MigrationResult::Success {
511-
entrylog(
512-
&format!("Successfully completed Enable LogArea\n")
513-
.into_bytes(),
514-
Level::Trace,
515-
wfr_info.mig_request_id,
516-
);
517-
log::trace!("Successfully completed Enable LogArea for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id);
485+
log::trace!(migration_request_id = wfr_info.mig_request_id; "Successfully completed Enable LogArea\n");
518486
} else {
519-
entrylog(
520-
&format!(
521-
"Failure during Enable LogArea, status code: {:x}\n",
522-
status.clone() as u8
523-
)
524-
.into_bytes(),
525-
Level::Error,
526-
wfr_info.mig_request_id,
527-
);
528-
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);
487+
log::error!(migration_request_id = wfr_info.mig_request_id; "Failure during Enable LogArea status code: {:x}\n", status.clone() as u8);
529488
}
530-
let _ =
531-
report_status(status as u8, wfr_info.mig_request_id, &data)
489+
let _ = report_status(status as u8, wfr_info.mig_request_id, &data)
532490
.await
533491
.map_err(|e| {
534-
log::error!(
535-
"Failed to report status for Enable LogArea mig_request_id {}: {:?}\n",
536-
wfr_info.mig_request_id,
492+
log::error!( migration_request_id = wfr_info.mig_request_id;
493+
"Failed to report status for Enable LogArea {:?}\n",
537494
e
538495
);
539496
});
540-
entrylog(
541-
&format!("ReportStatus for Enable LogArea completed\n")
542-
.into_bytes(),
543-
Level::Trace,
544-
wfr_info.mig_request_id,
545-
);
546-
log::trace!("ReportStatus for Enable LogArea completed for wfr_info.mig_request_id = {}\n", wfr_info.mig_request_id);
497+
log::trace!(migration_request_id = wfr_info.mig_request_id; "ReportStatus for Enable LogArea completed\n");
547498
REQUESTS.lock().remove(&wfr_info.mig_request_id);
548499
}
549500
}

‎src/migtd/src/migration/logging.rs‎

Lines changed: 42 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,17 @@ const PAGE_SIZE: usize = 0x1_000;
2626
const TDCALL_STATUS_SUCCESS: u64 = 0;
2727
const MIGRATION_REQUEST_ID_SENTINEL: u64 = 0xFFFF_FFFF_FFFF_FFFF;
2828

29+
pub fn u8_to_levelfilter(value: u8) -> LevelFilter {
30+
match value {
31+
0 => LevelFilter::Off,
32+
1 => LevelFilter::Error,
33+
2 => LevelFilter::Warn,
34+
3 => LevelFilter::Info,
35+
4 => LevelFilter::Debug,
36+
5 | _ => LevelFilter::Trace,
37+
}
38+
}
39+
2940
type Result<T> = core::result::Result<T, MigrationResult>;
3041

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

199-
log::info!(
210+
log::info!( migration_request_id = request_id;
200211
"enable_logarea: Logging has been enabled with MaxLevel: {}\n",
201212
log_max_level
202213
);
203-
entrylog(
204-
&format!(
205-
"enable_logarea: Logging has been enabled with MaxLevel: {}\n",
206-
log_max_level
207-
)
208-
.into_bytes(),
209-
Level::Info,
210-
request_id,
211-
);
212214
}
213215
#[cfg(test)]
214216
{
@@ -236,10 +238,9 @@ pub async fn enable_logarea(log_max_level: u8, request_id: u64, data: &mut Vec<u
236238
}
237239
Ok(())
238240
} else {
239-
entrylog(
240-
&format!("enable_logarea: Invalid MaxLogLevel: {:x}\n", log_max_level).into_bytes(),
241-
Level::Error,
242-
request_id,
241+
log::error!( migration_request_id = request_id;
242+
"enable_logarea: Logging has been enabled with MaxLevel: {}\n",
243+
log_max_level
243244
);
244245
data.extend_from_slice(
245246
&format!(
@@ -492,10 +493,18 @@ pub struct VmmLoggerBackend;
492493

493494
impl log::Log for VmmLoggerBackend {
494495
fn enabled(&self, metadata: &Metadata) -> bool {
495-
let log_max_level = LOGGING_INFORMATION.maxloglevel.load(Ordering::SeqCst);
496-
let log_level = loglevel_to_u8(metadata.level());
497-
498496
// Enable if logging is configured and level is appropriate
497+
let mut log_max_level = log::max_level();
498+
499+
let logarea_initialized = LOGGING_INFORMATION
500+
.logarea_initialized
501+
.load(Ordering::SeqCst);
502+
if logarea_initialized {
503+
log_max_level =
504+
u8_to_levelfilter(LOGGING_INFORMATION.maxloglevel.load(Ordering::SeqCst));
505+
}
506+
507+
let log_level = metadata.level();
499508
log_level <= log_max_level
500509
}
501510

@@ -515,14 +524,22 @@ impl log::Log for VmmLoggerBackend {
515524
entrylog(&msg.into_bytes(), record.level(), mig_request_id);
516525

517526
// Also output to debug console for development (skip in test mode to avoid issues)
518-
#[cfg(not(test))]
519-
if mig_request_id != MIGRATION_REQUEST_ID_SENTINEL {
520-
td_logger::dbg_write_string(&format!(
521-
"{} - [req_id: {}] {}\n",
522-
record.level(),
523-
mig_request_id,
524-
record.args()
525-
));
527+
#[cfg(all(not(test), debug_assertions))]
528+
{
529+
if mig_request_id != MIGRATION_REQUEST_ID_SENTINEL {
530+
td_logger::dbg_write_string(&format!(
531+
"{} - [req_id: {}] {}\n",
532+
record.level(),
533+
mig_request_id,
534+
record.args()
535+
));
536+
} else {
537+
td_logger::dbg_write_string(&format!(
538+
"{} - {}\n",
539+
record.level(),
540+
record.args()
541+
));
542+
}
526543
}
527544
}
528545
}

0 commit comments

Comments
 (0)