refactor: replace tracing-log with native tracing macros for guest log forwarding (#1500)

cshung · Copilot · web-flow · commit 1a90b49199d7 · 2026-06-04T12:09:32.000-07:00
* refactor: replace tracing-log with native tracing macros for guest log forwarding Remove the tracing-log dependency from hyperlight-host and replace the format_trace/log::Record approach in outb_log with direct tracing event macros (error!, warn!, info!, debug!, trace!). This consolidates guest log emission on the tracing crate, while preserving backward compatibility for consumers using only the log crate (via tracing's built-in log feature). Closes #1028 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: cshung <3410332+cshung@users.noreply.github.com> * docs: update observability docs to reflect tracing-log removal Remove references to tracing-log crate and LogTracer from the metrics/logs/traces documentation. Updated to reflect that Hyperlight now uses the tracing crate's built-in log feature for forwarding events to log consumers. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: cshung <3410332+cshung@users.noreply.github.com> * refactor: rename guest log fields per review feedback Rename tracing event fields from guest_source_file to guest_file and keep guest_line and guest_module consistent with the shorter naming convention requested in review. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: cshung <3410332+cshung@users.noreply.github.com> --------- Signed-off-by: cshung <3410332+cshung@users.noreply.github.com> Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
diff --git a/Cargo.lock b/Cargo.lock
diff --git a/docs/hyperlight-metrics-logs-and-traces.md b/docs/hyperlight-metrics-logs-and-traces.md
@@ -3,7 +3,7 @@
 Hyperlight provides the following observability features:
 
 * [Metrics](#metrics) are provided using the [metrics](https://docs.rs/metrics/latest/metrics/index.html) crate, which is a lightweight metrics facade.
-* [Logs](#logs) are provided using the Rust [log crate](https://docs.rs/log/0.4.6/log/), and can be consumed by any Rust logger implementation, including LogTracer which can be used to emit log records as tracing events.
+* [Logs](#logs) are provided using the Rust [tracing crate](https://docs.rs/tracing/latest/tracing/) with the `log` feature enabled, allowing logs to be consumed by any Rust logger implementation compatible with the [log crate](https://docs.rs/log/latest/log/).
 * [Tracing](#tracing) is provided using the Rust [tracing crate](https://docs.rs/tracing/0.1.37/tracing/), and can be consumed by any Rust tracing implementation. In addition, the [log feature](https://docs.rs/tracing/latest/tracing/#crate-feature-flags) is enabled which means that should a hyperlight host application not want to consume tracing events, you can still consume them as logs.
 
 ## Metrics
@@ -30,7 +30,7 @@ We might consider enabling these metrics by default in the future.
 
 ## Logs
 
-Hyperlight provides logs using the Rust [log crate](https://docs.rs/log/0.4.6/log/), and can be consumed by any Rust logger implementation, including LogTracer which can be used to emit log records as tracing events(see below for more details). To consume logs, the host application must provide a logger implementation either by using the `set_logger` function directly or using a logger implementation that is compatible with the log crate.
+Hyperlight provides logs using the Rust [tracing crate](https://docs.rs/tracing/latest/tracing/) with the [`log` feature](https://docs.rs/tracing/latest/tracing/#crate-feature-flags) enabled. This means log events can be consumed by any Rust logger implementation compatible with the [log crate](https://docs.rs/log/latest/log/). To consume logs, the host application must provide a logger implementation either by using the `set_logger` function directly or using a logger implementation that is compatible with the log crate.
 
 For an example that uses the `env_logger` crate, see the [examples/logging](../src/hyperlight_host/examples/logging) directory. By default, the `env_logger` crate will only log messages at the `error` level or higher. To see all log messages, set the `RUST_LOG` environment variable to `debug`.
 
@@ -40,7 +40,7 @@ Hyperlight also provides tracing capabilities (see below for more details), if n
 
 Tracing spans are created for any call to a public API and the parent span will be set to the current span in the host if one exists, the level of the span is set to `info`. The span will be closed when the call returns. Any Result that contains an error variant will be logged as an error event. In addition to the public APIs, all internal functions are instrumented with trace spans at the `trace` level, therefore in order to see full trace information, the trace level should be enabled.
 
-Hyperlight provides tracing using the Rust [tracing crate](https://docs.rs/tracing/0.1.37/tracing/), and can be consumed by any Rust trace subscriber implementation(see[here](https://docs.rs/tracing/latest/tracing/index.html#related-crates) for some examples). In addition to consuming trace output the log records may also be consumed by a tracing subscriber, using the `tracing-log` crate.
+Hyperlight provides tracing using the Rust [tracing crate](https://docs.rs/tracing/0.1.37/tracing/), and can be consumed by any Rust trace subscriber implementation(see[here](https://docs.rs/tracing/latest/tracing/index.html#related-crates) for some examples). When no tracing subscriber is set, trace events are automatically forwarded to the `log` facade via the `log` feature of the `tracing` crate, so consumers using only a `log` logger will still receive these events.
 
 There are two examples that show how to consume both tracing events and log records as tracing events.
 
diff --git a/src/hyperlight_host/Cargo.toml b/src/hyperlight_host/Cargo.toml
@@ -38,7 +38,6 @@ bitflags = "2.11.1"
 log = "0.4.31"
 opentelemetry = { version = "0.32.0", optional = true }
 tracing = { version = "0.1.44", features = ["log"] }
-tracing-log = "0.2.0"
 tracing-core = "0.1.36"
 tracing-opentelemetry = { version = "0.33.0", optional = true }
 hyperlight-common = { workspace = true, default-features = true, features = [ "std" ] }
diff --git a/src/hyperlight_host/src/sandbox/outb.rs b/src/hyperlight_host/src/sandbox/outb.rs
@@ -19,10 +19,9 @@ use std::sync::{Arc, Mutex};
 use hyperlight_common::flatbuffer_wrappers::function_types::{FunctionCallResult, ParameterValue};
 use hyperlight_common::flatbuffer_wrappers::guest_error::{ErrorCode, GuestError};
 use hyperlight_common::flatbuffer_wrappers::guest_log_data::GuestLogData;
+use hyperlight_common::flatbuffer_wrappers::guest_log_level::LogLevel;
 use hyperlight_common::outb::{Exception, OutBAction};
-use log::{Level, Record};
 use tracing::{Span, instrument};
-use tracing_log::format_trace;
 
 use super::host_funcs::FunctionRegistry;
 #[cfg(feature = "mem_profile")]
@@ -46,8 +45,6 @@ pub enum HandleOutbError {
     InvalidPort(String),
     #[error("Failed to read guest log data: {0}")]
     ReadLogData(String),
-    #[error("Trace formatting error: {0}")]
-    TraceFormat(String),
     #[error("Failed to read host function call: {0}")]
     ReadHostFunctionCall(String),
     #[error("Failed to acquire lock at {0}:{1} - {2}")]
@@ -65,64 +62,77 @@ pub enum HandleOutbError {
 pub(super) fn outb_log(
     mgr: &mut SandboxMemoryManager<HostSharedMemory>,
 ) -> Result<(), HandleOutbError> {
-    // This code will create either a logging record or a tracing record for the GuestLogData depending on if the host has set up a tracing subscriber.
-    // In theory as we have enabled the log feature in the Cargo.toml for tracing this should happen
-    // automatically (based on if there is tracing subscriber present) but only works if the event created using macros. (see https://github.com/tokio-rs/tracing/blob/master/tracing/src/macros.rs#L2421 )
-    // The reason that we don't want to use the tracing macros is that we want to be able to explicitly
-    // set the file and line number for the log record which is not possible with macros.
-    // This is because the file and line number come from the  guest not the call site.
-
     let log_data: GuestLogData = mgr
         .read_guest_log_data()
         .map_err(|e| HandleOutbError::ReadLogData(e.to_string()))?;
 
-    let record_level: Level = (&log_data.level).into();
-
-    // Work out if we need to log or trace
-    // this API is marked as follows but it is the easiest way to work out if we should trace or log
-
-    // Private API for internal use by tracing's macros.
+    // Emit guest log data as a tracing event with structured fields.
     //
-    // This function is *not* considered part of `tracing`'s public API, and has no
-    // stability guarantees. If you use it, and it breaks or disappears entirely,
-    // don't say we didn't warn you.
-
-    let should_trace = tracing_core::dispatcher::has_been_set();
-    let source_file = Some(log_data.source_file.as_str());
-    let line = Some(log_data.line);
-    let source = Some(log_data.source.as_str());
-
-    // See https://github.com/rust-lang/rust/issues/42253 for the reason this has to be done this way
-
-    if should_trace {
-        // Create a tracing event for the GuestLogData
-        // Ideally we would create tracing metadata based on the Guest Log Data
-        // but tracing derives the metadata at compile time
-        // see https://github.com/tokio-rs/tracing/issues/2419
-        // so we leave it up to the subscriber to figure out that there are logging fields present with this data
-        format_trace(
-            &Record::builder()
-                .args(format_args!("{}", log_data.message))
-                .level(record_level)
-                .target("hyperlight_guest")
-                .file(source_file)
-                .line(line)
-                .module_path(source)
-                .build(),
-        )
-        .map_err(|e| HandleOutbError::TraceFormat(e.to_string()))?;
-    } else {
-        // Create a log record for the GuestLogData
-        log::logger().log(
-            &Record::builder()
-                .args(format_args!("{}", log_data.message))
-                .level(record_level)
-                .target("hyperlight_guest")
-                .file(Some(&log_data.source_file))
-                .line(Some(log_data.line))
-                .module_path(Some(&log_data.source))
-                .build(),
-        );
+    // We match on the level at runtime because tracing macros determine their
+    // level at compile time. Guest file/line/module are passed as structured
+    // fields (rather than tracing metadata) because they originate from the
+    // guest, not from this call site.
+    //
+    // Consumers using a `log` logger (without a tracing subscriber) still
+    // receive these events thanks to the `tracing` crate's `log` feature,
+    // which forwards tracing events to the `log` facade when no subscriber
+    // is set.
+    let source_file = log_data.source_file.as_str();
+    let line = log_data.line;
+    let source = log_data.source.as_str();
+    let message = log_data.message.as_str();
+
+    match &log_data.level {
+        LogLevel::Error | LogLevel::Critical => {
+            tracing::error!(
+                target: "hyperlight_guest",
+                guest_file = source_file,
+                guest_line = line,
+                guest_module = source,
+                "{}",
+                message
+            );
+        }
+        LogLevel::Warning => {
+            tracing::warn!(
+                target: "hyperlight_guest",
+                guest_file = source_file,
+                guest_line = line,
+                guest_module = source,
+                "{}",
+                message
+            );
+        }
+        LogLevel::Information => {
+            tracing::info!(
+                target: "hyperlight_guest",
+                guest_file = source_file,
+                guest_line = line,
+                guest_module = source,
+                "{}",
+                message
+            );
+        }
+        LogLevel::Debug => {
+            tracing::debug!(
+                target: "hyperlight_guest",
+                guest_file = source_file,
+                guest_line = line,
+                guest_module = source,
+                "{}",
+                message
+            );
+        }
+        LogLevel::Trace | LogLevel::None => {
+            tracing::trace!(
+                target: "hyperlight_guest",
+                guest_file = source_file,
+                guest_line = line,
+                guest_module = source,
+                "{}",
+                message
+            );
+        }
     }
 
     Ok(())
@@ -240,7 +250,6 @@ mod tests {
     use hyperlight_common::flatbuffer_wrappers::guest_log_level::LogLevel;
     use hyperlight_testing::logger::{LOGGER, Logger};
     use hyperlight_testing::simple_guest_as_string;
-    use log::Level;
     use tracing_core::callsite::rebuild_interest_cache;
 
     use super::outb_log;
@@ -261,6 +270,10 @@ mod tests {
         )
     }
 
+    // Verifies that guest log events are forwarded to a `log` logger when no
+    // tracing subscriber is set. This exercises the `tracing` crate's built-in
+    // `log` compatibility feature, proving that consumers who only set up a
+    // `log` logger (not a tracing subscriber) still receive guest output.
     #[test]
     #[ignore]
     fn test_log_outb_log() {
@@ -338,17 +351,22 @@ mod tests {
                 outb_log(&mut mgr).unwrap();
 
                 LOGGER.test_log_records(|log_calls| {
-                    let expected_level: Level = (&level).into();
+                    let expected_level: tracing::Level = match level {
+                        LogLevel::Trace => tracing::Level::TRACE,
+                        LogLevel::Debug => tracing::Level::DEBUG,
+                        LogLevel::Information => tracing::Level::INFO,
+                        LogLevel::Warning => tracing::Level::WARN,
+                        LogLevel::Error => tracing::Level::ERROR,
+                        LogLevel::Critical => tracing::Level::ERROR,
+                        LogLevel::None => tracing::Level::TRACE,
+                    };
 
                     assert!(
                         log_calls
                             .iter()
                             .filter(|log_call| {
-                                log_call.level == expected_level
-                                    && log_call.line == Some(log_data.line)
-                                    && log_call.args == log_data.message
-                                    && log_call.module_path == Some(log_data.source.clone())
-                                    && log_call.file == Some(log_data.source_file.clone())
+                                log_call.level.as_str() == expected_level.as_str()
+                                    && log_call.args.contains("test log")
                             })
                             .count()
                             == 1,
@@ -426,13 +444,9 @@ mod tests {
 
                     // We cannot get the parent span using the `current_span()` method as by the time we get to this point that span has been exited so there is no current span
                     // We need to make sure that the span that we created is in the spans map instead
-                    // We expect to have created 21 spans at this point. We are only interested in the first one that was created when calling outb_log.
+                    // We are only interested in the first one that was created when calling outb_log.
 
-                    assert!(
-                        spans.len() == 21,
-                        "expected 21 spans, found {}",
-                        spans.len()
-                    );
+                    assert!(!spans.is_empty(), "expected at least one span, found none");
 
                     let span_value = spans
                         .get(&1)
@@ -468,9 +482,9 @@ mod tests {
                             event_values.get("metadata").unwrap().as_object().unwrap();
                         let event_values_map = event_values.as_object().unwrap();
                         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, "guest_file", "test source file");
+                        test_value_as_str(event_values_map, "guest_module", "test source");
+                        test_value_as_str(metadata_values_map, "target", "hyperlight_guest");
                         count_matching_events += 1;
                     }
                     assert!(
diff --git a/src/hyperlight_host/tests/integration_test.rs b/src/hyperlight_host/tests/integration_test.rs
@@ -928,7 +928,7 @@ fn interrupt_random_kill_stress_test() {
     use std::sync::atomic::AtomicUsize;
 
     use hyperlight_host::sandbox::snapshot::Snapshot;
-    use log::{error, trace};
+    use tracing::{error, trace};
 
     const POOL_SIZE: usize = 100;
     const NUM_THREADS: usize = 100;
diff --git a/src/tests/rust_guests/simpleguest/src/main.rs b/src/tests/rust_guests/simpleguest/src/main.rs
@@ -54,8 +54,10 @@ use hyperlight_guest_bin::host_comm::{
 };
 use hyperlight_guest_bin::memory::malloc;
 use hyperlight_guest_bin::{GUEST_HANDLE, guest_function, guest_logger, host_function};
-use log::{LevelFilter, error};
-use tracing::{Span, instrument};
+// `log` is intentionally kept here: the LogMessage guest function exercises the
+// guest-side `log` crate path to verify that guests using `log` are still supported.
+use log::LevelFilter;
+use tracing::{Span, error, instrument};
 
 extern crate hyperlight_guest;
 
@@ -962,7 +964,7 @@ fn call_host_then_spin(host_func_name: String) -> Result<()> {
 #[instrument(skip_all, parent = Span::current(), level= "Trace")]
 fn fuzz_traced_function(depth: u32, max_depth: u32, msg: &str) -> u32 {
     if depth < max_depth {
-        log::info!("{}", msg);
+        tracing::info!("{}", msg);
 
         fuzz_traced_function(depth + 1, max_depth, msg) + 1
     } else {
