Fix issues in guest logging

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

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,
 }
@@ -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(),
                                 );

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<super::hypervisor_handler::HypervisorHandler>,
+        _guest_max_log_level: Option<LevelFilter>,
         #[cfg(gdb)] _dbg_mem_access_fn: DbgMemAccessHandlerWrapper,
     ) -> crate::Result<()> {
         let entrypoint_fn: extern "win64" fn(u64, u64, u64, u64) =

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,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);

src/hyperlight_host/src/sandbox/outb.rs

@@ -88,7 +88,7 @@ pub(super) fn outb_log(mgr: &mut SandboxMemoryManager<HostSharedMemory>) -> 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<HostSharedMemory>) -> 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!(

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,
         )?;
@@ -99,13 +101,15 @@ pub(super) fn evolve_impl_multi_use(u_sbox: UninitializedSandbox) -> Result<Mult
 }
 
 #[instrument(err(Debug), skip_all, parent = Span::current(), level = "Trace")]
+#[allow(clippy::too_many_arguments)]
 fn hv_init(
     hshm: &MemMgrWrapper<HostSharedMemory>,
     gshm: SandboxMemoryManager<GuestSharedMemory>,
     host_funcs: Arc<Mutex<HostFuncsWrapper>>,
     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 +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`.