fix: non-deferred interleaved span enter events

Author: ten3roberts

examples/concurrent_eager.rs

@@ -0,0 +1,101 @@
+use std::{
+ future::Future,
+ pin::Pin,
+ task::{Context, Poll},
+};
+
+use futures::{pin_mut, FutureExt};
+use tracing::Instrument;
+use tracing_subscriber::{layer::SubscriberExt, registry::Registry};
+use tracing_tree::HierarchicalLayer;
+
+fn main() {
+ let layer = HierarchicalLayer::default()
+ .with_writer(std::io::stdout)
+ .with_indent_lines(true)
+ .with_indent_amount(4)
+ .with_thread_names(true)
+ .with_thread_ids(true)
+ .with_span_retrace(true)
+ .with_deferred_spans(false)
+ .with_targets(true);
+
+ let subscriber = Registry::default().with(layer);
+ tracing::subscriber::set_global_default(subscriber).unwrap();
+ #[cfg(feature = "tracing-log")]
+ tracing_log::LogTracer::init().unwrap();
+
+ let fut_a = spawn_fut("a", a);
+ pin_mut!(fut_a);
+
+ let waker = futures::task::noop_waker();
+ let mut cx = Context::from_waker(&waker);
+ assert!(fut_a.poll_unpin(&mut cx).is_pending());
+
+ let fut_b = spawn_fut("b", b);
+ pin_mut!(fut_b);
+
+ assert!(fut_b.poll_unpin(&mut cx).is_pending());
+
+ assert!(fut_a.poll_unpin(&mut cx).is_pending());
+ assert!(fut_b.poll_unpin(&mut cx).is_pending());
+
+ assert!(fut_a.poll_unpin(&mut cx).is_ready());
+ assert!(fut_b.poll_unpin(&mut cx).is_ready());
+}
+
+fn spawn_fut<F: Fn() -> Fut, Fut: Future<Output = ()>>(
+ key: &'static str,
+ inner: F,
+) -> impl Future<Output = ()> {
+ let span = tracing::info_span!("spawn_fut", key);
+
+ async move {
+ countdown(1).await;
+
+ inner().await;
+ }
+ .instrument(span)
+}
+
+fn a() -> impl Future<Output = ()> {
+ let span = tracing::info_span!("a");
+
+ async move {
+ countdown(1).await;
+ tracing::info!("a");
+ }
+ .instrument(span)
+}
+
+fn b() -> impl Future<Output = ()> {
+ let span = tracing::info_span!("b");
+
+ async move {
+ countdown(1).await;
+ tracing::info!("b");
+ }
+ .instrument(span)
+}
+
+fn countdown(count: u32) -> impl Future<Output = ()> {
+ CountdownFuture { count }
+}
+
+struct CountdownFuture {
+ count: u32,
+}
+
+impl Future for CountdownFuture {
+ type Output = ();
+
+ fn poll(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
+ if self.count == 0 {
+ Poll::Ready(())
+ } else {
+ self.count -= 1;
+ cx.waker().wake_by_ref();
+ Poll::Pending
+ }
+ }
+}

examples/concurrent_eager.stdout

@@ -0,0 +1,16 @@
+1:main┐concurrent_eager::spawn_fut key="a"
+1:main┐concurrent_eager::spawn_fut key="b"
+1:main┐concurrent_eager::spawn_fut key="a"
+1:main├───┐concurrent_eager::a 
+1:main┐concurrent_eager::spawn_fut key="b"
+1:main├───┐concurrent_eager::b 
+1:main┐concurrent_eager::spawn_fut key="a"
+1:main├───┐concurrent_eager::a 
+1:main│ ├─── Xms INFO concurrent_eager a
+1:main├───┘
+1:main┐concurrent_eager::spawn_fut key="b"
+1:main├───┐concurrent_eager::b 
+1:main│ ├─── Xms INFO concurrent_eager b
+1:main├───┘
+1:main┘
+1:main┘

src/lib.rs

@@ -267,7 +267,7 @@ where
  Ok(())
  }
 
- /// If `span_retrace` ensures that `new_span` is properly printed before an event
+ /// Ensures that `new_span` and all its ancestors are properly printed before an event
  fn write_retrace_span<'a, S>(
  &self,
  new_span: &SpanRef<'a, S>,
@@ -276,61 +276,55 @@ where
  ) where
  S: Subscriber + for<'new_span> LookupSpan<'new_span>,
  {
- let should_write = if self.config.deferred_spans {
- if let Some(data) = new_span.extensions_mut().get_mut::<Data>() {
- !data.written
- } else {
- false
- }
- } else {
- false
- };
-
  // Also handle deferred spans along with retrace since deferred spans may need to print
  // multiple spans at once as a whole tree can be deferred
- if self.config.span_retrace || should_write {
- let old_span_id = bufs.current_span.replace((new_span.id()).clone());
- let old_span_id = old_span_id.as_ref();
-
- if Some(&new_span.id()) != old_span_id {
- let old_span = old_span_id.as_ref().and_then(|v| ctx.span(v));
- let old_path = old_span.as_ref().map(scope_path).into_iter().flatten();
-
- let new_path = scope_path(new_span);
-
- // Print the path from the common base of the two spans
- let new_path = DifferenceIter::new(old_path, new_path, |v| v.id());
-
- for (i, span) in new_path.enumerate() {
- // Mark traversed spans as *written*
- let was_written = if let Some(data) = span.extensions_mut().get_mut::<Data>() {
- mem::replace(&mut data.written, true)
- } else {
- // `on_new_span` was not called, before
- // Consider if this should panic instead, which is *technically* correct but is
- // bad behavior for a logging layer in production.
- false
- };
-
- // Print the previous span before entering a new deferred or retraced span
- if i == 0 && self.config.verbose_entry {
- if let Some(parent) = &span.parent() {
- self.write_span_info(parent, bufs, SpanMode::PreOpen);
- }
+ //
+ // If a another event occurs right after a previous event in the same span, this will
+ // simply print nothing since the path to the common lowest ancestor is empty
+ // if self.config.span_retrace || self.config.deferred_spans {
+ let old_span_id = bufs.current_span.replace((new_span.id()).clone());
+ let old_span_id = old_span_id.as_ref();
+ let new_span_id = new_span.id();
+
+ if Some(&new_span_id) != old_span_id {
+ let old_span = old_span_id.as_ref().and_then(|v| ctx.span(v));
+ let old_path = old_span.as_ref().map(scope_path).into_iter().flatten();
+
+ let new_path = scope_path(new_span);
+
+ // Print the path from the common base of the two spans
+ let new_path = DifferenceIter::new(old_path, new_path, |v| v.id());
+
+ for (i, span) in new_path.enumerate() {
+ // Mark traversed spans as *written*
+ let was_written = if let Some(data) = span.extensions_mut().get_mut::<Data>() {
+ mem::replace(&mut data.written, true)
+ } else {
+ // `on_new_span` was not called, before
+ // Consider if this should panic instead, which is *technically* correct but is
+ // bad behavior for a logging layer in production.
+ false
+ };
+
+ // Print the previous span before entering a new deferred or retraced span
+ if i == 0 && self.config.verbose_entry {
+ if let Some(parent) = &span.parent() {
+ self.write_span_info(parent, bufs, SpanMode::PreOpen);
  }
- let verbose = self.config.verbose_entry && i == 0;
-
- self.write_span_info(
- &span,
- bufs,
- if was_written {
- SpanMode::Retrace { verbose }
- } else {
- SpanMode::Open { verbose }
- },
- )
  }
+ let verbose = self.config.verbose_entry && i == 0;
+
+ self.write_span_info(
+ &span,
+ bufs,
+ if was_written {
+ SpanMode::Retrace { verbose }
+ } else {
+ SpanMode::Open { verbose }
+ },
+ )
  }
+ // }
  }
  }
 
@@ -491,22 +485,25 @@ where
 
  let bufs = &mut *self.bufs.lock().unwrap();
 
- // Store the most recently entered span
- bufs.current_span = Some(span.id());
-
  if self.config.verbose_entry {
  if let Some(span) = span.parent() {
  self.write_span_info(&span, bufs, SpanMode::PreOpen);
  }
  }
 
- self.write_span_info(
- &span,
- bufs,
- SpanMode::Open {
- verbose: self.config.verbose_entry,
- },
- );
+ if self.config.span_retrace {
+ self.write_retrace_span(&span, bufs, &ctx);
+ } else {
+ // Store the most recently entered span
+ bufs.current_span = Some(span.id());
+ self.write_span_info(
+ &span,
+ bufs,
+ SpanMode::Open {
+ verbose: self.config.verbose_entry,
+ },
+ );
+ }
  }
 
  fn on_event(&self, event: &Event<'_>, ctx: Context<S>) {
@@ -518,7 +515,9 @@ where
  let bufs = &mut *guard;
 
  if let Some(new_span) = &span {
- self.write_retrace_span(new_span, bufs, &ctx);
+ if self.config.span_retrace || self.config.deferred_spans {
+ self.write_retrace_span(new_span, bufs, &ctx);
+ }
  }
 
  let mut event_buf = &mut bufs.current_buf;