Improvement: better concurrency support of interleaved futures

Cargo.toml

@@ -10,11 +10,18 @@ readme = "README.md"
 
 [dependencies]
 tracing-core = "0.1"
-tracing-subscriber = { version = "0.3", default-features = false, features = ["registry", "fmt", "std"] }
+tracing-subscriber = { version = "0.3", default-features = false, features = [
+    "registry",
+    "fmt",
+    "std",
+] }
 nu-ansi-term = "0.46.0"
 is-terminal = "0.4.7"
 tracing-log = { version = "0.1", optional = true }
-time = { version = "0.3.20", optional = true, features = ["formatting", "local-offset"] }
+time = { version = "0.3.20", optional = true, features = [
+    "formatting",
+    "local-offset",
+] }
 
 [features]
 default = ["tracing-log"]
@@ -23,6 +30,7 @@ default = ["tracing-log"]
 tracing = "0.1"
 glob = "0.3"
 ui_test = "0.7"
+futures = "0.3"
 log = "0.4"
 
 [[test]]

examples/concurrent.rs

@@ -0,0 +1,96 @@
+use std::{
+    future::Future,
+    pin::Pin,
+    task::{Context, Poll},
+};
+
+use futures::FutureExt;
+use tracing::{debug, debug_span, error, info, instrument, span, warn, Instrument, Level};
+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(2)
+        .with_thread_names(true)
+        .with_thread_ids(true)
+        .with_verbose_exit(true)
+        .with_verbose_entry(true)
+        .with_verbose_retrace(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 app_span = span!(Level::TRACE, "hierarchical-example", version = %0.1);
+
+    let _e = app_span.enter();
+
+    let server_span = span!(Level::TRACE, "server", host = "localhost", port = 8080);
+
+    let _e2 = server_span.enter();
+    info!("starting");
+
+    std::thread::sleep(std::time::Duration::from_millis(1000));
+
+    info!("listening");
+
+    let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
+
+    debug!("starting countdowns");
+    debug_span!("countdowns").in_scope(|| {
+        let mut countdown_a = CountdownFuture {
+            label: "a",
+            count: 3,
+        }
+        .instrument(span!(Level::DEBUG, "countdown_a"))
+        .fuse();
+
+        let mut countdown_b = CountdownFuture {
+            label: "b",
+            count: 5,
+        }
+        .instrument(span!(Level::DEBUG, "countdown_b"))
+        .fuse();
+
+        // We don't care if the futures are ready, as we poll manually
+        let waker = futures::task::noop_waker();
+        let mut cx = Context::from_waker(&waker);
+
+        let _ = countdown_a.poll_unpin(&mut cx);
+        let _ = countdown_b.poll_unpin(&mut cx);
+
+        std::thread::sleep(std::time::Duration::from_millis(300));
+
+        let _ = countdown_b.poll_unpin(&mut cx);
+    });
+
+    tracing::info!("finished countdowns");
+
+    info!("exit")
+}
+
+struct CountdownFuture {
+    label: &'static str,
+    count: u32,
+}
+
+impl Future for CountdownFuture {
+    type Output = ();
+
+    fn poll(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
+        debug!(label=?self.label, count=?self.count, "polling countdown");
+        self.count -= 1;
+
+        if self.count == 0 {
+            Poll::Ready(())
+        } else {
+            cx.waker().wake_by_ref();
+            Poll::Pending
+        }
+    }
+}

src/format.rs

@@ -14,11 +14,19 @@ pub(crate) const LINE_BRANCH: &str = "├";
 pub(crate) const LINE_CLOSE: &str = "┘";
 pub(crate) const LINE_OPEN: &str = "┐";
 
-#[derive(Copy, Clone)]
+#[derive(Debug, Copy, Clone)]
 pub(crate) enum SpanMode {
     PreOpen,
-    Open { verbose: bool },
-    Close { verbose: bool },
+    Open {
+        verbose: bool,
+    },
+    Close {
+        verbose: bool,
+    },
+    /// A span has been entered but another *different* span has been entered in the meantime.
+    Retrace {
+        verbose: bool,
+    },
     PostClose,
     Event,
 }
@@ -43,6 +51,8 @@ pub struct Config {
     pub verbose_entry: bool,
     /// Whether to print the current span before exiting it.
     pub verbose_exit: bool,
+    /// Print the path leading up to a span if a different span was entered concurrently
+    pub verbose_retrace: bool,
     /// Whether to print squiggly brackets (`{}`) around the list of fields in a span.
     pub bracketed_fields: bool,
 }
@@ -95,6 +105,13 @@ impl Config {
         }
     }
 
+    pub fn with_verbose_retrace(self, verbose_retrace: bool) -> Self {
+        Self {
+            verbose_retrace,
+            ..self
+        }
+    }
+
     pub fn with_bracketed_fields(self, bracketed_fields: bool) -> Self {
         Self {
             bracketed_fields,
@@ -137,6 +154,7 @@ impl Default for Config {
             wraparound: usize::max_value(),
             verbose_entry: false,
             verbose_exit: false,
+            verbose_retrace: false,
             bracketed_fields: false,
         }
     }
@@ -277,6 +295,7 @@ fn indent_block_with_lines(
             if indent == 0 {
                 match style {
                     SpanMode::Open { .. } => buf.push_str(LINE_OPEN),
+                    SpanMode::Retrace { .. } => buf.push_str("*"),
                     SpanMode::Close { .. } => buf.push_str(LINE_CLOSE),
                     SpanMode::PreOpen | SpanMode::PostClose => {}
                     SpanMode::Event => {}
@@ -318,6 +337,13 @@ fn indent_block_with_lines(
             }
             buf.push_str(LINE_OPEN);
         }
+        SpanMode::Retrace { verbose: false } => {
+            buf.push_str(LINE_BRANCH);
+            for _ in 1..indent_amount {
+                buf.push_str(LINE_HORIZ);
+            }
+            buf.push_str(LINE_OPEN);
+        }
         SpanMode::Open { verbose: true } => {
             buf.push_str(LINE_VERT);
             for _ in 1..(indent_amount / 2) {
@@ -337,6 +363,25 @@ fn indent_block_with_lines(
                 buf.push_str(LINE_VERT);
             }
         }
+        SpanMode::Retrace { verbose: true } => {
+            buf.push_str("I");
+            for _ in 1..(indent_amount / 2) {
+                buf.push(' ');
+            }
+            // We don't have the space for fancy rendering at single space indent.
+            if indent_amount > 1 {
+                buf.push('L');
+            }
+            for _ in (indent_amount / 2)..(indent_amount - 1) {
+                buf.push_str("_");
+            }
+            // We don't have the space for fancy rendering at single space indent.
+            if indent_amount > 1 {
+                buf.push_str("*");
+            } else {
+                buf.push_str("|");
+            }
+        }
         SpanMode::Close { verbose: false } => {
             buf.push_str(LINE_BRANCH);
             for _ in 1..indent_amount {