Fix issues in guest logging (#410)

* fix inconsistent logging crate names

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

* 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]>

---------

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

Author: simongdavies

Diff for: 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 for: 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()
         };

Diff for: 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()

Diff for: 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(),
                                 );

Diff for: 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) =

Diff for: 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()
         };

Diff for: 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);

Diff for: 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!(

Diff for: 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

Diff for: 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`.