diff --git a/examples/concurrent_eager.rs b/examples/concurrent_eager.rs new file mode 100644 index 0000000..3f1ed9f --- /dev/null +++ b/examples/concurrent_eager.rs @@ -0,0 +1,102 @@ +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_verbose_entry(true) + .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/examples/deferred.stdout b/examples/deferred.stdout index dac8e24..e2fc729 100644 --- a/examples/deferred.stdout +++ b/examples/deferred.stdout @@ -1,5 +1,5 @@ -> This prints before the span open message -1:main┐open(v): deferred::hierarchical-example version=0.1 +1:main┐open: deferred::hierarchical-example version=0.1 1:main├─┐open: deferred::server host="localhost", port=8080 1:main│ ├─ Xms INFO deferred starting 1:main│ ├─ Xs INFO deferred listening 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, diff --git a/src/lib.rs b/src/lib.rs index 2915259..ba12922 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, @@ -267,69 +267,64 @@ 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>, bufs: &mut Buffers, ctx: &'a Context, + pre_open: bool, ) 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 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); } - let verbose = self.config.verbose_entry && i == 0; - - self.write_span_info( - &span, - bufs, - if was_written { - SpanMode::Retrace { verbose } - } else { - SpanMode::Open { verbose } - }, - ) } + + self.write_span_info( + &span, + bufs, + if was_written { + SpanMode::Retrace { verbose } + } else { + SpanMode::Open { verbose } + }, + ) } } } @@ -491,22 +486,24 @@ 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); + if self.config.span_retrace { + 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( + &span, + bufs, + SpanMode::Open { + verbose: self.config.verbose_entry, + }, + ); } - - 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, self.config.verbose_entry); + } } let mut event_buf = &mut bufs.current_buf;