Skip to content

Commit 2326701

Browse files
ten3robertsten3roberts
committed
fix: deferred span event generation
1 parent 234285a commit 2326701

File tree

4 files changed

+192
-64
lines changed

4 files changed

+192
-64
lines changed

‎examples/concurrent.rs

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,9 +18,8 @@ fn main() {
1818
.with_thread_ids(true)
1919
.with_verbose_exit(true)
2020
.with_verbose_entry(true)
21-
.with_span_retrace(true)
21+
.with_span_retrace(false)
2222
.with_deferred_spans(true)
23-
.with_deferred_spans(false)
2423
.with_span_modes(true)
2524
.with_targets(true);
2625

‎examples/deferred.rs

Lines changed: 100 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,100 @@
1+
use tracing::{debug, error, info, instrument, span, trace, warn, Level};
2+
use tracing_core::LevelFilter;
3+
use tracing_subscriber::{layer::SubscriberExt, registry::Registry, Layer};
4+
use tracing_tree::HierarchicalLayer;
5+
6+
fn main() {
7+
let layer = HierarchicalLayer::default()
8+
.with_writer(std::io::stdout)
9+
.with_indent_lines(true)
10+
.with_indent_amount(2)
11+
.with_thread_names(true)
12+
.with_thread_ids(true)
13+
.with_verbose_exit(true)
14+
.with_verbose_entry(true)
15+
.with_deferred_spans(true)
16+
.with_targets(true)
17+
.with_span_modes(true)
18+
.with_filter(LevelFilter::DEBUG);
19+
20+
let subscriber = Registry::default().with(layer);
21+
tracing::subscriber::set_global_default(subscriber).unwrap();
22+
#[cfg(feature = "tracing-log")]
23+
tracing_log::LogTracer::init().unwrap();
24+
25+
let app_span = span!(Level::DEBUG, "hierarchical-example", version = %0.1);
26+
let _e = app_span.enter();
27+
28+
let server_span = span!(Level::DEBUG, "server", host = "localhost", port = 8080);
29+
30+
println!("This prints before the span open message");
31+
32+
let _e2 = server_span.enter();
33+
info!("starting");
34+
std::thread::sleep(std::time::Duration::from_millis(1000));
35+
info!("listening");
36+
let peer1 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 42381);
37+
peer1.in_scope(|| {
38+
debug!(peer = "peer1", "connected");
39+
std::thread::sleep(std::time::Duration::from_millis(300));
40+
debug!(length = 2, "message received");
41+
});
42+
43+
drop(peer1);
44+
let peer2 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 61548);
45+
46+
// This span will not be printed at all since no event in it will pass the filter
47+
peer2.in_scope(|| {
48+
trace!(peer = "peer2", "connected");
49+
std::thread::sleep(std::time::Duration::from_millis(300));
50+
trace!(length = 2, "message received");
51+
});
52+
drop(peer2);
53+
let peer3 = span!(Level::DEBUG, "conn", peer_addr = "8.8.8.8", port = 18230);
54+
peer3.in_scope(|| {
55+
std::thread::sleep(std::time::Duration::from_millis(300));
56+
debug!(peer = "peer3", "connected");
57+
});
58+
drop(peer3);
59+
let peer4 = span!(
60+
Level::DEBUG,
61+
"foomp",
62+
normal_var = 43,
63+
"{} <- format string",
64+
42
65+
);
66+
peer4.in_scope(|| {
67+
error!("hello");
68+
});
69+
drop(peer4);
70+
let peer1 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 42381);
71+
peer1.in_scope(|| {
72+
warn!(algo = "xor", "weak encryption requested");
73+
std::thread::sleep(std::time::Duration::from_millis(300));
74+
debug!(length = 8, "response sent");
75+
debug!("disconnected");
76+
});
77+
drop(peer1);
78+
let peer2 = span!(Level::DEBUG, "conn", peer_addr = "8.8.8.8", port = 18230);
79+
peer2.in_scope(|| {
80+
debug!(length = 5, "message received");
81+
std::thread::sleep(std::time::Duration::from_millis(300));
82+
debug!(length = 8, "response sent");
83+
debug!("disconnected");
84+
});
85+
drop(peer2);
86+
warn!("internal error");
87+
log::error!("this is a log message");
88+
info!("exit");
89+
}
90+
91+
#[instrument]
92+
fn call_a(name: &str) {
93+
info!(name, "got a name");
94+
call_b(name)
95+
}
96+
97+
#[instrument]
98+
fn call_b(name: &str) {
99+
info!(name, "got a name");
100+
}

‎src/format.rs

Lines changed: 4 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -25,9 +25,7 @@ pub(crate) enum SpanMode {
2525
verbose: bool,
2626
},
2727
/// A span has been entered but another *different* span has been entered in the meantime.
28-
Retrace {
29-
verbose: bool,
30-
},
28+
Retrace,
3129
PostClose,
3230
Event,
3331
}
@@ -311,8 +309,7 @@ pub(crate) fn write_span_mode(buf: &mut String, style: SpanMode) {
311309
match style {
312310
SpanMode::Open { verbose: true } => buf.push_str("open(v)"),
313311
SpanMode::Open { verbose: false } => buf.push_str("open"),
314-
SpanMode::Retrace { verbose: true } => buf.push_str("retrace(v)"),
315-
SpanMode::Retrace { verbose: false } => buf.push_str("retrace"),
312+
SpanMode::Retrace => buf.push_str("retrace"),
316313
SpanMode::Close { verbose: true } => buf.push_str("close(v)"),
317314
SpanMode::Close { verbose: false } => buf.push_str("close"),
318315
SpanMode::PreOpen => buf.push_str("pre_open"),
@@ -342,7 +339,7 @@ fn indent_block_with_lines(
342339
if indent == 0 {
343340
match style {
344341
SpanMode::Open { .. } => buf.push_str(LINE_OPEN),
345-
SpanMode::Retrace { .. } => buf.push_str("*"),
342+
SpanMode::Retrace { .. } => buf.push_str(LINE_OPEN),
346343
SpanMode::Close { .. } => buf.push_str(LINE_CLOSE),
347344
SpanMode::PreOpen | SpanMode::PostClose => {
348345
unreachable!(
@@ -383,7 +380,7 @@ fn indent_block_with_lines(
383380
}
384381
buf.push_str(LINE_OPEN);
385382
}
386-
SpanMode::Open { verbose: false } | SpanMode::Retrace { verbose: false } => {
383+
SpanMode::Open { verbose: false } | SpanMode::Retrace => {
387384
buf.push_str(LINE_BRANCH);
388385
for _ in 1..indent_amount {
389386
buf.push_str(LINE_HORIZ);
@@ -409,13 +406,6 @@ fn indent_block_with_lines(
409406
buf.push_str(LINE_VERT);
410407
}
411408
}
412-
SpanMode::Retrace { verbose: true } => {
413-
buf.push_str(LINE_BRANCH);
414-
for _ in 1..indent_amount {
415-
buf.push_str(LINE_HORIZ);
416-
}
417-
buf.push_str(LINE_OPEN);
418-
}
419409
SpanMode::Close { verbose: false } => {
420410
buf.push_str(LINE_BRANCH);
421411
for _ in 1..indent_amount {

‎src/lib.rs

Lines changed: 87 additions & 48 deletions
Original file line numberDiff line numberDiff line change
@@ -265,6 +265,84 @@ where
265265
Ok(())
266266
}
267267

268+
/// If `span_retrace` ensures that `new_span` is properly printed before an event
269+
fn write_retrace_span<'a, S>(
270+
&self,
271+
new_span: &SpanRef<'a, S>,
272+
bufs: &mut Buffers,
273+
ctx: &'a Context<S>,
274+
) where
275+
S: Subscriber + for<'new_span> LookupSpan<'new_span>,
276+
{
277+
{
278+
// let was_written = if let Some(data) = new_span.extensions_mut().get_mut::<Data>() {
279+
// let written = data.written;
280+
// data.written = true;
281+
// written
282+
// } else {
283+
// eprintln!("Span not written");
284+
// false
285+
// };
286+
287+
let should_write = if self.config.deferred_spans {
288+
if let Some(data) = new_span.extensions_mut().get_mut::<Data>() {
289+
!data.written
290+
} else {
291+
false
292+
}
293+
} else {
294+
false
295+
};
296+
297+
if self.config.span_retrace || should_write {
298+
let was_written = if let Some(data) = new_span.extensions_mut().get_mut::<Data>() {
299+
mem::replace(&mut data.written, true)
300+
} else {
301+
// `on_new_span` was not called, before
302+
// Consider if this should panic instead, which is *technically* correct but is
303+
// bad behavior for a logging layer in production.
304+
false
305+
};
306+
307+
let old_span_id = bufs.current_span.replace((new_span.id()).clone());
308+
let old_span_id = old_span_id.as_ref();
309+
310+
if Some(&new_span.id()) != old_span_id {
311+
let old_span = old_span_id.as_ref().and_then(|v| ctx.span(v));
312+
313+
// Print the previous span before entering a new deferred or retraced span
314+
if self.config.verbose_entry {
315+
if let Some(old_span) = &old_span {
316+
self.write_span_info(old_span, bufs, ctx, SpanMode::PreOpen);
317+
}
318+
}
319+
320+
let old_path = old_span.as_ref().map(scope_path).into_iter().flatten();
321+
322+
let new_path = scope_path(new_span);
323+
324+
// Print the path from the common base of the two spans
325+
let new_path = DifferenceIter::new(old_path, new_path, |v| v.id());
326+
327+
for span in new_path {
328+
self.write_span_info(
329+
&span,
330+
bufs,
331+
ctx,
332+
if was_written {
333+
SpanMode::Retrace
334+
} else {
335+
SpanMode::Open {
336+
verbose: self.config.verbose_entry,
337+
}
338+
},
339+
)
340+
}
341+
}
342+
}
343+
}
344+
}
345+
268346
fn write_span_info<S>(
269347
&self,
270348
span: &SpanRef<S>,
@@ -274,10 +352,6 @@ where
274352
) where
275353
S: Subscriber + for<'span> LookupSpan<'span>,
276354
{
277-
// let span = ctx
278-
// .span(id)
279-
// .expect("in on_enter/on_exit but span does not exist");
280-
281355
let ext = span.extensions();
282356
let data = ext.get::<Data>().expect("span does not have data");
283357

@@ -294,7 +368,8 @@ where
294368
// Print the parent of a new span again before entering the child
295369
SpanMode::PreOpen if self.config.verbose_entry => true,
296370
SpanMode::Close { verbose } => verbose,
297-
SpanMode::Retrace { verbose } => verbose,
371+
// Generated if `span_retrace` is enabled
372+
SpanMode::Retrace => true,
298373
// Generated if `verbose_exit` is enabled
299374
SpanMode::PostClose => true,
300375
_ => false,
@@ -388,51 +463,13 @@ where
388463
fn on_event(&self, event: &Event<'_>, ctx: Context<S>) {
389464
let span = ctx.current_span();
390465
let span_id = span.id();
391-
let span = span_id.and_then(|id| ctx.span(id).map(|span| (id, span)));
466+
let span = span_id.and_then(|id| ctx.span(id));
392467

393468
let mut guard = self.bufs.lock().unwrap();
394469
let bufs = &mut *guard;
395470

396-
if let Some((span_id, current_span)) = &span {
397-
if self.config.span_retrace
398-
|| current_span
399-
.extensions()
400-
.get::<Data>()
401-
.is_some_and(|v| !v.written)
402-
{
403-
if let Some(data) = current_span.extensions_mut().get_mut::<Data>() {
404-
data.written = true;
405-
}
406-
407-
let old_span_id = bufs.current_span.replace((*span_id).clone());
408-
409-
if Some(*span_id) != old_span_id.as_ref() {
410-
let old_span = old_span_id.as_ref().and_then(|v| ctx.span(v));
411-
412-
// eprintln!(
413-
// "concurrent old: {:?}, new: {:?}",
414-
// old_span.as_ref().map(|v| v.metadata().name()),
415-
// current_span.metadata().name()
416-
// );
417-
418-
let old_path = old_span.as_ref().map(scope_path).into_iter().flatten();
419-
let new_path = scope_path(current_span);
420-
421-
// Print the path from the common base of the two spans
422-
let new_path = DifferenceIter::new(old_path, new_path, |v| v.id());
423-
424-
for span in new_path {
425-
self.write_span_info(
426-
&span,
427-
bufs,
428-
&ctx,
429-
SpanMode::Retrace {
430-
verbose: self.config.span_retrace,
431-
},
432-
)
433-
}
434-
}
435-
}
471+
if let Some(new_span) = &span {
472+
self.write_retrace_span(new_span, bufs, &ctx);
436473
}
437474

438475
let mut event_buf = &mut bufs.current_buf;
@@ -461,7 +498,7 @@ where
461498
// check if this event occurred in the context of a span.
462499
// if it has, get the start time of this span.
463500
let start = match span {
464-
Some((id, span)) => {
501+
Some(span) => {
465502
// if the event is in a span, get the span's starting point.
466503
let ext = span.extensions();
467504
let data = ext
@@ -534,7 +571,7 @@ where
534571

535572
// Store the most recently entered span
536573
if bufs.current_span.as_ref() == Some(&id) {
537-
bufs.current_span = None;
574+
// bufs.current_span = None;
538575
}
539576

540577
let span = ctx.span(&id).expect("invalid span in on_close");
@@ -544,6 +581,8 @@ where
544581
&& span.extensions().get::<Data>().map(|v| v.written) != Some(true)
545582
{}
546583

584+
self.write_retrace_span(&span, bufs, &ctx);
585+
547586
self.write_span_info(
548587
&span,
549588
bufs,

0 commit comments

Comments
 (0)