Skip to content

Commit 2065d20

Browse files
ten3robertsten3roberts
committed
fix: ensure open and close lines are connected
1 parent f523ad5 commit 2065d20

File tree

7 files changed

+316
-96
lines changed

7 files changed

+316
-96
lines changed

‎examples/basic.rs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@ fn main() {
66
let layer = HierarchicalLayer::default()
77
.with_writer(std::io::stdout)
88
.with_indent_lines(true)
9-
.with_indent_amount(2)
9+
.with_indent_amount(4)
1010
.with_thread_names(true)
1111
.with_thread_ids(true)
1212
.with_verbose_exit(true)

‎examples/concurrent.rs

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -5,22 +5,19 @@ use std::{
55
};
66

77
use futures::FutureExt;
8-
use tracing::{debug, debug_span, error, info, instrument, span, warn, Instrument, Level};
8+
use tracing::{debug, debug_span, info, span, warn, Instrument, Level};
99
use tracing_subscriber::{layer::SubscriberExt, registry::Registry};
1010
use tracing_tree::HierarchicalLayer;
1111

1212
fn main() {
1313
let layer = HierarchicalLayer::default()
1414
.with_writer(std::io::stdout)
1515
.with_indent_lines(true)
16-
.with_indent_amount(2)
16+
.with_indent_amount(4)
1717
.with_thread_names(true)
1818
.with_thread_ids(true)
19-
.with_verbose_exit(true)
20-
.with_verbose_entry(true)
21-
.with_span_retrace(false)
19+
.with_span_retrace(true)
2220
.with_deferred_spans(true)
23-
.with_span_modes(true)
2421
.with_targets(true);
2522

2623
let subscriber = Registry::default().with(layer);
@@ -73,6 +70,7 @@ fn main() {
7370
std::thread::sleep(std::time::Duration::from_millis(300));
7471

7572
let _ = countdown_b.poll_unpin(&mut cx);
73+
let _ = countdown_a.poll_unpin(&mut cx);
7674

7775
peer1.in_scope(|| {
7876
warn!("peer1 warning");

‎examples/concurrent_verbose.rs

Lines changed: 110 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,110 @@
1+
use std::{
2+
future::Future,
3+
pin::Pin,
4+
task::{Context, Poll},
5+
};
6+
7+
use futures::FutureExt;
8+
use tracing::{debug, debug_span, info, span, warn, Instrument, Level};
9+
use tracing_subscriber::{layer::SubscriberExt, registry::Registry};
10+
use tracing_tree::HierarchicalLayer;
11+
12+
fn main() {
13+
let layer = HierarchicalLayer::default()
14+
.with_writer(std::io::stdout)
15+
.with_indent_lines(true)
16+
.with_indent_amount(4)
17+
.with_thread_names(true)
18+
.with_thread_ids(true)
19+
.with_verbose_exit(true)
20+
.with_verbose_entry(true)
21+
.with_span_retrace(true)
22+
.with_deferred_spans(true)
23+
.with_targets(true);
24+
25+
let subscriber = Registry::default().with(layer);
26+
tracing::subscriber::set_global_default(subscriber).unwrap();
27+
#[cfg(feature = "tracing-log")]
28+
tracing_log::LogTracer::init().unwrap();
29+
30+
let app_span = span!(Level::TRACE, "hierarchical-example", version = %0.1);
31+
32+
let _e = app_span.enter();
33+
34+
let server_span = span!(Level::TRACE, "server", host = "localhost", port = 8080);
35+
36+
let _e2 = server_span.enter();
37+
info!("starting");
38+
39+
std::thread::sleep(std::time::Duration::from_millis(1000));
40+
41+
info!("listening");
42+
43+
let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
44+
45+
span!(Level::INFO, "empty-span").in_scope(|| {
46+
// empty span
47+
});
48+
49+
debug!("starting countdowns");
50+
debug_span!("countdowns").in_scope(|| {
51+
let mut countdown_a = CountdownFuture {
52+
label: "a",
53+
count: 3,
54+
}
55+
.instrument(span!(Level::DEBUG, "countdown_a"))
56+
.fuse();
57+
58+
let mut countdown_b = CountdownFuture {
59+
label: "b",
60+
count: 5,
61+
}
62+
.instrument(span!(Level::DEBUG, "countdown_b"))
63+
.fuse();
64+
65+
// We don't care if the futures are ready, as we poll manually
66+
let waker = futures::task::noop_waker();
67+
let mut cx = Context::from_waker(&waker);
68+
69+
let _ = countdown_a.poll_unpin(&mut cx);
70+
let _ = countdown_b.poll_unpin(&mut cx);
71+
72+
std::thread::sleep(std::time::Duration::from_millis(300));
73+
74+
let _ = countdown_b.poll_unpin(&mut cx);
75+
let _ = countdown_a.poll_unpin(&mut cx);
76+
77+
peer1.in_scope(|| {
78+
warn!("peer1 warning");
79+
});
80+
81+
tracing::info!("finished polling countdowns");
82+
});
83+
84+
drop(peer1);
85+
86+
tracing::info!("all done!");
87+
88+
info!("exit")
89+
}
90+
91+
struct CountdownFuture {
92+
label: &'static str,
93+
count: u32,
94+
}
95+
96+
impl Future for CountdownFuture {
97+
type Output = ();
98+
99+
fn poll(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
100+
debug!(label=?self.label, count=?self.count, "polling countdown");
101+
self.count -= 1;
102+
103+
if self.count == 0 {
104+
Poll::Ready(())
105+
} else {
106+
cx.waker().wake_by_ref();
107+
Poll::Pending
108+
}
109+
}
110+
}

‎examples/deferred.rs

Lines changed: 57 additions & 47 deletions
Original file line numberDiff line numberDiff line change
@@ -33,57 +33,67 @@ fn main() {
3333
let _e2 = server_span.enter();
3434
info!("starting");
3535
std::thread::sleep(std::time::Duration::from_millis(1000));
36-
info!("listening");
37-
let peer1 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 42381);
38-
peer1.in_scope(|| {
39-
debug!(peer = "peer1", "connected");
40-
std::thread::sleep(std::time::Duration::from_millis(300));
41-
debug!(length = 2, "message received");
36+
37+
span!(Level::INFO, "empty-span").in_scope(|| {
38+
// empty span
4239
});
4340

44-
drop(peer1);
45-
let peer2 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 61548);
41+
info!("listening");
42+
// Defer two levels of spans
43+
println!("Deferring two levels of spans");
44+
span!(Level::INFO, "connections").in_scope(|| {
45+
let peer1 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 42381);
46+
peer1.in_scope(|| {
47+
debug!(peer = "peer1", "connected");
48+
std::thread::sleep(std::time::Duration::from_millis(300));
49+
debug!(length = 2, "message received");
50+
});
4651

47-
// This span will not be printed at all since no event in it will pass the filter
48-
peer2.in_scope(|| {
49-
trace!(peer = "peer2", "connected");
50-
std::thread::sleep(std::time::Duration::from_millis(300));
51-
trace!(length = 2, "message received");
52-
});
53-
drop(peer2);
54-
let peer3 = span!(Level::DEBUG, "conn", peer_addr = "8.8.8.8", port = 18230);
55-
peer3.in_scope(|| {
56-
std::thread::sleep(std::time::Duration::from_millis(300));
57-
debug!(peer = "peer3", "connected");
58-
});
59-
drop(peer3);
60-
let peer4 = span!(
61-
Level::DEBUG,
62-
"foomp",
63-
normal_var = 43,
64-
"{} <- format string",
65-
42
66-
);
67-
peer4.in_scope(|| {
68-
error!("hello");
69-
});
70-
drop(peer4);
71-
let peer1 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 42381);
72-
peer1.in_scope(|| {
73-
warn!(algo = "xor", "weak encryption requested");
74-
std::thread::sleep(std::time::Duration::from_millis(300));
75-
debug!(length = 8, "response sent");
76-
debug!("disconnected");
77-
});
78-
drop(peer1);
79-
let peer2 = span!(Level::DEBUG, "conn", peer_addr = "8.8.8.8", port = 18230);
80-
peer2.in_scope(|| {
81-
debug!(length = 5, "message received");
82-
std::thread::sleep(std::time::Duration::from_millis(300));
83-
debug!(length = 8, "response sent");
84-
debug!("disconnected");
52+
drop(peer1);
53+
let peer2 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 61548);
54+
55+
// This span will not be printed at all since no event in it will pass the filter
56+
peer2.in_scope(|| {
57+
trace!(peer = "peer2", "connected");
58+
std::thread::sleep(std::time::Duration::from_millis(300));
59+
trace!(length = 2, "message received");
60+
});
61+
drop(peer2);
62+
let peer3 = span!(Level::DEBUG, "conn", peer_addr = "8.8.8.8", port = 18230);
63+
peer3.in_scope(|| {
64+
std::thread::sleep(std::time::Duration::from_millis(300));
65+
debug!(peer = "peer3", "connected");
66+
});
67+
drop(peer3);
68+
let peer4 = span!(
69+
Level::DEBUG,
70+
"foomp",
71+
normal_var = 43,
72+
"{} <- format string",
73+
42
74+
);
75+
peer4.in_scope(|| {
76+
error!("hello");
77+
});
78+
drop(peer4);
79+
let peer1 = span!(Level::DEBUG, "conn", peer_addr = "82.9.9.9", port = 42381);
80+
peer1.in_scope(|| {
81+
warn!(algo = "xor", "weak encryption requested");
82+
std::thread::sleep(std::time::Duration::from_millis(300));
83+
debug!(length = 8, "response sent");
84+
debug!("disconnected");
85+
});
86+
drop(peer1);
87+
let peer2 = span!(Level::DEBUG, "conn", peer_addr = "8.8.8.8", port = 18230);
88+
peer2.in_scope(|| {
89+
debug!(length = 5, "message received");
90+
std::thread::sleep(std::time::Duration::from_millis(300));
91+
debug!(length = 8, "response sent");
92+
debug!("disconnected");
93+
});
94+
drop(peer2);
8595
});
86-
drop(peer2);
96+
8797
warn!("internal error");
8898
log::error!("this is a log message");
8999
info!("exit");

‎output.log

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,50 @@
1+
Compiling tracing-tree v0.2.3 (/Users/teiroberts/dev/tracing-tree)
2+
warning: unused imports: `error`, `instrument`
3+
--> examples/concurrent.rs:8:34
4+
|
5+
8 | use tracing::{debug, debug_span, error, info, instrument, span, warn, Instrument, Level};
6+
| ^^^^^ ^^^^^^^^^^
7+
|
8+
= note: `#[warn(unused_imports)]` on by default
9+
10+
warning: `tracing-tree` (example "concurrent") generated 1 warning (run `cargo fix --example "concurrent"` to apply 1 suggestion)
11+
Finished dev [unoptimized + debuginfo] target(s) in 0.45s
12+
Running `target/debug/examples/concurrent`
13+
1:main┐open(v): concurrent::hierarchical-example version=0.1
14+
1:main├─┐open: concurrent::server host="localhost", port=8080
15+
1:main│ ├─ 0ms INFO concurrent starting
16+
1:main│ ├─ 1s INFO concurrent listening
17+
1:main│ ├┐pre_open: concurrent::server host="localhost", port=8080
18+
1:main│ │└┐open(v): concurrent::empty-span
19+
1:main│ │┌┘close(v): concurrent::empty-span
20+
1:main│ ├┘post_close: concurrent::server host="localhost", port=8080
21+
1:main│ ├─ 1s DEBUG concurrent starting countdowns
22+
1:main│ ├┐pre_open: concurrent::server host="localhost", port=8080
23+
1:main│ │└┐open(v): concurrent::countdowns
24+
1:main│ │ ├─┐open: concurrent::countdown_a
25+
1:main│ │ │ ├─ 0ms DEBUG concurrent polling countdown, label="a", count=3
26+
1:main│ │ │ ├┐pre_open: concurrent::countdown_a
27+
1:main│ │ │└┐open(v): concurrent::countdown_b
28+
1:main│ │ │ ├─ 0ms DEBUG concurrent polling countdown, label="b", count=5
29+
1:main│ │ │ ├─304ms DEBUG concurrent polling countdown, label="b", count=4
30+
1:main│ │ │ ├┐pre_open: concurrent::countdown_b
31+
1:main│ │└┐open(v): concurrent::conn peer_addr="82.9.9.9", port=42381
32+
1:main│ │ ├─304ms WARN concurrent peer1 warning
33+
1:main│ │ ├┐pre_open: concurrent::conn peer_addr="82.9.9.9", port=42381
34+
1:main│ │└┐open(v): concurrent::countdowns
35+
1:main│ │ ├─304ms INFO concurrent finished polling countdowns
36+
1:main│ │ │┌┘close(v): concurrent::countdown_b
37+
1:main│ │ ├┘post_close: concurrent::countdowns
38+
1:main│ │ │┌┘close(v): concurrent::countdown_a
39+
1:main│ │ ├┘post_close: concurrent::countdowns
40+
1:main│ │┌┘close(v): concurrent::countdowns
41+
1:main│ ├┘post_close: concurrent::server host="localhost", port=8080
42+
1:main│ │┌┘close(v): concurrent::conn peer_addr="82.9.9.9", port=42381
43+
1:main│ ├┘post_close: concurrent::server host="localhost", port=8080
44+
1:main│ ├─ 1s INFO concurrent all done!
45+
1:main│ ├─ 1s INFO concurrent exit
46+
1:main│┌┘close(v): concurrent::server host="localhost", port=8080
47+
1:main├┘post_close: concurrent::hierarchical-example version=0.1
48+
1:main┘close(v): concurrent::hierarchical-example version=0.1
49+
50+
[Process exited 0]

0 commit comments

Comments
 (0)