Fix guest tracing filter

src/hyperlight_guest/src/exit.rs

@@ -25,7 +25,7 @@ use tracing::instrument;
 /// this means we can instrument it as a trace point because the trace state
 /// shall not be locked at this point (we are not in an exception context).
 #[inline(never)]
-#[instrument(skip_all, level = "Trace")]
+#[instrument(skip_all, level = "Info")]
 pub fn halt() {
     #[cfg(all(feature = "trace_guest", target_arch = "x86_64"))]
     {

src/hyperlight_guest/src/guest_handle/host_comm.rs

@@ -65,6 +65,7 @@ impl GuestHandle {
     ///
     /// When calling `call_host_function<T>`, this function is called
     /// internally to get the return value.
+    #[instrument(skip_all, level = "Trace")]
     pub fn get_host_return_value<T: TryFrom<ReturnValue>>(&self) -> Result<T> {
         let inner = self
             .try_pop_shared_input_data_into::<FunctionCallResult>()
@@ -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<T: TryFrom<ReturnValue>>(
         &self,
         function_name: &str,

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<T>(&self) -> Result<T>
     where
         T: for<'a> TryFrom<&'a [u8]>,

src/hyperlight_guest_bin/src/guest_function/call.rs

@@ -23,13 +23,13 @@ use hyperlight_common::flatbuffer_wrappers::function_types::{FunctionCallResult,
 use hyperlight_common::flatbuffer_wrappers::guest_error::{ErrorCode, GuestError};
 use hyperlight_guest::error::{HyperlightGuestError, Result};
 use hyperlight_guest::exit::halt;
-use tracing::{Span, instrument};
+use tracing::instrument;
 
 use crate::{GUEST_HANDLE, REGISTERED_GUEST_FUNCTIONS};
 
 type GuestFunc = fn(&FunctionCall) -> Result<Vec<u8>>;
 
-#[instrument(skip_all, parent = Span::current(), level= "Trace")]
+#[instrument(skip_all, level = "Info")]
 pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result<Vec<u8>> {
     // Validate this is a Guest Function Call
     if function_call.function_call_type() != FunctionCallType::Guest {
@@ -85,7 +85,7 @@ pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result<Vec<u8>
 // This function may panic, as we have no other ways of dealing with errors at this level
 #[unsafe(no_mangle)]
 #[inline(never)]
-#[instrument(skip_all, parent = Span::current(), level= "Trace")]
+#[instrument(skip_all, level = "Trace")]
 fn internal_dispatch_function() {
     let handle = unsafe { GUEST_HANDLE };
 
@@ -119,7 +119,7 @@ fn internal_dispatch_function() {
 // This is implemented as a separate function to make sure that epilogue in the internal_dispatch_function is called before the halt()
 // which if it were included in the internal_dispatch_function cause the epilogue to not be called because the halt() would not return
 // when running in the hypervisor.
-#[instrument(skip_all, parent = Span::current(), level= "Trace")]
+#[instrument(skip_all, level = "Info")]
 pub(crate) extern "C" fn dispatch_function() {
     // The hyperlight host likes to use one partition and reset it in
     // various ways; if that has happened, there might stale TLB

src/hyperlight_guest_bin/src/lib.rs

@@ -236,7 +236,7 @@ pub extern "C" fn entrypoint(peb_address: u64, seed: u64, ops: u64, max_log_leve
             // 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);
+                hyperlight_guest_tracing::init_guest_tracing(guest_start_tsc, max_log_level);
             }
 
             #[cfg(feature = "macros")]

src/hyperlight_guest_bin/src/paging.rs

@@ -17,7 +17,7 @@ limitations under the License.
 use alloc::alloc::Layout;
 use core::arch::asm;
 
-use tracing::{Span, instrument};
+use tracing::instrument;
 
 use crate::OS_PAGE_SIZE;
 
@@ -117,7 +117,7 @@ impl hyperlight_common::vmem::TableOps for GuestMappingOperations {
 ///   as such do not use concurrently with any other page table operations
 /// - TLB invalidation is not performed,
 ///   if previously-unmapped ranges are not being mapped, TLB invalidation may need to be performed afterwards.
-#[instrument(skip_all, parent = Span::current(), level= "Trace")]
+#[instrument(skip_all, level = "Trace")]
 pub unsafe fn map_region(phys_base: u64, virt_base: *mut u8, len: u64) {
     use hyperlight_common::vmem;
     unsafe {

src/hyperlight_guest_tracing/Cargo.toml

@@ -12,7 +12,7 @@ description = """Provides the tracing functionality for the hyperlight guest."""
 [dependencies]
 hyperlight-common = { workspace = true, default-features = false }
 spin = "0.10.0"
-tracing = { version = "0.1.44", default-features = false, features = ["attributes"] }
+tracing = { version = "0.1.44", default-features = false, features = ["attributes", "log"] }
 tracing-core = { version = "0.1.36", default-features = false }
 
 [lints]

src/hyperlight_guest_tracing/src/lib.rs

@@ -48,6 +48,7 @@ mod trace {
     use alloc::sync::{Arc, Weak};
 
     use spin::Mutex;
+    use tracing::log::LevelFilter;
 
     use crate::state::GuestState;
     use crate::subscriber::GuestSubscriber;
@@ -61,12 +62,12 @@ mod trace {
     static GUEST_STATE: spin::Once<Weak<Mutex<GuestState>>> = 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<GuestState> to use later at runtime
         GUEST_STATE.call_once(|| Arc::downgrade(state));

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,42 @@ 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<Mutex<GuestState>>,
+    /// Maximum log level to record
+    max_log_level: LevelFilter,
+}
+
+/// Converts a `tracing::log::LevelFilter` to a `tracing_core::LevelFilter`
+/// Used to check if an event should be recorded based on the maximum log level
+fn convert_level_filter(filter: tracing::log::LevelFilter) -> tracing_core::LevelFilter {
+    match filter {
+        tracing::log::LevelFilter::Off => tracing_core::LevelFilter::OFF,
+        tracing::log::LevelFilter::Error => tracing_core::LevelFilter::ERROR,
+        tracing::log::LevelFilter::Warn => tracing_core::LevelFilter::WARN,
+        tracing::log::LevelFilter::Info => tracing_core::LevelFilter::INFO,
+        tracing::log::LevelFilter::Debug => tracing_core::LevelFilter::DEBUG,
+        tracing::log::LevelFilter::Trace => tracing_core::LevelFilter::TRACE,
+    }
 }
 
 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, max_log_level: tracing::log::LevelFilter) -> Self {
         Self {
             state: Arc::new(Mutex::new(GuestState::new(guest_start_tsc))),
+            max_log_level: convert_level_filter(max_log_level),
         }
     }
+    /// 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<Mutex<GuestState>> {
         &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
+        self.max_log_level >= *md.level()
     }
 
     fn new_span(&self, attrs: &Attributes<'_>) -> Id {

src/hyperlight_host/src/sandbox/trace/context.rs

@@ -137,7 +137,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();
 
@@ -380,7 +380,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);

src/hyperlight_host/tests/integration_test.rs

@@ -757,10 +757,16 @@ fn log_message() {
         22 * 6
     };
 
+    // Calculate fixed info logs
+    // - 10 logs per iteration from infrastructure at Info level (halt, dispatch_function, call_guest_function)
+    //   (halt x 3 calls + dispatch x 1 + call_guest x 1) * 2 logs (Enter/Exit) = 10 logs
+    // - 6 iterations
+    let num_fixed_info_log = 10 * 6;
+
     let tests = vec![
         (LevelFilter::Trace, 5 + num_fixed_trace_log),
-        (LevelFilter::Debug, 4),
-        (LevelFilter::Info, 3),
+        (LevelFilter::Debug, 4 + num_fixed_info_log),
+        (LevelFilter::Info, 3 + num_fixed_info_log),
         (LevelFilter::Warn, 2),
         (LevelFilter::Error, 1),
         (LevelFilter::Off, 0),