Allow explicit setting of max guest log level, check RUST_LOG to set guest log_level if not set

The guest log level impacts the amount of logs produced by the guest, its presently set by examining the value of max_log_level in the host.

This may not be appropriate since logging in the guest is expensive and it may cause logs to be emitted from the guest but ignored in the host. This change introduces a function on an uninitializedsandbox to set the level explicitly, if this is not set the env var RUST_LOG is parsed to determine the log level so that logs  are only produced if they are going to be consumed.  If RUST_LOG is not set then the max guest log level is set to error.

Signed-off-by: Simon Davies <[email protected]>

Author: simongdavies

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<HypervisorHandler>,
+        max_guest_log_level: Option<LevelFilter>,
         #[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()
         };

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<HypervisorHandler>,
+        max_guest_log_level: Option<LevelFilter>,
         #[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()

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<LevelFilter>,
     #[cfg(gdb)]
     pub(crate) dbg_mem_access_handler: DbgMemAccessHandlerWrapper,
 }
@@ -361,6 +362,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(),
                                 );

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<HypervisorHandler>,
+        max_guest_log_level: Option<LevelFilter>,
         #[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()
         };

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<HypervisorHandler>,
+        guest_max_log_level: Option<LevelFilter>,
         #[cfg(gdb)] dbg_mem_access_fn: DbgMemAccessHandlerWrapper,
     ) -> Result<()>;
 
@@ -191,7 +194,44 @@ 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 = match std::env::var("RUST_LOG") {
+            Ok(s) => s,
+            Err(_) => String::new(),
+        };
+
+        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 +396,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);

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<LevelFilter>,
     #[cfg(gdb)]
     pub(crate) debug_info: Option<DebugInfo>,
 }
@@ -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

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,
         )?;
@@ -106,6 +108,7 @@ fn hv_init(
     max_init_time: Duration,
     max_exec_time: Duration,
     max_wait_for_cancellation: Duration,
+    max_guest_log_level: Option<LevelFilter>,
     #[cfg(gdb)] debug_info: Option<DebugInfo>,
 ) -> Result<HypervisorHandler> {
     let outb_hdl = outb_handler_wrapper(hshm.clone(), host_funcs);
@@ -134,6 +137,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`.

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,58 @@ 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 mut tests = Vec::new();
+    tests.push((LevelFilter::Trace, 5 + num_fixed_trace_log));
+    tests.push((LevelFilter::Debug, 4));
+    tests.push((LevelFilter::Info, 3));
+    tests.push((LevelFilter::Warn, 2));
+    tests.push((LevelFilter::Error, 1));
+    tests.push((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<log::LevelFilter>) {
     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