gnosis/lighthouse
1
0
Fork 0
mirror of https://github.com/sigp/lighthouse.git synced 2026-05-09 03:17:55 +00:00
Code Issues Packages Projects Releases Wiki Activity

Fix duplicate fields being logged when the field exists in both the span and the event (#8183)

Browse Source 
Closes #7995.

Fix duplicate fields being logged when the field exists in both the span and the event. Prefer event fields when this happens.

```
Sep 15 08:13:46.339 WARN State cache missed state_root: 0xc34826ff7794de63a553832b7aff13572d1c716b9e03d5ef7b29649adf98abe2, block_root: 0xf16d3f5b4cc6ec876b7faeccd9f2d4102dc56ed32e828754b62601637910ec1f, state_root: 0xc34826ff7794de63a553832b7aff13572d1c716b9e03d5ef7b29649adf98abe2, block_root: 0xf16d3f5b4cc6ec876b7faeccd9f2d4102dc56ed32e828754b62601637910ec1f
```

becomes

```
Sep 15 08:13:46.339 WARN State cache missed state_root: 0xc34826ff7794de63a553832b7aff13572d1c716b9e03d5ef7b29649adf98abe2, block_root: 0xf16d3f5b4cc6ec876b7faeccd9f2d4102dc56ed32e828754b62601637910ec1f
```


  


Co-Authored-By: Jimmy Chen <jchen.tc@gmail.com>
This commit is contained in:
Jimmy Chen
2025-10-13 12:12:46 +11:00
committed by GitHub
parent 0c9fdea28d
commit 178df7a7d6
1 changed files with 63 additions and 51 deletions
Download Patch File Download Diff File Expand all files Collapse all files

114
common/logging/src/tracing_logging_layer.rs
View File

@@ -1,4 +1,5 @@
use crate::utils::is_ascii_control; use crate::utils::is_ascii_control;
use std::collections::HashSet;
use chrono::prelude::*; use chrono::prelude::*;
use serde_json::{Map, Value}; use serde_json::{Map, Value};
@@ -261,6 +262,12 @@ fn build_log_json(
let module_field = format!("{}:{}", module_path, line_number); let module_field = format!("{}:{}", module_path, line_number);
log_map.insert("module".to_string(), Value::String(module_field)); log_map.insert("module".to_string(), Value::String(module_field));
// Avoid adding duplicate fields; prefer event fields when duplicates exist.
for (key, val) in span_fields {
let parsed_span_val = parse_field(val);
log_map.insert(key.clone(), parsed_span_val);
}
for (key, val) in visitor.fields.clone().into_iter() { for (key, val) in visitor.fields.clone().into_iter() {
let cleaned_value = if val.starts_with('\"') && val.ends_with('\"') && val.len() >= 2 { let cleaned_value = if val.starts_with('\"') && val.ends_with('\"') && val.len() >= 2 {
&val[1..val.len() - 1] &val[1..val.len() - 1]
@@ -272,11 +279,6 @@ fn build_log_json(
log_map.insert(key, parsed_val); log_map.insert(key, parsed_val);
} }
for (key, val) in span_fields {
let parsed_span_val = parse_field(val);
log_map.insert(key.clone(), parsed_span_val);
}
let json_obj = Value::Object(log_map); let json_obj = Value::Object(log_map);
let output = format!("{}\n", json_obj); let output = format!("{}\n", json_obj);
@@ -299,23 +301,6 @@ fn build_log_text(
let bold_start = "\x1b[1m"; let bold_start = "\x1b[1m";
let bold_end = "\x1b[0m"; let bold_end = "\x1b[0m";
let mut formatted_spans = String::new();
for (i, (field_name, field_value)) in span_fields.iter().rev().enumerate() {
if use_color {
formatted_spans.push_str(&format!(
"{}{}{}: {}",
bold_start, field_name, bold_end, field_value
));
} else {
formatted_spans.push_str(&format!("{}: {}", field_name, field_value));
}
// Check if this is not the last span.
if i != span_fields.len() - 1 {
formatted_spans.push_str(", ");
}
}
let pad = if plain_level_str.len() < ALIGNED_LEVEL_WIDTH { let pad = if plain_level_str.len() < ALIGNED_LEVEL_WIDTH {
" " " "
} else { } else {
@@ -351,24 +336,26 @@ fn build_log_text(
message_content.clone() message_content.clone()
}; };
let mut formatted_fields = String::new(); // Avoid adding duplicate fields; prefer event fields when duplicates exist.
for (i, (field_name, field_value)) in visitor.fields.iter().enumerate() { let mut added_field_names = HashSet::new();
if i > 0 { let formatted_fields = visitor
formatted_fields.push_str(", "); .fields
} .iter()
if use_color { .chain(span_fields.iter())
formatted_fields.push_str(&format!( .filter_map(|(field_name, field_value)| {
"{}{}{}: {}", if added_field_names.insert(field_name) {
bold_start, field_name, bold_end, field_value let formatted_field = if use_color {
)); format!("{}{}{}: {}", bold_start, field_name, bold_end, field_value)
} else { } else {
formatted_fields.push_str(&format!("{}: {}", field_name, field_value)); format!("{}: {}", field_name, field_value)
} };
// Check if this is the last field and that we are also adding spans. Some(formatted_field)
if i == visitor.fields.len() - 1 && !span_fields.is_empty() { } else {
formatted_fields.push(','); None
} }
} })
.collect::<Vec<_>>()
.join(", ");
let full_message = if !formatted_fields.is_empty() { let full_message = if !formatted_fields.is_empty() {
format!("{} {}", padded_message, formatted_fields) format!("{} {}", padded_message, formatted_fields)
@@ -378,14 +365,11 @@ fn build_log_text(
let message = if !location.is_empty() { let message = if !location.is_empty() {
format!( format!(
"{} {} {} {} {}\n", "{} {} {} {}\n",
timestamp, level_str, location, full_message, formatted_spans timestamp, level_str, location, full_message
) )
} else { } else {
format!( format!("{} {} {}\n", timestamp, level_str, full_message)
"{} {} {} {}\n",
timestamp, level_str, full_message, formatted_spans
)
}; };
if let Err(e) = writer.write_all(message.as_bytes()) { if let Err(e) = writer.write_all(message.as_bytes()) {
@@ -436,7 +420,7 @@ mod tests {
fn test_build_log_text_single_log_field() { fn test_build_log_text_single_log_field() {
let log_fields = vec![("field_name".to_string(), "field_value".to_string())]; let log_fields = vec![("field_name".to_string(), "field_value".to_string())];
let span_fields = vec![]; let span_fields = vec![];
let expected = "Jan 1 08:00:00.000 INFO test message field_name: field_value \n"; let expected = "Jan 1 08:00:00.000 INFO test message field_name: field_value\n";
test_build_log_text(log_fields, span_fields, expected); test_build_log_text(log_fields, span_fields, expected);
} }
@@ -447,7 +431,7 @@ mod tests {
("field_name2".to_string(), "field_value2".to_string()), ("field_name2".to_string(), "field_value2".to_string()),
]; ];
let span_fields = vec![]; let span_fields = vec![];
let expected = "Jan 1 08:00:00.000 INFO test message field_name1: field_value1, field_name2: field_value2 \n"; let expected = "Jan 1 08:00:00.000 INFO test message field_name1: field_value1, field_name2: field_value2\n";
test_build_log_text(log_fields, span_fields, expected); test_build_log_text(log_fields, span_fields, expected);
} }
@@ -469,7 +453,7 @@ mod tests {
"span_field_name".to_string(), "span_field_name".to_string(),
"span_field_value".to_string(), "span_field_value".to_string(),
)]; )];
let expected = "Jan 1 08:00:00.000 INFO test message span_field_name: span_field_value\n"; let expected = "Jan 1 08:00:00.000 INFO test message span_field_name: span_field_value\n";
test_build_log_text(log_fields, span_fields, expected); test_build_log_text(log_fields, span_fields, expected);
} }
@@ -486,7 +470,7 @@ mod tests {
"span_field_value2".to_string(), "span_field_value2".to_string(),
), ),
]; ];
let expected = "Jan 1 08:00:00.000 INFO test message span_field_name2: span_field_value2, span_field_name1: span_field_value1\n"; let expected = "Jan 1 08:00:00.000 INFO test message span_field_name1: span_field_value1, span_field_name2: span_field_value2\n";
test_build_log_text(log_fields, span_fields, expected); test_build_log_text(log_fields, span_fields, expected);
} }
@@ -503,7 +487,35 @@ mod tests {
"span_field_value1-2".to_string(), "span_field_value1-2".to_string(),
), ),
]; ];
let expected = "Jan 1 08:00:00.000 INFO test message span_field_name1-2: span_field_value1-2, span_field_name1-1: span_field_value1-1\n"; let expected = "Jan 1 08:00:00.000 INFO test message span_field_name1-1: span_field_value1-1, span_field_name1-2: span_field_value1-2\n";
test_build_log_text(log_fields, span_fields, expected);
}
#[test]
fn test_build_log_text_no_duplicate_log_span_fields() {
let log_fields = vec![
("field_name_1".to_string(), "field_value_1".to_string()),
("field_name_2".to_string(), "field_value_2".to_string()),
];
let span_fields = vec![
("field_name_1".to_string(), "field_value_1".to_string()),
("field_name_3".to_string(), "field_value_3".to_string()),
];
let expected = "Jan 1 08:00:00.000 INFO test message field_name_1: field_value_1, field_name_2: field_value_2, field_name_3: field_value_3\n";
test_build_log_text(log_fields, span_fields, expected);
}
#[test]
fn test_build_log_text_duplicate_fields_prefer_log_fields() {
let log_fields = vec![
("field_name_1".to_string(), "field_value_1_log".to_string()),
("field_name_2".to_string(), "field_value_2".to_string()),
];
let span_fields = vec![
("field_name_1".to_string(), "field_value_1_span".to_string()),
("field_name_3".to_string(), "field_value_3".to_string()),
];
let expected = "Jan 1 08:00:00.000 INFO test message field_name_1: field_value_1_log, field_name_2: field_value_2, field_name_3: field_value_3\n";
test_build_log_text(log_fields, span_fields, expected); test_build_log_text(log_fields, span_fields, expected);
} }