From df00edf62082a257905832c146ccfb89c66f702c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Doru=20Bl=C3=A2nzeanu?= Date: Fri, 24 Oct 2025 17:30:21 +0300 Subject: [PATCH 1/3] [trace-guest] Update guest library trace levels and remove explicit parent MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Doru Blânzeanu --- src/hyperlight_guest/src/exit.rs | 2 +- src/hyperlight_guest/src/guest_handle/host_comm.rs | 4 +++- src/hyperlight_guest/src/guest_handle/io.rs | 4 ++-- src/hyperlight_guest_bin/src/guest_function/call.rs | 8 ++++---- src/hyperlight_host/tests/integration_test.rs | 10 ++++++++-- 5 files changed, 18 insertions(+), 10 deletions(-) diff --git a/src/hyperlight_guest/src/exit.rs b/src/hyperlight_guest/src/exit.rs index 6e7a61465..be388b4dc 100644 --- a/src/hyperlight_guest/src/exit.rs +++ b/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"))] { diff --git a/src/hyperlight_guest/src/guest_handle/host_comm.rs b/src/hyperlight_guest/src/guest_handle/host_comm.rs index da92a8e71..c72de8a3f 100644 --- a/src/hyperlight_guest/src/guest_handle/host_comm.rs +++ b/src/hyperlight_guest/src/guest_handle/host_comm.rs @@ -65,6 +65,7 @@ impl GuestHandle { /// /// When calling `call_host_function`, this function is called /// internally to get the return value. + #[instrument(skip_all, level = "Trace")] pub fn get_host_return_value>(&self) -> Result { let inner = self .try_pop_shared_input_data_into::() @@ -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>( &self, function_name: &str, diff --git a/src/hyperlight_guest/src/guest_handle/io.rs b/src/hyperlight_guest/src/guest_handle/io.rs index 4c7f1b819..46c1d68f6 100644 --- a/src/hyperlight_guest/src/guest_handle/io.rs +++ b/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(&self) -> Result where T: for<'a> TryFrom<&'a [u8]>, diff --git a/src/hyperlight_guest_bin/src/guest_function/call.rs b/src/hyperlight_guest_bin/src/guest_function/call.rs index c460b06c6..219604ccb 100644 --- a/src/hyperlight_guest_bin/src/guest_function/call.rs +++ b/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>; -#[instrument(skip_all, parent = Span::current(), level= "Trace")] +#[instrument(skip_all, level = "Info")] pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result> { // 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 // 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 diff --git a/src/hyperlight_host/tests/integration_test.rs b/src/hyperlight_host/tests/integration_test.rs index 953c6b7e4..8289e4be3 100644 --- a/src/hyperlight_host/tests/integration_test.rs +++ b/src/hyperlight_host/tests/integration_test.rs @@ -721,10 +721,16 @@ fn log_message() { 20 * 6 }; + // Calculate fixed info logs + // - 8 logs per iteration from infrastructure at Info level (halt, dispatch_function, call_guest_function) + // (halt x 2 calls + dispatch x 1 + call_guest x 1) * 2 logs (Enter/Exit) = 8 logs + // - 6 iterations + let num_fixed_info_log = 8 * 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), From 887d003692e7c331ede0d5942f2d33840ec77cab Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Doru=20Bl=C3=A2nzeanu?= Date: Fri, 24 Oct 2025 17:41:11 +0300 Subject: [PATCH 2/3] [trace-guest] Add trace/events filtering based on max_log_level MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Doru Blânzeanu --- src/hyperlight_guest_bin/src/lib.rs | 2 +- src/hyperlight_guest_tracing/Cargo.toml | 2 +- src/hyperlight_guest_tracing/src/lib.rs | 5 ++-- .../src/subscriber.rs | 28 ++++++++++++++++--- .../src/sandbox/trace/context.rs | 4 +-- src/tests/rust_guests/dummyguest/Cargo.lock | 1 + src/tests/rust_guests/witguest/Cargo.lock | 1 + 7 files changed, 33 insertions(+), 10 deletions(-) diff --git a/src/hyperlight_guest_bin/src/lib.rs b/src/hyperlight_guest_bin/src/lib.rs index 69ffc37af..d0583c4bd 100644 --- a/src/hyperlight_guest_bin/src/lib.rs +++ b/src/hyperlight_guest_bin/src/lib.rs @@ -220,7 +220,7 @@ pub(crate) extern "C" fn generic_init(peb_address: u64, seed: u64, ops: u64, max // 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")] diff --git a/src/hyperlight_guest_tracing/Cargo.toml b/src/hyperlight_guest_tracing/Cargo.toml index 20506f625..dfdd59247 100644 --- a/src/hyperlight_guest_tracing/Cargo.toml +++ b/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] diff --git a/src/hyperlight_guest_tracing/src/lib.rs b/src/hyperlight_guest_tracing/src/lib.rs index 36a5906b4..5ef110dd6 100644 --- a/src/hyperlight_guest_tracing/src/lib.rs +++ b/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>> = 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 to use later at runtime GUEST_STATE.call_once(|| Arc::downgrade(state)); diff --git a/src/hyperlight_guest_tracing/src/subscriber.rs b/src/hyperlight_guest_tracing/src/subscriber.rs index e36f71c59..e9e5dc247 100644 --- a/src/hyperlight_guest_tracing/src/subscriber.rs +++ b/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>, + /// 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> { &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 { diff --git a/src/hyperlight_host/src/sandbox/trace/context.rs b/src/hyperlight_host/src/sandbox/trace/context.rs index c885a1732..17c68b954 100644 --- a/src/hyperlight_host/src/sandbox/trace/context.rs +++ b/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); diff --git a/src/tests/rust_guests/dummyguest/Cargo.lock b/src/tests/rust_guests/dummyguest/Cargo.lock index fbf3bc62c..a16bf4e2a 100644 --- a/src/tests/rust_guests/dummyguest/Cargo.lock +++ b/src/tests/rust_guests/dummyguest/Cargo.lock @@ -383,6 +383,7 @@ version = "0.1.44" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" dependencies = [ + "log", "pin-project-lite", "tracing-attributes", "tracing-core", diff --git a/src/tests/rust_guests/witguest/Cargo.lock b/src/tests/rust_guests/witguest/Cargo.lock index 3715fc832..7f2d67f88 100644 --- a/src/tests/rust_guests/witguest/Cargo.lock +++ b/src/tests/rust_guests/witguest/Cargo.lock @@ -608,6 +608,7 @@ version = "0.1.44" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" dependencies = [ + "log", "pin-project-lite", "tracing-attributes", "tracing-core", From 72aaf11e8c0583126b95fd891cc3b3a90e171cd8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Doru=20Bl=C3=A2nzeanu?= Date: Thu, 19 Feb 2026 12:58:42 +0200 Subject: [PATCH 3/3] [trace-guest] Define a common log level filter to be used for tracing and logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Doru Blânzeanu --- Cargo.lock | 1 + src/hyperlight_common/Cargo.toml | 1 + src/hyperlight_common/src/lib.rs | 3 + src/hyperlight_common/src/log_level.rs | 109 ++++++++++++++++++ src/hyperlight_guest_bin/src/guest_logger.rs | 4 +- src/hyperlight_guest_bin/src/lib.rs | 16 +-- src/hyperlight_guest_tracing/src/lib.rs | 2 +- .../src/subscriber.rs | 17 +-- .../src/hypervisor/hyperlight_vm.rs | 59 ++++++++-- src/hyperlight_host/src/hypervisor/mod.rs | 42 +------ .../src/sandbox/uninitialized.rs | 2 +- src/hyperlight_host/tests/integration_test.rs | 28 +++-- src/tests/rust_guests/dummyguest/Cargo.lock | 1 + src/tests/rust_guests/simpleguest/Cargo.lock | 1 + src/tests/rust_guests/simpleguest/src/main.rs | 3 + src/tests/rust_guests/witguest/Cargo.lock | 1 + 16 files changed, 206 insertions(+), 84 deletions(-) create mode 100644 src/hyperlight_common/src/log_level.rs diff --git a/Cargo.lock b/Cargo.lock index 914f18c86..960cd3322 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1416,6 +1416,7 @@ dependencies = [ "spin", "thiserror 2.0.18", "tracing", + "tracing-core", ] [[package]] diff --git a/src/hyperlight_common/Cargo.toml b/src/hyperlight_common/Cargo.toml index 7b6ded9c5..3e3c615b2 100644 --- a/src/hyperlight_common/Cargo.toml +++ b/src/hyperlight_common/Cargo.toml @@ -22,6 +22,7 @@ tracing = { version = "0.1.44", optional = true } arbitrary = {version = "1.4.2", optional = true, features = ["derive"]} spin = "0.10.0" thiserror = { version = "2.0.18", default-features = false } +tracing-core = { version = "0.1.36", default-features = false } [features] default = ["tracing"] diff --git a/src/hyperlight_common/src/lib.rs b/src/hyperlight_common/src/lib.rs index 478aeef8b..bcfbf6cce 100644 --- a/src/hyperlight_common/src/lib.rs +++ b/src/hyperlight_common/src/lib.rs @@ -30,6 +30,9 @@ mod flatbuffers; // cbindgen:ignore pub mod layout; +// cbindgen:ignore +pub mod log_level; + /// cbindgen:ignore pub mod mem; diff --git a/src/hyperlight_common/src/log_level.rs b/src/hyperlight_common/src/log_level.rs new file mode 100644 index 000000000..83f8d3055 --- /dev/null +++ b/src/hyperlight_common/src/log_level.rs @@ -0,0 +1,109 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +/// This type is a unified definition of log level filters between the guest and host. +/// +/// This is needed because currently the guest uses both the `log` and `tracing` crates, +/// and needs each type of `LevelFilter` from both crates. +/// +/// To avoid as much as possible the amount of conversions between the two types, we define a +/// single type that can be converted to both `log::LevelFilter` and `tracing::LevelFilter`. +/// NOTE: This also takes care of the fact that the `tracing` and `log` enum types for the log +/// levels are not guaranteed to have the same discriminants, so we can't just cast between them. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum GuestLogFilter { + Off, + Error, + Warn, + Info, + Debug, + Trace, +} + +impl From for tracing_core::LevelFilter { + fn from(filter: GuestLogFilter) -> Self { + match filter { + GuestLogFilter::Off => tracing_core::LevelFilter::OFF, + GuestLogFilter::Error => tracing_core::LevelFilter::ERROR, + GuestLogFilter::Warn => tracing_core::LevelFilter::WARN, + GuestLogFilter::Info => tracing_core::LevelFilter::INFO, + GuestLogFilter::Debug => tracing_core::LevelFilter::DEBUG, + GuestLogFilter::Trace => tracing_core::LevelFilter::TRACE, + } + } +} + +impl From for log::LevelFilter { + fn from(filter: GuestLogFilter) -> Self { + match filter { + GuestLogFilter::Off => log::LevelFilter::Off, + GuestLogFilter::Error => log::LevelFilter::Error, + GuestLogFilter::Warn => log::LevelFilter::Warn, + GuestLogFilter::Info => log::LevelFilter::Info, + GuestLogFilter::Debug => log::LevelFilter::Debug, + GuestLogFilter::Trace => log::LevelFilter::Trace, + } + } +} + +/// Used by the host to convert a [`tracing_core::LevelFilter`] to the intermediary [`GuestLogFilter`] +/// filter that is later converted to `u64` and passed to the guest via the C API. +impl From for GuestLogFilter { + fn from(value: tracing_core::LevelFilter) -> Self { + match value { + tracing_core::LevelFilter::OFF => Self::Off, + tracing_core::LevelFilter::ERROR => Self::Error, + tracing_core::LevelFilter::WARN => Self::Warn, + tracing_core::LevelFilter::INFO => Self::Info, + tracing_core::LevelFilter::DEBUG => Self::Debug, + tracing_core::LevelFilter::TRACE => Self::Trace, + } + } +} + +/// Used by the guest to convert a `u64` value passed from the host via the C API to the +/// intermediary [`GuestLogFilter`] filter that is later converted to both +/// `tracing_core::LevelFilter` and `log::LevelFilter`. +impl TryFrom for GuestLogFilter { + type Error = (); + + fn try_from(value: u64) -> Result>::Error> { + match value { + 0 => Ok(Self::Off), + 1 => Ok(Self::Error), + 2 => Ok(Self::Warn), + 3 => Ok(Self::Info), + 4 => Ok(Self::Debug), + 5 => Ok(Self::Trace), + _ => Err(()), + } + } +} + +/// Used by the host to convert the [`GuestLogFilter`] to a `u64` that is passed to the guest via +/// the C API. +impl From for u64 { + fn from(value: GuestLogFilter) -> Self { + match value { + GuestLogFilter::Off => 0, + GuestLogFilter::Error => 1, + GuestLogFilter::Warn => 2, + GuestLogFilter::Info => 3, + GuestLogFilter::Debug => 4, + GuestLogFilter::Trace => 5, + } + } +} diff --git a/src/hyperlight_guest_bin/src/guest_logger.rs b/src/hyperlight_guest_bin/src/guest_logger.rs index c4223d7ea..7ff3d97fc 100644 --- a/src/hyperlight_guest_bin/src/guest_logger.rs +++ b/src/hyperlight_guest_bin/src/guest_logger.rs @@ -24,11 +24,11 @@ use crate::GUEST_HANDLE; // this is private on purpose so that `log` can only be called though the `log!` macros. struct GuestLogger {} -pub(crate) fn init_logger(level: LevelFilter) { +pub(crate) fn init_logger(filter: LevelFilter) { // if this `expect` fails we have no way to recover anyway, so we actually prefer a panic here // below temporary guest logger is promoted to static by the compiler. log::set_logger(&GuestLogger {}).expect("unable to setup guest logger"); - log::set_max_level(level); + log::set_max_level(filter); } impl log::Log for GuestLogger { diff --git a/src/hyperlight_guest_bin/src/lib.rs b/src/hyperlight_guest_bin/src/lib.rs index d0583c4bd..093356d7a 100644 --- a/src/hyperlight_guest_bin/src/lib.rs +++ b/src/hyperlight_guest_bin/src/lib.rs @@ -25,12 +25,12 @@ use guest_function::call::dispatch_function; use guest_function::register::GuestFunctionRegister; use guest_logger::init_logger; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; +use hyperlight_common::log_level::GuestLogFilter; use hyperlight_common::mem::HyperlightPEB; #[cfg(feature = "mem_profile")] use hyperlight_common::outb::OutBAction; use hyperlight_guest::exit::write_abort; use hyperlight_guest::guest_handle::handle::GuestHandle; -use log::LevelFilter; // === Modules === #[cfg_attr(target_arch = "x86_64", path = "arch/amd64/mod.rs")] @@ -212,15 +212,17 @@ pub(crate) extern "C" fn generic_init(peb_address: u64, seed: u64, ops: u64, max } // set up the logger - let max_log_level = LevelFilter::iter() - .nth(max_log_level as usize) - .expect("Invalid log level"); - init_logger(max_log_level); + let guest_log_level_filter = + GuestLogFilter::try_from(max_log_level).expect("Invalid log level"); + init_logger(guest_log_level_filter.into()); // 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, max_log_level); + if guest_log_level_filter != GuestLogFilter::Off { + hyperlight_guest_tracing::init_guest_tracing( + guest_start_tsc, + guest_log_level_filter.into(), + ); } #[cfg(feature = "macros")] diff --git a/src/hyperlight_guest_tracing/src/lib.rs b/src/hyperlight_guest_tracing/src/lib.rs index 5ef110dd6..c04c8b41d 100644 --- a/src/hyperlight_guest_tracing/src/lib.rs +++ b/src/hyperlight_guest_tracing/src/lib.rs @@ -48,7 +48,7 @@ mod trace { use alloc::sync::{Arc, Weak}; use spin::Mutex; - use tracing::log::LevelFilter; + use tracing_core::LevelFilter; use crate::state::GuestState; use crate::subscriber::GuestSubscriber; diff --git a/src/hyperlight_guest_tracing/src/subscriber.rs b/src/hyperlight_guest_tracing/src/subscriber.rs index e9e5dc247..15ece0752 100644 --- a/src/hyperlight_guest_tracing/src/subscriber.rs +++ b/src/hyperlight_guest_tracing/src/subscriber.rs @@ -35,25 +35,12 @@ pub(crate) struct GuestSubscriber { 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 { /// 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 { + pub(crate) fn new(guest_start_tsc: u64, filter: LevelFilter) -> Self { Self { state: Arc::new(Mutex::new(GuestState::new(guest_start_tsc))), - max_log_level: convert_level_filter(max_log_level), + max_log_level: filter, } } /// Returns a reference to the internal state of the subscriber diff --git a/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs b/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs index f8285d425..1f6a3c8e8 100644 --- a/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs +++ b/src/hyperlight_host/src/hypervisor/hyperlight_vm.rs @@ -18,6 +18,7 @@ limitations under the License. use std::collections::HashMap; #[cfg(crashdump)] use std::path::Path; +use std::str::FromStr; #[cfg(any(kvm, mshv3))] use std::sync::atomic::AtomicBool; use std::sync::atomic::AtomicU8; @@ -25,8 +26,9 @@ use std::sync::atomic::AtomicU8; use std::sync::atomic::AtomicU64; use std::sync::{Arc, Mutex}; -use log::LevelFilter; +use hyperlight_common::log_level::GuestLogFilter; use tracing::{Span, instrument}; +use tracing_core::LevelFilter; #[cfg(gdb)] use super::gdb::arch::VcpuStopReasonError; @@ -59,7 +61,7 @@ use crate::hypervisor::virtual_machine::{ HypervisorType, MapMemoryError, RegisterError, RunVcpuError, UnmapMemoryError, VmError, VmExit, get_available_hypervisor, }; -use crate::hypervisor::{InterruptHandle, InterruptHandleImpl, get_max_log_level}; +use crate::hypervisor::{InterruptHandle, InterruptHandleImpl}; use crate::mem::memory_region::{MemoryRegion, MemoryRegionFlags, MemoryRegionType}; use crate::mem::mgr::SandboxMemoryManager; use crate::mem::ptr::RawPtr; @@ -73,6 +75,52 @@ use crate::sandbox::trace::MemTraceInfo; #[cfg(crashdump)] use crate::sandbox::uninitialized::SandboxRuntimeConfig; +/// Get the logging level filter to pass to the guest entrypoint +fn get_max_log_level_filter() -> LevelFilter { + // 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("") + }; + + tracing::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) +} + +/// Converts a given [`Option`] to a `u64` value to be passed to the guest entrypoint +fn get_guest_log_filter(guest_max_log_level: Option) -> u64 { + let guest_log_level_filter = match guest_max_log_level { + Some(level) => level, + None => get_max_log_level_filter(), + }; + GuestLogFilter::from(guest_log_level_filter).into() +} + /// Represents a Hyperlight Virtual Machine instance. /// /// This struct manages the lifecycle of the VM, including: @@ -468,11 +516,6 @@ impl HyperlightVm { self.page_size = page_size as usize; - let guest_max_log_level: u64 = match guest_max_log_level { - Some(level) => level as u64, - None => get_max_log_level().into(), - }; - let regs = CommonRegisters { rip: entrypoint, // We usually keep the top of the stack 16-byte @@ -487,7 +530,7 @@ impl HyperlightVm { rdi: peb_addr.into(), rsi: seed, rdx: page_size.into(), - rcx: guest_max_log_level, + rcx: get_guest_log_filter(guest_max_log_level), rflags: 1 << 1, ..Default::default() diff --git a/src/hyperlight_host/src/hypervisor/mod.rs b/src/hyperlight_host/src/hypervisor/mod.rs index 66a5a8cd5..ddc3da3ee 100644 --- a/src/hyperlight_host/src/hypervisor/mod.rs +++ b/src/hyperlight_host/src/hypervisor/mod.rs @@ -14,8 +14,6 @@ See the License for the specific language governing permissions and limitations under the License. */ -use log::LevelFilter; - /// GDB debugging support #[cfg(gdb)] pub(crate) mod gdb; @@ -41,7 +39,6 @@ pub(crate) mod crashdump; pub(crate) mod hyperlight_vm; use std::fmt::Debug; -use std::str::FromStr; #[cfg(any(kvm, mshv3))] use std::sync::atomic::{AtomicBool, AtomicU8, AtomicU64, Ordering}; #[cfg(target_os = "windows")] @@ -49,43 +46,6 @@ use std::sync::atomic::{AtomicU8, Ordering}; #[cfg(any(kvm, mshv3))] use std::time::Duration; -/// Get the logging level to pass to the guest entrypoint -fn get_max_log_level() -> 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 -} - /// A trait for platform-specific interrupt handle implementation details pub(crate) trait InterruptHandleImpl: InterruptHandle { /// Set the thread ID for the vcpu thread @@ -543,7 +503,7 @@ pub(crate) mod tests { let seed = 12345u64; // Random seed let page_size = 4096u32; // Standard page size let host_funcs = Arc::new(Mutex::new(FunctionRegistry::default())); - let guest_max_log_level = Some(log::LevelFilter::Error); + let guest_max_log_level = Some(tracing_core::LevelFilter::ERROR); #[cfg(gdb)] let dbg_mem_access_fn = Arc::new(Mutex::new(mem_mgr.clone())); diff --git a/src/hyperlight_host/src/sandbox/uninitialized.rs b/src/hyperlight_host/src/sandbox/uninitialized.rs index f09fe70a0..43e3ce26b 100644 --- a/src/hyperlight_host/src/sandbox/uninitialized.rs +++ b/src/hyperlight_host/src/sandbox/uninitialized.rs @@ -19,8 +19,8 @@ use std::option::Option; use std::path::Path; use std::sync::{Arc, Mutex}; -use log::LevelFilter; use tracing::{Span, instrument}; +use tracing_core::LevelFilter; use super::host_funcs::{FunctionRegistry, default_writer_func}; use super::snapshot::Snapshot; diff --git a/src/hyperlight_host/tests/integration_test.rs b/src/hyperlight_host/tests/integration_test.rs index 8289e4be3..db69d1e3f 100644 --- a/src/hyperlight_host/tests/integration_test.rs +++ b/src/hyperlight_host/tests/integration_test.rs @@ -20,11 +20,12 @@ use std::thread; use std::time::Duration; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; +use hyperlight_common::log_level::GuestLogFilter; use hyperlight_host::sandbox::SandboxConfiguration; use hyperlight_host::{HyperlightError, MultiUseSandbox}; use hyperlight_testing::simplelogger::{LOGGER, SimpleLogger}; -use log::LevelFilter; use serial_test::serial; +use tracing_core::LevelFilter; pub mod common; // pub to disable dead_code warning use crate::common::{ @@ -728,12 +729,12 @@ fn log_message() { let num_fixed_info_log = 8 * 6; let tests = vec![ - (LevelFilter::Trace, 5 + num_fixed_trace_log), - (LevelFilter::Debug, 4 + num_fixed_info_log), - (LevelFilter::Info, 3 + num_fixed_info_log), - (LevelFilter::Warn, 2), - (LevelFilter::Error, 1), - (LevelFilter::Off, 0), + (LevelFilter::TRACE, 5 + num_fixed_trace_log), + (LevelFilter::DEBUG, 4 + num_fixed_info_log), + (LevelFilter::INFO, 3 + num_fixed_info_log), + (LevelFilter::WARN, 2), + (LevelFilter::ERROR, 1), + (LevelFilter::OFF, 0), ]; // init @@ -771,10 +772,18 @@ fn log_message() { assert_eq!(1, LOGGER.num_log_calls()); } -fn log_test_messages(levelfilter: Option) { +fn log_test_messages(levelfilter: Option) { LOGGER.clear_log_calls(); assert_eq!(0, LOGGER.num_log_calls()); - for level in log::LevelFilter::iter() { + let filters = [ + LevelFilter::OFF, + LevelFilter::TRACE, + LevelFilter::DEBUG, + LevelFilter::INFO, + LevelFilter::WARN, + LevelFilter::ERROR, + ]; + for level in filters.iter() { // Only use Rust guest because the C guest has a different signature for LogMessage // (Long vs Int for the level parameter) with_rust_uninit_sandbox(|mut sbox| { @@ -784,6 +793,7 @@ fn log_test_messages(levelfilter: Option) { let mut sbox1 = sbox.evolve().unwrap(); + let level: u64 = GuestLogFilter::from(*level).into(); let message = format!("Hello from log_message level {}", level as i32); sbox1 .call::<()>("LogMessage", (message.to_string(), level as i32)) diff --git a/src/tests/rust_guests/dummyguest/Cargo.lock b/src/tests/rust_guests/dummyguest/Cargo.lock index a16bf4e2a..5570b2372 100644 --- a/src/tests/rust_guests/dummyguest/Cargo.lock +++ b/src/tests/rust_guests/dummyguest/Cargo.lock @@ -89,6 +89,7 @@ dependencies = [ "log", "spin", "thiserror", + "tracing-core", ] [[package]] diff --git a/src/tests/rust_guests/simpleguest/Cargo.lock b/src/tests/rust_guests/simpleguest/Cargo.lock index 0faead807..5110cece3 100644 --- a/src/tests/rust_guests/simpleguest/Cargo.lock +++ b/src/tests/rust_guests/simpleguest/Cargo.lock @@ -82,6 +82,7 @@ dependencies = [ "log", "spin", "thiserror", + "tracing-core", ] [[package]] diff --git a/src/tests/rust_guests/simpleguest/src/main.rs b/src/tests/rust_guests/simpleguest/src/main.rs index 80f734224..13b652f0a 100644 --- a/src/tests/rust_guests/simpleguest/src/main.rs +++ b/src/tests/rust_guests/simpleguest/src/main.rs @@ -41,6 +41,7 @@ use hyperlight_common::flatbuffer_wrappers::function_types::{ use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; use hyperlight_common::flatbuffer_wrappers::guest_log_level::LogLevel; use hyperlight_common::flatbuffer_wrappers::util::get_flatbuffer_result; +use hyperlight_common::log_level::GuestLogFilter; use hyperlight_guest::error::{HyperlightGuestError, Result}; use hyperlight_guest::exit::{abort_with_code, abort_with_code_and_message}; use hyperlight_guest_bin::exception::arch::{Context, ExceptionInfo}; @@ -462,6 +463,8 @@ fn test_rust_malloc(code: i32) -> i32 { #[guest_function("LogMessage")] fn log_message(message: String, level: i32) { + let level = + LevelFilter::from(GuestLogFilter::try_from(level as u64).expect("Invalid log level")); let level = LevelFilter::iter().nth(level as usize).unwrap().to_level(); match level { diff --git a/src/tests/rust_guests/witguest/Cargo.lock b/src/tests/rust_guests/witguest/Cargo.lock index 7f2d67f88..d4ab5818b 100644 --- a/src/tests/rust_guests/witguest/Cargo.lock +++ b/src/tests/rust_guests/witguest/Cargo.lock @@ -192,6 +192,7 @@ dependencies = [ "log", "spin", "thiserror", + "tracing-core", ] [[package]]