Skip to content

Commit bcb8f97

Browse files
ludfjigludfjig
committed
Allow test_trace_trace to run concurrently (by removing unused TestLogger)
Signed-off-by: Ludvig Liljenberg <4257730+ludfjig@users.noreply.github.com>
1 parent b92b32a commit bcb8f97

File tree

3 files changed

+70
-160
lines changed

3 files changed

+70
-160
lines changed

‎Justfile‎

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -163,7 +163,6 @@ test-unit target=default-target features="":
163163

164164
# runs tests that requires being run separately, for example due to global state
165165
test-isolated target=default-target features="" :
166-
{{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F init-paging," + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::uninitialized::tests::test_trace_trace --exact --ignored
167166
{{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F init-paging," + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::uninitialized::tests::test_log_trace --exact --ignored
168167
{{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F init-paging," + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::outb::tests::test_log_outb_log --exact --ignored
169168
{{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F init-paging," + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --test integration_test -- log_message --exact --ignored

‎src/hyperlight_host/src/sandbox/uninitialized.rs‎

Lines changed: 70 additions & 95 deletions
Original file line numberDiff line numberDiff line change
@@ -758,115 +758,90 @@ mod tests {
758758
}
759759
}
760760

761+
/// Tests that tracing spans and events are properly emitted when a tracing subscriber is set.
762+
///
763+
/// This test verifies:
764+
/// 1. Spans are created with correct attributes (correlation_id)
765+
/// 2. Nested spans from UninitializedSandbox::new are properly parented
766+
/// 3. Error events are emitted when sandbox creation fails
761767
#[test]
762-
// Tests that trace data are emitted when a trace subscriber is set
763-
// this test is ignored because it is incompatible with other tests , specifically those which require a logger for tracing
764-
// marking this test as ignored means that running `cargo test` will not run this test but will allow a developer who runs that command
765-
// from their workstation to be successful without needed to know about test interdependencies
766-
// this test will be run explicitly as a part of the CI pipeline
767-
#[ignore]
768768
#[cfg(feature = "build-metadata")]
769769
fn test_trace_trace() {
770-
use hyperlight_testing::logger::Logger as TestLogger;
771-
use hyperlight_testing::tracing_subscriber::TracingSubscriber as TestSubscriber;
772-
use serde_json::{Map, Value};
773-
use tracing::Level as tracing_level;
770+
use hyperlight_testing::tracing_subscriber::TracingSubscriber;
771+
use tracing::Level;
774772
use tracing_core::Subscriber;
775-
use tracing_core::callsite::rebuild_interest_cache;
776773
use uuid::Uuid;
777774

778-
use crate::testing::log_values::build_metadata_testing::try_to_strings;
779-
use crate::testing::log_values::test_value_as_str;
780-
781-
TestLogger::initialize_log_tracer();
782-
rebuild_interest_cache();
783-
let subscriber = TestSubscriber::new(tracing_level::TRACE);
784-
tracing::subscriber::with_default(subscriber.clone(), || {
785-
let correlation_id = Uuid::new_v4().as_hyphenated().to_string();
786-
let span = tracing::error_span!("test_trace_logs", correlation_id).entered();
787-
788-
// We should be in span 1
789-
790-
let current_span = subscriber.current_span();
791-
assert!(current_span.is_known(), "Current span is unknown");
792-
let current_span_metadata = current_span.into_inner().unwrap();
793-
assert_eq!(
794-
current_span_metadata.0.into_u64(),
795-
1,
796-
"Current span is not span 1"
797-
);
798-
assert_eq!(current_span_metadata.1.name(), "test_trace_logs");
799-
800-
// Get the span data and check the correlation id
801-
802-
let span_data = subscriber.get_span(1);
803-
let span_attributes: &Map<String, Value> = span_data
804-
.get("span")
805-
.unwrap()
806-
.get("attributes")
807-
.unwrap()
808-
.as_object()
809-
.unwrap();
810-
811-
test_value_as_str(span_attributes, "correlation_id", correlation_id.as_str());
812-
813-
let mut binary_path = simple_guest_as_string().unwrap();
814-
binary_path.push_str("does_not_exist");
775+
/// Helper to extract a string value from nested JSON: obj["span"]["attributes"][key]
776+
fn get_span_attr<'a>(span: &'a serde_json::Value, key: &str) -> Option<&'a str> {
777+
span.get("span")?.get("attributes")?.get(key)?.as_str()
778+
}
815779

816-
let sbox = UninitializedSandbox::new(GuestBinary::FilePath(binary_path), None);
817-
assert!(sbox.is_err());
780+
/// Helper to extract event field: obj["event"][field]
781+
fn get_event_field<'a>(event: &'a serde_json::Value, field: &str) -> Option<&'a str> {
782+
event.get("event")?.get(field)?.as_str()
783+
}
818784

819-
// Now we should still be in span 1 but span 2 should be created (we created entered and exited span 2 when we called UninitializedSandbox::new)
785+
/// Helper to extract event metadata field: obj["event"]["metadata"][field]
786+
fn get_event_metadata<'a>(event: &'a serde_json::Value, field: &str) -> Option<&'a str> {
787+
event.get("event")?.get("metadata")?.get(field)?.as_str()
788+
}
820789

821-
let current_span = subscriber.current_span();
822-
assert!(current_span.is_known(), "Current span is unknown");
823-
let current_span_metadata = current_span.into_inner().unwrap();
824-
assert_eq!(
825-
current_span_metadata.0.into_u64(),
826-
1,
827-
"Current span is not span 1"
828-
);
790+
let subscriber = TracingSubscriber::new(Level::TRACE);
829791

830-
let span_metadata = subscriber.get_span_metadata(2);
831-
assert_eq!(span_metadata.name(), "new");
792+
tracing::subscriber::with_default(subscriber.clone(), || {
793+
let correlation_id = Uuid::new_v4().to_string();
794+
let _span = tracing::error_span!("test_trace_logs", %correlation_id).entered();
795+
796+
// Verify we're in span 1 with correct name
797+
let (span_id, span_meta) = subscriber
798+
.current_span()
799+
.into_inner()
800+
.expect("Should be inside a span");
801+
assert_eq!(span_id.into_u64(), 1, "Should be in span 1");
802+
assert_eq!(span_meta.name(), "test_trace_logs");
803+
804+
// Verify correlation_id was recorded
805+
let span_data = subscriber.get_span(1);
806+
let recorded_id =
807+
get_span_attr(&span_data, "correlation_id").expect("correlation_id not found");
808+
assert_eq!(recorded_id, correlation_id);
809+
810+
// Try to create a sandbox with a non-existent binary - this should fail
811+
// and emit an error event
812+
let bad_path = simple_guest_as_string().unwrap() + "does_not_exist";
813+
let result = UninitializedSandbox::new(GuestBinary::FilePath(bad_path), None);
814+
assert!(result.is_err(), "Sandbox creation should fail");
815+
816+
// Verify we're still in span 1 (our test span)
817+
let (span_id, _) = subscriber
818+
.current_span()
819+
.into_inner()
820+
.expect("Should still be inside a span");
821+
assert_eq!(span_id.into_u64(), 1, "Should still be in span 1");
822+
823+
// Verify span 2 was created by UninitializedSandbox::new
824+
let inner_span_meta = subscriber.get_span_metadata(2);
825+
assert_eq!(inner_span_meta.name(), "new");
826+
827+
// Verify the error event was emitted
828+
let events = subscriber.get_events();
829+
assert_eq!(events.len(), 1, "Expected exactly one error event");
832830

833-
// There should be one event for the error that the binary path does not exist plus 14 info events for the logging of the crate info
831+
let event = &events[0];
832+
let level = get_event_metadata(event, "level").expect("event should have level");
833+
let error = get_event_field(event, "error").expect("event should have error field");
834+
let target = get_event_metadata(event, "target").expect("event should have target");
835+
let module_path =
836+
get_event_metadata(event, "module_path").expect("event should have module_path");
834837

835-
let events = subscriber.get_events();
836-
assert_eq!(events.len(), 1);
837-
838-
let mut count_matching_events = 0;
839-
840-
for json_value in events {
841-
let event_values = json_value.as_object().unwrap().get("event").unwrap();
842-
let metadata_values_map =
843-
event_values.get("metadata").unwrap().as_object().unwrap();
844-
let event_values_map = event_values.as_object().unwrap();
845-
846-
let expected_error_start = "Error(\"GuestBinary not found:";
847-
848-
let err_vals_res = try_to_strings([
849-
(metadata_values_map, "level"),
850-
(event_values_map, "error"),
851-
(metadata_values_map, "module_path"),
852-
(metadata_values_map, "target"),
853-
]);
854-
if let Ok(err_vals) = err_vals_res
855-
&& err_vals[0] == "ERROR"
856-
&& err_vals[1].starts_with(expected_error_start)
857-
&& err_vals[2] == "hyperlight_host::sandbox::uninitialized"
858-
&& err_vals[3] == "hyperlight_host::sandbox::uninitialized"
859-
{
860-
count_matching_events += 1;
861-
}
862-
}
838+
assert_eq!(level, "ERROR");
863839
assert!(
864-
count_matching_events == 1,
865-
"Unexpected number of matching events {}",
866-
count_matching_events
840+
error.contains("GuestBinary not found"),
841+
"Error should mention 'GuestBinary not found', got: {error}"
867842
);
868-
span.exit();
869-
subscriber.clear();
843+
assert_eq!(target, "hyperlight_host::sandbox::uninitialized");
844+
assert_eq!(module_path, "hyperlight_host::sandbox::uninitialized");
870845
});
871846
}
872847

‎src/hyperlight_host/src/testing/log_values.rs‎

Lines changed: 0 additions & 64 deletions
Original file line numberDiff line numberDiff line change
@@ -60,67 +60,3 @@ fn try_to_string<'a>(values: &'a Map<String, Value>, key: &'a str) -> Result<&'a
6060
Err(new_error!("value for key {} was not found", key))
6161
}
6262
}
63-
64-
#[cfg(feature = "build-metadata")]
65-
pub(crate) mod build_metadata_testing {
66-
use super::*;
67-
68-
/// A single value in the parameter list for the `try_to_strings`
69-
/// function.
70-
pub(crate) type MapLookup<'a> = (&'a Map<String, Value>, &'a str);
71-
72-
/// Given a constant-size slice of `MapLookup`s, attempt to look up the
73-
/// string value in each `MapLookup`'s map (the first tuple element) for
74-
/// that `MapLookup`'s key (the second tuple element). If the lookup
75-
/// succeeded, attempt to convert the resulting value to a string. Return
76-
/// `Ok` with all the successfully looked-up string values, or `Err`
77-
/// if any one or more lookups or string conversions failed.
78-
pub(crate) fn try_to_strings<'a, const NUM: usize>(
79-
lookups: [MapLookup<'a>; NUM],
80-
) -> Result<[&'a str; NUM]> {
81-
// Note (from arschles) about this code:
82-
//
83-
// In theory, there's a way to write this function in the functional
84-
// programming (FP) style -- e.g. with a fold, map, flat_map, or
85-
// something similar -- and without any mutability.
86-
//
87-
// In practice, however, since we're taking in a statically-sized slice,
88-
// and we are expected to return a statically-sized slice of the same
89-
// size, we are more limited in what we can do. There is a way to design
90-
// a fold or flat_map to iterate over the lookups parameter and attempt to
91-
// transform each MapLookup into the string value at that key.
92-
//
93-
// I wrote that code, which I'll called the "FP code" hereafter, and
94-
// noticed two things:
95-
//
96-
// - It required several places where I had to explicitly deal with long
97-
// and complex (in my opinion) types
98-
// - It wasn't much more succinct or shorter than the code herein
99-
//
100-
// The FP code is functionally "pure" and maybe fun to write (if you like
101-
// Rust or you love FP), but not fun to read. In fact, because of all the
102-
// explicit type ceremony, I bet it'd make even the most hardcore Haskell
103-
// programmer blush.
104-
//
105-
// So, I've decided to use a little bit of mutability to implement this
106-
// function in a way I think most programmers would agree is easier to
107-
// reason about and understand quickly.
108-
//
109-
// Final performance note:
110-
//
111-
// It's likely, but not certain, that the FP code is probably not
112-
// significantly more memory efficient than this, since the compiler knows
113-
// the size of both the input and output slices. Plus, this is test code,
114-
// so even if this were 2x slower, I'd still argue the ease of
115-
// understanding is more valuable than the (relatively small) memory
116-
// savings.
117-
let mut ret_slc: [&'a str; NUM] = [""; NUM];
118-
for (idx, lookup) in lookups.iter().enumerate() {
119-
let map = lookup.0;
120-
let key = lookup.1;
121-
let val = try_to_string(map, key)?;
122-
ret_slc[idx] = val
123-
}
124-
Ok(ret_slc)
125-
}
126-
}

0 commit comments

Comments
 (0)