diff --git a/Cargo.lock b/Cargo.lock index 261782df5..6a5aba988 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1417,6 +1417,7 @@ dependencies = [ "spin", "thiserror 2.0.18", "tracing", + "tracing-core", ] [[package]] diff --git a/src/hyperlight_common/Cargo.toml b/src/hyperlight_common/Cargo.toml index 880e40185..951676cf6 100644 --- a/src/hyperlight_common/Cargo.toml +++ b/src/hyperlight_common/Cargo.toml @@ -22,6 +22,7 @@ tracing = { version = "0.1.44", optional = true } arbitrary = {version = "1.4.2", optional = true, features = ["derive"]} spin = "0.10.0" thiserror = { version = "2.0.18", default-features = false } +tracing-core = { version = "0.1.36", default-features = false } [features] default = ["tracing"] diff --git a/src/hyperlight_common/src/lib.rs b/src/hyperlight_common/src/lib.rs index 478aeef8b..bcfbf6cce 100644 --- a/src/hyperlight_common/src/lib.rs +++ b/src/hyperlight_common/src/lib.rs @@ -30,6 +30,9 @@ mod flatbuffers; // cbindgen:ignore pub mod layout; +// cbindgen:ignore +pub mod log_level; + /// cbindgen:ignore pub mod mem; diff --git a/src/hyperlight_common/src/log_level.rs b/src/hyperlight_common/src/log_level.rs new file mode 100644 index 000000000..668958ada --- /dev/null +++ b/src/hyperlight_common/src/log_level.rs @@ -0,0 +1,184 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +/// This type is a unified definition of log level filters between the guest and host. +/// +/// This is needed because currently the guest uses both the `log` and `tracing` crates, +/// and needs each type of `LevelFilter` from both crates. +/// +/// To avoid as much as possible the amount of conversions between the two types, we define a +/// single type that can be converted to both `log::LevelFilter` and `tracing_core::LevelFilter`. +/// NOTE: This also takes care of the fact that the `tracing` and `log` enum types for the log +/// levels are not guaranteed to have the same discriminants, so we can't just cast between them. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum GuestLogFilter { + Off, + Error, + Warn, + Info, + Debug, + Trace, +} + +impl From for tracing_core::LevelFilter { + fn from(filter: GuestLogFilter) -> Self { + match filter { + GuestLogFilter::Off => tracing_core::LevelFilter::OFF, + GuestLogFilter::Error => tracing_core::LevelFilter::ERROR, + GuestLogFilter::Warn => tracing_core::LevelFilter::WARN, + GuestLogFilter::Info => tracing_core::LevelFilter::INFO, + GuestLogFilter::Debug => tracing_core::LevelFilter::DEBUG, + GuestLogFilter::Trace => tracing_core::LevelFilter::TRACE, + } + } +} + +impl From for log::LevelFilter { + fn from(filter: GuestLogFilter) -> Self { + match filter { + GuestLogFilter::Off => log::LevelFilter::Off, + GuestLogFilter::Error => log::LevelFilter::Error, + GuestLogFilter::Warn => log::LevelFilter::Warn, + GuestLogFilter::Info => log::LevelFilter::Info, + GuestLogFilter::Debug => log::LevelFilter::Debug, + GuestLogFilter::Trace => log::LevelFilter::Trace, + } + } +} + +/// Used by the host to convert a [`tracing_core::LevelFilter`] to the intermediary [`GuestLogFilter`] +/// filter that is later converted to `u64` and passed to the guest via the C API. +impl From for GuestLogFilter { + fn from(value: tracing_core::LevelFilter) -> Self { + match value { + tracing_core::LevelFilter::OFF => Self::Off, + tracing_core::LevelFilter::ERROR => Self::Error, + tracing_core::LevelFilter::WARN => Self::Warn, + tracing_core::LevelFilter::INFO => Self::Info, + tracing_core::LevelFilter::DEBUG => Self::Debug, + tracing_core::LevelFilter::TRACE => Self::Trace, + } + } +} + +/// Used by the guest to convert a `u64` value passed from the host via the C API to the +/// intermediary [`GuestLogFilter`] filter that is later converted to both +/// `tracing_core::LevelFilter` and `log::LevelFilter`. +impl TryFrom for GuestLogFilter { + type Error = (); + + fn try_from(value: u64) -> Result>::Error> { + match value { + 0 => Ok(Self::Off), + 1 => Ok(Self::Error), + 2 => Ok(Self::Warn), + 3 => Ok(Self::Info), + 4 => Ok(Self::Debug), + 5 => Ok(Self::Trace), + _ => Err(()), + } + } +} + +/// Used by the host to convert the [`GuestLogFilter`] to a `u64` that is passed to the guest via +/// the C API. +impl From for u64 { + fn from(value: GuestLogFilter) -> Self { + match value { + GuestLogFilter::Off => 0, + GuestLogFilter::Error => 1, + GuestLogFilter::Warn => 2, + GuestLogFilter::Info => 3, + GuestLogFilter::Debug => 4, + GuestLogFilter::Trace => 5, + } + } +} + +#[cfg(test)] +mod tests { + use super::GuestLogFilter; + + #[test] + fn guest_log_filter_u64_roundtrip() { + let variants = [ + GuestLogFilter::Off, + GuestLogFilter::Error, + GuestLogFilter::Warn, + GuestLogFilter::Info, + GuestLogFilter::Debug, + GuestLogFilter::Trace, + ]; + + for variant in variants { + let as_u64: u64 = variant.into(); + let back = + GuestLogFilter::try_from(as_u64).expect("conversion from u64 should succeed"); + assert_eq!(variant, back); + } + } + + #[test] + fn guest_log_filter_tracing_roundtrip() { + let variants = [ + GuestLogFilter::Off, + GuestLogFilter::Error, + GuestLogFilter::Warn, + GuestLogFilter::Info, + GuestLogFilter::Debug, + GuestLogFilter::Trace, + ]; + + for variant in variants { + let tracing_filter: tracing_core::LevelFilter = variant.into(); + let back: GuestLogFilter = tracing_filter.into(); + assert_eq!(variant, back); + } + } + + #[test] + fn guest_log_filter_log_conversion() { + let variants = [ + GuestLogFilter::Off, + GuestLogFilter::Error, + GuestLogFilter::Warn, + GuestLogFilter::Info, + GuestLogFilter::Debug, + GuestLogFilter::Trace, + ]; + + let log_variants = [ + log::LevelFilter::Off, + log::LevelFilter::Error, + log::LevelFilter::Warn, + log::LevelFilter::Info, + log::LevelFilter::Debug, + log::LevelFilter::Trace, + ]; + + for (variant, log_variant) in variants.into_iter().zip(log_variants) { + let log_filter = log::LevelFilter::from(variant); + assert_eq!(log_filter, log_variant); + } + } + + #[test] + fn guest_log_filter_try_from_u64_rejects_invalid() { + // Any value outside the defined range [0, 5] should be rejected. + assert!(GuestLogFilter::try_from(u64::MAX).is_err()); + assert!(GuestLogFilter::try_from(6).is_err()); + } +} diff --git a/src/hyperlight_guest/src/guest_handle/host_comm.rs b/src/hyperlight_guest/src/guest_handle/host_comm.rs index da92a8e71..c72de8a3f 100644 --- a/src/hyperlight_guest/src/guest_handle/host_comm.rs +++ b/src/hyperlight_guest/src/guest_handle/host_comm.rs @@ -65,6 +65,7 @@ impl GuestHandle { /// /// When calling `call_host_function`, this function is called /// internally to get the return value. + #[instrument(skip_all, level = "Trace")] pub fn get_host_return_value>(&self) -> Result { let inner = self .try_pop_shared_input_data_into::() @@ -106,6 +107,7 @@ impl GuestHandle { /// /// Note: The function return value must be obtained by calling /// `get_host_return_value`. + #[instrument(skip_all, level = "Trace")] pub fn call_host_function_without_returning_result( &self, function_name: &str, @@ -139,7 +141,7 @@ impl GuestHandle { /// sends it to the host, and then retrieves the return value. /// /// The return value is deserialized into the specified type `T`. - #[instrument(skip_all, level = "Trace")] + #[instrument(skip_all, level = "Info")] pub fn call_host_function>( &self, function_name: &str, diff --git a/src/hyperlight_guest/src/guest_handle/io.rs b/src/hyperlight_guest/src/guest_handle/io.rs index 4c7f1b819..46c1d68f6 100644 --- a/src/hyperlight_guest/src/guest_handle/io.rs +++ b/src/hyperlight_guest/src/guest_handle/io.rs @@ -20,14 +20,14 @@ use core::any::type_name; use core::slice::from_raw_parts_mut; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; -use tracing::{Span, instrument}; +use tracing::instrument; use super::handle::GuestHandle; use crate::error::{HyperlightGuestError, Result}; impl GuestHandle { /// Pops the top element from the shared input data buffer and returns it as a T - #[instrument(skip_all, parent = Span::current(), level= "Trace")] + #[instrument(skip_all, level = "Trace")] pub fn try_pop_shared_input_data_into(&self) -> Result where T: for<'a> TryFrom<&'a [u8]>, diff --git a/src/hyperlight_guest_bin/src/guest_function/call.rs b/src/hyperlight_guest_bin/src/guest_function/call.rs index 4287a125f..ebadda540 100644 --- a/src/hyperlight_guest_bin/src/guest_function/call.rs +++ b/src/hyperlight_guest_bin/src/guest_function/call.rs @@ -22,11 +22,11 @@ use hyperlight_common::flatbuffer_wrappers::function_call::{FunctionCall, Functi use hyperlight_common::flatbuffer_wrappers::function_types::{FunctionCallResult, ParameterType}; use hyperlight_common::flatbuffer_wrappers::guest_error::{ErrorCode, GuestError}; use hyperlight_guest::error::{HyperlightGuestError, Result}; -use tracing::{Span, instrument}; +use tracing::instrument; use crate::{GUEST_HANDLE, REGISTERED_GUEST_FUNCTIONS}; -#[instrument(skip_all, parent = Span::current(), level= "Trace")] +#[instrument(skip_all, level = "Info")] pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result> { // Validate this is a Guest Function Call if function_call.function_call_type() != FunctionCallType::Guest { diff --git a/src/hyperlight_guest_bin/src/guest_logger.rs b/src/hyperlight_guest_bin/src/guest_logger.rs index c4223d7ea..7ff3d97fc 100644 --- a/src/hyperlight_guest_bin/src/guest_logger.rs +++ b/src/hyperlight_guest_bin/src/guest_logger.rs @@ -24,11 +24,11 @@ use crate::GUEST_HANDLE; // this is private on purpose so that `log` can only be called though the `log!` macros. struct GuestLogger {} -pub(crate) fn init_logger(level: LevelFilter) { +pub(crate) fn init_logger(filter: LevelFilter) { // if this `expect` fails we have no way to recover anyway, so we actually prefer a panic here // below temporary guest logger is promoted to static by the compiler. log::set_logger(&GuestLogger {}).expect("unable to setup guest logger"); - log::set_max_level(level); + log::set_max_level(filter); } impl log::Log for GuestLogger { diff --git a/src/hyperlight_guest_bin/src/lib.rs b/src/hyperlight_guest_bin/src/lib.rs index 5aee17f5c..04d7b117a 100644 --- a/src/hyperlight_guest_bin/src/lib.rs +++ b/src/hyperlight_guest_bin/src/lib.rs @@ -25,12 +25,12 @@ use buddy_system_allocator::LockedHeap; use guest_function::register::GuestFunctionRegister; use guest_logger::init_logger; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; +use hyperlight_common::log_level::GuestLogFilter; use hyperlight_common::mem::HyperlightPEB; #[cfg(feature = "mem_profile")] use hyperlight_common::outb::OutBAction; use hyperlight_guest::exit::write_abort; use hyperlight_guest::guest_handle::handle::GuestHandle; -use log::LevelFilter; // === Modules === #[cfg_attr(target_arch = "x86_64", path = "arch/amd64/mod.rs")] @@ -215,15 +215,17 @@ pub(crate) extern "C" fn generic_init( } // set up the logger - let max_log_level = LevelFilter::iter() - .nth(max_log_level as usize) - .expect("Invalid log level"); - init_logger(max_log_level); + let guest_log_level_filter = + GuestLogFilter::try_from(max_log_level).expect("Invalid log level"); + init_logger(guest_log_level_filter.into()); // It is important that all the tracing events are produced after the tracing is initialized. #[cfg(feature = "trace_guest")] - if max_log_level != LevelFilter::Off { - hyperlight_guest_tracing::init_guest_tracing(guest_start_tsc); + if guest_log_level_filter != GuestLogFilter::Off { + hyperlight_guest_tracing::init_guest_tracing( + guest_start_tsc, + guest_log_level_filter.into(), + ); } // Open a span to partly capture the initialization of the guest. diff --git a/src/hyperlight_guest_tracing/src/lib.rs b/src/hyperlight_guest_tracing/src/lib.rs index 36a5906b4..c04c8b41d 100644 --- a/src/hyperlight_guest_tracing/src/lib.rs +++ b/src/hyperlight_guest_tracing/src/lib.rs @@ -48,6 +48,7 @@ mod trace { use alloc::sync::{Arc, Weak}; use spin::Mutex; + use tracing_core::LevelFilter; use crate::state::GuestState; use crate::subscriber::GuestSubscriber; @@ -61,12 +62,12 @@ mod trace { static GUEST_STATE: spin::Once>> = spin::Once::new(); /// Initialize the guest tracing subscriber as global default. - pub fn init_guest_tracing(guest_start_tsc: u64) { + pub fn init_guest_tracing(guest_start_tsc: u64, max_log_level: LevelFilter) { // Set as global default if not already set. if tracing_core::dispatcher::has_been_set() { return; } - let sub = GuestSubscriber::new(guest_start_tsc); + let sub = GuestSubscriber::new(guest_start_tsc, max_log_level); let state = sub.state(); // Store state Weak to use later at runtime GUEST_STATE.call_once(|| Arc::downgrade(state)); diff --git a/src/hyperlight_guest_tracing/src/subscriber.rs b/src/hyperlight_guest_tracing/src/subscriber.rs index e36f71c59..667c4e696 100644 --- a/src/hyperlight_guest_tracing/src/subscriber.rs +++ b/src/hyperlight_guest_tracing/src/subscriber.rs @@ -20,7 +20,7 @@ use alloc::sync::Arc; use spin::Mutex; use tracing_core::span::{Attributes, Id, Record}; use tracing_core::subscriber::Subscriber; -use tracing_core::{Event, Metadata}; +use tracing_core::{Event, LevelFilter, Metadata}; use crate::state::GuestState; @@ -31,22 +31,29 @@ pub(crate) struct GuestSubscriber { /// A reference to this state is stored in a static variable /// so it can be accessed from the guest tracing API state: Arc>, + /// Maximum log level to record + max_log_level: LevelFilter, } impl GuestSubscriber { - pub(crate) fn new(guest_start_tsc: u64) -> Self { + /// Creates a new `GuestSubscriber` with the given guest start TSC and maximum log level + pub(crate) fn new(guest_start_tsc: u64, filter: LevelFilter) -> Self { Self { state: Arc::new(Mutex::new(GuestState::new(guest_start_tsc))), + max_log_level: filter, } } + /// Returns a reference to the internal state of the subscriber + /// This is used to access the spans and events collected by the subscriber pub(crate) fn state(&self) -> &Arc> { &self.state } } impl Subscriber for GuestSubscriber { - fn enabled(&self, _md: &Metadata<'_>) -> bool { - true + fn enabled(&self, md: &Metadata<'_>) -> bool { + // Check if the metadata level is less than or equal to the maximum log level filter + md.level() <= &self.max_log_level } fn new_span(&self, attrs: &Attributes<'_>) -> Id { diff --git a/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs b/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs index 93cdd1216..80298a79e 100644 --- a/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs +++ b/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs @@ -18,6 +18,7 @@ limitations under the License. use std::collections::HashMap; #[cfg(crashdump)] use std::path::Path; +use std::str::FromStr; #[cfg(any(kvm, mshv3))] use std::sync::atomic::AtomicBool; use std::sync::atomic::AtomicU8; @@ -25,8 +26,9 @@ use std::sync::atomic::AtomicU8; use std::sync::atomic::AtomicU64; use std::sync::{Arc, Mutex}; -use log::LevelFilter; +use hyperlight_common::log_level::GuestLogFilter; use tracing::{Span, instrument}; +use tracing_core::LevelFilter; #[cfg(gdb)] use super::gdb::arch::VcpuStopReasonError; @@ -59,7 +61,7 @@ use crate::hypervisor::virtual_machine::{ HypervisorType, MapMemoryError, RegisterError, RunVcpuError, UnmapMemoryError, VmError, VmExit, get_available_hypervisor, }; -use crate::hypervisor::{InterruptHandle, InterruptHandleImpl, get_max_log_level}; +use crate::hypervisor::{InterruptHandle, InterruptHandleImpl}; use crate::mem::memory_region::{MemoryRegion, MemoryRegionFlags, MemoryRegionType}; use crate::mem::mgr::SandboxMemoryManager; use crate::mem::ptr::RawPtr; @@ -74,6 +76,69 @@ use crate::sandbox::trace::MemTraceInfo; #[cfg(crashdump)] use crate::sandbox::uninitialized::SandboxRuntimeConfig; +/// Get the logging level filter to pass to the guest entrypoint +/// +/// The guest entrypoint uses this to determine the maximum log level to enable for the guest. +/// The `RUST_LOG` environment variable is expected to be in the format of comma-separated +/// key-value pairs, where the key is a log target (e.g., "hyperlight_guest_bin") and the value is +/// a log level (e.g., "debug"). +/// +/// NOTE: This prioritizes the log level for the targets containing "hyperlight_guest" string, then +/// "hyperlight_host", and then general log level. If none of these targets are found, it +/// defaults to "error". +fn get_max_log_level_filter(rust_log: String) -> LevelFilter { + // This is done as the guest will produce logs based on the log level returned here + // producing those logs is expensive and we don't want to do it if the host is not + // going to process them + let level_str = rust_log + .split(',') + // Prioritize targets containing "hyperlight_guest" + .find_map(|part| { + let mut kv = part.splitn(2, '='); + match (kv.next(), kv.next()) { + (Some(k), Some(v)) if k.trim().contains("hyperlight_guest") => Some(v.trim()), + _ => None, + } + }) + // Then check for "hyperlight_host" + .or_else(|| { + rust_log.split(',').find_map(|part| { + let mut kv = part.splitn(2, '='); + match (kv.next(), kv.next()) { + (Some(k), Some(v)) if k.trim().contains("hyperlight_host") => Some(v.trim()), + _ => None, + } + }) + }) + // Finally, check for general log level + .or_else(|| { + rust_log.split(',').find_map(|part| { + if part.contains("=") { + None + } else { + Some(part.trim()) + } + }) + }) + .unwrap_or(""); + + tracing::info!("Determined guest log level: {}", level_str); + + // If no value is found, default to Error + LevelFilter::from_str(level_str).unwrap_or(LevelFilter::ERROR) +} + +/// Converts a given [`Option`] to a `u64` value to be passed to the guest entrypoint +/// If the provided filter is `None`, it uses the `RUST_LOG` environment variable to determine the +/// maximum log level filter for the guest and converts it to a `u64` value. +fn get_guest_log_filter(guest_max_log_level: Option) -> u64 { + let guest_log_level_filter = match guest_max_log_level { + Some(level) => level, + None => get_max_log_level_filter(std::env::var("RUST_LOG").unwrap_or_default()), + }; + GuestLogFilter::from(guest_log_level_filter).into() +} + /// Represents a Hyperlight Virtual Machine instance. /// /// This struct manages the lifecycle of the VM, including: @@ -477,11 +542,6 @@ impl HyperlightVm { self.page_size = page_size as usize; - let guest_max_log_level: u64 = match guest_max_log_level { - Some(level) => level as u64, - None => get_max_log_level().into(), - }; - let regs = CommonRegisters { rip: initialise, // We usually keep the top of the stack 16-byte @@ -496,7 +556,7 @@ impl HyperlightVm { rdi: peb_addr.into(), rsi: seed, rdx: page_size.into(), - rcx: guest_max_log_level, + rcx: get_guest_log_filter(guest_max_log_level), rflags: 1 << 1, ..Default::default() @@ -2816,4 +2876,104 @@ mod tests { FxsaveTestContext { ctx, fxsave_offset } } } + + /// ======================================================================== + /// Misc tests + /// ======================================================================== + #[test] + fn test_get_max_log_level_filter_both_guest_and_host() { + let rust_log = "hyperlight_guest=trace,hyperlight_host=debug".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::TRACE, "Max log level should be Trace"); + } + #[test] + fn test_get_max_log_level_filter_only_guest() { + let rust_log = "hyperlight_guest=info".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::INFO, "Max log level should be Info"); + } + #[test] + fn test_get_max_log_level_filter_only_host() { + let rust_log = "hyperlight_host=debug".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::DEBUG, "Max log level should be Debug"); + } + #[test] + fn test_get_max_log_level_filter_only_general() { + let rust_log = "trace".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::TRACE, "Max log level should be Trace"); + } + #[test] + fn test_get_max_log_level_filter_complex_rust_log_00() { + let rust_log = + "error,hyperlight_guest=debug,hyperlight_host=info,hyperlight_guest_bin=trace" + .to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::DEBUG, "Max log level should be Debug"); + } + #[test] + fn test_get_max_log_level_filter_complex_rust_log_01() { + let rust_log = + "error,hyperlight_host=info,hyperlight_guest=debug,hyperlight_guest_bin=trace" + .to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::DEBUG, "Max log level should be Debug"); + } + #[test] + fn test_get_max_log_level_filter_complex_rust_log_02() { + let rust_log = + "hyperlight_host=info,error,hyperlight_guest=debug,hyperlight_guest_bin=trace" + .to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::DEBUG, "Max log level should be Debug"); + } + #[test] + fn test_get_max_log_level_filter_general_and_others() { + let rust_log = + "trace,hyperlight_component_macro=debug,hyperlight_component_util=error".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!(filter, LevelFilter::TRACE, "Max log level should be Trace"); + } + #[test] + fn test_get_max_log_level_filter_default() { + let rust_log = "hyperlight_common=debug,hyperlight_component_util=info".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!( + filter, + LevelFilter::ERROR, + "Max log level should default to Error" + ); + } + #[test] + fn test_get_max_log_level_filter_invalid_rust_log() { + let rust_log = "this is an invalid rust log string".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!( + filter, + LevelFilter::ERROR, + "Max log level should default to Error" + ); + } + #[test] + fn test_get_max_log_level_filter_empty_rust_log() { + let rust_log = "".to_string(); + let filter = get_max_log_level_filter(rust_log); + + assert_eq!( + filter, + LevelFilter::ERROR, + "Max log level should default to Error" + ); + } } diff --git a/src/hyperlight_host/src/hypervisor/mod.rs b/src/hyperlight_host/src/hypervisor/mod.rs index 66a5a8cd5..ddc3da3ee 100644 --- a/src/hyperlight_host/src/hypervisor/mod.rs +++ b/src/hyperlight_host/src/hypervisor/mod.rs @@ -14,8 +14,6 @@ See the License for the specific language governing permissions and limitations under the License. */ -use log::LevelFilter; - /// GDB debugging support #[cfg(gdb)] pub(crate) mod gdb; @@ -41,7 +39,6 @@ pub(crate) mod crashdump; pub(crate) mod hyperlight_vm; use std::fmt::Debug; -use std::str::FromStr; #[cfg(any(kvm, mshv3))] use std::sync::atomic::{AtomicBool, AtomicU8, AtomicU64, Ordering}; #[cfg(target_os = "windows")] @@ -49,43 +46,6 @@ use std::sync::atomic::{AtomicU8, Ordering}; #[cfg(any(kvm, mshv3))] use std::time::Duration; -/// Get the logging level to pass to the guest entrypoint -fn get_max_log_level() -> u32 { - // Check to see if the RUST_LOG environment variable is set - // and if so, parse it to get the log_level for hyperlight_guest - // if that is not set get the log level for the hyperlight_host - - // This is done as the guest will produce logs based on the log level returned here - // producing those logs is expensive and we don't want to do it if the host is not - // going to process them - - let val = std::env::var("RUST_LOG").unwrap_or_default(); - - let level = if val.contains("hyperlight_guest") { - val.split(',') - .find(|s| s.contains("hyperlight_guest")) - .unwrap_or("") - .split('=') - .nth(1) - .unwrap_or("") - } else if val.contains("hyperlight_host") { - val.split(',') - .find(|s| s.contains("hyperlight_host")) - .unwrap_or("") - .split('=') - .nth(1) - .unwrap_or("") - } else { - // look for a value string that does not contain "=" - val.split(',').find(|s| !s.contains("=")).unwrap_or("") - }; - - log::info!("Determined guest log level: {}", level); - // Convert the log level string to a LevelFilter - // If no value is found, default to Error - LevelFilter::from_str(level).unwrap_or(LevelFilter::Error) as u32 -} - /// A trait for platform-specific interrupt handle implementation details pub(crate) trait InterruptHandleImpl: InterruptHandle { /// Set the thread ID for the vcpu thread @@ -543,7 +503,7 @@ pub(crate) mod tests { let seed = 12345u64; // Random seed let page_size = 4096u32; // Standard page size let host_funcs = Arc::new(Mutex::new(FunctionRegistry::default())); - let guest_max_log_level = Some(log::LevelFilter::Error); + let guest_max_log_level = Some(tracing_core::LevelFilter::ERROR); #[cfg(gdb)] let dbg_mem_access_fn = Arc::new(Mutex::new(mem_mgr.clone())); diff --git a/src/hyperlight_host/src/sandbox/trace/context.rs b/src/hyperlight_host/src/sandbox/trace/context.rs index 3ac89f32c..62af150b9 100644 --- a/src/hyperlight_host/src/sandbox/trace/context.rs +++ b/src/hyperlight_host/src/sandbox/trace/context.rs @@ -120,7 +120,7 @@ impl TraceContext { let current_ctx = Span::current().context(); - let span = tracing::trace_span!("call-to-guest"); + let span = tracing::info_span!("call-to-guest"); let _ = span.set_parent(current_ctx); let entered = span.entered(); @@ -369,7 +369,7 @@ impl TraceContext { } pub fn new_host_trace(&mut self, ctx: Context) { - let span = tracing::trace_span!("call-to-host"); + let span = tracing::info_span!("call-to-host"); let _ = span.set_parent(ctx); let entered = span.entered(); self.host_spans.push(entered); diff --git a/src/hyperlight_host/src/sandbox/uninitialized.rs b/src/hyperlight_host/src/sandbox/uninitialized.rs index 7c2541f82..5545bafab 100644 --- a/src/hyperlight_host/src/sandbox/uninitialized.rs +++ b/src/hyperlight_host/src/sandbox/uninitialized.rs @@ -19,8 +19,8 @@ use std::option::Option; use std::path::Path; use std::sync::{Arc, Mutex}; -use log::LevelFilter; use tracing::{Span, instrument}; +use tracing_core::LevelFilter; use super::host_funcs::{FunctionRegistry, default_writer_func}; use super::snapshot::Snapshot; diff --git a/src/hyperlight_host/tests/integration_test.rs b/src/hyperlight_host/tests/integration_test.rs index b58711958..80f997360 100644 --- a/src/hyperlight_host/tests/integration_test.rs +++ b/src/hyperlight_host/tests/integration_test.rs @@ -20,11 +20,12 @@ use std::thread; use std::time::Duration; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; +use hyperlight_common::log_level::GuestLogFilter; use hyperlight_host::sandbox::SandboxConfiguration; use hyperlight_host::{HyperlightError, MultiUseSandbox}; use hyperlight_testing::simplelogger::{LOGGER, SimpleLogger}; -use log::LevelFilter; use serial_test::serial; +use tracing_core::LevelFilter; pub mod common; // pub to disable dead_code warning use crate::common::{ @@ -741,21 +742,26 @@ fn recursive_stack_allocate_overflow() { fn log_message() { // The magic numbers below represent the number of fixed log messages that are emitted as // follows: - // - internal_dispatch_function does a log::trace! in debug mode // - logs from trace level tracing spans created as logs because of the tracing `log` feature - // - 4 from evolve call (hyperlight_main + halt) - // - 7 from guest call + // - 4 from evolve call (generic_init + hyperlight_main) + // - 8 from guest call // and are multiplied because we make 6 calls to `log_test_messages` // NOTE: These numbers need to be updated if log messages or spans are added/removed let num_fixed_trace_log = 12 * 6; + // Calculate fixed info logs + // - 4 logs per iteration from infrastructure at Info level (internal_dispatch_function) + // (dispatch x 1 + call_guest x 1) * 2 logs (Enter/Exit) = 4 logs + // - 6 iterations + let num_fixed_info_log = 4 * 6; + let tests = vec![ - (LevelFilter::Trace, 5 + num_fixed_trace_log), - (LevelFilter::Debug, 4), - (LevelFilter::Info, 3), - (LevelFilter::Warn, 2), - (LevelFilter::Error, 1), - (LevelFilter::Off, 0), + (LevelFilter::TRACE, 5 + num_fixed_trace_log), + (LevelFilter::DEBUG, 4 + num_fixed_info_log), + (LevelFilter::INFO, 3 + num_fixed_info_log), + (LevelFilter::WARN, 2), + (LevelFilter::ERROR, 1), + (LevelFilter::OFF, 0), ]; // init @@ -793,10 +799,18 @@ fn log_message() { assert_eq!(1, LOGGER.num_log_calls()); } -fn log_test_messages(levelfilter: Option) { +fn log_test_messages(levelfilter: Option) { LOGGER.clear_log_calls(); assert_eq!(0, LOGGER.num_log_calls()); - for level in log::LevelFilter::iter() { + let filters = [ + LevelFilter::OFF, + LevelFilter::TRACE, + LevelFilter::DEBUG, + LevelFilter::INFO, + LevelFilter::WARN, + LevelFilter::ERROR, + ]; + for level in filters.iter() { // Only use Rust guest because the C guest has a different signature for LogMessage // (Long vs Int for the level parameter) with_rust_uninit_sandbox(|mut sbox| { @@ -806,6 +820,7 @@ fn log_test_messages(levelfilter: Option) { let mut sbox1 = sbox.evolve().unwrap(); + let level: u64 = GuestLogFilter::from(*level).into(); let message = format!("Hello from log_message level {}", level as i32); sbox1 .call::<()>("LogMessage", (message.to_string(), level as i32)) diff --git a/src/tests/rust_guests/dummyguest/Cargo.lock b/src/tests/rust_guests/dummyguest/Cargo.lock index f86e894fa..b9c7fa23c 100644 --- a/src/tests/rust_guests/dummyguest/Cargo.lock +++ b/src/tests/rust_guests/dummyguest/Cargo.lock @@ -89,6 +89,7 @@ dependencies = [ "log", "spin", "thiserror", + "tracing-core", ] [[package]] diff --git a/src/tests/rust_guests/simpleguest/Cargo.lock b/src/tests/rust_guests/simpleguest/Cargo.lock index 05115d62f..9950adcfb 100644 --- a/src/tests/rust_guests/simpleguest/Cargo.lock +++ b/src/tests/rust_guests/simpleguest/Cargo.lock @@ -82,6 +82,7 @@ dependencies = [ "log", "spin", "thiserror", + "tracing-core", ] [[package]] diff --git a/src/tests/rust_guests/simpleguest/src/main.rs b/src/tests/rust_guests/simpleguest/src/main.rs index fa94a3677..6d53c94c6 100644 --- a/src/tests/rust_guests/simpleguest/src/main.rs +++ b/src/tests/rust_guests/simpleguest/src/main.rs @@ -41,6 +41,7 @@ use hyperlight_common::flatbuffer_wrappers::function_types::{ use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; use hyperlight_common::flatbuffer_wrappers::guest_log_level::LogLevel; use hyperlight_common::flatbuffer_wrappers::util::get_flatbuffer_result; +use hyperlight_common::log_level::GuestLogFilter; use hyperlight_common::vmem::{BasicMapping, MappingKind}; use hyperlight_guest::error::{HyperlightGuestError, Result}; use hyperlight_guest::exit::{abort_with_code, abort_with_code_and_message}; @@ -463,10 +464,15 @@ fn test_rust_malloc(code: i32) -> i32 { #[guest_function("LogMessage")] fn log_message(message: String, level: i32) { - let level = LevelFilter::iter().nth(level as usize).unwrap().to_level(); + let level_filter = + LevelFilter::from(GuestLogFilter::try_from(level as u64).expect("Invalid log level")); + let level = level_filter.to_level(); match level { - Some(level) => log::log!(level, "{}", &message), + Some(level) => { + // Shall not fail because we have already validated the log level + log::log!(level, "{}", &message) + } None => { // was passed LevelFilter::Off, do nothing } diff --git a/src/tests/rust_guests/witguest/Cargo.lock b/src/tests/rust_guests/witguest/Cargo.lock index 37314df38..6a6225c70 100644 --- a/src/tests/rust_guests/witguest/Cargo.lock +++ b/src/tests/rust_guests/witguest/Cargo.lock @@ -187,6 +187,7 @@ dependencies = [ "log", "spin", "thiserror", + "tracing-core", ] [[package]] @@ -764,4 +765,4 @@ dependencies = [ name = "zmij" version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0f4a4e8e9dc5c62d159f04fcdbe07f4c3fb710415aab4754bf11505501e3251d" \ No newline at end of file +checksum = "0f4a4e8e9dc5c62d159f04fcdbe07f4c3fb710415aab4754bf11505501e3251d"