fix: print any span outside the context of current span

Retracing may print parent spans leading up to the current span. The
indent was always formatted as the depth of the subscribers
*current_span* which is not connect for spans in the middle of the tree.

This fixes this issue

Author: ten3roberts

examples/basic.rs

@@ -10,7 +10,7 @@ fn main() {
         .with_thread_names(true)
         .with_thread_ids(true)
         .with_verbose_exit(true)
-        .with_verbose_entry(false)
+        .with_verbose_entry(true)
         .with_span_modes(true)
         .with_targets(true);
 

examples/concurrent.rs

@@ -19,7 +19,8 @@ fn main() {
         .with_verbose_exit(true)
         .with_verbose_entry(true)
         .with_verbose_retrace(true)
-        .with_deferred_spans(true)
+        .with_deferred_spans(false)
+        .with_span_modes(true)
         .with_targets(true);
 
     let subscriber = Registry::default().with(layer);
@@ -47,32 +48,34 @@ fn main() {
     });
 
     debug!("starting countdowns");
-    debug_span!("countdowns").in_scope(|| {
-        let mut countdown_a = CountdownFuture {
-            label: "a",
-            count: 3,
-        }
-        .instrument(span!(Level::DEBUG, "countdown_a"))
-        .fuse();
-
-        let mut countdown_b = CountdownFuture {
-            label: "b",
-            count: 5,
-        }
-        .instrument(span!(Level::DEBUG, "countdown_b"))
-        .fuse();
-
-        // We don't care if the futures are ready, as we poll manually
-        let waker = futures::task::noop_waker();
-        let mut cx = Context::from_waker(&waker);
-
-        let _ = countdown_a.poll_unpin(&mut cx);
-        let _ = countdown_b.poll_unpin(&mut cx);
-
-        std::thread::sleep(std::time::Duration::from_millis(300));
-
-        let _ = countdown_b.poll_unpin(&mut cx);
-    });
+    debug_span!("countdowns").in_scope(
+        || {
+            let mut countdown_a = CountdownFuture {
+                label: "a",
+                count: 3,
+            }
+            .instrument(span!(Level::DEBUG, "countdown_a"))
+            .fuse();
+
+            let mut countdown_b = CountdownFuture {
+                label: "b",
+                count: 5,
+            }
+            .instrument(span!(Level::DEBUG, "countdown_b"))
+            .fuse();
+
+            // We don't care if the futures are ready, as we poll manually
+            let waker = futures::task::noop_waker();
+            let mut cx = Context::from_waker(&waker);
+
+            let _ = countdown_a.poll_unpin(&mut cx);
+            let _ = countdown_b.poll_unpin(&mut cx);
+
+            std::thread::sleep(std::time::Duration::from_millis(300));
+
+            let _ = countdown_b.poll_unpin(&mut cx);
+        }, //
+    );
 
     tracing::info!("finished countdowns");
 

src/format.rs

@@ -332,6 +332,7 @@ fn indent_block_with_lines(
     style: SpanMode,
 ) {
     let indent_spaces = indent * indent_amount;
+
     if lines.is_empty() {
         return;
     } else if indent_spaces == 0 {
@@ -343,7 +344,12 @@ fn indent_block_with_lines(
                     SpanMode::Open { .. } => buf.push_str(LINE_OPEN),
                     SpanMode::Retrace { .. } => buf.push_str("*"),
                     SpanMode::Close { .. } => buf.push_str(LINE_CLOSE),
-                    SpanMode::PreOpen | SpanMode::PostClose => {}
+                    SpanMode::PreOpen | SpanMode::PostClose => {
+                        unreachable!(
+                            "indent_amount: {} {}, style: {:?}",
+                            indent_amount, indent, style
+                        )
+                    }
                     SpanMode::Event => {}
                 }
             }
@@ -352,6 +358,7 @@ fn indent_block_with_lines(
         }
         return;
     }
+
     let mut s = String::with_capacity(indent_spaces + prefix.len());
     s.push_str(prefix);
 
@@ -383,7 +390,7 @@ fn indent_block_with_lines(
             }
             buf.push_str(LINE_OPEN);
         }
-        SpanMode::Open { verbose: true } | SpanMode::Retrace { verbose: true } => {
+        SpanMode::Open { verbose: true } => {
             buf.push_str(LINE_VERT);
             for _ in 1..(indent_amount / 2) {
                 buf.push(' ');
@@ -402,6 +409,13 @@ fn indent_block_with_lines(
                 buf.push_str(LINE_VERT);
             }
         }
+        SpanMode::Retrace { verbose: true } => {
+            buf.push_str(LINE_BRANCH);
+            for _ in 1..indent_amount {
+                buf.push_str(LINE_HORIZ);
+            }
+            buf.push_str(LINE_OPEN);
+        }
         SpanMode::Close { verbose: false } => {
             buf.push_str(LINE_BRANCH);
             for _ in 1..indent_amount {
@@ -468,7 +482,7 @@ fn indent_block_with_lines(
 fn indent_block(
     block: &mut String,
     buf: &mut String,
-    indent: usize,
+    mut indent: usize,
     indent_amount: usize,
     indent_lines: bool,
     prefix: &str,
@@ -477,6 +491,12 @@ fn indent_block(
     let lines: Vec<&str> = block.lines().collect();
     let indent_spaces = indent * indent_amount;
     buf.reserve(block.len() + (lines.len() * indent_spaces));
+
+    // The PreOpen and PostClose events are generated for the indent of the child span
+    if matches!(style, SpanMode::PreOpen | SpanMode::PostClose) {
+        indent += 1;
+    }
+
     if indent_lines {
         indent_block_with_lines(&lines, buf, indent, indent_amount, prefix, style);
     } else {

src/lib.rs

@@ -36,15 +36,15 @@ use tracing_subscriber::{
 pub(crate) struct Data {
     start: Instant,
     kvs: Vec<(&'static str, String)>,
-    printed: bool,
+    written: bool,
 }
 
 impl Data {
     pub fn new(attrs: &Attributes<'_>, printed: bool) -> Self {
         let mut span = Self {
             start: Instant::now(),
             kvs: Vec::new(),
-            printed,
+            written: printed,
         };
         attrs.record(&mut span);
         span
@@ -265,13 +265,18 @@ where
         Ok(())
     }
 
-    fn write_span_info<S>(&self, id: &Id, bufs: &mut Buffers, ctx: &Context<S>, style: SpanMode)
-    where
+    fn write_span_info<S>(
+        &self,
+        span: &SpanRef<S>,
+        bufs: &mut Buffers,
+        ctx: &Context<S>,
+        style: SpanMode,
+    ) where
         S: Subscriber + for<'span> LookupSpan<'span>,
     {
-        let span = ctx
-            .span(id)
-            .expect("in on_enter/on_exit but span does not exist");
+        // let span = ctx
+        //     .span(id)
+        //     .expect("in on_enter/on_exit but span does not exist");
 
         let ext = span.extensions();
         let data = ext.get::<Data>().expect("span does not have data");
@@ -282,13 +287,7 @@ where
             write_span_mode(current_buf, style)
         }
 
-        let indent = ctx
-            .lookup_current()
-            .as_ref()
-            .map(scope_path)
-            .into_iter()
-            .flatten()
-            .count();
+        let indent = scope_path(span).skip(1).count();
 
         let should_write = match style {
             SpanMode::Open { .. } | SpanMode::Event => true,
@@ -372,12 +371,12 @@ where
 
         if self.config.verbose_entry {
             if let Some(span) = span.parent() {
-                self.write_span_info(&span.id(), bufs, &ctx, SpanMode::PreOpen);
+                self.write_span_info(&span, bufs, &ctx, SpanMode::PreOpen);
             }
         }
 
         self.write_span_info(
-            id,
+            &span,
             bufs,
             &ctx,
             SpanMode::Open {
@@ -399,10 +398,10 @@ where
                 || current_span
                     .extensions()
                     .get::<Data>()
-                    .is_some_and(|v| !v.printed)
+                    .is_some_and(|v| !v.written)
             {
                 if let Some(data) = current_span.extensions_mut().get_mut::<Data>() {
-                    data.printed = true;
+                    data.written = true;
                 }
 
                 let old_span_id = bufs.current_span.replace((*span_id).clone());
@@ -412,11 +411,11 @@ where
                 if Some(*span_id) != old_span_id.as_ref() {
                     let old_span = old_span_id.as_ref().and_then(|v| ctx.span(v));
 
-                    eprintln!(
-                        "concurrent old: {:?}, new: {:?}",
-                        old_span.as_ref().map(|v| v.metadata().name()),
-                        current_span.metadata().name()
-                    );
+                    // eprintln!(
+                    //     "concurrent old: {:?}, new: {:?}",
+                    //     old_span.as_ref().map(|v| v.metadata().name()),
+                    //     current_span.metadata().name()
+                    // );
 
                     let old_path = old_span.as_ref().map(scope_path).into_iter().flatten();
                     let new_path = scope_path(current_span);
@@ -425,9 +424,8 @@ where
                     let new_path = DifferenceIter::new(old_path, new_path, |v| v.id());
 
                     for span in new_path {
-                        eprintln!("Writing span {:?}", span.id());
                         self.write_span_info(
-                            &span.id(),
+                            &span,
                             bufs,
                             &ctx,
                             SpanMode::Retrace {
@@ -541,18 +539,15 @@ where
             bufs.current_span = None;
         }
 
-        let span = ctx.span(&id);
+        let span = ctx.span(&id).expect("invalid span in on_close");
 
         // Span was not printed, so don't print an exit
         if self.config.deferred_spans
-            && span
-                .as_ref()
-                .and_then(|v| v.extensions().get::<Data>().map(|v| v.printed))
-                != Some(true)
+            && span.extensions().get::<Data>().map(|v| v.written) != Some(true)
         {}
 
         self.write_span_info(
-            &id,
+            &span,
             bufs,
             &ctx,
             SpanMode::Close {
@@ -561,11 +556,11 @@ where
         );
 
         if self.config.verbose_exit {
-            if let Some(parent_span) = span.and_then(|span| span.parent()) {
+            if let Some(parent_span) = span.parent() {
                 // Consider parent as entered
                 bufs.current_span = Some(parent_span.id());
 
-                self.write_span_info(&parent_span.id(), bufs, &ctx, SpanMode::PostClose);
+                self.write_span_info(&parent_span, bufs, &ctx, SpanMode::PostClose);
             }
         }
     }