From 09adf545d9805ebff49371861bdae6249a37167c Mon Sep 17 00:00:00 2001 From: Freja Roberts Date: Tue, 12 Dec 2023 15:46:25 +0100 Subject: [PATCH 1/4] fix: non-deferred interleaved span enter events --- examples/concurrent_eager.rs | 101 +++++++++++++++++++++++++ examples/concurrent_eager.stdout | 16 ++++ src/lib.rs | 123 +++++++++++++++---------------- 3 files changed, 178 insertions(+), 62 deletions(-) create mode 100644 examples/concurrent_eager.rs create mode 100644 examples/concurrent_eager.stdout diff --git a/examples/concurrent_eager.rs b/examples/concurrent_eager.rs new file mode 100644 index 0000000..8a627a7 --- /dev/null +++ b/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 Fut, Fut: Future>( + key: &'static str, + inner: F, +) -> impl Future { + let span = tracing::info_span!("spawn_fut", key); + + async move { + countdown(1).await; + + inner().await; + } + .instrument(span) +} + +fn a() -> impl Future { + let span = tracing::info_span!("a"); + + async move { + countdown(1).await; + tracing::info!("a"); + } + .instrument(span) +} + +fn b() -> impl Future { + let span = tracing::info_span!("b"); + + async move { + countdown(1).await; + tracing::info!("b"); + } + .instrument(span) +} + +fn countdown(count: u32) -> impl Future { + CountdownFuture { count } +} + +struct CountdownFuture { + count: u32, +} + +impl Future for CountdownFuture { + type Output = (); + + fn poll(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll { + if self.count == 0 { + Poll::Ready(()) + } else { + self.count -= 1; + cx.waker().wake_by_ref(); + Poll::Pending + } + } +} diff --git a/examples/concurrent_eager.stdout b/examples/concurrent_eager.stdout new file mode 100644 index 0000000..dac84ac --- /dev/null +++ b/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┘ diff --git a/src/lib.rs b/src/lib.rs index 2915259..de6df51 100644 --- a/src/lib.rs +++ b/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.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::() { - 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::() { + 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) { @@ -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; From f861bac78808ba37cfd2cf9c1250377f67e72d30 Mon Sep 17 00:00:00 2001 From: Freja Roberts Date: Fri, 19 Jan 2024 16:39:13 +0100 Subject: [PATCH 2/4] 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); } } From 26b48a708a50a9f94c7724280831ccefc8437996 Mon Sep 17 00:00:00 2001 From: Freja Roberts Date: Fri, 16 Feb 2024 13:20:37 +0100 Subject: [PATCH 3/4] chore: print parent of retrace chain root during pre_open The previous behavior was to print the parent of the new span, leading to a parent being printed twice if the parent was also included in the retrace chain. --- examples/concurrent_eager.stdout | 12 ++++-------- examples/concurrent_verbose.stdout | 21 ++++++++++++--------- examples/deferred.stdout | 21 ++++++++++++--------- src/lib.rs | 7 ++++--- 4 files changed, 32 insertions(+), 29 deletions(-) diff --git a/examples/concurrent_eager.stdout b/examples/concurrent_eager.stdout index 289a83b..dac84ac 100644 --- a/examples/concurrent_eager.stdout +++ b/examples/concurrent_eager.stdout @@ -1,19 +1,15 @@ 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::spawn_fut key="a" -1:main│ └─┐concurrent_eager::a +1:main├───┐concurrent_eager::a 1:main┐concurrent_eager::spawn_fut key="b" -1:main├─┐concurrent_eager::spawn_fut key="b" -1:main│ └─┐concurrent_eager::b +1:main├───┐concurrent_eager::b 1:main┐concurrent_eager::spawn_fut key="a" -1:main├─┐concurrent_eager::spawn_fut key="a" -1:main│ └─┐concurrent_eager::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::spawn_fut key="b" -1:main│ └─┐concurrent_eager::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 363b957..73d1e57 100644 --- a/examples/concurrent_verbose.stdout +++ b/examples/concurrent_verbose.stdout @@ -1,21 +1,24 @@ 1:main┐concurrent_verbose::hierarchical-example version=0.1 -1:main├─┐concurrent_verbose::hierarchical-example version=0.1 -1:main│ └─┐concurrent_verbose::server host="localhost", port=8080 +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::countdowns -1:main│ │ ├─┐concurrent_verbose::countdowns -1:main│ │ │ └─┐concurrent_verbose::countdown_a +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::countdown_b +1:main│ │ ├─┐concurrent_verbose::countdowns +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::countdown_a +1:main│ │ ├─┐concurrent_verbose::countdowns +1:main│ │ │ └─┐concurrent_verbose::countdown_a 1:main│ │ │ ├─── Xms DEBUG concurrent_verbose polling countdown, label="a", count=2 -1:main│ ├───┐concurrent_verbose::conn peer_addr="82.9.9.9", port=42381 +1:main│ ├─┐concurrent_verbose::server host="localhost", port=8080 +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::countdowns +1:main│ ├─┐concurrent_verbose::server host="localhost", port=8080 +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 7793e1c..e2fc729 100644 --- a/examples/deferred.stdout +++ b/examples/deferred.stdout @@ -1,32 +1,35 @@ -> This prints before the span open message 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├─┐open: 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│ ├─┐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│ ├┐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│ │ │ ├─ 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│ │ ├─┐open: deferred::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├┐pre_open: deferred::connections +1:main│ │ │└┐open(v): 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│ │ ├─┐open: deferred::foomp 42 <- format string, normal_var=43 +1:main│ │ ├┐pre_open: deferred::connections +1:main│ │ │└┐open(v): 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│ │ ├─┐open: deferred::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├┐pre_open: deferred::connections +1:main│ │ │└┐open(v): 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│ │ ├─┐open: deferred::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├┐pre_open: deferred::connections +1:main│ │ │└┐open(v): 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 f0c66b0..ba12922 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -307,10 +307,11 @@ where false }; - let verbose = i == 1 && pre_open && span.id() == new_span_id; - // Print the parent of the new span if `pre_open==true` - if verbose { + // Print the parent of the first span + let mut verbose = false; + if i == 0 && pre_open { if let Some(span) = span.parent() { + verbose = true; self.write_span_info(&span, bufs, SpanMode::PreOpen); } } From 757f1548b61a70818497ebf8d2ea9eac6f693b31 Mon Sep 17 00:00:00 2001 From: Freja Roberts Date: Fri, 16 Feb 2024 13:25:30 +0100 Subject: [PATCH 4/4] chore: fix new clippy lint for string slices --- src/format.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/format.rs b/src/format.rs index a7d95a3..176faf6 100644 --- a/src/format.rs +++ b/src/format.rs @@ -246,7 +246,7 @@ impl Buffers { } indent_block( - &mut self.current_buf, + &self.current_buf, &mut self.indent_buf, indent % config.wraparound, config.indent_amount, @@ -479,7 +479,7 @@ fn indent_block_with_lines( } fn indent_block( - block: &mut String, + block: &str, buf: &mut String, mut indent: usize, indent_amount: usize,