Instrumentation leads to extra fields in logs

[michaelsproul]

The instrumentation we've added has lead to the addition of the instrumented fields to logs. E.g. this state cache missed triggered by (presumably) blob verification, results in 3x block_root, 2x state_root, slot and index fields being logged:

Aug 27 03:12:14.471 WARN State cache missed state_root: 0xabbf84a7d9e8305916ddd9558f27241aa7a4bc22d5f4455d5ce4b6aea42a50b7, block_root: 0xc6dfece48906334a091f99cd5f07826ff00816b5765fd0caa34771efcafadafe, state_root: 0xabbf84a7d9e8305916ddd9558f27241aa7a4bc22d5f4455d5ce4b6aea42a50b7, block_root: 0xc6dfece48906334a091f99cd5f07826ff00816b5765fd0caa34771efcafadafe, index: 1, block_root: 0x6ddc3ab728146617dc9626938c53c285d8703b0aa234c0e32ec5f9d59fa967d3, slot: Slot(12453293)

This is despite the event in the code only logging the state_root and block_root:

lighthouse/beacon_node/store/src/hot_cold_store.rs

Line 1029 in cfb1f73

warn!(?state_root, ?block_root, "State cache missed");

I think to fix this we probably want to remove redundant fields from each log event? Or maybe we should somehow exclude the fields from logs and just keep them in traces.

Additional Info

In our example the duplication is especially confusing because the block_roots are different. One is the block_root of the blob itself, and the other two (lower-level) fields are the parent block being loaded from the DB.

Instrumentation added in:

• Instrument tracing spans for block processing and import #7816

[jimmygchen]

Yeah i think we could just add unique fields here instead of adding all fields of the spans and ancester spans:

lighthouse/common/logging/src/tracing_logging_layer.rs

Lines 304 to 318 in 522bd9e

	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(", ");
	}
	}

span_fields is a &[(String, String)] here and we don't check for uniqueness.

Or even better, just use a more suitable data structure to capture the span fields:

lighthouse/common/logging/src/tracing_logging_layer.rs

Lines 82 to 89 in 522bd9e

	let mut span_data = Vec::new();
	if let Some(scope) = ctx.event_scope(event) {
	for span in scope.from_root() {
	if let Some(data) = span.extensions().get::<SpanData>() {
	span_data.extend(data.fields.clone());
	}
	}
	}

[PoulavBhowmick03]

In our example the duplication is especially confusing because the block_roots are different. One is the block_root of the blob itself, and the other two (lower-level) fields are the parent block being loaded from the DB.

In that case instead of removing the excess block_root, do you think it would be make more sense to add the data.field and data.name? and as @jimmygchen said,
we could do something like:
firstly change span_data to a HashMap and

for span in scope.from_root() {
    if let Some(data) = span.extensions().get::<SpanData>() {
        for (k, v) in &data.fields.clone() {
            let span_name = format!("{}.{}", data.name, k);
            span_data.insert(span_name, v.clone());
        }
    }
}

and then make the required changes..