fix: pre-open for retraced spans

davidbarsky · Jan 22, 2024 · f861bac · f861bac
1 parent 09adf54
commit f861bac
Show file tree

Hide file tree

Showing 5 changed files with 42 additions and 44 deletions.
diff --git a/examples/concurrent_eager.rs b/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);

diff --git a/examples/concurrent_eager.stdout b/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┘

diff --git a/examples/concurrent_verbose.stdout b/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 

diff --git a/examples/deferred.stdout b/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

diff --git a/src/lib.rs b/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);
             }
         }