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_guest_bin/src/lib.rs b/src/hyperlight_guest_bin/src/lib.rs index d692e0b26..72941d886 100644 --- a/src/hyperlight_guest_bin/src/lib.rs +++ b/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")] diff --git a/src/hyperlight_guest_bin/src/paging.rs b/src/hyperlight_guest_bin/src/paging.rs index 09cb85cf3..f7d8648c8 100644 --- a/src/hyperlight_guest_bin/src/paging.rs +++ b/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 { 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/hyperlight_host/tests/integration_test.rs b/src/hyperlight_host/tests/integration_test.rs index 3bc29d98b..9c06c8a04 100644 --- a/src/hyperlight_host/tests/integration_test.rs +++ b/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), diff --git a/src/tests/rust_guests/dummyguest/Cargo.lock b/src/tests/rust_guests/dummyguest/Cargo.lock index 7c63e8c58..5a2e601ca 100644 --- a/src/tests/rust_guests/dummyguest/Cargo.lock +++ b/src/tests/rust_guests/dummyguest/Cargo.lock @@ -22,11 +22,11 @@ checksum = "34efbcccd345379ca2868b2b2c9d3782e9cc58ba87bc7d79d5b53d9c9ae6f25d" [[package]] name = "buddy_system_allocator" -version = "0.11.0" +version = "0.12.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a1a0108968a3a2dab95b089c0fc3f1afa7759aa5ebe6f1d86d206d6f7ba726eb" +checksum = "b672b945a3e4f4f40bfd4cd5ee07df9e796a42254ce7cd6d2599ad969244c44a" dependencies = [ - "spin 0.9.8", + "spin", ] [[package]] @@ -60,9 +60,9 @@ checksum = "877a4ace8713b0bcf2a4e7eec82529c029f1d0619886d18145fea96c3ffe5c0f" [[package]] name = "flatbuffers" -version = "25.9.23" +version = "25.12.19" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "09b6620799e7340ebd9968d2e0708eb82cf1971e9a16821e2091b6d6e475eed5" +checksum = "35f6839d7b3b98adde531effaf34f0c2badc6f4735d26fe74709d8e513a96ef3" dependencies = [ "bitflags", "rustc_version", @@ -87,7 +87,7 @@ dependencies = [ "anyhow", "flatbuffers", "log", - "spin 0.10.0", + "spin", "thiserror", ] @@ -118,7 +118,7 @@ dependencies = [ "hyperlight-guest-tracing", "linkme", "log", - "spin 0.10.0", + "spin", "tracing", ] @@ -137,7 +137,7 @@ name = "hyperlight-guest-tracing" version = "0.12.0" dependencies = [ "hyperlight-common", - "spin 0.10.0", + "spin", "tracing", "tracing-core", ] @@ -307,15 +307,6 @@ version = "1.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0fda2ff0d084019ba4d7c6f371c95d8fd75ce3524c3cb8fb653a3023f6323e64" -[[package]] -name = "spin" -version = "0.9.8" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6980e8d7511241f8acf4aebddbb1ff938df5eebe98691418c4468d0b72a96a67" -dependencies = [ - "lock_api", -] - [[package]] name = "spin" version = "0.10.0" @@ -338,18 +329,18 @@ dependencies = [ [[package]] name = "thiserror" -version = "2.0.17" +version = "2.0.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f63587ca0f12b72a0600bcba1d40081f830876000bb46dd2337a3051618f4fc8" +checksum = "4288b5bcbc7920c07a1149a35cf9590a2aa808e0bc1eafaade0b80947865fbc4" dependencies = [ "thiserror-impl", ] [[package]] name = "thiserror-impl" -version = "2.0.17" +version = "2.0.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3ff15c8ecd7de3849db632e14d18d2571fa09dfc5ed93479bc4485c7a517c913" +checksum = "ebc4ee7f67670e9b64d05fa4253e753e016c6c95ff35b89b7941d6b856dec1d5" dependencies = [ "proc-macro2", "quote", @@ -392,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/simpleguest/Cargo.lock b/src/tests/rust_guests/simpleguest/Cargo.lock index 00cc2a942..17e3e12da 100644 --- a/src/tests/rust_guests/simpleguest/Cargo.lock +++ b/src/tests/rust_guests/simpleguest/Cargo.lock @@ -333,18 +333,18 @@ dependencies = [ [[package]] name = "thiserror" -version = "2.0.17" +version = "2.0.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f63587ca0f12b72a0600bcba1d40081f830876000bb46dd2337a3051618f4fc8" +checksum = "4288b5bcbc7920c07a1149a35cf9590a2aa808e0bc1eafaade0b80947865fbc4" dependencies = [ "thiserror-impl", ] [[package]] name = "thiserror-impl" -version = "2.0.17" +version = "2.0.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3ff15c8ecd7de3849db632e14d18d2571fa09dfc5ed93479bc4485c7a517c913" +checksum = "ebc4ee7f67670e9b64d05fa4253e753e016c6c95ff35b89b7941d6b856dec1d5" dependencies = [ "proc-macro2", "quote", diff --git a/src/tests/rust_guests/witguest/Cargo.lock b/src/tests/rust_guests/witguest/Cargo.lock index 08d4f9a4b..1600ed1c6 100644 --- a/src/tests/rust_guests/witguest/Cargo.lock +++ b/src/tests/rust_guests/witguest/Cargo.lock @@ -81,11 +81,11 @@ checksum = "34efbcccd345379ca2868b2b2c9d3782e9cc58ba87bc7d79d5b53d9c9ae6f25d" [[package]] name = "buddy_system_allocator" -version = "0.11.0" +version = "0.12.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a1a0108968a3a2dab95b089c0fc3f1afa7759aa5ebe6f1d86d206d6f7ba726eb" +checksum = "b672b945a3e4f4f40bfd4cd5ee07df9e796a42254ce7cd6d2599ad969244c44a" dependencies = [ - "spin 0.9.8", + "spin", ] [[package]] @@ -146,9 +146,9 @@ checksum = "877a4ace8713b0bcf2a4e7eec82529c029f1d0619886d18145fea96c3ffe5c0f" [[package]] name = "flatbuffers" -version = "25.9.23" +version = "25.12.19" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "09b6620799e7340ebd9968d2e0708eb82cf1971e9a16821e2091b6d6e475eed5" +checksum = "35f6839d7b3b98adde531effaf34f0c2badc6f4735d26fe74709d8e513a96ef3" dependencies = [ "bitflags", "rustc_version", @@ -189,7 +189,7 @@ dependencies = [ "anyhow", "flatbuffers", "log", - "spin 0.10.0", + "spin", "thiserror", ] @@ -247,7 +247,7 @@ dependencies = [ "hyperlight-guest-tracing", "linkme", "log", - "spin 0.10.0", + "spin", "tracing", ] @@ -266,7 +266,7 @@ name = "hyperlight-guest-tracing" version = "0.12.0" dependencies = [ "hyperlight-common", - "spin 0.10.0", + "spin", "tracing", "tracing-core", ] @@ -418,18 +418,18 @@ dependencies = [ [[package]] name = "proc-macro2" -version = "1.0.103" +version = "1.0.106" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5ee95bc4ef87b8d5ba32e8b7714ccc834865276eab0aed5c9958d00ec45f49e8" +checksum = "8fd00f0bb2e90d81d1044c2b32617f68fcb9fa3bb7640c23e9c748e53fb30934" dependencies = [ "unicode-ident", ] [[package]] name = "quote" -version = "1.0.42" +version = "1.0.43" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a338cc41d27e6cc6dce6cefc13a0729dfbb81c262b1f519331575dd80ef3067f" +checksum = "dc74d9a594b72ae6656596548f56f667211f8a97b3d4c3d467150794690dc40a" dependencies = [ "proc-macro2", ] @@ -537,15 +537,6 @@ version = "1.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0fda2ff0d084019ba4d7c6f371c95d8fd75ce3524c3cb8fb653a3023f6323e64" -[[package]] -name = "spin" -version = "0.9.8" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6980e8d7511241f8acf4aebddbb1ff938df5eebe98691418c4468d0b72a96a67" -dependencies = [ - "lock_api", -] - [[package]] name = "spin" version = "0.10.0" @@ -557,9 +548,9 @@ dependencies = [ [[package]] name = "syn" -version = "2.0.111" +version = "2.0.114" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "390cc9a294ab71bdb1aa2e99d13be9c753cd2d7bd6560c77118597410c4d2e87" +checksum = "d4d107df263a3013ef9b1879b0df87d706ff80f65a86ea879bd9c31f9b307c2a" dependencies = [ "proc-macro2", "quote", @@ -568,18 +559,18 @@ dependencies = [ [[package]] name = "thiserror" -version = "2.0.17" +version = "2.0.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f63587ca0f12b72a0600bcba1d40081f830876000bb46dd2337a3051618f4fc8" +checksum = "4288b5bcbc7920c07a1149a35cf9590a2aa808e0bc1eafaade0b80947865fbc4" dependencies = [ "thiserror-impl", ] [[package]] name = "thiserror-impl" -version = "2.0.17" +version = "2.0.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3ff15c8ecd7de3849db632e14d18d2571fa09dfc5ed93479bc4485c7a517c913" +checksum = "ebc4ee7f67670e9b64d05fa4253e753e016c6c95ff35b89b7941d6b856dec1d5" dependencies = [ "proc-macro2", "quote", @@ -622,6 +613,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", @@ -766,5 +758,5 @@ dependencies = [ "hyperlight-component-macro", "hyperlight-guest", "hyperlight-guest-bin", - "spin 0.10.0", + "spin", ]