From f861bac78808ba37cfd2cf9c1250377f67e72d30 Mon Sep 17 00:00:00 2001 From: Freja Roberts Date: Fri, 19 Jan 2024 16:39:13 +0100 Subject: [PATCH] fix: pre-open for retraced spans --- examples/concurrent_eager.rs | 1 + examples/concurrent_eager.stdout | 12 ++++++++---- examples/concurrent_verbose.stdout | 21 +++++++++------------ examples/deferred.stdout | 23 ++++++++++------------- src/lib.rs | 29 ++++++++++++++--------------- 5 files changed, 42 insertions(+), 44 deletions(-) diff --git a/examples/concurrent_eager.rs b/examples/concurrent_eager.rs index 8a627a7..3f1ed9f 100644 --- 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 index dac84ac..289a83b 100644 --- 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 index 73d1e57..363b957 100644 --- 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 index dac8e24..7793e1c 100644 --- 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 index de6df51..f0c66b0 100644 --- 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, + 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); } }