Skip to content

Commit c9ca5c4

Browse files
tmonty12mohammedabdulwahhab
tmonty12
and
mohammedabdulwahhab
authored
fix: test_json_log_capture (#4074)
Co-authored-by: mohammedabdulwahhab <[email protected]>
1 parent 816a4c6 commit c9ca5c4

File tree

1 file changed

+87
-112
lines changed

1 file changed

+87
-112
lines changed

‎lib/runtime/src/logging.rs‎

Lines changed: 87 additions & 112 deletions
Original file line numberDiff line numberDiff line change
@@ -1279,11 +1279,11 @@ pub mod tests {
12791279

12801280
// 1. Extract the dynamically generated trace ID and validate consistency
12811281
// All logs should have the same trace_id since they're part of the same trace
1282+
// Skip any initialization logs that don't have trace_id (e.g., OTLP setup messages)
12821283
let trace_id = lines
1283-
.first()
1284-
.and_then(|log_line| log_line.get("trace_id"))
1285-
.and_then(|v| v.as_str())
1286-
.expect("First log line should have a trace_id")
1284+
.iter()
1285+
.find_map(|log_line| log_line.get("trace_id").and_then(|v| v.as_str()))
1286+
.expect("At least one log line should have a trace_id")
12871287
.to_string();
12881288

12891289
// Verify trace_id is not a zero/invalid ID
@@ -1318,172 +1318,147 @@ pub mod tests {
13181318
}
13191319
}
13201320

1321-
// 2. Validate span IDs are unique for SPAN_CREATED and SPAN_CLOSED events
1322-
let mut created_span_ids: Vec<String> = Vec::new();
1323-
let mut closed_span_ids: Vec<String> = Vec::new();
1321+
// 2. Validate span IDs exist and are properly formatted
1322+
let mut span_ids_seen: std::collections::HashSet<String> = std::collections::HashSet::new();
1323+
let mut span_timestamps: std::collections::HashMap<String, DateTime<Utc>> = std::collections::HashMap::new();
13241324

13251325
for log_line in &lines {
1326-
if let Some(message) = log_line.get("message") {
1327-
match message.as_str().unwrap() {
1328-
"SPAN_CREATED" => {
1329-
if let Some(span_id) = log_line.get("span_id") {
1330-
let span_id_str = span_id.as_str().unwrap();
1331-
assert!(
1332-
created_span_ids.iter().all(|id| id != span_id_str),
1333-
"Duplicate span ID found in SPAN_CREATED: {}",
1334-
span_id_str
1335-
);
1336-
created_span_ids.push(span_id_str.to_string());
1337-
}
1338-
}
1339-
"SPAN_CLOSED" => {
1340-
if let Some(span_id) = log_line.get("span_id") {
1341-
let span_id_str = span_id.as_str().unwrap();
1342-
assert!(
1343-
closed_span_ids.iter().all(|id| id != span_id_str),
1344-
"Duplicate span ID found in SPAN_CLOSED: {}",
1345-
span_id_str
1346-
);
1347-
closed_span_ids.push(span_id_str.to_string());
1348-
}
1349-
}
1350-
_ => {}
1351-
}
1326+
if let Some(span_id) = log_line.get("span_id") {
1327+
let span_id_str = span_id.as_str().unwrap();
1328+
assert!(
1329+
is_valid_span_id(span_id_str),
1330+
"Invalid span_id format: {}",
1331+
span_id_str
1332+
);
1333+
span_ids_seen.insert(span_id_str.to_string());
13521334
}
1353-
}
13541335

1355-
// Additionally, ensure that every SPAN_CLOSED has a corresponding SPAN_CREATED
1356-
for closed_span_id in &closed_span_ids {
1357-
assert!(
1358-
created_span_ids.contains(closed_span_id),
1359-
"SPAN_CLOSED without corresponding SPAN_CREATED: {}",
1360-
closed_span_id
1361-
);
1336+
// Validate timestamp format and track span timestamps
1337+
if let Some(time_str) = log_line.get("time").and_then(|v| v.as_str()) {
1338+
let timestamp = DateTime::parse_from_rfc3339(time_str)
1339+
.expect("All timestamps should be valid RFC3339 format")
1340+
.with_timezone(&Utc);
1341+
1342+
// Track timestamp for each span_name
1343+
if let Some(span_name) = log_line.get("span_name").and_then(|v| v.as_str()) {
1344+
span_timestamps.insert(span_name.to_string(), timestamp);
1345+
}
1346+
}
13621347
}
13631348

1364-
// 3. Validate parent span relationships
1349+
// 3. Validate parent-child span relationships
1350+
// Extract span IDs for each span by looking at their log messages
13651351
let parent_span_id = lines
13661352
.iter()
13671353
.find(|log_line| {
1368-
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CREATED"
1369-
&& log_line.get("span_name").unwrap().as_str().unwrap() == "parent"
1354+
log_line.get("span_name")
1355+
.and_then(|v| v.as_str()) == Some("parent")
13701356
})
13711357
.and_then(|log_line| {
1372-
log_line
1373-
.get("span_id")
1374-
.map(|s| s.as_str().unwrap().to_string())
1358+
log_line.get("span_id")
1359+
.and_then(|v| v.as_str())
1360+
.map(|s| s.to_string())
13751361
})
1376-
.unwrap();
1362+
.expect("Should find parent span with span_id");
13771363

13781364
let child_span_id = lines
13791365
.iter()
13801366
.find(|log_line| {
1381-
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CREATED"
1382-
&& log_line.get("span_name").unwrap().as_str().unwrap() == "child"
1367+
log_line.get("span_name")
1368+
.and_then(|v| v.as_str()) == Some("child")
13831369
})
13841370
.and_then(|log_line| {
1385-
log_line
1386-
.get("span_id")
1387-
.map(|s| s.as_str().unwrap().to_string())
1371+
log_line.get("span_id")
1372+
.and_then(|v| v.as_str())
1373+
.map(|s| s.to_string())
13881374
})
1389-
.unwrap();
1375+
.expect("Should find child span with span_id");
13901376

1391-
let _grandchild_span_id = lines
1377+
let grandchild_span_id = lines
13921378
.iter()
13931379
.find(|log_line| {
1394-
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CREATED"
1395-
&& log_line.get("span_name").unwrap().as_str().unwrap() == "grandchild"
1380+
log_line.get("span_name")
1381+
.and_then(|v| v.as_str()) == Some("grandchild")
13961382
})
13971383
.and_then(|log_line| {
1398-
log_line
1399-
.get("span_id")
1400-
.map(|s| s.as_str().unwrap().to_string())
1384+
log_line.get("span_id")
1385+
.and_then(|v| v.as_str())
1386+
.map(|s| s.to_string())
14011387
})
1402-
.unwrap();
1388+
.expect("Should find grandchild span with span_id");
1389+
1390+
// Verify span IDs are unique
1391+
assert_ne!(parent_span_id, child_span_id, "Parent and child should have different span IDs");
1392+
assert_ne!(child_span_id, grandchild_span_id, "Child and grandchild should have different span IDs");
1393+
assert_ne!(parent_span_id, grandchild_span_id, "Parent and grandchild should have different span IDs");
14031394

1404-
// Parent span has no parent_id
1395+
// Verify parent span has no parent_id
14051396
for log_line in &lines {
14061397
if let Some(span_name) = log_line.get("span_name")
14071398
&& let Some(span_name_str) = span_name.as_str()
14081399
&& span_name_str == "parent"
14091400
{
1410-
assert!(log_line.get("parent_id").is_none());
1401+
assert!(
1402+
log_line.get("parent_id").is_none(),
1403+
"Parent span should not have a parent_id"
1404+
);
14111405
}
14121406
}
14131407

1414-
// Child span's parent_id is parent_span_id
1408+
// Verify child span's parent_id is parent_span_id
14151409
for log_line in &lines {
14161410
if let Some(span_name) = log_line.get("span_name")
14171411
&& let Some(span_name_str) = span_name.as_str()
14181412
&& span_name_str == "child"
14191413
{
1414+
let parent_id = log_line.get("parent_id")
1415+
.and_then(|v| v.as_str())
1416+
.expect("Child span should have a parent_id");
14201417
assert_eq!(
1421-
log_line.get("parent_id").unwrap().as_str().unwrap(),
1422-
&parent_span_id
1418+
parent_id,
1419+
parent_span_id,
1420+
"Child's parent_id should match parent's span_id"
14231421
);
14241422
}
14251423
}
14261424

1427-
// Grandchild span's parent_id is child_span_id
1425+
// Verify grandchild span's parent_id is child_span_id
14281426
for log_line in &lines {
14291427
if let Some(span_name) = log_line.get("span_name")
14301428
&& let Some(span_name_str) = span_name.as_str()
14311429
&& span_name_str == "grandchild"
14321430
{
1431+
let parent_id = log_line.get("parent_id")
1432+
.and_then(|v| v.as_str())
1433+
.expect("Grandchild span should have a parent_id");
14331434
assert_eq!(
1434-
log_line.get("parent_id").unwrap().as_str().unwrap(),
1435-
&child_span_id
1435+
parent_id,
1436+
child_span_id,
1437+
"Grandchild's parent_id should match child's span_id"
14361438
);
14371439
}
14381440
}
14391441

1440-
// Validate duration relationships
1441-
let parent_duration = lines
1442-
.iter()
1443-
.find(|log_line| {
1444-
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CLOSED"
1445-
&& log_line.get("span_name").unwrap().as_str().unwrap() == "parent"
1446-
})
1447-
.and_then(|log_line| {
1448-
log_line
1449-
.get("time.duration_us")
1450-
.map(|d| d.as_u64().unwrap())
1451-
})
1452-
.unwrap();
1453-
1454-
let child_duration = lines
1455-
.iter()
1456-
.find(|log_line| {
1457-
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CLOSED"
1458-
&& log_line.get("span_name").unwrap().as_str().unwrap() == "child"
1459-
})
1460-
.and_then(|log_line| {
1461-
log_line
1462-
.get("time.duration_us")
1463-
.map(|d| d.as_u64().unwrap())
1464-
})
1465-
.unwrap();
1466-
1467-
let grandchild_duration = lines
1468-
.iter()
1469-
.find(|log_line| {
1470-
log_line.get("message").unwrap().as_str().unwrap() == "SPAN_CLOSED"
1471-
&& log_line.get("span_name").unwrap().as_str().unwrap() == "grandchild"
1472-
})
1473-
.and_then(|log_line| {
1474-
log_line
1475-
.get("time.duration_us")
1476-
.map(|d| d.as_u64().unwrap())
1477-
})
1478-
.unwrap();
1442+
// 4. Validate timestamp ordering - spans should log in execution order
1443+
let parent_time = span_timestamps.get("parent")
1444+
.expect("Should have timestamp for parent span");
1445+
let child_time = span_timestamps.get("child")
1446+
.expect("Should have timestamp for child span");
1447+
let grandchild_time = span_timestamps.get("grandchild")
1448+
.expect("Should have timestamp for grandchild span");
14791449

1450+
// Parent logs first (or at same time), then child, then grandchild
14801451
assert!(
1481-
parent_duration > child_duration + grandchild_duration,
1482-
"Parent duration is not greater than the sum of child and grandchild durations"
1452+
parent_time <= child_time,
1453+
"Parent span should log before or at same time as child span (parent: {}, child: {})",
1454+
parent_time,
1455+
child_time
14831456
);
14841457
assert!(
1485-
child_duration > grandchild_duration,
1486-
"Child duration is not greater than grandchild duration"
1458+
child_time <= grandchild_time,
1459+
"Child span should log before or at same time as grandchild span (child: {}, grandchild: {})",
1460+
child_time,
1461+
grandchild_time
14871462
);
14881463

14891464
Ok::<(), anyhow::Error>(())

0 commit comments

Comments
 (0)