Skip to content

Commit 14bbdd0

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 cdb87f1 commit 14bbdd0

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
@@ -213,7 +213,6 @@ test-unit target=default-target features="":
213213

214214
# runs tests that requires being run separately, for example due to global state
215215
test-isolated target=default-target features="" :
216-
{{ 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
217216
{{ 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
218217
{{ 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
219218
{{ 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
@@ -761,115 +761,90 @@ mod tests {
761761
}
762762
}
763763

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

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

819-
let sbox = UninitializedSandbox::new(GuestBinary::FilePath(binary_path), None);
820-
assert!(sbox.is_err());
783+
/// Helper to extract event field: obj["event"][field]
784+
fn get_event_field<'a>(event: &'a serde_json::Value, field: &str) -> Option<&'a str> {
785+
event.get("event")?.get(field)?.as_str()
786+
}
821787

822-
// 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)
788+
/// Helper to extract event metadata field: obj["event"]["metadata"][field]
789+
fn get_event_metadata<'a>(event: &'a serde_json::Value, field: &str) -> Option<&'a str> {
790+
event.get("event")?.get("metadata")?.get(field)?.as_str()
791+
}
823792

824-
let current_span = subscriber.current_span();
825-
assert!(current_span.is_known(), "Current span is unknown");
826-
let current_span_metadata = current_span.into_inner().unwrap();
827-
assert_eq!(
828-
current_span_metadata.0.into_u64(),
829-
1,
830-
"Current span is not span 1"
831-
);
793+
let subscriber = TracingSubscriber::new(Level::TRACE);
832794

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

836-
// 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
834+
let event = &events[0];
835+
let level = get_event_metadata(event, "level").expect("event should have level");
836+
let error = get_event_field(event, "error").expect("event should have error field");
837+
let target = get_event_metadata(event, "target").expect("event should have target");
838+
let module_path =
839+
get_event_metadata(event, "module_path").expect("event should have module_path");
837840

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

‎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)