diff --git a/docs/hyperlight-metrics-logs-and-traces.md b/docs/hyperlight-metrics-logs-and-traces.md index 3a22e5a82..700b8117e 100644 --- a/docs/hyperlight-metrics-logs-and-traces.md +++ b/docs/hyperlight-metrics-logs-and-traces.md @@ -66,13 +66,13 @@ In the [examples/tracing](../src/hyperlight_host/examples/tracing) directory, th #### Linux ```bash -RUST_LOG='none,hyperlight-host=info,tracing=info' cargo run --example tracing +RUST_LOG='none,hyperlight_host=info,tracing=info' cargo run --example tracing ``` #### Windows ```powershell -$env:RUST_LOG='none,hyperlight-host=info,tracing=info'; cargo run --example tracing +$env:RUST_LOG='none,hyperlight_host=info,tracing=info'; cargo run --example tracing ``` ### Using OTLP exporter and Jaeger diff --git a/src/hyperlight_host/src/hypervisor/hyperv_linux.rs b/src/hyperlight_host/src/hypervisor/hyperv_linux.rs index 8c419c18b..6e1e8ec6d 100644 --- a/src/hyperlight_host/src/hypervisor/hyperv_linux.rs +++ b/src/hyperlight_host/src/hypervisor/hyperv_linux.rs @@ -26,7 +26,7 @@ extern crate mshv_ioctls3 as mshv_ioctls; use std::fmt::{Debug, Formatter}; -use log::error; +use log::{error, LevelFilter}; #[cfg(mshv2)] use mshv_bindings::hv_message; #[cfg(gdb)] @@ -463,8 +463,14 @@ impl Hypervisor for HypervLinuxDriver { outb_hdl: OutBHandlerWrapper, mem_access_hdl: MemAccessHandlerWrapper, hv_handler: Option, + max_guest_log_level: Option, #[cfg(gdb)] dbg_mem_access_fn: DbgMemAccessHandlerWrapper, ) -> Result<()> { + let max_guest_log_level: u64 = match max_guest_log_level { + Some(level) => level as u64, + None => self.get_max_log_level().into(), + }; + let regs = StandardRegisters { rip: self.entrypoint, rsp: self.orig_rsp.absolute()?, @@ -474,7 +480,7 @@ impl Hypervisor for HypervLinuxDriver { rcx: peb_addr.into(), rdx: seed, r8: page_size.into(), - r9: self.get_max_log_level().into(), + r9: max_guest_log_level, ..Default::default() }; diff --git a/src/hyperlight_host/src/hypervisor/hyperv_windows.rs b/src/hyperlight_host/src/hypervisor/hyperv_windows.rs index 6b7c621b5..47fbaaa9d 100644 --- a/src/hyperlight_host/src/hypervisor/hyperv_windows.rs +++ b/src/hyperlight_host/src/hypervisor/hyperv_windows.rs @@ -20,6 +20,7 @@ use std::fmt::{Debug, Formatter}; use std::string::String; use hyperlight_common::mem::PAGE_SIZE_USIZE; +use log::LevelFilter; use tracing::{instrument, Span}; use windows::Win32::System::Hypervisor::{ WHvX64RegisterCr0, WHvX64RegisterCr3, WHvX64RegisterCr4, WHvX64RegisterCs, WHvX64RegisterEfer, @@ -307,8 +308,14 @@ impl Hypervisor for HypervWindowsDriver { outb_hdl: OutBHandlerWrapper, mem_access_hdl: MemAccessHandlerWrapper, hv_handler: Option, + max_guest_log_level: Option, #[cfg(gdb)] dbg_mem_access_hdl: DbgMemAccessHandlerWrapper, ) -> Result<()> { + let max_guest_log_level: u64 = match max_guest_log_level { + Some(level) => level as u64, + None => self.get_max_log_level().into(), + }; + let regs = WHvGeneralRegisters { rip: self.entrypoint, rsp: self.orig_rsp.absolute()?, @@ -317,7 +324,7 @@ impl Hypervisor for HypervWindowsDriver { rcx: peb_address.into(), rdx: seed, r8: page_size.into(), - r9: self.get_max_log_level().into(), + r9: max_guest_log_level, rflags: 1 << 1, // eflags bit index 1 is reserved and always needs to be 1 ..Default::default() diff --git a/src/hyperlight_host/src/hypervisor/hypervisor_handler.rs b/src/hyperlight_host/src/hypervisor/hypervisor_handler.rs index d0fbd84b5..7b30d7c6e 100644 --- a/src/hyperlight_host/src/hypervisor/hypervisor_handler.rs +++ b/src/hyperlight_host/src/hypervisor/hypervisor_handler.rs @@ -28,7 +28,7 @@ use crossbeam::atomic::AtomicCell; use crossbeam_channel::{Receiver, Sender}; #[cfg(target_os = "linux")] use libc::{pthread_kill, pthread_self, ESRCH}; -use log::{error, info}; +use log::{error, info, LevelFilter}; use tracing::{instrument, Span}; #[cfg(target_os = "linux")] use vmm_sys_util::signal::SIGRTMIN; @@ -191,6 +191,7 @@ pub(crate) struct HvHandlerConfig { pub(crate) outb_handler: OutBHandlerWrapper, pub(crate) mem_access_handler: MemAccessHandlerWrapper, pub(crate) max_wait_for_cancellation: Duration, + pub(crate) max_guest_log_level: Option, #[cfg(gdb)] pub(crate) dbg_mem_access_handler: DbgMemAccessHandlerWrapper, } @@ -360,6 +361,7 @@ impl HypervisorHandler { configuration.outb_handler.clone(), configuration.mem_access_handler.clone(), Some(hv_handler_clone.clone()), + configuration.max_guest_log_level, #[cfg(gdb)] configuration.dbg_mem_access_handler.clone(), ); diff --git a/src/hyperlight_host/src/hypervisor/inprocess.rs b/src/hyperlight_host/src/hypervisor/inprocess.rs index 1fec3df54..0a87c30d2 100644 --- a/src/hyperlight_host/src/hypervisor/inprocess.rs +++ b/src/hyperlight_host/src/hypervisor/inprocess.rs @@ -17,6 +17,8 @@ limitations under the License. use std::fmt::Debug; use std::os::raw::c_void; +use log::LevelFilter; + #[cfg(gdb)] use super::handlers::DbgMemAccessHandlerWrapper; use super::{HyperlightExit, Hypervisor}; @@ -75,6 +77,7 @@ impl<'a> Hypervisor for InprocessDriver<'a> { _outb_handle_fn: super::handlers::OutBHandlerWrapper, _mem_access_fn: super::handlers::MemAccessHandlerWrapper, _hv_handler: Option, + _guest_max_log_level: Option, #[cfg(gdb)] _dbg_mem_access_fn: DbgMemAccessHandlerWrapper, ) -> crate::Result<()> { let entrypoint_fn: extern "win64" fn(u64, u64, u64, u64) = diff --git a/src/hyperlight_host/src/hypervisor/kvm.rs b/src/hyperlight_host/src/hypervisor/kvm.rs index 67cc8093c..e106755c5 100644 --- a/src/hyperlight_host/src/hypervisor/kvm.rs +++ b/src/hyperlight_host/src/hypervisor/kvm.rs @@ -22,6 +22,7 @@ use std::sync::{Arc, Mutex}; use kvm_bindings::{kvm_fpu, kvm_regs, kvm_userspace_memory_region, KVM_MEM_READONLY}; use kvm_ioctls::Cap::UserMemory; use kvm_ioctls::{Kvm, VcpuExit, VcpuFd, VmFd}; +use log::LevelFilter; use tracing::{instrument, Span}; use super::fpu::{FP_CONTROL_WORD_DEFAULT, FP_TAG_WORD_DEFAULT, MXCSR_DEFAULT}; @@ -406,8 +407,14 @@ impl Hypervisor for KVMDriver { outb_hdl: OutBHandlerWrapper, mem_access_hdl: MemAccessHandlerWrapper, hv_handler: Option, + max_guest_log_level: Option, #[cfg(gdb)] dbg_mem_access_fn: DbgMemAccessHandlerWrapper, ) -> Result<()> { + let max_guest_log_level: u64 = match max_guest_log_level { + Some(level) => level as u64, + None => self.get_max_log_level().into(), + }; + let regs = kvm_regs { rip: self.entrypoint, rsp: self.orig_rsp.absolute()?, @@ -416,7 +423,7 @@ impl Hypervisor for KVMDriver { rcx: peb_addr.into(), rdx: seed, r8: page_size.into(), - r9: self.get_max_log_level().into(), + r9: max_guest_log_level, ..Default::default() }; diff --git a/src/hyperlight_host/src/hypervisor/mod.rs b/src/hyperlight_host/src/hypervisor/mod.rs index 929aff0ab..bec42f350 100644 --- a/src/hyperlight_host/src/hypervisor/mod.rs +++ b/src/hyperlight_host/src/hypervisor/mod.rs @@ -14,6 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ +use log::LevelFilter; use tracing::{instrument, Span}; use crate::error::HyperlightError::ExecutionCanceledByHost; @@ -63,6 +64,7 @@ pub(crate) mod wrappers; pub(crate) mod crashdump; use std::fmt::Debug; +use std::str::FromStr; use std::sync::{Arc, Mutex}; #[cfg(gdb)] @@ -130,6 +132,7 @@ pub(crate) trait Hypervisor: Debug + Sync + Send { outb_handle_fn: OutBHandlerWrapper, mem_access_fn: MemAccessHandlerWrapper, hv_handler: Option, + guest_max_log_level: Option, #[cfg(gdb)] dbg_mem_access_fn: DbgMemAccessHandlerWrapper, ) -> Result<()>; @@ -191,7 +194,39 @@ pub(crate) trait Hypervisor: Debug + Sync + Send { /// Get the logging level to pass to the guest entrypoint fn get_max_log_level(&self) -> u32 { - log::max_level() as 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 } /// get a mutable trait object from self @@ -356,6 +391,7 @@ pub(crate) mod tests { max_wait_for_cancellation: Duration::from_millis( SandboxConfiguration::DEFAULT_MAX_WAIT_FOR_CANCELLATION as u64, ), + max_guest_log_level: None, }; let mut hv_handler = HypervisorHandler::new(hv_handler_config); diff --git a/src/hyperlight_host/src/sandbox/outb.rs b/src/hyperlight_host/src/sandbox/outb.rs index fa1c6e09c..3679cb2e9 100644 --- a/src/hyperlight_host/src/sandbox/outb.rs +++ b/src/hyperlight_host/src/sandbox/outb.rs @@ -88,7 +88,7 @@ pub(super) fn outb_log(mgr: &mut SandboxMemoryManager) -> Resu &Record::builder() .args(format_args!("{}", log_data.message)) .level(record_level) - .target("hyperlight-guest") + .target("hyperlight_guest") .file(source_file) .line(line) .module_path(source) @@ -100,7 +100,7 @@ pub(super) fn outb_log(mgr: &mut SandboxMemoryManager) -> Resu &Record::builder() .args(format_args!("{}", log_data.message)) .level(record_level) - .target("hyperlight-guest") + .target("hyperlight_guest") .file(Some(&log_data.source_file)) .line(Some(log_data.line)) .module_path(Some(&log_data.source)) @@ -442,7 +442,7 @@ mod tests { test_value_as_str(metadata_values_map, "level", expected_level); test_value_as_str(event_values_map, "log.file", "test source file"); test_value_as_str(event_values_map, "log.module_path", "test source"); - test_value_as_str(event_values_map, "log.target", "hyperlight-guest"); + test_value_as_str(event_values_map, "log.target", "hyperlight_guest"); count_matching_events += 1; } assert!( diff --git a/src/hyperlight_host/src/sandbox/uninitialized.rs b/src/hyperlight_host/src/sandbox/uninitialized.rs index ae3b5c05f..c1527a5c2 100644 --- a/src/hyperlight_host/src/sandbox/uninitialized.rs +++ b/src/hyperlight_host/src/sandbox/uninitialized.rs @@ -20,6 +20,7 @@ use std::path::Path; use std::sync::{Arc, Mutex}; use std::time::Duration; +use log::LevelFilter; use tracing::{instrument, Span}; #[cfg(gdb)] @@ -54,6 +55,7 @@ pub struct UninitializedSandbox { pub(crate) max_initialization_time: Duration, pub(crate) max_execution_time: Duration, pub(crate) max_wait_for_cancellation: Duration, + pub(crate) max_guest_log_level: Option, #[cfg(gdb)] pub(crate) debug_info: Option, } @@ -195,6 +197,7 @@ impl UninitializedSandbox { max_wait_for_cancellation: Duration::from_millis( sandbox_cfg.get_max_wait_for_cancellation() as u64, ), + max_guest_log_level: None, #[cfg(gdb)] debug_info, }; @@ -299,6 +302,13 @@ impl UninitializedSandbox { SandboxMemoryManager::load_guest_binary_into_memory(cfg, &mut exe_info, inprocess) } } + + /// Set the max log level to be used by the guest. + /// If this is not set then the log level will be determined by parsing the RUST_LOG environment variable. + /// If the RUST_LOG environment variable is not set then the max log level will be set to `LevelFilter::Error`. + pub fn set_max_guest_log_level(&mut self, log_level: LevelFilter) { + self.max_guest_log_level = Some(log_level); + } } // Check to see if the current version of Windows is supported // Hyperlight is only supported on Windows 11 and Windows Server 2022 and later diff --git a/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs b/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs index e962f0515..6ddba5e29 100644 --- a/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs +++ b/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs @@ -17,6 +17,7 @@ limitations under the License. use core::time::Duration; use std::sync::{Arc, Mutex}; +use log::LevelFilter; use rand::Rng; use tracing::{instrument, Span}; @@ -70,6 +71,7 @@ where u_sbox.max_initialization_time, u_sbox.max_execution_time, u_sbox.max_wait_for_cancellation, + u_sbox.max_guest_log_level, #[cfg(gdb)] u_sbox.debug_info, )?; @@ -99,6 +101,7 @@ pub(super) fn evolve_impl_multi_use(u_sbox: UninitializedSandbox) -> Result, gshm: SandboxMemoryManager, @@ -106,6 +109,7 @@ fn hv_init( max_init_time: Duration, max_exec_time: Duration, max_wait_for_cancellation: Duration, + max_guest_log_level: Option, #[cfg(gdb)] debug_info: Option, ) -> Result { let outb_hdl = outb_handler_wrapper(hshm.clone(), host_funcs); @@ -134,6 +138,7 @@ fn hv_init( max_init_time, max_exec_time, max_wait_for_cancellation, + max_guest_log_level, }; // Note: `dispatch_function_addr` is set by the Hyperlight guest library, and so it isn't in // shared memory at this point in time. We will set it after the execution of `hv_init`. diff --git a/src/hyperlight_host/tests/integration_test.rs b/src/hyperlight_host/tests/integration_test.rs index eb3ad8228..6359909b0 100644 --- a/src/hyperlight_host/tests/integration_test.rs +++ b/src/hyperlight_host/tests/integration_test.rs @@ -21,7 +21,9 @@ use hyperlight_host::sandbox::SandboxConfiguration; use hyperlight_host::sandbox_state::sandbox::EvolvableSandbox; use hyperlight_host::sandbox_state::transition::Noop; use hyperlight_host::{GuestBinary, HyperlightError, MultiUseSandbox, UninitializedSandbox}; +use hyperlight_testing::simplelogger::{SimpleLogger, LOGGER}; use hyperlight_testing::{c_simple_guest_as_string, simple_guest_as_string}; +use log::LevelFilter; pub mod common; // pub to disable dead_code warning use crate::common::{new_uninit, new_uninit_rust}; @@ -471,69 +473,59 @@ fn recursive_stack_allocate_overflow() { #[test] #[ignore] fn log_message() { - use hyperlight_testing::simplelogger::{SimpleLogger, LOGGER}; + // internal_dispatch_function does a log::trace! in debug mode, and we call it 6 times in `log_test_messages` + let num_fixed_trace_log = if cfg!(debug_assertions) { 6 } else { 0 }; + + 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), + ]; + // init SimpleLogger::initialize_test_logger(); - // internal_dispatch_function does a log::trace! in debug mode, and we call it 6 times in `log_test_messages` - let num_fixed_trace_log = if cfg!(debug_assertions) { 6 } else { 0 }; + for test in tests { + let (level, expected) = test; - // test trace level - log::set_max_level(log::LevelFilter::Trace); - LOGGER.clear_log_calls(); - assert_eq!(0, LOGGER.num_log_calls()); - log_test_messages(); - assert_eq!(5 + num_fixed_trace_log, LOGGER.num_log_calls()); - // The number of enabled calls is the number of times that the enabled function is called - // with a target of "hyperlight-guest" - // This should be the same as the number of log calls as all the log calls for the "hyperlight-guest" target should be filtered in - // the guest - assert_eq!(LOGGER.num_log_calls(), LOGGER.num_enabled_calls()); - - // test debug level - log::set_max_level(log::LevelFilter::Debug); - LOGGER.clear_log_calls(); - assert_eq!(0, LOGGER.num_log_calls()); - log_test_messages(); - assert_eq!(4, LOGGER.num_log_calls()); - assert_eq!(LOGGER.num_log_calls(), LOGGER.num_enabled_calls()); + // Test setting max log level via method on uninit sandbox + log_test_messages(Some(level)); + assert_eq!(expected, LOGGER.num_log_calls()); - // test info level - log::set_max_level(log::LevelFilter::Info); - LOGGER.clear_log_calls(); - assert_eq!(0, LOGGER.num_log_calls()); - log_test_messages(); - assert_eq!(3, LOGGER.num_log_calls()); - assert_eq!(LOGGER.num_log_calls(), LOGGER.num_enabled_calls()); + // Set the log level via env var + std::env::set_var("RUST_LOG", format!("hyperlight_guest={}", level)); + log_test_messages(None); + assert_eq!(expected, LOGGER.num_log_calls()); - // test warn level - log::set_max_level(log::LevelFilter::Warn); - LOGGER.clear_log_calls(); - assert_eq!(0, LOGGER.num_log_calls()); - log_test_messages(); - assert_eq!(2, LOGGER.num_log_calls()); - assert_eq!(LOGGER.num_log_calls(), LOGGER.num_enabled_calls()); + std::env::set_var("RUST_LOG", format!("hyperlight_host={}", level)); + log_test_messages(None); + assert_eq!(expected, LOGGER.num_log_calls()); - // test error level - log::set_max_level(log::LevelFilter::Error); - LOGGER.clear_log_calls(); - assert_eq!(0, LOGGER.num_log_calls()); - log_test_messages(); + std::env::set_var("RUST_LOG", format!("{}", level)); + log_test_messages(None); + assert_eq!(expected, LOGGER.num_log_calls()); + + std::env::remove_var("RUST_LOG"); + } + + // Test that if no log level is set, the default is error + log_test_messages(None); assert_eq!(1, LOGGER.num_log_calls()); - assert_eq!(LOGGER.num_log_calls(), LOGGER.num_enabled_calls()); +} - // test off level - log::set_max_level(log::LevelFilter::Off); +fn log_test_messages(levelfilter: Option) { LOGGER.clear_log_calls(); assert_eq!(0, LOGGER.num_log_calls()); - log_test_messages(); - assert_eq!(0, LOGGER.num_log_calls()); - assert_eq!(LOGGER.num_log_calls(), LOGGER.num_enabled_calls()); -} - -fn log_test_messages() { for level in log::LevelFilter::iter() { - let mut sbox1 = new_uninit().unwrap().evolve(Noop::default()).unwrap(); + let mut sbox = new_uninit().unwrap(); + if let Some(levelfilter) = levelfilter { + sbox.set_max_guest_log_level(levelfilter); + } + + let mut sbox1 = sbox.evolve(Noop::default()).unwrap(); let message = format!("Hello from log_message level {}", level as i32); sbox1 diff --git a/src/hyperlight_testing/src/logger.rs b/src/hyperlight_testing/src/logger.rs index 136558b0d..113f11000 100644 --- a/src/hyperlight_testing/src/logger.rs +++ b/src/hyperlight_testing/src/logger.rs @@ -90,7 +90,7 @@ impl Log for Logger { } LOGCALLS.with(|log_calls| { - if record.target().contains("hyperlight-guest") { + if record.target().contains("hyperlight_guest") { println!("Thread {:?} {:?}", current().id(), record); println!("Thread {:?} {:?}", current().id(), record.metadata()); } diff --git a/src/hyperlight_testing/src/simplelogger.rs b/src/hyperlight_testing/src/simplelogger.rs index 0abdf89bd..5e99f0110 100644 --- a/src/hyperlight_testing/src/simplelogger.rs +++ b/src/hyperlight_testing/src/simplelogger.rs @@ -15,7 +15,7 @@ limitations under the License. */ // this is a non threadsafe logger for testing purposes, to test the log messages emitted by the guest. -// it will only log messages from the hyperlight-guest target. It will not log messages from other targets. +// it will only log messages from the hyperlight_guest target. It will not log messages from other targets. // this target is only used when handling an outb log request from the guest, so this logger will only capture those messages. use std::sync::Once; @@ -80,13 +80,13 @@ impl Log for SimpleLogger { fn enabled(&self, metadata: &Metadata) -> bool { // This allows us to count the actual number of messages that have been logged by the guest // because the guest derives its log level from the host log level then the number times that enabled is called for - // the "hyperlight-guest" target will be the same as the number of messages logged by the guest. - // In other words this function should always return true for the "hyperlight-guest" target. + // the "hyperlight_guest" target will be the same as the number of messages logged by the guest. + // In other words this function should always return true for the "hyperlight_guest" target. unsafe { - if metadata.target() == "hyperlight-guest" { + if metadata.target() == "hyperlight_guest" { NUMBER_OF_ENABLED_CALLS += 1; } - metadata.target() == "hyperlight-guest" && metadata.level() <= log::max_level() + metadata.target() == "hyperlight_guest" && metadata.level() <= log::max_level() } } fn log(&self, record: &Record) {