Make tracing-tree usable in contexts with span re-entry (#27)

This PR: - Connects the verbose entry/exit configuration to the formatters. - Skips emitting span entry/exit information
davidbarsky · Nov 15, 2020 · 876f942 · 876f942
1 parent c613581
commit 876f942
Show file tree

Hide file tree

Showing 7 changed files with 291 additions and 179 deletions.
diff --git a/examples/basic.rs b/examples/basic.rs
@@ -31,11 +31,13 @@ fn main() {
         std::thread::sleep(std::time::Duration::from_millis(300));
         debug!(length = 2, "message received");
     });
+    drop(peer1);
     let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
     peer2.in_scope(|| {
         std::thread::sleep(std::time::Duration::from_millis(300));
         debug!("connected");
     });
+    drop(peer2);
     let peer3 = span!(
         Level::TRACE,
         "foomp",
@@ -46,18 +48,23 @@ fn main() {
     peer3.in_scope(|| {
         error!("hello");
     });
+    drop(peer3);
+    let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
     peer1.in_scope(|| {
         warn!(algo = "xor", "weak encryption requested");
         std::thread::sleep(std::time::Duration::from_millis(300));
         debug!(length = 8, "response sent");
         debug!("disconnected");
     });
+    drop(peer1);
+    let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
     peer2.in_scope(|| {
         debug!(length = 5, "message received");
         std::thread::sleep(std::time::Duration::from_millis(300));
         debug!(length = 8, "response sent");
         debug!("disconnected");
     });
+    drop(peer2);
     warn!("internal error");
     log::error!("this is a log message");
     info!("exit");

diff --git a/examples/quiet.rs b/examples/quiet.rs
@@ -0,0 +1,79 @@
+use tracing::{debug, error, info, instrument, span, warn, Level};
+use tracing_subscriber::{layer::SubscriberExt, registry::Registry};
+use tracing_tree::HierarchicalLayer;
+
+fn main() {
+    let layer = HierarchicalLayer::default()
+        .with_indent_lines(true)
+        .with_indent_amount(2)
+        .with_thread_names(true)
+        .with_thread_ids(true)
+        .with_verbose_exit(false)
+        .with_verbose_entry(false)
+        .with_targets(true);
+
+    let subscriber = Registry::default().with(layer);
+    tracing::subscriber::set_global_default(subscriber).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(300));
+    info!("listening");
+    let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
+    peer1.in_scope(|| {
+        debug!("connected");
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!(length = 2, "message received");
+    });
+    drop(peer1);
+    let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
+    peer2.in_scope(|| {
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!("connected");
+    });
+    drop(peer2);
+    let peer3 = span!(
+        Level::TRACE,
+        "foomp",
+        normal_var = 43,
+        "{} <- format string",
+        42
+    );
+    peer3.in_scope(|| {
+        error!("hello");
+    });
+    drop(peer3);
+    let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
+    peer1.in_scope(|| {
+        warn!(algo = "xor", "weak encryption requested");
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!(length = 8, "response sent");
+        debug!("disconnected");
+    });
+    drop(peer1);
+    let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
+    peer2.in_scope(|| {
+        debug!(length = 5, "message received");
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!(length = 8, "response sent");
+        debug!("disconnected");
+    });
+    drop(peer2);
+    warn!("internal error");
+    info!("exit");
+}
+
+#[instrument]
+fn call_a(name: &str) {
+    info!(name, "got a name");
+    call_b(name)
+}
+
+#[instrument]
+fn call_b(name: &str) {
+    info!(name, "got a name");
+}
diff --git a/examples/quiet.stdout b/examples/quiet.stdout
@@ -0,0 +1,28 @@
+1:mainquiet::hierarchical-example version=0.1
+1:main├─┐quiet::server host="localhost", port=8080
+1:main│ ├─ms INFO quiet starting
+1:main│ ├─ms INFO quiet listening
+1:main│ ├─┐quiet::conn peer_addr="82.9.9.9", port=42381
+1:main│ │ ├─ms DEBUG quiet connected
+1:main│ │ ├─ms DEBUG quiet message received, length=2
+1:main│ ├─┘
+1:main│ ├─┐quiet::conn peer_addr="8.8.8.8", port=18230
+1:main│ │ ├─ms DEBUG quiet connected
+1:main│ ├─┘
+1:main│ ├─┐quiet::foomp 42 <- format string, normal_var=43
+1:main│ │ ├─ms ERROR quiet hello
+1:main│ ├─┘
+1:main│ ├─┐quiet::conn peer_addr="82.9.9.9", port=42381
+1:main│ │ ├─ms WARN quiet weak encryption requested, algo="xor"
+1:main│ │ ├─ms DEBUG quiet response sent, length=8
+1:main│ │ ├─ms DEBUG quiet disconnected
+1:main│ ├─┘
+1:main│ ├─┐quiet::conn peer_addr="8.8.8.8", port=18230
+1:main│ │ ├─ms DEBUG quiet message received, length=5
+1:main│ │ ├─ms DEBUG quiet response sent, length=8
+1:main│ │ ├─ms DEBUG quiet disconnected
+1:main│ ├─┘
+1:main│ ├─ms WARN quiet internal error
+1:main│ ├─ms INFO quiet exit
+1:main├─┘
+1:main
diff --git a/examples/stderr.stderr b/examples/stderr.stderr
@@ -1,110 +1,111 @@
 fibonacci_seq{to=5}
 ├─ms DEBUG Pushing 0 fibonacci
-├┐fibonacci_seq{to=5}
-│└┐nth_fibonacci{n=0}
+├─┐nth_fibonacci{n=0}
 │ ├─ms DEBUG Base case
+├─┘
 ├─ms DEBUG Pushing 1 fibonacci
-├┐fibonacci_seq{to=5}
-│└┐nth_fibonacci{n=1}
+├─┐nth_fibonacci{n=1}
 │ ├─ms DEBUG Base case
+├─┘
 ├─ms DEBUG Pushing 2 fibonacci
-├┐fibonacci_seq{to=5}
-│└┐nth_fibonacci{n=2}
+├─┐nth_fibonacci{n=2}
 │ ├─ms DEBUG Recursing
-│ ├┐nth_fibonacci{n=2}
-│ │└┐nth_fibonacci{n=1}
+│ ├─┐nth_fibonacci{n=1}
 │ │ ├─ms DEBUG Base case
-│ ├┐nth_fibonacci{n=2}
-│ │└┐nth_fibonacci{n=0}
+│ ├─┘
+│ ├─┐nth_fibonacci{n=0}
 │ │ ├─ms DEBUG Base case
+│ ├─┘
+├─┘
 ├─ms DEBUG Pushing 3 fibonacci
-├┐fibonacci_seq{to=5}
-│└┐nth_fibonacci{n=3}
+├─┐nth_fibonacci{n=3}
 │ ├─ms DEBUG Recursing
-│ ├┐nth_fibonacci{n=3}
-│ │└┐nth_fibonacci{n=2}
+│ ├─┐nth_fibonacci{n=2}
 │ │ ├─ms DEBUG Recursing
-│ │ ├┐nth_fibonacci{n=2}
-│ │ │└┐nth_fibonacci{n=1}
+│ │ ├─┐nth_fibonacci{n=1}
 │ │ │ ├─ms DEBUG Base case
-│ │ ├┐nth_fibonacci{n=2}
-│ │ │└┐nth_fibonacci{n=0}
+│ │ ├─┘
+│ │ ├─┐nth_fibonacci{n=0}
 │ │ │ ├─ms DEBUG Base case
-│ ├┐nth_fibonacci{n=3}
-│ │└┐nth_fibonacci{n=1}
+│ │ ├─┘
+│ ├─┘
+│ ├─┐nth_fibonacci{n=1}
 │ │ ├─ms DEBUG Base case
+│ ├─┘
+├─┘
 ├─ms DEBUG Pushing 4 fibonacci
-├┐fibonacci_seq{to=5}
-│└┐nth_fibonacci{n=4}
+├─┐nth_fibonacci{n=4}
 │ ├─ms DEBUG Recursing
-│ ├┐nth_fibonacci{n=4}
-│ │└┐nth_fibonacci{n=3}
+│ ├─┐nth_fibonacci{n=3}
 │ │ ├─ms DEBUG Recursing
-│ │ ├┐nth_fibonacci{n=3}
-│ │ │└┐nth_fibonacci{n=2}
+│ │ ├─┐nth_fibonacci{n=2}
 │ │ │ ├─ms DEBUG Recursing
-│ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │└┐nth_fibonacci{n=1}
+│ │ │ ├─┐nth_fibonacci{n=1}
 │ │ │ │ ├─ms DEBUG Base case
-│ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │└┐nth_fibonacci{n=0}
+│ │ │ ├─┘
+│ │ │ ├─┐nth_fibonacci{n=0}
 │ │ │ │ ├─ms DEBUG Base case
-│ │ ├┐nth_fibonacci{n=3}
-│ │ │└┐nth_fibonacci{n=1}
+│ │ │ ├─┘
+│ │ ├─┘
+│ │ ├─┐nth_fibonacci{n=1}
 │ │ │ ├─ms DEBUG Base case
-│ ├┐nth_fibonacci{n=4}
-│ │└┐nth_fibonacci{n=2}
+│ │ ├─┘
+│ ├─┘
+│ ├─┐nth_fibonacci{n=2}
 │ │ ├─ms DEBUG Recursing
-│ │ ├┐nth_fibonacci{n=2}
-│ │ │└┐nth_fibonacci{n=1}
+│ │ ├─┐nth_fibonacci{n=1}
 │ │ │ ├─ms DEBUG Base case
-│ │ ├┐nth_fibonacci{n=2}
-│ │ │└┐nth_fibonacci{n=0}
+│ │ ├─┘
+│ │ ├─┐nth_fibonacci{n=0}
 │ │ │ ├─ms DEBUG Base case
+│ │ ├─┘
+│ ├─┘
+├─┘
 ├─ms DEBUG Pushing 5 fibonacci
-├┐fibonacci_seq{to=5}
-│└┐nth_fibonacci{n=5}
+├─┐nth_fibonacci{n=5}
 │ ├─ms DEBUG Recursing
-│ ├┐nth_fibonacci{n=5}
-│ │└┐nth_fibonacci{n=4}
+│ ├─┐nth_fibonacci{n=4}
 │ │ ├─ms DEBUG Recursing
-│ │ ├┐nth_fibonacci{n=4}
-│ │ │└┐nth_fibonacci{n=3}
+│ │ ├─┐nth_fibonacci{n=3}
 │ │ │ ├─ms DEBUG Recursing
-│ │ │ ├┐nth_fibonacci{n=3}
-│ │ │ │└┐nth_fibonacci{n=2}
+│ │ │ ├─┐nth_fibonacci{n=2}
 │ │ │ │ ├─ms DEBUG Recursing
-│ │ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │ │└┐nth_fibonacci{n=1}
+│ │ │ │ ├─┐nth_fibonacci{n=1}
 │ │ │ │ │ ├─ms DEBUG Base case
-│ │ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │ │└┐nth_fibonacci{n=0}
+│ │ │ │ ├─┘
+│ │ │ │ ├─┐nth_fibonacci{n=0}
 │ │ │ │ │ ├─ms DEBUG Base case
-│ │ │ ├┐nth_fibonacci{n=3}
-│ │ │ │└┐nth_fibonacci{n=1}
+│ │ │ │ ├─┘
+│ │ │ ├─┘
+│ │ │ ├─┐nth_fibonacci{n=1}
 │ │ │ │ ├─ms DEBUG Base case
-│ │ ├┐nth_fibonacci{n=4}
-│ │ │└┐nth_fibonacci{n=2}
+│ │ │ ├─┘
+│ │ ├─┘
+│ │ ├─┐nth_fibonacci{n=2}
 │ │ │ ├─ms DEBUG Recursing
-│ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │└┐nth_fibonacci{n=1}
+│ │ │ ├─┐nth_fibonacci{n=1}
 │ │ │ │ ├─ms DEBUG Base case
-│ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │└┐nth_fibonacci{n=0}
+│ │ │ ├─┘
+│ │ │ ├─┐nth_fibonacci{n=0}
 │ │ │ │ ├─ms DEBUG Base case
-│ ├┐nth_fibonacci{n=5}
-│ │└┐nth_fibonacci{n=3}
+│ │ │ ├─┘
+│ │ ├─┘
+│ ├─┘
+│ ├─┐nth_fibonacci{n=3}
 │ │ ├─ms DEBUG Recursing
-│ │ ├┐nth_fibonacci{n=3}
-│ │ │└┐nth_fibonacci{n=2}
+│ │ ├─┐nth_fibonacci{n=2}
 │ │ │ ├─ms DEBUG Recursing
-│ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │└┐nth_fibonacci{n=1}
+│ │ │ ├─┐nth_fibonacci{n=1}
 │ │ │ │ ├─ms DEBUG Base case
-│ │ │ ├┐nth_fibonacci{n=2}
-│ │ │ │└┐nth_fibonacci{n=0}
+│ │ │ ├─┘
+│ │ │ ├─┐nth_fibonacci{n=0}
 │ │ │ │ ├─ms DEBUG Base case
-│ │ ├┐nth_fibonacci{n=3}
-│ │ │└┐nth_fibonacci{n=1}
+│ │ │ ├─┘
+│ │ ├─┘
+│ │ ├─┐nth_fibonacci{n=1}
 │ │ │ ├─ms DEBUG Base case
+│ │ ├─┘
+│ ├─┘
+├─┘
+
 INFO The first 5 fibonacci numbers are [1, 1, 2, 3, 5, 8]