diff --git a/Cargo.toml b/Cargo.toml index 54e7854..62a8a5f 100644 --- a/Cargo.toml +++ b/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]] diff --git a/examples/basic_non_verbose.rs b/examples/basic_non_verbose.rs new file mode 100644 index 0000000..0e5c009 --- /dev/null +++ b/examples/basic_non_verbose.rs @@ -0,0 +1,81 @@ +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_writer(std::io::stdout) + .with_indent_lines(true) + .with_indent_amount(2) + .with_thread_names(true) + .with_thread_ids(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(3000)); + 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"); + log::error!("this is a log message"); + 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/basic_non_verbose.stdout b/examples/basic_non_verbose.stdout new file mode 100644 index 0000000..fcdd9b5 --- /dev/null +++ b/examples/basic_non_verbose.stdout @@ -0,0 +1,29 @@ +1:main┐basic_non_verbose::hierarchical-example version=0.1 +1:main├─┐basic_non_verbose::server host="localhost", port=8080 +1:main│ ├─ Xms INFO basic_non_verbose starting +1:main│ ├─ Xs INFO basic_non_verbose listening +1:main│ ├─┐basic_non_verbose::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├─ Xms DEBUG basic_non_verbose connected +1:main│ │ ├─ Xms DEBUG basic_non_verbose message received, length=2 +1:main│ ├─┘ +1:main│ ├─┐basic_non_verbose::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├─ Xms DEBUG basic_non_verbose connected +1:main│ ├─┘ +1:main│ ├─┐basic_non_verbose::foomp 42 <- format string, normal_var=43 +1:main│ │ ├─ Xms ERROR basic_non_verbose hello +1:main│ ├─┘ +1:main│ ├─┐basic_non_verbose::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├─ Xms WARN basic_non_verbose weak encryption requested, algo="xor" +1:main│ │ ├─ Xms DEBUG basic_non_verbose response sent, length=8 +1:main│ │ ├─ Xms DEBUG basic_non_verbose disconnected +1:main│ ├─┘ +1:main│ ├─┐basic_non_verbose::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├─ Xms DEBUG basic_non_verbose message received, length=5 +1:main│ │ ├─ Xms DEBUG basic_non_verbose response sent, length=8 +1:main│ │ ├─ Xms DEBUG basic_non_verbose disconnected +1:main│ ├─┘ +1:main│ ├─ Xs WARN basic_non_verbose internal error +1:main│ ├─ Xs ERROR basic_non_verbose this is a log message +1:main│ ├─ Xs INFO basic_non_verbose exit +1:main├─┘ +1:main┘ diff --git a/examples/basic_verbose_entry.rs b/examples/basic_verbose_entry.rs new file mode 100644 index 0000000..73c7a90 --- /dev/null +++ b/examples/basic_verbose_entry.rs @@ -0,0 +1,83 @@ +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_writer(std::io::stdout) + .with_indent_lines(true) + .with_indent_amount(2) + .with_thread_names(true) + .with_thread_ids(true) + .with_verbose_exit(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 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(3000)); + 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"); + log::error!("this is a log message"); + 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/basic_verbose_entry.stdout b/examples/basic_verbose_entry.stdout new file mode 100644 index 0000000..d564a50 --- /dev/null +++ b/examples/basic_verbose_entry.stdout @@ -0,0 +1,35 @@ +1:main┐basic_verbose_entry::hierarchical-example version=0.1 +1:main├┐basic_verbose_entry::hierarchical-example version=0.1 +1:main│└┐basic_verbose_entry::server host="localhost", port=8080 +1:main│ ├─ Xms INFO basic_verbose_entry starting +1:main│ ├─ Xs INFO basic_verbose_entry listening +1:main│ ├┐basic_verbose_entry::server host="localhost", port=8080 +1:main│ │└┐basic_verbose_entry::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├─ Xms DEBUG basic_verbose_entry connected +1:main│ │ ├─ Xms DEBUG basic_verbose_entry message received, length=2 +1:main│ ├─┘ +1:main│ ├┐basic_verbose_entry::server host="localhost", port=8080 +1:main│ │└┐basic_verbose_entry::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├─ Xms DEBUG basic_verbose_entry connected +1:main│ ├─┘ +1:main│ ├┐basic_verbose_entry::server host="localhost", port=8080 +1:main│ │└┐basic_verbose_entry::foomp 42 <- format string, normal_var=43 +1:main│ │ ├─ Xms ERROR basic_verbose_entry hello +1:main│ ├─┘ +1:main│ ├┐basic_verbose_entry::server host="localhost", port=8080 +1:main│ │└┐basic_verbose_entry::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├─ Xms WARN basic_verbose_entry weak encryption requested, algo="xor" +1:main│ │ ├─ Xms DEBUG basic_verbose_entry response sent, length=8 +1:main│ │ ├─ Xms DEBUG basic_verbose_entry disconnected +1:main│ ├─┘ +1:main│ ├┐basic_verbose_entry::server host="localhost", port=8080 +1:main│ │└┐basic_verbose_entry::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├─ Xms DEBUG basic_verbose_entry message received, length=5 +1:main│ │ ├─ Xms DEBUG basic_verbose_entry response sent, length=8 +1:main│ │ ├─ Xms DEBUG basic_verbose_entry disconnected +1:main│ ├─┘ +1:main│ ├─ Xs WARN basic_verbose_entry internal error +1:main│ ├─ Xs ERROR basic_verbose_entry this is a log message +1:main│ ├─ Xs INFO basic_verbose_entry exit +1:main├─┘ +1:main┘ diff --git a/examples/basic_verbose_exit.rs b/examples/basic_verbose_exit.rs new file mode 100644 index 0000000..3efa21d --- /dev/null +++ b/examples/basic_verbose_exit.rs @@ -0,0 +1,83 @@ +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_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(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 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(3000)); + 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"); + log::error!("this is a log message"); + 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/basic_verbose_exit.stdout b/examples/basic_verbose_exit.stdout new file mode 100644 index 0000000..08898a2 --- /dev/null +++ b/examples/basic_verbose_exit.stdout @@ -0,0 +1,35 @@ +1:main┐basic_verbose_exit::hierarchical-example version=0.1 +1:main├─┐basic_verbose_exit::server host="localhost", port=8080 +1:main│ ├─ Xms INFO basic_verbose_exit starting +1:main│ ├─ Xs INFO basic_verbose_exit listening +1:main│ ├─┐basic_verbose_exit::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├─ Xms DEBUG basic_verbose_exit connected +1:main│ │ ├─ Xms DEBUG basic_verbose_exit message received, length=2 +1:main│ │┌┘basic_verbose_exit::conn peer_addr="82.9.9.9", port=42381 +1:main│ ├┘basic_verbose_exit::server host="localhost", port=8080 +1:main│ ├─┐basic_verbose_exit::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├─ Xms DEBUG basic_verbose_exit connected +1:main│ │┌┘basic_verbose_exit::conn peer_addr="8.8.8.8", port=18230 +1:main│ ├┘basic_verbose_exit::server host="localhost", port=8080 +1:main│ ├─┐basic_verbose_exit::foomp 42 <- format string, normal_var=43 +1:main│ │ ├─ Xms ERROR basic_verbose_exit hello +1:main│ │┌┘basic_verbose_exit::foomp 42 <- format string, normal_var=43 +1:main│ ├┘basic_verbose_exit::server host="localhost", port=8080 +1:main│ ├─┐basic_verbose_exit::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├─ Xms WARN basic_verbose_exit weak encryption requested, algo="xor" +1:main│ │ ├─ Xms DEBUG basic_verbose_exit response sent, length=8 +1:main│ │ ├─ Xms DEBUG basic_verbose_exit disconnected +1:main│ │┌┘basic_verbose_exit::conn peer_addr="82.9.9.9", port=42381 +1:main│ ├┘basic_verbose_exit::server host="localhost", port=8080 +1:main│ ├─┐basic_verbose_exit::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├─ Xms DEBUG basic_verbose_exit message received, length=5 +1:main│ │ ├─ Xms DEBUG basic_verbose_exit response sent, length=8 +1:main│ │ ├─ Xms DEBUG basic_verbose_exit disconnected +1:main│ │┌┘basic_verbose_exit::conn peer_addr="8.8.8.8", port=18230 +1:main│ ├┘basic_verbose_exit::server host="localhost", port=8080 +1:main│ ├─ Xs WARN basic_verbose_exit internal error +1:main│ ├─ Xs ERROR basic_verbose_exit this is a log message +1:main│ ├─ Xs INFO basic_verbose_exit exit +1:main│┌┘basic_verbose_exit::server host="localhost", port=8080 +1:main├┘basic_verbose_exit::hierarchical-example version=0.1 +1:main┘basic_verbose_exit::hierarchical-example version=0.1 diff --git a/examples/concurrent.rs b/examples/concurrent.rs new file mode 100644 index 0000000..044f7fc --- /dev/null +++ b/examples/concurrent.rs @@ -0,0 +1,108 @@ +use std::{ + future::Future, + pin::Pin, + task::{Context, Poll}, +}; + +use futures::FutureExt; +use tracing::{debug, debug_span, info, 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(4) + .with_thread_names(true) + .with_thread_ids(true) + .with_span_retrace(true) + .with_deferred_spans(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); + + span!(Level::INFO, "empty-span").in_scope(|| { + // empty span + }); + + 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); + let _ = countdown_a.poll_unpin(&mut cx); + + peer1.in_scope(|| { + warn!("peer1 warning"); + }); + + tracing::info!("finished polling countdowns"); + }); + + drop(peer1); + + tracing::info!("all done!"); + + 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 { + 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 + } + } +} diff --git a/examples/concurrent.stdout b/examples/concurrent.stdout new file mode 100644 index 0000000..7ad1533 --- /dev/null +++ b/examples/concurrent.stdout @@ -0,0 +1,25 @@ +1:main┐concurrent::hierarchical-example version=0.1 +1:main├───┐concurrent::server host="localhost", port=8080 +1:main│ ├─── Xms INFO concurrent starting +1:main│ ├─── Xs INFO concurrent listening +1:main│ ├─── Xs DEBUG concurrent starting countdowns +1:main│ ├───┐concurrent::countdowns +1:main│ │ ├───┐concurrent::countdown_a +1:main│ │ │ ├─── Xms DEBUG concurrent polling countdown, label="a", count=3 +1:main│ │ ├───┐concurrent::countdown_b +1:main│ │ │ ├─── Xms DEBUG concurrent polling countdown, label="b", count=5 +1:main│ │ │ ├─── Xms DEBUG concurrent polling countdown, label="b", count=4 +1:main│ │ ├───┐concurrent::countdown_a +1:main│ │ │ ├─── Xms DEBUG concurrent polling countdown, label="a", count=2 +1:main│ ├───┐concurrent::conn peer_addr="82.9.9.9", port=42381 +1:main│ │ ├─── Xms WARN concurrent peer1 warning +1:main│ ├───┐concurrent::countdowns +1:main│ │ ├─── Xms INFO concurrent finished polling countdowns +1:main│ │ ├───┘ +1:main│ │ ├───┘ +1:main│ ├───┘ +1:main│ ├───┘ +1:main│ ├─── Xs INFO concurrent all done! +1:main│ ├─── Xs INFO concurrent exit +1:main├───┘ +1:main┘ diff --git a/examples/concurrent_verbose.rs b/examples/concurrent_verbose.rs new file mode 100644 index 0000000..5e3be02 --- /dev/null +++ b/examples/concurrent_verbose.rs @@ -0,0 +1,110 @@ +use std::{ + future::Future, + pin::Pin, + task::{Context, Poll}, +}; + +use futures::FutureExt; +use tracing::{debug, debug_span, info, 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(4) + .with_thread_names(true) + .with_thread_ids(true) + .with_verbose_exit(true) + .with_verbose_entry(true) + .with_span_retrace(true) + .with_deferred_spans(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); + + span!(Level::INFO, "empty-span").in_scope(|| { + // empty span + }); + + 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); + let _ = countdown_a.poll_unpin(&mut cx); + + peer1.in_scope(|| { + warn!("peer1 warning"); + }); + + tracing::info!("finished polling countdowns"); + }); + + drop(peer1); + + tracing::info!("all done!"); + + 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 { + 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 + } + } +} diff --git a/examples/concurrent_verbose.stdout b/examples/concurrent_verbose.stdout new file mode 100644 index 0000000..73d1e57 --- /dev/null +++ b/examples/concurrent_verbose.stdout @@ -0,0 +1,35 @@ +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::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│ │ │ ├─── 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│ │ ├─── Xms WARN concurrent_verbose peer1 warning +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 +1:main│ │ │ ┌─┘concurrent_verbose::countdown_a +1:main│ │ ├─┘concurrent_verbose::countdowns +1:main│ │ ┌─┘concurrent_verbose::countdowns +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::server host="localhost", port=8080 +1:main│ ├─── Xs INFO concurrent_verbose all done! +1:main│ ├─── Xs INFO concurrent_verbose exit +1:main│ ┌─┘concurrent_verbose::server host="localhost", port=8080 +1:main├─┘concurrent_verbose::hierarchical-example version=0.1 +1:main┘concurrent_verbose::hierarchical-example version=0.1 diff --git a/examples/deferred.rs b/examples/deferred.rs new file mode 100644 index 0000000..81a4232 --- /dev/null +++ b/examples/deferred.rs @@ -0,0 +1,111 @@ +use tracing::{ + debug, error, info, instrument, level_filters::LevelFilter, span, trace, warn, Level, +}; +use tracing_subscriber::{layer::SubscriberExt, registry::Registry, Layer}; +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_deferred_spans(true) + .with_targets(true) + .with_span_modes(true) + .with_filter(LevelFilter::DEBUG); + + 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::DEBUG, "hierarchical-example", version = %0.1); + let _e = app_span.enter(); + + let server_span = span!(Level::DEBUG, "server", host = "localhost", port = 8080); + + println!("-> This prints before the span open message"); + + let _e2 = server_span.enter(); + info!("starting"); + std::thread::sleep(std::time::Duration::from_millis(1000)); + + span!(Level::INFO, "empty-span").in_scope(|| { + // empty span + }); + + info!("listening"); + // Defer two levels of spans + println!("-> Deferring two levels of spans"); + span!(Level::INFO, "connections").in_scope(|| { + let peer1 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 42381); + peer1.in_scope(|| { + debug!(peer = "peer1", "connected"); + std::thread::sleep(std::time::Duration::from_millis(300)); + debug!(length = 2, "message received"); + }); + + drop(peer1); + let peer2 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 61548); + + // This span will not be printed at all since no event in it will pass the filter + peer2.in_scope(|| { + trace!(peer = "peer2", "connected"); + std::thread::sleep(std::time::Duration::from_millis(300)); + trace!(length = 2, "message received"); + }); + drop(peer2); + let peer3 = span!(Level::DEBUG, "conn", peer_addr = "8.8.8.8", port = 18230); + peer3.in_scope(|| { + std::thread::sleep(std::time::Duration::from_millis(300)); + debug!(peer = "peer3", "connected"); + }); + drop(peer3); + let peer4 = span!( + Level::DEBUG, + "foomp", + normal_var = 43, + "{} <- format string", + 42 + ); + peer4.in_scope(|| { + error!("hello"); + }); + drop(peer4); + let peer1 = span!(Level::DEBUG, "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::DEBUG, "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"); +} + +#[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/deferred.stdout b/examples/deferred.stdout new file mode 100644 index 0000000..dac8e24 --- /dev/null +++ b/examples/deferred.stdout @@ -0,0 +1,45 @@ +-> 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│ ├─ 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│ │ │ ├─ 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│ │ │ ├─ 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│ │ │ ├─ 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│ │ │ ├─ 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│ │ │ ├─ Xms DEBUG deferred message received, length=5 +1:main│ │ │ ├─ Xms DEBUG deferred response sent, length=8 +1:main│ │ │ ├─ Xms DEBUG deferred disconnected +1:main│ │ │┌┘close(v): deferred::conn peer_addr="8.8.8.8", port=18230 +1:main│ │ ├┘post_close: deferred::connections +1:main│ │┌┘close(v): deferred::connections +1:main│ ├┘post_close: deferred::server host="localhost", port=8080 +1:main│ ├─ Xs WARN deferred internal error +1:main│ ├─ Xs ERROR deferred this is a log message +1:main│ ├─ Xs INFO deferred exit +1:main│┌┘close(v): deferred::server host="localhost", port=8080 +1:main├┘post_close: deferred::hierarchical-example version=0.1 +1:main┘close(v): deferred::hierarchical-example version=0.1 diff --git a/src/format.rs b/src/format.rs index aa56178..57d5fc2 100644 --- a/src/format.rs +++ b/src/format.rs @@ -5,7 +5,7 @@ use std::{ }; use tracing_core::{ field::{Field, Visit}, - Level, + span, Level, }; pub(crate) const LINE_VERT: &str = "│"; @@ -14,11 +14,20 @@ 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 { + /// Executed on the parent before entering a child span 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,8 +52,14 @@ 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 span_retrace: bool, /// Whether to print squiggly brackets (`{}`) around the list of fields in a span. pub bracketed_fields: bool, + /// Defer printing a span until an event is generated inside of it + pub deferred_spans: bool, + /// Print a label of the span mode (open/close etc). + pub span_modes: bool, } impl Config { @@ -95,6 +110,27 @@ impl Config { } } + pub fn with_span_retrace(self, enabled: bool) -> Self { + Self { + span_retrace: enabled, + ..self + } + } + + pub fn with_deferred_spans(self, enable: bool) -> Self { + Self { + deferred_spans: enable, + ..self + } + } + + pub fn with_span_modes(self, enable: bool) -> Self { + Self { + span_modes: enable, + ..self + } + } + pub fn with_bracketed_fields(self, bracketed_fields: bool) -> Self { Self { bracketed_fields, @@ -137,7 +173,10 @@ impl Default for Config { wraparound: usize::max_value(), verbose_entry: false, verbose_exit: false, + span_retrace: false, bracketed_fields: false, + deferred_spans: false, + span_modes: false, } } } @@ -146,6 +185,13 @@ impl Default for Config { pub struct Buffers { pub current_buf: String, pub indent_buf: String, + + /// The last seen span of this layer + /// + /// This serves to serialize spans as two events can be generated in different spans + /// without the spans entering and exiting beforehand. This happens for multithreaded code + /// and instrumented futures + pub current_span: Option, } impl Buffers { @@ -153,6 +199,7 @@ impl Buffers { Self { current_buf: String::new(), indent_buf: String::new(), + current_span: None, } } @@ -197,13 +244,14 @@ impl Buffers { &prefix, style, ); + self.current_buf.clear(); self.flush_indent_buf(); // Render something when wraparound occurs so the user is aware of it if config.indent_lines { match style { - SpanMode::PreOpen | SpanMode::Open { .. } => { + SpanMode::PreOpen { .. } | SpanMode::Open { .. } => { if indent > 0 && (indent + 1) % config.wraparound == 0 { self.current_buf.push_str(&prefix); for _ in 0..(indent % config.wraparound * config.indent_amount) { @@ -259,15 +307,33 @@ impl<'a> fmt::Display for ColorLevel<'a> { } } +pub(crate) fn write_span_mode(buf: &mut String, style: SpanMode) { + match style { + SpanMode::Open { verbose: true } => buf.push_str("open(v)"), + SpanMode::Open { verbose: false } => buf.push_str("open"), + SpanMode::Retrace { verbose: false } => buf.push_str("retrace"), + SpanMode::Retrace { verbose: true } => buf.push_str("retrace(v)"), + SpanMode::Close { verbose: true } => buf.push_str("close(v)"), + SpanMode::Close { verbose: false } => buf.push_str("close"), + SpanMode::PreOpen => buf.push_str("pre_open"), + SpanMode::PostClose => buf.push_str("post_close"), + SpanMode::Event => buf.push_str("event"), + } + + buf.push_str(": ") +} + fn indent_block_with_lines( lines: &[&str], buf: &mut String, indent: usize, + // width of one level of indent indent_amount: usize, prefix: &str, style: SpanMode, ) { let indent_spaces = indent * indent_amount; + if lines.is_empty() { return; } else if indent_spaces == 0 { @@ -277,8 +343,9 @@ fn indent_block_with_lines( if indent == 0 { match style { SpanMode::Open { .. } => buf.push_str(LINE_OPEN), + SpanMode::Retrace { .. } => buf.push_str(LINE_OPEN), SpanMode::Close { .. } => buf.push_str(LINE_CLOSE), - SpanMode::PreOpen | SpanMode::PostClose => {} + SpanMode::PreOpen { .. } | SpanMode::PostClose => {} SpanMode::Event => {} } } @@ -287,6 +354,7 @@ fn indent_block_with_lines( } return; } + let mut s = String::with_capacity(indent_spaces + prefix.len()); s.push_str(prefix); @@ -311,14 +379,14 @@ fn indent_block_with_lines( } buf.push_str(LINE_OPEN); } - SpanMode::Open { verbose: false } => { + SpanMode::Open { verbose: false } | 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 } => { + SpanMode::Open { verbose: true } | SpanMode::Retrace { verbose: true } => { buf.push_str(LINE_VERT); for _ in 1..(indent_amount / 2) { buf.push(' '); @@ -403,7 +471,7 @@ fn indent_block_with_lines( fn indent_block( block: &mut String, buf: &mut String, - indent: usize, + mut indent: usize, indent_amount: usize, indent_lines: bool, prefix: &str, @@ -412,6 +480,16 @@ fn indent_block( let lines: Vec<&str> = block.lines().collect(); let indent_spaces = indent * indent_amount; buf.reserve(block.len() + (lines.len() * indent_spaces)); + + // The PreOpen and PostClose need to match up with the indent of the entered child span one more indent + // deep + match style { + SpanMode::PreOpen | SpanMode::PostClose => { + indent += 1; + } + _ => (), + } + if indent_lines { indent_block_with_lines(&lines, buf, indent, indent_amount, prefix, style); } else { diff --git a/src/lib.rs b/src/lib.rs index d171c76..a11dd06 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -2,13 +2,15 @@ pub(crate) mod format; pub mod time; use crate::time::FormatTime; -use format::{Buffers, ColorLevel, Config, FmtEvent, SpanMode}; +use format::{write_span_mode, Buffers, ColorLevel, Config, FmtEvent, SpanMode}; use is_terminal::IsTerminal; use nu_ansi_term::{Color, Style}; use std::{ fmt::{self, Write as _}, io, + iter::Fuse, + mem, sync::Mutex, time::Instant, }; @@ -22,19 +24,22 @@ use tracing_log::NormalizeEvent; use tracing_subscriber::{ fmt::MakeWriter, layer::{Context, Layer}, - registry::{self, LookupSpan}, + registry::{LookupSpan, ScopeFromRoot, SpanRef}, }; +// Span extension data pub(crate) struct Data { start: Instant, kvs: Vec<(&'static str, String)>, + written: bool, } impl Data { - pub fn new(attrs: &Attributes<'_>) -> Self { + pub fn new(attrs: &Attributes<'_>, written: bool) -> Self { let mut span = Self { start: Instant::now(), kvs: Vec::new(), + written, }; attrs.record(&mut span); span @@ -46,6 +51,7 @@ impl Visit for Data { self.kvs.push((field.name(), format!("{:?}", value))) } } + #[derive(Debug)] pub struct HierarchicalLayer io::Stderr, FT = ()> where @@ -189,6 +195,35 @@ where } } + /// Whether to print the currently active span's message again if another span was entered in + /// the meantime + /// This helps during concurrent or multi-threaded events where threads are entered, but not + /// necessarily *exited* before other *divergent* spans are entered and generating events. + pub fn with_span_retrace(self, enabled: bool) -> Self { + Self { + config: self.config.with_span_retrace(enabled), + ..self + } + } + + /// Defers printing span opening until an event is generated within the span. + /// + /// Avoids printing empty spans with no generated events. + pub fn with_deferred_spans(self, enabled: bool) -> Self { + Self { + config: self.config.with_deferred_spans(enabled), + ..self + } + } + + /// Prefixes each branch with the event mode, such as `open`, or `close` + pub fn with_span_modes(self, enabled: bool) -> Self { + Self { + config: self.config.with_span_modes(enabled), + ..self + } + } + /// Whether to print `{}` around the fields when printing a span. /// This can help visually distinguish fields from the rest of the message. pub fn with_bracketed_fields(self, bracketed_fields: bool) -> Self { @@ -225,30 +260,101 @@ where Ok(()) } - fn write_span_info(&self, id: &Id, ctx: &Context, style: SpanMode) + /// If `span_retrace` ensures that `new_span` is properly printed before an event + fn write_retrace_span<'a, S>( + &self, + new_span: &SpanRef<'a, S>, + bufs: &mut Buffers, + ctx: &'a Context, + ) 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); + } + } + let verbose = self.config.verbose_entry && i == 0; + + self.write_span_info( + &span, + bufs, + if was_written { + SpanMode::Retrace { verbose } + } else { + SpanMode::Open { verbose } + }, + ) + } + } + } + } + + fn write_span_info(&self, span: &SpanRef, bufs: &mut Buffers, style: SpanMode) where S: Subscriber + for<'span> LookupSpan<'span>, { - let span = ctx - .span(id) - .expect("in on_enter/on_exit but span does not exist"); let ext = span.extensions(); let data = ext.get::().expect("span does not have data"); - let mut guard = self.bufs.lock().unwrap(); - let bufs = &mut *guard; let mut current_buf = &mut bufs.current_buf; - let indent = ctx - .lookup_current() - .as_ref() - .map(registry::SpanRef::scope) - .map(registry::Scope::from_root) - .into_iter() - .flatten() - .count(); - - if self.config.verbose_entry || matches!(style, SpanMode::Open { .. } | SpanMode::Event) { + if self.config.span_modes { + write_span_mode(current_buf, style) + } + + let indent = scope_path(span).skip(1).count(); + + let should_write = match style { + SpanMode::Open { .. } | SpanMode::Event => true, + // Print the parent of a new span again before entering the child + SpanMode::PreOpen { .. } if self.config.verbose_entry => true, + SpanMode::Close { verbose } => verbose, + // Generated if `span_retrace` is enabled + SpanMode::Retrace { .. } => true, + // Generated if `verbose_exit` is enabled + SpanMode::PostClose => true, + _ => false, + }; + + if should_write { if self.config.targets { let target = span.metadata().target(); write!( @@ -301,20 +407,31 @@ where { fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context) { let span = ctx.span(id).expect("in new_span but span does not exist"); + if span.extensions().get::().is_none() { - let data = Data::new(attrs); + let data = Data::new(attrs, !self.config.deferred_spans); span.extensions_mut().insert(data); } - if self.config.verbose_exit { + // Entry will be printed in on_event along with retrace + if self.config.deferred_spans { + return; + } + + 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.id(), &ctx, SpanMode::PreOpen); + self.write_span_info(&span, bufs, SpanMode::PreOpen); } } self.write_span_info( - id, - &ctx, + &span, + bufs, SpanMode::Open { verbose: self.config.verbose_entry, }, @@ -322,8 +439,17 @@ where } fn on_event(&self, event: &Event<'_>, ctx: Context) { + let span = ctx.current_span(); + let span_id = span.id(); + let span = span_id.and_then(|id| ctx.span(id)); + let mut guard = self.bufs.lock().unwrap(); let bufs = &mut *guard; + + if let Some(new_span) = &span { + self.write_retrace_span(new_span, bufs, &ctx); + } + let mut event_buf = &mut bufs.current_buf; // Time. @@ -349,20 +475,19 @@ where // check if this event occurred in the context of a span. // if it has, get the start time of this span. - let start = match ctx.current_span().id() { - Some(id) => match ctx.span(id) { + let start = match span { + Some(span) => { // if the event is in a span, get the span's starting point. - Some(ctx) => { - let ext = ctx.extensions(); - let data = ext - .get::() - .expect("Data cannot be found in extensions"); - Some(data.start) - } - None => None, - }, + let ext = span.extensions(); + let data = ext + .get::() + .expect("Data cannot be found in extensions"); + + Some(data.start) + } None => None, }; + if let Some(start) = start { let elapsed = start.elapsed(); let millis = elapsed.as_millis(); @@ -397,6 +522,7 @@ where } else { level.to_string() }; + write!(&mut event_buf, "{level}", level = level).expect("Unable to write to buffer"); if self.config.targets { @@ -419,17 +545,73 @@ where } fn on_close(&self, id: Id, ctx: Context) { + let bufs = &mut *self.bufs.lock().unwrap(); + + let span = ctx.span(&id).expect("invalid span in on_close"); + + // Span was not printed, so don't print an exit + if self.config.deferred_spans + && span.extensions().get::().map(|v| v.written) != Some(true) + { + return; + } + + // self.write_retrace_span(&span, bufs, &ctx); + self.write_span_info( - &id, - &ctx, + &span, + bufs, SpanMode::Close { verbose: self.config.verbose_exit, }, ); - if self.config.verbose_exit { - if let Some(span) = ctx.span(&id).and_then(|span| span.parent()) { - self.write_span_info(&span.id(), &ctx, SpanMode::PostClose); + if let Some(parent_span) = span.parent() { + bufs.current_span = Some(parent_span.id()); + if self.config.verbose_exit { + // Consider parent as entered + + self.write_span_info(&parent_span, bufs, SpanMode::PostClose); + } + } + } +} + +fn scope_path<'a, R: LookupSpan<'a>>(span: &SpanRef<'a, R>) -> ScopeFromRoot<'a, R> { + span.scope().from_root() +} + +/// Runs `A` and `B` side by side and only yields items present in `B` +struct DifferenceIter { + left: Fuse, + right: R, + compare: F, +} + +impl, R: Iterator, T, U: PartialEq, F: Fn(&T) -> U> + DifferenceIter +{ + fn new(left: L, right: R, compare: F) -> Self { + Self { + left: left.fuse(), + right, + compare, + } + } +} + +impl, R: Iterator, T, U: PartialEq, F: Fn(&T) -> U> Iterator + for DifferenceIter +{ + type Item = T; + + fn next(&mut self) -> Option { + loop { + let left = self.left.next(); + let right = self.right.next()?; + + if left.as_ref().map(&self.compare) != Some((self.compare)(&right)) { + return Some(right); } } } diff --git a/test_dependencies/Cargo.lock b/test_dependencies/Cargo.lock index ba9c28a..3d21eaa 100644 --- a/test_dependencies/Cargo.lock +++ b/test_dependencies/Cargo.lock @@ -2,6 +2,12 @@ # It is not intended for manual editing. version = 3 +[[package]] +name = "autocfg" +version = "1.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d468802bab17cbc0cc575e9b053f41e72aa36bfa6b7f55e3529ffa43161b97fa" + [[package]] name = "bitflags" version = "1.3.2" @@ -41,6 +47,95 @@ dependencies = [ "libc", ] +[[package]] +name = "futures" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "23342abe12aba583913b2e62f22225ff9c950774065e4bfb61a19cd9770fec40" +dependencies = [ + "futures-channel", + "futures-core", + "futures-executor", + "futures-io", + "futures-sink", + "futures-task", + "futures-util", +] + +[[package]] +name = "futures-channel" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "955518d47e09b25bbebc7a18df10b81f0c766eaf4c4f1cccef2fca5f2a4fb5f2" +dependencies = [ + "futures-core", + "futures-sink", +] + +[[package]] +name = "futures-core" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4bca583b7e26f571124fe5b7561d49cb2868d79116cfa0eefce955557c6fee8c" + +[[package]] +name = "futures-executor" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ccecee823288125bd88b4d7f565c9e58e41858e47ab72e8ea2d64e93624386e0" +dependencies = [ + "futures-core", + "futures-task", + "futures-util", +] + +[[package]] +name = "futures-io" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4fff74096e71ed47f8e023204cfd0aa1289cd54ae5430a9523be060cdb849964" + +[[package]] +name = "futures-macro" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "89ca545a94061b6365f2c7355b4b32bd20df3ff95f02da9329b34ccc3bd6ee72" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.28", +] + +[[package]] +name = "futures-sink" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f43be4fe21a13b9781a69afa4985b0f6ee0e1afab2c6f454a8cf30e2b2237b6e" + +[[package]] +name = "futures-task" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "76d3d132be6c0e6aa1534069c705a74a5997a356c0dc2f86a47765e5617c5b65" + +[[package]] +name = "futures-util" +version = "0.3.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "26b01e40b772d54cf6c6d721c1d1abd0647a0106a12ecaa1c186273392a69533" +dependencies = [ + "futures-channel", + "futures-core", + "futures-io", + "futures-macro", + "futures-sink", + "futures-task", + "memchr", + "pin-project-lite", + "pin-utils", + "slab", +] + [[package]] name = "glob" version = "0.3.1" @@ -103,6 +198,12 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "memchr" +version = "2.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2dffe52ecf27772e601905b7522cb4ef790d2cc203488bbd0e2fe85fcb74566d" + [[package]] name = "nu-ansi-term" version = "0.46.0" @@ -131,20 +232,26 @@ version = "0.2.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e0a7ae3ac2f1173085d398531c705756c94a4c56843785df85a60c1a0afac116" +[[package]] +name = "pin-utils" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b870d8c151b6f2fb93e84a13146138f05d02ed11c7e7c54f8826aaaf7c9f184" + [[package]] name = "proc-macro2" -version = "1.0.56" +version = "1.0.66" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2b63bdb0cd06f1f4dedf69b254734f9b45af66e4a031e42a7480257d9898b435" +checksum = "18fb31db3f9bddb2ea821cde30a9f70117e3f119938b5ee630b7403aa6e2ead9" dependencies = [ "unicode-ident", ] [[package]] name = "quote" -version = "1.0.26" +version = "1.0.32" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4424af4bf778aae2051a77b60283332f386554255d722233d09fbfc7e30da2fc" +checksum = "50f3b39ccfb720540debaa0164757101c08ecb8d326b15358ce76a62c7e85965" dependencies = [ "proc-macro2", ] @@ -172,6 +279,15 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "slab" +version = "0.4.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6528351c9bc8ab22353f9d776db39a20288e8d6c37ef8cfe3317cf875eecfc2d" +dependencies = [ + "autocfg", +] + [[package]] name = "syn" version = "1.0.109" @@ -183,10 +299,22 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "syn" +version = "2.0.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "04361975b3f5e348b2189d8dc55bc942f278b2d482a6a0365de5bdd62d351567" +dependencies = [ + "proc-macro2", + "quote", + "unicode-ident", +] + [[package]] name = "test_dependencies" version = "0.1.0" dependencies = [ + "futures", "glob", "log", "tracing", @@ -225,7 +353,7 @@ checksum = "4017f8f45139870ca7e672686113917c71c7a6e02d4924eda67186083c03081a" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.109", ] [[package]] diff --git a/test_dependencies/Cargo.toml b/test_dependencies/Cargo.toml index 0329a8c..17571c0 100644 --- a/test_dependencies/Cargo.toml +++ b/test_dependencies/Cargo.toml @@ -4,9 +4,14 @@ version = "0.1.0" edition = "2021" [dependencies] +futures = "0.3" tracing = "0.1" glob = "0.3" log = "0.4" -tracing-subscriber = { version = "0.3", default-features = false, features = ["registry", "fmt", "std"] } +tracing-subscriber = { version = "0.3", default-features = false, features = [ + "registry", + "fmt", + "std", +] } tracing-tree = { path = ".." } tracing-log = "0.1"