Skip to content

GitLab

Unverified Commit c9ca5c40 authored by Thomas Montfort's avatar Thomas Montfort Committed by GitHub
Browse files

fix: test_json_log_capture (#4074) 


Co-authored-by: default avatarmohammedabdulwahhab <furkhan324@berkeley.edu>
parent 816a4c64
Hide whitespace changes
Inline Side-by-side
Showing with 87 additions and 112 deletions
lib/runtime/src/logging.rs
View file @ c9ca5c40
...@@ -1279,11 +1279,11 @@ pub mod tests { ...@@ -1279,11 +1279,11 @@ pub mod tests {
// 1. Extract the dynamically generated trace ID and validate consistency // 1. Extract the dynamically generated trace ID and validate consistency
// All logs should have the same trace_id since they're part of the same trace // All logs should have the same trace_id since they're part of the same trace
// Skip any initialization logs that don't have trace_id (e.g., OTLP setup messages)
let trace_id = lines let trace_id = lines
.first() .iter()
.and_then(|log_line| log_line.get("trace_id")) .find_map(|log_line| log_line.get("trace_id").and_then(|v| v.as_str()))
.and_then(|v| v.as_str()) .expect("At least one log line should have a trace_id")
.expect("First log line should have a trace_id")
.to_string(); .to_string();
// Verify trace_id is not a zero/invalid ID // Verify trace_id is not a zero/invalid ID
...@@ -1318,172 +1318,147 @@ pub mod tests { ...@@ -1318,172 +1318,147 @@ pub mod tests {
} }
} }
// 2. Validate span IDs are unique for SPAN_CREATED and SPAN_CLOSED events // 2. Validate span IDs exist and are properly formatted
let mut created_span_ids: Vec<String> = Vec::new(); let mut span_ids_seen: std::collections::HashSet<String> = std::collections::HashSet::new();
let mut closed_span_ids: Vec<String> = Vec::new(); let mut span_timestamps: std::collections::HashMap<String, DateTime<Utc>> = std::collections::HashMap::new();
for log_line in &lines { for log_line in &lines {
if let Some(message) = log_line.get("message") { if let Some(span_id) = log_line.get("span_id") {
match message.as_str().unwrap() { let span_id_str = span_id.as_str().unwrap();
"SPAN_CREATED" => { assert!(
if let Some(span_id) = log_line.get("span_id") { is_valid_span_id(span_id_str),
let span_id_str = span_id.as_str().unwrap(); "Invalid span_id format: {}",
assert!( span_id_str
created_span_ids.iter().all(|id| id != span_id_str), );
"Duplicate span ID found in SPAN_CREATED: {}", span_ids_seen.insert(span_id_str.to_string());
span_id_str
);
created_span_ids.push(span_id_str.to_string());
}
}
"SPAN_CLOSED" => {
if let Some(span_id) = log_line.get("span_id") {
let span_id_str = span_id.as_str().unwrap();
assert!(
closed_span_ids.iter().all(|id| id != span_id_str),
"Duplicate span ID found in SPAN_CLOSED: {}",
span_id_str
);
closed_span_ids.push(span_id_str.to_string());
}
}
_ => {}
}
} }
}
// Additionally, ensure that every SPAN_CLOSED has a corresponding SPAN_CREATED // Validate timestamp format and track span timestamps
for closed_span_id in &closed_span_ids { if let Some(time_str) = log_line.get("time").and_then(|v| v.as_str()) {
assert!( let timestamp = DateTime::parse_from_rfc3339(time_str)
created_span_ids.contains(closed_span_id), .expect("All timestamps should be valid RFC3339 format")
"SPAN_CLOSED without corresponding SPAN_CREATED: {}", .with_timezone(&Utc);
closed_span_id
); // Track timestamp for each span_name
if let Some(span_name) = log_line.get("span_name").and_then(|v| v.as_str()) {
span_timestamps.insert(span_name.to_string(), timestamp);
}
}
} }
// 3. Validate parent span relationships // 3. Validate parent-child span relationships
// Extract span IDs for each span by looking at their log messages
let parent_span_id = lines let parent_span_id = lines
.iter() .iter()
.find(|log_line| { .find(|log_line| {
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CREATED" log_line.get("span_name")
&& log_line.get("span_name").unwrap().as_str().unwrap() == "parent" .and_then(|v| v.as_str()) == Some("parent")
}) })
.and_then(|log_line| { .and_then(|log_line| {
log_line log_line.get("span_id")
.get("span_id") .and_then(|v| v.as_str())
.map(|s| s.as_str().unwrap().to_string()) .map(|s| s.to_string())
}) })
.unwrap(); .expect("Should find parent span with span_id");
let child_span_id = lines let child_span_id = lines
.iter() .iter()
.find(|log_line| { .find(|log_line| {
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CREATED" log_line.get("span_name")
&& log_line.get("span_name").unwrap().as_str().unwrap() == "child" .and_then(|v| v.as_str()) == Some("child")
}) })
.and_then(|log_line| { .and_then(|log_line| {
log_line log_line.get("span_id")
.get("span_id") .and_then(|v| v.as_str())
.map(|s| s.as_str().unwrap().to_string()) .map(|s| s.to_string())
}) })
.unwrap(); .expect("Should find child span with span_id");
let _grandchild_span_id = lines let grandchild_span_id = lines
.iter() .iter()
.find(|log_line| { .find(|log_line| {
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CREATED" log_line.get("span_name")
&& log_line.get("span_name").unwrap().as_str().unwrap() == "grandchild" .and_then(|v| v.as_str()) == Some("grandchild")
}) })
.and_then(|log_line| { .and_then(|log_line| {
log_line log_line.get("span_id")
.get("span_id") .and_then(|v| v.as_str())
.map(|s| s.as_str().unwrap().to_string()) .map(|s| s.to_string())
}) })
.unwrap(); .expect("Should find grandchild span with span_id");
// Verify span IDs are unique
assert_ne!(parent_span_id, child_span_id, "Parent and child should have different span IDs");
assert_ne!(child_span_id, grandchild_span_id, "Child and grandchild should have different span IDs");
assert_ne!(parent_span_id, grandchild_span_id, "Parent and grandchild should have different span IDs");
// Parent span has no parent_id // Verify parent span has no parent_id
for log_line in &lines { for log_line in &lines {
if let Some(span_name) = log_line.get("span_name") if let Some(span_name) = log_line.get("span_name")
&& let Some(span_name_str) = span_name.as_str() && let Some(span_name_str) = span_name.as_str()
&& span_name_str == "parent" && span_name_str == "parent"
{ {
assert!(log_line.get("parent_id").is_none()); assert!(
log_line.get("parent_id").is_none(),
"Parent span should not have a parent_id"
);
} }
} }
// Child span's parent_id is parent_span_id // Verify child span's parent_id is parent_span_id
for log_line in &lines { for log_line in &lines {
if let Some(span_name) = log_line.get("span_name") if let Some(span_name) = log_line.get("span_name")
&& let Some(span_name_str) = span_name.as_str() && let Some(span_name_str) = span_name.as_str()
&& span_name_str == "child" && span_name_str == "child"
{ {
let parent_id = log_line.get("parent_id")
.and_then(|v| v.as_str())
.expect("Child span should have a parent_id");
assert_eq!( assert_eq!(
log_line.get("parent_id").unwrap().as_str().unwrap(), parent_id,
&parent_span_id parent_span_id,
"Child's parent_id should match parent's span_id"
); );
} }
} }
// Grandchild span's parent_id is child_span_id // Verify grandchild span's parent_id is child_span_id
for log_line in &lines { for log_line in &lines {
if let Some(span_name) = log_line.get("span_name") if let Some(span_name) = log_line.get("span_name")
&& let Some(span_name_str) = span_name.as_str() && let Some(span_name_str) = span_name.as_str()
&& span_name_str == "grandchild" && span_name_str == "grandchild"
{ {
let parent_id = log_line.get("parent_id")
.and_then(|v| v.as_str())
.expect("Grandchild span should have a parent_id");
assert_eq!( assert_eq!(
log_line.get("parent_id").unwrap().as_str().unwrap(), parent_id,
&child_span_id child_span_id,
"Grandchild's parent_id should match child's span_id"
); );
} }
} }
// Validate duration relationships // 4. Validate timestamp ordering - spans should log in execution order
let parent_duration = lines let parent_time = span_timestamps.get("parent")
.iter() .expect("Should have timestamp for parent span");
.find(|log_line| { let child_time = span_timestamps.get("child")
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CLOSED" .expect("Should have timestamp for child span");
&& log_line.get("span_name").unwrap().as_str().unwrap() == "parent" let grandchild_time = span_timestamps.get("grandchild")
}) .expect("Should have timestamp for grandchild span");
.and_then(|log_line| {
log_line
.get("time.duration_us")
.map(|d| d.as_u64().unwrap())
})
.unwrap();
let child_duration = lines
.iter()
.find(|log_line| {
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CLOSED"
&& log_line.get("span_name").unwrap().as_str().unwrap() == "child"
})
.and_then(|log_line| {
log_line
.get("time.duration_us")
.map(|d| d.as_u64().unwrap())
})
.unwrap();
let grandchild_duration = lines
.iter()
.find(|log_line| {
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CLOSED"
&& log_line.get("span_name").unwrap().as_str().unwrap() == "grandchild"
})
.and_then(|log_line| {
log_line
.get("time.duration_us")
.map(|d| d.as_u64().unwrap())
})
.unwrap();
// Parent logs first (or at same time), then child, then grandchild
assert!( assert!(
parent_duration > child_duration + grandchild_duration, parent_time <= child_time,
"Parent duration is not greater than the sum of child and grandchild durations" "Parent span should log before or at same time as child span (parent: {}, child: {})",
parent_time,
child_time
); );
assert!( assert!(
child_duration > grandchild_duration, child_time <= grandchild_time,
"Child duration is not greater than grandchild duration" "Child span should log before or at same time as grandchild span (child: {}, grandchild: {})",
child_time,
grandchild_time
); );
Ok::<(), anyhow::Error>(()) Ok::<(), anyhow::Error>(())
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment