fix: pre-open for retraced spans

Author: ten3roberts

examples/concurrent_eager.rs

@@ -18,6 +18,7 @@ fn main() {
  .with_thread_ids(true)
  .with_span_retrace(true)
  .with_deferred_spans(false)
+ .with_verbose_entry(true)
  .with_targets(true);
 
  let subscriber = Registry::default().with(layer);

examples/concurrent_eager.stdout

@@ -1,15 +1,19 @@
 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="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="b"
+1:main│ └─┐concurrent_eager::b 
 1:main┐concurrent_eager::spawn_fut key="a"
-1:main├───┐concurrent_eager::a 
+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├─┐concurrent_eager::spawn_fut key="b"
+1:main│ └─┐concurrent_eager::b 
 1:main│ ├─── Xms INFO concurrent_eager b
 1:main├───┘
 1:main┘

examples/concurrent_verbose.stdout

@@ -1,24 +1,21 @@
 1:main┐concurrent_verbose::hierarchical-example version=0.1
-1:main├───┐concurrent_verbose::server host="localhost", port=8080
+1:main├─┐concurrent_verbose::hierarchical-example version=0.1
+1:main│ └─┐concurrent_verbose::server host="localhost", port=8080
 1:main│ ├─── Xms INFO concurrent_verbose starting
 1:main│ ├─── Xs INFO concurrent_verbose listening
 1:main│ ├─── Xs DEBUG concurrent_verbose starting countdowns
-1:main│ ├─┐concurrent_verbose::server host="localhost", port=8080
-1:main│ │ └─┐concurrent_verbose::countdowns 
-1:main│ │ ├───┐concurrent_verbose::countdown_a 
-1:main│ │ │ ├─── Xms DEBUG concurrent_verbose polling countdown, label="a", count=3
+1:main│ ├───┐concurrent_verbose::countdowns 
 1:main│ │ ├─┐concurrent_verbose::countdowns 
-1:main│ │ │ └─┐concurrent_verbose::countdown_b 
+1:main│ │ │ └─┐concurrent_verbose::countdown_a 
+1:main│ │ │ ├─── Xms DEBUG concurrent_verbose polling countdown, label="a", count=3
+1:main│ │ ├───┐concurrent_verbose::countdown_b 
 1:main│ │ │ ├─── Xms DEBUG concurrent_verbose polling countdown, label="b", count=5
 1:main│ │ │ ├─── Xms DEBUG concurrent_verbose polling countdown, label="b", count=4
-1:main│ │ ├─┐concurrent_verbose::countdowns 
-1:main│ │ │ └─┐concurrent_verbose::countdown_a 
+1:main│ │ ├───┐concurrent_verbose::countdown_a 
 1:main│ │ │ ├─── Xms DEBUG concurrent_verbose polling countdown, label="a", count=2
-1:main│ ├─┐concurrent_verbose::server host="localhost", port=8080
-1:main│ │ └─┐concurrent_verbose::conn peer_addr="82.9.9.9", port=42381
+1:main│ ├───┐concurrent_verbose::conn peer_addr="82.9.9.9", port=42381
 1:main│ │ ├─── Xms WARN concurrent_verbose peer1 warning
-1:main│ ├─┐concurrent_verbose::server host="localhost", port=8080
-1:main│ │ └─┐concurrent_verbose::countdowns 
+1:main│ ├───┐concurrent_verbose::countdowns 
 1:main│ │ ├─── Xms INFO concurrent_verbose finished polling countdowns
 1:main│ │ │ ┌─┘concurrent_verbose::countdown_b 
 1:main│ │ ├─┘concurrent_verbose::countdowns 

examples/deferred.stdout

@@ -1,35 +1,32 @@
 -> This prints before the span open message
-1:main┐open(v): deferred::hierarchical-example version=0.1
-1:main├─┐open: deferred::server host="localhost", port=8080
+1:main┐open: deferred::hierarchical-example version=0.1
+1:main├┐pre_open: deferred::hierarchical-example version=0.1
+1:main│└┐open(v): deferred::server host="localhost", port=8080
 1:main│ ├─ Xms INFO deferred starting
 1:main│ ├─ Xs INFO deferred listening
 -> Deferring two levels of spans
-1:main│ ├┐pre_open: deferred::server host="localhost", port=8080
-1:main│ │└┐open(v): deferred::connections 
-1:main│ │ ├─┐open: deferred::conn peer_addr="82.9.9.9", port=42381
+1:main│ ├─┐open: deferred::connections 
+1:main│ │ ├┐pre_open: deferred::connections 
+1:main│ │ │└┐open(v): deferred::conn peer_addr="82.9.9.9", port=42381
 1:main│ │ │ ├─ Xms DEBUG deferred connected, peer="peer1"
 1:main│ │ │ ├─ Xms DEBUG deferred message received, length=2
 1:main│ │ │┌┘close(v): deferred::conn peer_addr="82.9.9.9", port=42381
 1:main│ │ ├┘post_close: deferred::connections 
-1:main│ │ ├┐pre_open: deferred::connections 
-1:main│ │ │└┐open(v): deferred::conn peer_addr="8.8.8.8", port=18230
+1:main│ │ ├─┐open: deferred::conn peer_addr="8.8.8.8", port=18230
 1:main│ │ │ ├─ Xms DEBUG deferred connected, peer="peer3"
 1:main│ │ │┌┘close(v): deferred::conn peer_addr="8.8.8.8", port=18230
 1:main│ │ ├┘post_close: deferred::connections 
-1:main│ │ ├┐pre_open: deferred::connections 
-1:main│ │ │└┐open(v): deferred::foomp 42 <- format string, normal_var=43
+1:main│ │ ├─┐open: deferred::foomp 42 <- format string, normal_var=43
 1:main│ │ │ ├─ Xms ERROR deferred hello
 1:main│ │ │┌┘close(v): deferred::foomp 42 <- format string, normal_var=43
 1:main│ │ ├┘post_close: deferred::connections 
-1:main│ │ ├┐pre_open: deferred::connections 
-1:main│ │ │└┐open(v): deferred::conn peer_addr="82.9.9.9", port=42381
+1:main│ │ ├─┐open: deferred::conn peer_addr="82.9.9.9", port=42381
 1:main│ │ │ ├─ Xms WARN deferred weak encryption requested, algo="xor"
 1:main│ │ │ ├─ Xms DEBUG deferred response sent, length=8
 1:main│ │ │ ├─ Xms DEBUG deferred disconnected
 1:main│ │ │┌┘close(v): deferred::conn peer_addr="82.9.9.9", port=42381
 1:main│ │ ├┘post_close: deferred::connections 
-1:main│ │ ├┐pre_open: deferred::connections 
-1:main│ │ │└┐open(v): deferred::conn peer_addr="8.8.8.8", port=18230
+1:main│ │ ├─┐open: deferred::conn peer_addr="8.8.8.8", port=18230
 1:main│ │ │ ├─ Xms DEBUG deferred message received, length=5
 1:main│ │ │ ├─ Xms DEBUG deferred response sent, length=8
 1:main│ │ │ ├─ Xms DEBUG deferred disconnected

src/lib.rs

@@ -6,7 +6,7 @@ use format::{write_span_mode, Buffers, ColorLevel, Config, FmtEvent, SpanMode};
 
 use nu_ansi_term::{Color, Style};
 use std::{
- fmt::{self, Write as _},
+ fmt::{self, Write},
  io::{self, IsTerminal},
  iter::Fuse,
  mem,
@@ -273,6 +273,7 @@ where
  new_span: &SpanRef<'a, S>,
  bufs: &mut Buffers,
  ctx: &'a Context<S>,
+ pre_open: bool,
  ) where
  S: Subscriber + for<'new_span> LookupSpan<'new_span>,
  {
@@ -306,13 +307,13 @@ where
  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 = i == 1 && pre_open && span.id() == new_span_id;
+ // Print the parent of the new span if `pre_open==true`
+ if verbose {
+ if let Some(span) = span.parent() {
+ self.write_span_info(&span, bufs, SpanMode::PreOpen);
  }
  }
- let verbose = self.config.verbose_entry && i == 0;
 
  self.write_span_info(
  &span,
@@ -324,7 +325,6 @@ where
  },
  )
  }
- // }
  }
  }
 
@@ -485,15 +485,14 @@ where
 
  let bufs = &mut *self.bufs.lock().unwrap();
 
- if self.config.verbose_entry {
- if let Some(span) = span.parent() {
- self.write_span_info(&span, bufs, SpanMode::PreOpen);
- }
- }
-
  if self.config.span_retrace {
- self.write_retrace_span(&span, bufs, &ctx);
+ self.write_retrace_span(&span, bufs, &ctx, self.config.verbose_entry);
  } else {
+ if self.config.verbose_entry {
+ if let Some(span) = span.parent() {
+ self.write_span_info(&span, bufs, SpanMode::PreOpen);
+ }
+ }
  // Store the most recently entered span
  bufs.current_span = Some(span.id());
  self.write_span_info(
@@ -516,7 +515,7 @@ where
 
  if let Some(new_span) = &span {
  if self.config.span_retrace || self.config.deferred_spans {
- self.write_retrace_span(new_span, bufs, &ctx);
+ self.write_retrace_span(new_span, bufs, &ctx, self.config.verbose_entry);
  }
  }