mirror of
https://github.com/tokio-rs/tracing.git
synced 2026-01-25 04:16:18 +00:00
03d6e802cb
<!-- Thank you for your Pull Request. Please provide a description above and review the requirements below. Bug fixes and new features should include tests. Contributors guide: https://github.com/tokio-rs/tokio/blob/master/CONTRIBUTING.md --> ## Motivation In asynchronous systems like Tokio, interpreting traditional log messages can often be quite challenging. Since individual tasks are multiplexed on the same thread, associated events and log lines are intermixed making it difficult to trace the logic flow. Currently, none of the available logging frameworks or libraries in Rust offer the ability to trace logical paths through a futures-based program. There also are complementary goals that can be accomplished with such a system. For example, metrics / instrumentation can be tracked by observing emitted events, or trace data can be exported to a distributed tracing or event processing system. In addition, it can often be useful to generate this diagnostic data in a structured manner that can be consumed programmatically. While prior art for structured logging in Rust exists, it is not currently standardized, and is not "Tokio-friendly". ## Solution This branch adds a new library to the tokio project, `tokio-trace`. `tokio-trace` expands upon logging-style diagnostics by allowing libraries and applications to record structured events with additional information about *temporality* and *causality* --- unlike a log message, a span in `tokio-trace` has a beginning and end time, may be entered and exited by the flow of execution, and may exist within a nested tree of similar spans. In addition, `tokio-trace` spans are *structured*, with the ability to record typed data as well as textual messages. The `tokio-trace-core` crate contains the core primitives for this system, which are expected to remain stable, while `tokio-trace` crate provides a more "batteries-included" API. In particular, it provides macros which are a superset of the `log` crate's `error!`, `warn!`, `info!`, `debug!`, and `trace!` macros, allowing users to begin the process of adopting `tokio-trace` by performing a drop-in replacement. ## Notes Work on this project had previously been carried out in the [tokio-trace-prototype] repository. In addition to the `tokio-trace` and `tokio-trace-core` crates, the `tokio-trace-prototype` repo also contains prototypes or sketches of adapter, compatibility, and utility crates which provide useful functionality for `tokio-trace`, but these crates are not yet ready for a release. When this branch is merged, that repository will be archived, and the remaining unstable crates will be moved to a new `tokio-trace-nursery` repository. Remaining issues on the `tokio-trace-prototype` repo will be moved to the appropriate new repo. The crates added in this branch are not _identical_ to the current head of the `tokio-trace-prototype` repo, as I did some final clean-up and docs polish in this branch prior to merging this PR. [tokio-trace-prototype]: https://github.com/hawkw/tokio-trace-prototype Closes: #561 Signed-off-by: Eliza Weisman <eliza@buoyant.io>
479 lines
14 KiB
Rust
479 lines
14 KiB
Rust
#[macro_use]
|
|
extern crate tokio_trace;
|
|
mod support;
|
|
|
|
use self::support::*;
|
|
use std::thread;
|
|
use tokio_trace::{
|
|
dispatcher,
|
|
field::{debug, display},
|
|
subscriber::with_default,
|
|
Dispatch, Level, Span,
|
|
};
|
|
|
|
#[test]
|
|
fn closed_handle_cannot_be_entered() {
|
|
let subscriber = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("bar"))
|
|
.enter(span::mock().named("bar"))
|
|
.exit(span::mock().named("bar"))
|
|
.drop_span(span::mock().named("bar"))
|
|
.exit(span::mock().named("foo"))
|
|
.run();
|
|
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
span!("foo").enter(|| {
|
|
let bar = span!("bar");
|
|
let mut another_bar = bar.clone();
|
|
drop(bar);
|
|
|
|
another_bar.enter(|| {});
|
|
|
|
another_bar.close();
|
|
// After we close `another_bar`, it should close and not be
|
|
// re-entered.
|
|
another_bar.enter(|| {});
|
|
});
|
|
});
|
|
}
|
|
|
|
#[test]
|
|
fn handles_to_the_same_span_are_equal() {
|
|
// Create a mock subscriber that will return `true` on calls to
|
|
// `Subscriber::enabled`, so that the spans will be constructed. We
|
|
// won't enter any spans in this test, so the subscriber won't actually
|
|
// expect to see any spans.
|
|
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
|
|
let foo1 = span!("foo");
|
|
let foo2 = foo1.clone();
|
|
// Two handles that point to the same span are equal.
|
|
assert_eq!(foo1, foo2);
|
|
});
|
|
}
|
|
|
|
#[test]
|
|
fn handles_to_different_spans_are_not_equal() {
|
|
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
|
|
// Even though these spans have the same name and fields, they will have
|
|
// differing metadata, since they were created on different lines.
|
|
let foo1 = span!("foo", bar = 1u64, baz = false);
|
|
let foo2 = span!("foo", bar = 1u64, baz = false);
|
|
|
|
assert_ne!(foo1, foo2);
|
|
});
|
|
}
|
|
|
|
#[test]
|
|
fn handles_to_different_spans_with_the_same_metadata_are_not_equal() {
|
|
// Every time time this function is called, it will return a _new
|
|
// instance_ of a span with the same metadata, name, and fields.
|
|
fn make_span() -> Span<'static> {
|
|
span!("foo", bar = 1u64, baz = false)
|
|
}
|
|
|
|
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
|
|
let foo1 = make_span();
|
|
let foo2 = make_span();
|
|
|
|
assert_ne!(foo1, foo2);
|
|
// assert_ne!(foo1.data(), foo2.data());
|
|
});
|
|
}
|
|
|
|
#[test]
|
|
fn spans_always_go_to_the_subscriber_that_tagged_them() {
|
|
let subscriber1 = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done();
|
|
let subscriber1 = Dispatch::new(subscriber1.run());
|
|
let subscriber2 = Dispatch::new(subscriber::mock().run());
|
|
|
|
let mut foo = dispatcher::with_default(subscriber1, || {
|
|
let mut foo = span!("foo");
|
|
foo.enter(|| {});
|
|
foo
|
|
});
|
|
// Even though we enter subscriber 2's context, the subscriber that
|
|
// tagged the span should see the enter/exit.
|
|
dispatcher::with_default(subscriber2, move || foo.enter(|| {}));
|
|
}
|
|
|
|
#[test]
|
|
fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() {
|
|
let subscriber1 = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done();
|
|
let subscriber1 = Dispatch::new(subscriber1.run());
|
|
let mut foo = dispatcher::with_default(subscriber1, || {
|
|
let mut foo = span!("foo");
|
|
foo.enter(|| {});
|
|
foo
|
|
});
|
|
|
|
// Even though we enter subscriber 2's context, the subscriber that
|
|
// tagged the span should see the enter/exit.
|
|
thread::spawn(move || {
|
|
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
|
|
foo.enter(|| {});
|
|
})
|
|
})
|
|
.join()
|
|
.unwrap();
|
|
}
|
|
|
|
#[test]
|
|
fn dropping_a_span_calls_drop_span() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let mut span = span!("foo");
|
|
span.enter(|| {});
|
|
drop(span);
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn span_closes_after_event() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.event(event::mock())
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
span!("foo").enter(|| {
|
|
event!(Level::DEBUG, {}, "my event!");
|
|
});
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn new_span_after_event() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.event(event::mock())
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.enter(span::mock().named("bar"))
|
|
.exit(span::mock().named("bar"))
|
|
.drop_span(span::mock().named("bar"))
|
|
.done()
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
span!("foo").enter(|| {
|
|
event!(Level::DEBUG, {}, "my event!");
|
|
});
|
|
span!("bar").enter(|| {});
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn event_outside_of_span() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.event(event::mock())
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
debug!("my event!");
|
|
span!("foo").enter(|| {});
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn cloning_a_span_calls_clone_span() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.clone_span(span::mock().named("foo"))
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let span = span!("foo");
|
|
let _span2 = span.clone();
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn drop_span_when_exiting_dispatchers_context() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.clone_span(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let span = span!("foo");
|
|
let _span2 = span.clone();
|
|
drop(span);
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn clone_and_drop_span_always_go_to_the_subscriber_that_tagged_the_span() {
|
|
let (subscriber1, handle1) = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.clone_span(span::mock().named("foo"))
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.run_with_handle();
|
|
let subscriber1 = Dispatch::new(subscriber1);
|
|
let subscriber2 = Dispatch::new(subscriber::mock().done().run());
|
|
|
|
let mut foo = dispatcher::with_default(subscriber1, || {
|
|
let mut foo = span!("foo");
|
|
foo.enter(|| {});
|
|
foo
|
|
});
|
|
// Even though we enter subscriber 2's context, the subscriber that
|
|
// tagged the span should see the enter/exit.
|
|
dispatcher::with_default(subscriber2, move || {
|
|
let foo2 = foo.clone();
|
|
foo.enter(|| {});
|
|
drop(foo);
|
|
drop(foo2);
|
|
});
|
|
|
|
handle1.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn span_closes_when_exited() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let mut foo = span!("foo");
|
|
assert!(!foo.is_closed());
|
|
|
|
foo.enter(|| {});
|
|
assert!(!foo.is_closed());
|
|
|
|
foo.close();
|
|
assert!(foo.is_closed());
|
|
|
|
// Now that `foo` has closed, entering it should do nothing.
|
|
foo.enter(|| {});
|
|
assert!(foo.is_closed());
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn entering_a_closed_span_again_is_a_no_op() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let mut foo = span!("foo");
|
|
|
|
foo.close();
|
|
foo.enter(|| {
|
|
// This should do nothing.
|
|
});
|
|
assert!(foo.is_closed());
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn moved_field() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.new_span(
|
|
span::mock().named("foo").with_field(
|
|
field::mock("bar")
|
|
.with_value(&display("hello from my span"))
|
|
.only(),
|
|
),
|
|
)
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let from = "my span";
|
|
let mut span = span!("foo", bar = display(format!("hello from {}", from)));
|
|
span.enter(|| {});
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn borrowed_field() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.new_span(
|
|
span::mock().named("foo").with_field(
|
|
field::mock("bar")
|
|
.with_value(&display("hello from my span"))
|
|
.only(),
|
|
),
|
|
)
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let from = "my span";
|
|
let mut message = format!("hello from {}", from);
|
|
let mut span = span!("foo", bar = display(&message));
|
|
span.enter(|| {
|
|
message.insert_str(10, " inside");
|
|
});
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn move_field_out_of_struct() {
|
|
#[derive(Debug)]
|
|
struct Position {
|
|
x: f32,
|
|
y: f32,
|
|
}
|
|
|
|
let pos = Position {
|
|
x: 3.234,
|
|
y: -1.223,
|
|
};
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.new_span(
|
|
span::mock().named("foo").with_field(
|
|
field::mock("x")
|
|
.with_value(&debug(3.234))
|
|
.and(field::mock("y").with_value(&debug(-1.223)))
|
|
.only(),
|
|
),
|
|
)
|
|
.new_span(
|
|
span::mock()
|
|
.named("bar")
|
|
.with_field(field::mock("position").with_value(&debug(&pos)).only()),
|
|
)
|
|
.run_with_handle();
|
|
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let pos = Position {
|
|
x: 3.234,
|
|
y: -1.223,
|
|
};
|
|
let mut foo = span!("foo", x = debug(pos.x), y = debug(pos.y));
|
|
let mut bar = span!("bar", position = debug(pos));
|
|
foo.enter(|| {});
|
|
bar.enter(|| {});
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn add_field_after_new_span() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.new_span(
|
|
span::mock()
|
|
.named("foo")
|
|
.with_field(field::mock("bar").with_value(&5).only()),
|
|
)
|
|
.record(
|
|
span::mock().named("foo"),
|
|
field::mock("baz").with_value(&true).only(),
|
|
)
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let mut span = span!("foo", bar = 5, baz);
|
|
span.record("baz", &true);
|
|
span.enter(|| {})
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn add_fields_only_after_new_span() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.new_span(span::mock().named("foo"))
|
|
.record(
|
|
span::mock().named("foo"),
|
|
field::mock("bar").with_value(&5).only(),
|
|
)
|
|
.record(
|
|
span::mock().named("foo"),
|
|
field::mock("baz").with_value(&true).only(),
|
|
)
|
|
.enter(span::mock().named("foo"))
|
|
.exit(span::mock().named("foo"))
|
|
.drop_span(span::mock().named("foo"))
|
|
.done()
|
|
.run_with_handle();
|
|
|
|
dispatcher::with_default(Dispatch::new(subscriber), || {
|
|
let mut span = span!("foo", bar, baz);
|
|
span.record("bar", &5);
|
|
span.record("baz", &true);
|
|
span.enter(|| {})
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|
|
|
|
#[test]
|
|
fn new_span_with_target_and_log_level() {
|
|
let (subscriber, handle) = subscriber::mock()
|
|
.new_span(
|
|
span::mock()
|
|
.named("foo")
|
|
.with_target("app_span")
|
|
.at_level(tokio_trace::Level::DEBUG),
|
|
)
|
|
.done()
|
|
.run_with_handle();
|
|
|
|
with_default(subscriber, || {
|
|
span!(target: "app_span", level: tokio_trace::Level::DEBUG, "foo");
|
|
});
|
|
|
|
handle.assert_finished();
|
|
}
|