Skip to content

Commit 0cee7a4

Browse files
davidhewittdavidhewitt
authored
revert to only emit pending spans on first enter (#29)
1 parent d113364 commit 0cee7a4

File tree

5 files changed

+179
-555
lines changed

5 files changed

+179
-555
lines changed

‎src/bridges/tracing.rs

Lines changed: 61 additions & 248 deletions
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,27 @@ where
3636
level_to_level_number(*attrs.metadata().level()),
3737
));
3838
attributes.push(KeyValue::new("logfire.span_type", "span"));
39+
}
40+
}
41+
42+
/// Emit a pending span when this span is first entered, if this span will be sampled.
43+
///
44+
/// We do this on first enter, not on creation, because some SDKs set the parent span after
45+
/// creation.
46+
///
47+
/// e.g. <https://github.com/davidB/tracing-opentelemetry-instrumentation-sdk/blob/5830c9113b0d42b72167567bf8e5f4c6b20933c8/axum-tracing-opentelemetry/src/middleware/trace_extractor.rs#L132>
48+
fn on_enter(&self, id: &tracing::span::Id, ctx: tracing_subscriber::layer::Context<'_, S>) {
49+
let span = ctx.span(id).expect("span not found");
50+
let mut extensions = span.extensions_mut();
51+
52+
if extensions.get_mut::<LogfirePendingSpanSent>().is_some() {
53+
return;
54+
}
3955

56+
extensions.insert(LogfirePendingSpanSent);
57+
58+
// Guaranteed to be on first entering of the span
59+
if let Some(otel_data) = extensions.get_mut::<OtelData>() {
4060
// Emit a pending span, if this span will be sampled.
4161
let context = self.0.sampled_context(otel_data);
4262
let sampling_result = otel_data
@@ -121,6 +141,39 @@ where
121141
}
122142
}
123143

144+
/// Helper to print spans when dropped; if it was never entered then the pending span
145+
/// is never sent (the console writer uses pending spans).
146+
///
147+
/// This needs to be a separate layer so that it can access the `OtelData` before the
148+
/// `tracing_opentelemetry` layer removes it.
149+
pub struct LogfireTracingPendingSpanNotSentLayer;
150+
151+
impl<S> Layer<S> for LogfireTracingPendingSpanNotSentLayer
152+
where
153+
S: Subscriber + for<'span> LookupSpan<'span>,
154+
{
155+
fn on_close(&self, id: tracing::span::Id, ctx: tracing_subscriber::layer::Context<'_, S>) {
156+
let span = ctx.span(&id).expect("span not found");
157+
let mut extensions = span.extensions_mut();
158+
159+
if extensions.get_mut::<LogfirePendingSpanSent>().is_some() {
160+
return;
161+
}
162+
163+
// Guaranteed to be on first entering of the span
164+
if let Some(otel_data) = extensions.get_mut::<OtelData>() {
165+
try_with_logfire_tracer(|tracer| {
166+
if let Some(writer) = &tracer.console_writer {
167+
writer.write_tracing_opentelemetry_data(otel_data);
168+
}
169+
});
170+
}
171+
}
172+
}
173+
174+
/// Dummy struct to mark that we've already entered this span.
175+
struct LogfirePendingSpanSent;
176+
124177
pub(crate) fn level_to_level_number(level: tracing::Level) -> i64 {
125178
// These numbers were chosen to match the values emitted by the Python logfire SDK.
126179
match level {
@@ -223,18 +276,18 @@ impl Visit for FieldsVisitor {
223276

224277
#[cfg(test)]
225278
mod tests {
226-
use core::time;
227279
use std::sync::{Arc, Mutex};
228280

229281
use insta::{assert_debug_snapshot, assert_snapshot};
230282
use opentelemetry_sdk::trace::{InMemorySpanExporterBuilder, SimpleSpanProcessor};
231-
use regex::{Captures, Regex};
232283
use tracing::{Level, level_filters::LevelFilter};
233284

234285
use crate::{
235286
config::{AdvancedOptions, ConsoleOptions, Target},
236287
set_local_logfire,
237-
test_utils::{DeterministicExporter, DeterministicIdGenerator},
288+
test_utils::{
289+
DeterministicExporter, DeterministicIdGenerator, remap_timestamps_in_console_output,
290+
},
238291
};
239292

240293
#[test]
@@ -287,7 +340,7 @@ mod tests {
287340
},
288341
parent_span_id: 0000000000000000,
289342
span_kind: Internal,
290-
name: "event src/bridges/tracing.rs:261",
343+
name: "event src/bridges/tracing.rs:314",
291344
start_time: SystemTime {
292345
tv_sec: 0,
293346
tv_nsec: 0,
@@ -823,122 +876,6 @@ mod tests {
823876
attributes: [],
824877
},
825878
},
826-
SpanData {
827-
span_context: SpanContext {
828-
trace_id: 000000000000000000000000000000f2,
829-
span_id: 00000000000000f7,
830-
trace_flags: TraceFlags(
831-
1,
832-
),
833-
is_remote: false,
834-
trace_state: TraceState(
835-
None,
836-
),
837-
},
838-
parent_span_id: 00000000000000f6,
839-
span_kind: Internal,
840-
name: "debug span",
841-
start_time: SystemTime {
842-
tv_sec: 5,
843-
tv_nsec: 0,
844-
},
845-
end_time: SystemTime {
846-
tv_sec: 5,
847-
tv_nsec: 0,
848-
},
849-
attributes: [
850-
KeyValue {
851-
key: Static(
852-
"code.filepath",
853-
),
854-
value: String(
855-
Static(
856-
"src/bridges/tracing.rs",
857-
),
858-
),
859-
},
860-
KeyValue {
861-
key: Static(
862-
"code.namespace",
863-
),
864-
value: String(
865-
Static(
866-
"logfire::bridges::tracing::tests",
867-
),
868-
),
869-
},
870-
KeyValue {
871-
key: Static(
872-
"code.lineno",
873-
),
874-
value: I64(
875-
18,
876-
),
877-
},
878-
KeyValue {
879-
key: Static(
880-
"thread.id",
881-
),
882-
value: I64(
883-
0,
884-
),
885-
},
886-
KeyValue {
887-
key: Static(
888-
"thread.name",
889-
),
890-
value: String(
891-
Owned(
892-
"bridges::tracing::tests::test_tracing_bridge",
893-
),
894-
),
895-
},
896-
KeyValue {
897-
key: Static(
898-
"logfire.level_num",
899-
),
900-
value: I64(
901-
5,
902-
),
903-
},
904-
KeyValue {
905-
key: Static(
906-
"logfire.span_type",
907-
),
908-
value: String(
909-
Static(
910-
"pending_span",
911-
),
912-
),
913-
},
914-
KeyValue {
915-
key: Static(
916-
"logfire.pending_parent_id",
917-
),
918-
value: String(
919-
Owned(
920-
"00000000000000f2",
921-
),
922-
),
923-
},
924-
],
925-
dropped_attributes_count: 0,
926-
events: SpanEvents {
927-
events: [],
928-
dropped_count: 0,
929-
},
930-
links: SpanLinks {
931-
links: [],
932-
dropped_count: 0,
933-
},
934-
status: Unset,
935-
instrumentation_scope: InstrumentationScope {
936-
name: "logfire",
937-
version: None,
938-
schema_url: None,
939-
attributes: [],
940-
},
941-
},
942879
SpanData {
943880
span_context: SpanContext {
944881
trace_id: 000000000000000000000000000000f2,
@@ -1064,123 +1001,7 @@ mod tests {
10641001
SpanData {
10651002
span_context: SpanContext {
10661003
trace_id: 000000000000000000000000000000f2,
1067-
span_id: 00000000000000f9,
1068-
trace_flags: TraceFlags(
1069-
1,
1070-
),
1071-
is_remote: false,
1072-
trace_state: TraceState(
1073-
None,
1074-
),
1075-
},
1076-
parent_span_id: 00000000000000f8,
1077-
span_kind: Internal,
1078-
name: "debug span with explicit parent",
1079-
start_time: SystemTime {
1080-
tv_sec: 7,
1081-
tv_nsec: 0,
1082-
},
1083-
end_time: SystemTime {
1084-
tv_sec: 7,
1085-
tv_nsec: 0,
1086-
},
1087-
attributes: [
1088-
KeyValue {
1089-
key: Static(
1090-
"code.filepath",
1091-
),
1092-
value: String(
1093-
Static(
1094-
"src/bridges/tracing.rs",
1095-
),
1096-
),
1097-
},
1098-
KeyValue {
1099-
key: Static(
1100-
"code.namespace",
1101-
),
1102-
value: String(
1103-
Static(
1104-
"logfire::bridges::tracing::tests",
1105-
),
1106-
),
1107-
},
1108-
KeyValue {
1109-
key: Static(
1110-
"code.lineno",
1111-
),
1112-
value: I64(
1113-
19,
1114-
),
1115-
},
1116-
KeyValue {
1117-
key: Static(
1118-
"thread.id",
1119-
),
1120-
value: I64(
1121-
0,
1122-
),
1123-
},
1124-
KeyValue {
1125-
key: Static(
1126-
"thread.name",
1127-
),
1128-
value: String(
1129-
Owned(
1130-
"bridges::tracing::tests::test_tracing_bridge",
1131-
),
1132-
),
1133-
},
1134-
KeyValue {
1135-
key: Static(
1136-
"logfire.level_num",
1137-
),
1138-
value: I64(
1139-
5,
1140-
),
1141-
},
1142-
KeyValue {
1143-
key: Static(
1144-
"logfire.span_type",
1145-
),
1146-
value: String(
1147-
Static(
1148-
"pending_span",
1149-
),
1150-
),
1151-
},
1152-
KeyValue {
1153-
key: Static(
1154-
"logfire.pending_parent_id",
1155-
),
1156-
value: String(
1157-
Owned(
1158-
"00000000000000f2",
1159-
),
1160-
),
1161-
},
1162-
],
1163-
dropped_attributes_count: 0,
1164-
events: SpanEvents {
1165-
events: [],
1166-
dropped_count: 0,
1167-
},
1168-
links: SpanLinks {
1169-
links: [],
1170-
dropped_count: 0,
1171-
},
1172-
status: Unset,
1173-
instrumentation_scope: InstrumentationScope {
1174-
name: "logfire",
1175-
version: None,
1176-
schema_url: None,
1177-
attributes: [],
1178-
},
1179-
},
1180-
SpanData {
1181-
span_context: SpanContext {
1182-
trace_id: 000000000000000000000000000000f2,
1183-
span_id: 00000000000000f8,
1004+
span_id: 00000000000000f7,
11841005
trace_flags: TraceFlags(
11851006
1,
11861007
),
@@ -1459,7 +1280,7 @@ mod tests {
14591280
"code.lineno",
14601281
),
14611282
value: I64(
1462-
269,
1283+
322,
14631284
),
14641285
},
14651286
],
@@ -1525,7 +1346,7 @@ mod tests {
15251346
"code.lineno",
15261347
),
15271348
value: I64(
1528-
270,
1349+
323,
15291350
),
15301351
},
15311352
],
@@ -1587,15 +1408,7 @@ mod tests {
15871408

15881409
let output = output.lock().unwrap();
15891410
let output = std::str::from_utf8(&output).unwrap();
1590-
1591-
// Replace all timestamps in output to make them deterministic
1592-
let mut timestamp = chrono::DateTime::UNIX_EPOCH;
1593-
let re = Regex::new(r"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z").unwrap();
1594-
let output = re.replace_all(output, |_: &Captures<'_>| {
1595-
let replaced = timestamp.to_rfc3339_opts(chrono::SecondsFormat::Micros, true);
1596-
timestamp += time::Duration::from_micros(1);
1597-
replaced
1598-
});
1411+
let output = remap_timestamps_in_console_output(output);
15991412

16001413
assert_snapshot!(output, @r#"
16011414
1970-01-01T00:00:00.000000Z INFO logfire::bridges::tracing::tests root event

0 commit comments

Comments
 (0)