From 03d6e802cbed97369e1209f0c3df8bf1e5498afc Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 19 Feb 2019 12:15:01 -0800 Subject: [PATCH] Introduce `tokio-trace` (#827) ## 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 --- Cargo.toml | 32 + LICENSE | 38 +- README.md | 220 +++-- benches/no_subscriber.rs | 44 + benches/subscriber.rs | 145 ++++ examples/counters.rs | 138 ++++ examples/sloggish/main.rs | 53 ++ examples/sloggish/sloggish_subscriber.rs | 293 +++++++ src/field.rs | 54 ++ src/lib.rs | 983 +++++++++++++++++++++++ src/span.rs | 495 ++++++++++++ src/subscriber.rs | 19 + tests/dispatcher.rs | 73 ++ tests/event.rs | 169 ++++ tests/macros.rs | 145 ++++ tests/span.rs | 478 +++++++++++ tests/subscriber.rs | 170 ++++ tests/support/event.rs | 92 +++ tests/support/field.rs | 224 ++++++ tests/support/metadata.rs | 64 ++ tests/support/mod.rs | 6 + tests/support/span.rs | 109 +++ tests/support/subscriber.rs | 337 ++++++++ tokio-trace-core/Cargo.toml | 18 + tokio-trace-core/LICENSE | 25 + tokio-trace-core/README.md | 42 + tokio-trace-core/src/callsite.rs | 121 +++ tokio-trace-core/src/dispatcher.rs | 252 ++++++ tokio-trace-core/src/event.rs | 55 ++ tokio-trace-core/src/field.rs | 740 +++++++++++++++++ tokio-trace-core/src/lib.rs | 177 ++++ tokio-trace-core/src/metadata.rs | 272 +++++++ tokio-trace-core/src/span.rs | 22 + tokio-trace-core/src/subscriber.rs | 318 ++++++++ 34 files changed, 6340 insertions(+), 83 deletions(-) create mode 100644 benches/no_subscriber.rs create mode 100644 benches/subscriber.rs create mode 100644 examples/counters.rs create mode 100644 examples/sloggish/main.rs create mode 100644 examples/sloggish/sloggish_subscriber.rs create mode 100644 src/field.rs create mode 100644 src/lib.rs create mode 100644 src/span.rs create mode 100644 src/subscriber.rs create mode 100644 tests/dispatcher.rs create mode 100644 tests/event.rs create mode 100644 tests/macros.rs create mode 100644 tests/span.rs create mode 100644 tests/subscriber.rs create mode 100644 tests/support/event.rs create mode 100644 tests/support/field.rs create mode 100644 tests/support/metadata.rs create mode 100644 tests/support/mod.rs create mode 100644 tests/support/span.rs create mode 100644 tests/support/subscriber.rs create mode 100644 tokio-trace-core/Cargo.toml create mode 100644 tokio-trace-core/LICENSE create mode 100644 tokio-trace-core/README.md create mode 100644 tokio-trace-core/src/callsite.rs create mode 100644 tokio-trace-core/src/dispatcher.rs create mode 100644 tokio-trace-core/src/event.rs create mode 100644 tokio-trace-core/src/field.rs create mode 100644 tokio-trace-core/src/lib.rs create mode 100644 tokio-trace-core/src/metadata.rs create mode 100644 tokio-trace-core/src/span.rs create mode 100644 tokio-trace-core/src/subscriber.rs diff --git a/Cargo.toml b/Cargo.toml index 05c5c484f9..7b73744b7d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,7 @@ [workspace] members = [ + ".", "tokio-trace-proc-macros", "tokio-trace-fmt", "tokio-trace-futures", @@ -13,3 +14,34 @@ members = [ "tokio-trace-subscriber", "tokio-trace-serde", ] + +[package] +name = "tokio-trace" +version = "0.0.1" +authors = ["Eliza Weisman "] +license = "MIT" +repository = "https://github.com/tokio-rs/tokio" +homepage = "https://tokio.rs" +description = """ +A scoped, structured logging and diagnostics system. +""" +categories = ["development-tools::debugging", "asynchronous"] +keywords = ["logging", "tracing"] + +# Not yet ready for production. +publish = false + +[dependencies] +tokio-trace-core = { path = "tokio-trace-core" } + +[dev-dependencies] +ansi_term = "0.11" +humantime = "1.1.1" +futures = "0.1" +log = "0.4" + +# These are used for the "basic" example from the tokio-trace-prototype repo, +# which is currently not included as it used the `tokio-trace-log` crate, and +# that crate is currently unstable. +# env_logger = "0.5" +# tokio-trace-log = { path = "../tokio-trace-log" } diff --git a/LICENSE b/LICENSE index 731f4ad709..cdb28b4b56 100644 --- a/LICENSE +++ b/LICENSE @@ -1,21 +1,25 @@ -MIT License - Copyright (c) 2019 Tokio Contributors -Permission is hereby granted, free of charge, to any person obtaining a copy -of this software and associated documentation files (the "Software"), to deal -in the Software without restriction, including without limitation the rights -to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -copies of the Software, and to permit persons to whom the Software is -furnished to do so, subject to the following conditions: +Permission is hereby granted, free of charge, to any +person obtaining a copy of this software and associated +documentation files (the "Software"), to deal in the +Software without restriction, including without +limitation the rights to use, copy, modify, merge, +publish, distribute, sublicense, and/or sell copies of +the Software, and to permit persons to whom the Software +is furnished to do so, subject to the following +conditions: -The above copyright notice and this permission notice shall be included in all -copies or substantial portions of the Software. +The above copyright notice and this permission notice +shall be included in all copies or substantial portions +of the Software. -THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE -SOFTWARE. +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF +ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED +TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A +PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT +SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY +CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION +OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR +IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER +DEALINGS IN THE SOFTWARE. diff --git a/README.md b/README.md index 278bd1b77a..a21905141e 100644 --- a/README.md +++ b/README.md @@ -1,71 +1,161 @@ -# tokio-trace-nursery +# tokio-trace -Less-stable utility crates for [`tokio-trace`]. - -[![MIT licensed][mit-badge]][mit-url] -[![Build Status][travis-badge]][travis-url] -[![Gitter chat][gitter-badge]][gitter-url] - -[mit-badge]: https://img.shields.io/badge/license-MIT-blue.svg -[mit-url]: LICENSE -[travis-badge]: https://travis-ci.org/tokio-rs/tokio-trace-nursery.svg?branch=master -[travis-url]: https://travis-ci.org/tokio-rs/tokio-trace-nursery/branches -[gitter-badge]: https://img.shields.io/gitter/room/tokio-rs/tokio.svg -[gitter-url]: https://gitter.im/tokio-rs/tokio - -[Website](https://tokio.rs) | -[Chat](https://gitter.im/tokio-rs/tokio) +A scoped, structured logging and diagnostics system. ## Overview -[`tokio-trace`] is a framework for instrumenting Rust programs to collect -structured, event-based diagnostic information. This repository contains a set -of utility and compatibility crates for use with `tokio-trace`. - -### Stability - -While `tokio-trace` and `tokio-trace-core` have been published on crates.io and -adhere to the same stability policies as the rest of the Tokio project, the -crates in the nursery are generally less stable. Many of these crates are not -yet released and are undergoing active development. Therefore, users are warned -that breaking changes may occur. - -In general, when depending on a crate from the nursery as a git dependency, -users are advised to pin to a specific git revision using the [`rev`] Cargo key. -This prevents your build from breaking should a breaking change to that crate be -merged to master. - -[`rev`]: https://doc.rust-lang.org/cargo/reference/specifying-dependencies.html#specifying-dependencies-from-git-repositories - -## Getting Help - -First, see if the answer to your question can be found in the API documentation. -If the answer is not there, there is an active community in -the [Tokio Gitter channel][chat]. We would be happy to try to answer your -question. Last, if that doesn't work, try opening an [issue] with the question. - -[chat]: https://gitter.im/tokio-rs/tokio -[issue]: https://github.com/tokio-rs/tokio-trace-nursery/issues/new - -## Contributing - -:balloon: Thanks for your help improving the project! We are so happy to have -you! We have a [contributing guide][guide] to help you get involved in the Tokio -project. - -[guide]: CONTRIBUTING.md - - -## Supported Rust Versions - -Tokio is built against the latest stable, nightly, and beta Rust releases. The -minimum version supported is the stable release from three months before the -current stable release version. For example, if the latest stable Rust is 1.29, -the minimum version supported is 1.26. The current Tokio version is not -guaranteed to build on Rust versions earlier than the minimum supported version. +`tokio-trace` is a framework for instrumenting Rust programs to collect +structured, event-based diagnostic information. + +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. `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` crate provides the APIs necessary for instrumenting libraries +and applications to emit trace data. + +## Usage + +First, add this to your `Cargo.toml`: + +```toml +[dependencies] +tokio-trace = { git = "https://github.com/tokio-rs/tokio" } +``` + +Next, add this to your crate: + +```rust +#[macro_use] +extern crate tokio_trace; +``` + +This crate provides macros for creating `Span`s and `Event`s, which represent +periods of time and momentary events within the execution of a program, +respectively. + +As a rule of thumb, _spans_ should be used to represent discrete units of work +(e.g., a given request's lifetime in a server) or periods of time spent in a +given context (e.g., time spent interacting with an instance of an external +system, such as a database). In contrast, _events_ should be used to represent +points in time within a span — a request returned with a given status code, +_n_ new items were taken from a queue, and so on. + +`Span`s are constructed using the `span!` macro, and then _entered_ +to indicate that some code takes place within the context of that `Span`: + +```rust +// Construct a new span named "my span". +let mut span = span!("my span"); +span.enter(|| { + // Any trace events in this closure or code called by it will occur within + // the span. +}); +// Dropping the span will close it, indicating that it has ended. +``` + +The `Event` type represent an event that occurs instantaneously, and is +essentially a `Span` that cannot be entered. They are created using the `event!` +macro: + +```rust +use tokio_trace::Level; +event!(Level::INFO, "something has happened!"); +``` + +Users of the [`log`] crate should note that `tokio-trace` exposes a set of macros for +creating `Event`s (`trace!`, `debug!`, `info!`, `warn!`, and `error!`) which may +be invoked with the same syntax as the similarly-named macros from the `log` +crate. Often, the process of converting a project to use `tokio-trace` can begin +with a simple drop-in replacement. + +Let's consider the `log` crate's yak-shaving example: + +```rust +#[macro_use] +extern crate tokio_trace; +use tokio_trace::field; + +pub fn shave_the_yak(yak: &mut Yak) { + // Create a new span for this invocation of `shave_the_yak`, annotated + // with the yak being shaved as a *field* on the span. + span!("shave_the_yak", yak = field::debug(&yak)).enter(|| { + // Since the span is annotated with the yak, it is part of the context + // for everything happening inside the span. Therefore, we don't need + // to add it to the message for this event, as the `log` crate does. + info!(target: "yak_events", "Commencing yak shaving"); + + loop { + match find_a_razor() { + Ok(razor) => { + // We can add the razor as a field rather than formatting it + // as part of the message, allowing subscribers to consume it + // in a more structured manner: + info!({ razor = field::display(razor) }, "Razor located"); + yak.shave(razor); + break; + } + Err(err) => { + // However, we can also create events with formatted messages, + // just as we would for log records. + warn!("Unable to locate a razor: {}, retrying", err); + } + } + } + }) +} +``` + +You can find examples showing how to use this crate in the examples directory. + +### In libraries + +Libraries should link only to the `tokio-trace` crate, and use the provided +macros to record whatever information will be useful to downstream consumers. + +### In executables + +In order to record trace events, executables have to use a `Subscriber` +implementation compatible with `tokio-trace`. A `Subscriber` implements a way of +collecting trace data, such as by logging it to standard output. + +Unlike the `log` crate, `tokio-trace` does *not* use a global `Subscriber` which +is initialized once. Instead, it follows the `tokio` pattern of executing code +in a context. For example: + +```rust +#[macro_use] +extern crate tokio_trace; + +let my_subscriber = FooSubscriber::new(); + +tokio_trace::subscriber::with_default(subscriber, || { + // Any trace events generated in this closure or by functions it calls + // will be collected by `my_subscriber`. +}) +``` + +This approach allows trace data to be collected by multiple subscribers within +different contexts in the program. Alternatively, a single subscriber may be +constructed by the `main` function and all subsequent code executed with that +subscriber as the default. Any trace events generated outside the context of a +subscriber will not be collected. + +The executable itself may use the `tokio-trace` crate to instrument itself as +well. + +The [`tokio-trace-nursery`] repository contains less stable crates designed to +be used with the `tokio-trace` ecosystem. It includes a collection of +`Subscriber` implementations, as well as utility and adapter crates. + +[`log`]: https://docs.rs/log/0.4.6/log/ ## License @@ -76,5 +166,3 @@ This project is licensed under the [MIT license](LICENSE). Unless you explicitly state otherwise, any contribution intentionally submitted for inclusion in Tokio by you, shall be licensed as MIT, without any additional terms or conditions. - -[`tokio-trace`]: https://github.com/tokio-rs/tokio/tree/master/tokio-trace diff --git a/benches/no_subscriber.rs b/benches/no_subscriber.rs new file mode 100644 index 0000000000..84a5bc428a --- /dev/null +++ b/benches/no_subscriber.rs @@ -0,0 +1,44 @@ +#![feature(test)] +#[macro_use] +extern crate tokio_trace; +#[macro_use] +extern crate log; +extern crate test; +use test::Bencher; + +#[bench] +fn bench_span_no_subscriber(b: &mut Bencher) { + b.iter(|| { + span!("span"); + }); +} + +#[bench] +fn bench_log_no_logger(b: &mut Bencher) { + b.iter(|| { + log!(log::Level::Info, "log"); + }); +} + +#[bench] +fn bench_costly_field_no_subscriber(b: &mut Bencher) { + b.iter(|| { + span!( + "span", + foo = tokio_trace::field::display(format!("bar {:?}", 2)) + ); + }); +} + +#[bench] +fn bench_no_span_no_subscriber(b: &mut Bencher) { + b.iter(|| {}); +} + +#[bench] +fn bench_1_atomic_load(b: &mut Bencher) { + // This is just included as a baseline. + use std::sync::atomic::{AtomicUsize, Ordering}; + let foo = AtomicUsize::new(1); + b.iter(|| foo.load(Ordering::Relaxed)); +} diff --git a/benches/subscriber.rs b/benches/subscriber.rs new file mode 100644 index 0000000000..fd60979b1b --- /dev/null +++ b/benches/subscriber.rs @@ -0,0 +1,145 @@ +#![feature(test)] + +#[macro_use] +extern crate tokio_trace; +extern crate test; +use test::Bencher; + +use std::{ + fmt, + sync::{Mutex, MutexGuard}, +}; +use tokio_trace::{field, span, Event, Id, Metadata}; + +/// A subscriber that is enabled but otherwise does nothing. +struct EnabledSubscriber; + +impl tokio_trace::Subscriber for EnabledSubscriber { + fn new_span(&self, span: &Metadata, values: &field::ValueSet) -> Id { + let _ = (span, values); + Id::from_u64(0) + } + + fn event(&self, event: &Event) { + let _ = event; + } + + fn record(&self, span: &Id, values: &field::ValueSet) { + let _ = (span, values); + } + + fn record_follows_from(&self, span: &Id, follows: &Id) { + let _ = (span, follows); + } + + fn enabled(&self, metadata: &Metadata) -> bool { + let _ = metadata; + true + } + + fn enter(&self, span: &Id) { + let _ = span; + } + + fn exit(&self, span: &Id) { + let _ = span; + } +} + +/// Simulates a subscriber that records span data. +struct RecordingSubscriber(Mutex); + +struct Recorder<'a>(MutexGuard<'a, String>); + +impl<'a> field::Record for Recorder<'a> { + fn record_debug(&mut self, _field: &field::Field, value: &fmt::Debug) { + use std::fmt::Write; + let _ = write!(&mut *self.0, "{:?}", value); + } +} + +impl tokio_trace::Subscriber for RecordingSubscriber { + fn new_span(&self, _span: &Metadata, values: &field::ValueSet) -> Id { + let mut recorder = Recorder(self.0.lock().unwrap()); + values.record(&mut recorder); + Id::from_u64(0) + } + + fn record(&self, _span: &Id, values: &field::ValueSet) { + let mut recorder = Recorder(self.0.lock().unwrap()); + values.record(&mut recorder); + } + + fn event(&self, event: &Event) { + let mut recorder = Recorder(self.0.lock().unwrap()); + event.record(&mut recorder); + } + + fn record_follows_from(&self, span: &Id, follows: &Id) { + let _ = (span, follows); + } + + fn enabled(&self, metadata: &Metadata) -> bool { + let _ = metadata; + true + } + + fn enter(&self, span: &Id) { + let _ = span; + } + + fn exit(&self, span: &Id) { + let _ = span; + } +} + +const N_SPANS: usize = 100; + +#[bench] +fn span_no_fields(b: &mut Bencher) { + tokio_trace::subscriber::with_default(EnabledSubscriber, || b.iter(|| span!("span"))); +} + +#[bench] +fn span_repeatedly(b: &mut Bencher) { + #[inline] + fn mk_span(i: u64) -> tokio_trace::Span<'static> { + span!("span", i = i) + } + + let n = test::black_box(N_SPANS); + tokio_trace::subscriber::with_default(EnabledSubscriber, || { + b.iter(|| (0..n).fold(mk_span(0), |_, i| mk_span(i as u64))) + }); +} + +#[bench] +fn span_with_fields(b: &mut Bencher) { + tokio_trace::subscriber::with_default(EnabledSubscriber, || { + b.iter(|| { + span!( + "span", + foo = "foo", + bar = "bar", + baz = 3, + quuux = tokio_trace::field::debug(0.99) + ) + }) + }); +} + +#[bench] +fn span_with_fields_record(b: &mut Bencher) { + let subscriber = RecordingSubscriber(Mutex::new(String::from(""))); + tokio_trace::subscriber::with_default(subscriber, || { + b.iter(|| { + span!( + "span", + foo = "foo", + bar = "bar", + baz = 3, + quuux = tokio_trace::field::debug(0.99) + ) + }) + }); +} diff --git a/examples/counters.rs b/examples/counters.rs new file mode 100644 index 0000000000..9c617c4c6d --- /dev/null +++ b/examples/counters.rs @@ -0,0 +1,138 @@ +#[macro_use] +extern crate tokio_trace; + +use tokio_trace::{ + field::{self, Field, Record}, + span, + subscriber::{self, Subscriber}, + Event, Id, Metadata, +}; + +use std::{ + collections::HashMap, + fmt, + sync::{ + atomic::{AtomicUsize, Ordering}, + Arc, RwLock, RwLockReadGuard, + }, +}; + +#[derive(Clone)] +struct Counters(Arc>>); + +struct CounterSubscriber { + ids: AtomicUsize, + counters: Counters, +} + +struct Count<'a> { + counters: RwLockReadGuard<'a, HashMap>, +} + +impl<'a> Record for Count<'a> { + fn record_i64(&mut self, field: &Field, value: i64) { + if let Some(counter) = self.counters.get(field.name()) { + if value > 0 { + counter.fetch_add(value as usize, Ordering::Release); + } else { + counter.fetch_sub((value * -1) as usize, Ordering::Release); + } + }; + } + + fn record_u64(&mut self, field: &Field, value: u64) { + if let Some(counter) = self.counters.get(field.name()) { + counter.fetch_add(value as usize, Ordering::Release); + }; + } + + fn record_bool(&mut self, _: &Field, _: bool) {} + fn record_str(&mut self, _: &Field, _: &str) {} + fn record_debug(&mut self, _: &Field, _: &fmt::Debug) {} +} + +impl CounterSubscriber { + fn recorder(&self) -> Count { + Count { + counters: self.counters.0.read().unwrap(), + } + } +} + +impl Subscriber for CounterSubscriber { + fn register_callsite(&self, meta: &Metadata) -> subscriber::Interest { + let mut interest = subscriber::Interest::never(); + for key in meta.fields() { + let name = key.name(); + if name.contains("count") { + self.counters + .0 + .write() + .unwrap() + .entry(name.to_owned()) + .or_insert_with(|| AtomicUsize::new(0)); + interest = subscriber::Interest::always(); + } + } + interest + } + + fn new_span(&self, _new_span: &Metadata, values: &field::ValueSet) -> Id { + values.record(&mut self.recorder()); + let id = self.ids.fetch_add(1, Ordering::SeqCst); + Id::from_u64(id as u64) + } + + fn record_follows_from(&self, _span: &Id, _follows: &Id) { + // unimplemented + } + + fn record(&self, _: &Id, values: &field::ValueSet) { + values.record(&mut self.recorder()) + } + + fn event(&self, event: &Event) { + event.record(&mut self.recorder()) + } + + fn enabled(&self, metadata: &Metadata) -> bool { + metadata.fields().iter().any(|f| f.name().contains("count")) + } + + fn enter(&self, _span: &Id) {} + fn exit(&self, _span: &Id) {} +} + +impl Counters { + fn print_counters(&self) { + for (k, v) in self.0.read().unwrap().iter() { + println!("{}: {}", k, v.load(Ordering::Acquire)); + } + } + + fn new() -> (Self, CounterSubscriber) { + let counters = Counters(Arc::new(RwLock::new(HashMap::new()))); + let subscriber = CounterSubscriber { + ids: AtomicUsize::new(0), + counters: counters.clone(), + }; + (counters, subscriber) + } +} + +fn main() { + let (counters, subscriber) = Counters::new(); + + tokio_trace::subscriber::with_default(subscriber, || { + let mut foo: u64 = 2; + span!("my_great_span", foo_count = &foo).enter(|| { + foo += 1; + info!({ yak_shaved = true, yak_count = 1 }, "hi from inside my span"); + span!("my other span", foo_count = &foo, baz_count = 5).enter(|| { + warn!({ yak_shaved = false, yak_count = -1 }, "failed to shave yak"); + }); + }); + }); + + counters.print_counters(); +} diff --git a/examples/sloggish/main.rs b/examples/sloggish/main.rs new file mode 100644 index 0000000000..fb26a83503 --- /dev/null +++ b/examples/sloggish/main.rs @@ -0,0 +1,53 @@ +//! A simple example demonstrating how one might implement a custom +//! subscriber. +//! +//! This subscriber implements a tree-structured logger similar to +//! the "compact" formatter in [`slog-term`]. The demo mimicks the +//! example output in the screenshot in the [`slog` README]. +//! +//! Note that this logger isn't ready for actual production use. +//! Several corners were cut to make the example simple. +//! +//! [`slog-term`]: https://docs.rs/slog-term/2.4.0/slog_term/ +//! [`slog` README]: https://github.com/slog-rs/slog#terminal-output-example +#[macro_use] +extern crate tokio_trace; + +use tokio_trace::field; + +mod sloggish_subscriber; +use self::sloggish_subscriber::SloggishSubscriber; + +fn main() { + let subscriber = SloggishSubscriber::new(2); + + tokio_trace::dispatcher::with_default(tokio_trace::Dispatch::new(subscriber), || { + span!("", version = &field::display(5.0)).enter(|| { + span!("server", host = "localhost", port = 8080).enter(|| { + info!("starting"); + info!("listening"); + let mut peer1 = span!("conn", peer_addr = "82.9.9.9", port = 42381); + peer1.enter(|| { + debug!("connected"); + debug!({ length = 2 }, "message received"); + }); + let mut peer2 = span!("conn", peer_addr = "8.8.8.8", port = 18230); + peer2.enter(|| { + debug!("connected"); + }); + peer1.enter(|| { + warn!({ algo = "xor" }, "weak encryption requested"); + debug!({ length = 8 }, "response sent"); + debug!("disconnected"); + }); + peer2.enter(|| { + debug!({ length = 5 }, "message received"); + debug!({ length = 8 }, "response sent"); + debug!("disconnected"); + }); + warn!("internal error"); + info!("exit"); + }) + }); + }); +} diff --git a/examples/sloggish/sloggish_subscriber.rs b/examples/sloggish/sloggish_subscriber.rs new file mode 100644 index 0000000000..4a93f93533 --- /dev/null +++ b/examples/sloggish/sloggish_subscriber.rs @@ -0,0 +1,293 @@ +//! A simple example demonstrating how one might implement a custom +//! subscriber. +//! +//! This subscriber implements a tree-structured logger similar to +//! the "compact" formatter in [`slog-term`]. The demo mimicks the +//! example output in the screenshot in the [`slog` README]. +//! +//! Note that this logger isn't ready for actual production use. +//! Several corners were cut to make the example simple. +//! +//! [`slog-term`]: https://docs.rs/slog-term/2.4.0/slog_term/ +//! [`slog` README]: https://github.com/slog-rs/slog#terminal-output-example +extern crate ansi_term; +extern crate humantime; +use self::ansi_term::{Color, Style}; +use super::tokio_trace::{ + self, + field::{Field, Record}, + Id, Level, Subscriber, +}; + +use std::{ + cell::RefCell, + collections::HashMap, + fmt, + io::{self, Write}, + sync::{ + atomic::{AtomicUsize, Ordering}, + Mutex, + }, + thread, + time::SystemTime, +}; + +/// Tracks the currently executing span on a per-thread basis. +#[derive(Clone)] +pub struct CurrentSpanPerThread { + current: &'static thread::LocalKey>>, +} + +impl CurrentSpanPerThread { + pub fn new() -> Self { + thread_local! { + static CURRENT: RefCell> = RefCell::new(vec![]); + }; + Self { current: &CURRENT } + } + + /// Returns the [`Id`](::Id) of the span in which the current thread is + /// executing, or `None` if it is not inside of a span. + pub fn id(&self) -> Option { + self.current + .with(|current| current.borrow().last().cloned()) + } + + pub fn enter(&self, span: Id) { + self.current.with(|current| { + current.borrow_mut().push(span); + }) + } + + pub fn exit(&self) { + self.current.with(|current| { + let _ = current.borrow_mut().pop(); + }) + } +} + +pub struct SloggishSubscriber { + // TODO: this can probably be unified with the "stack" that's used for + // printing? + current: CurrentSpanPerThread, + indent_amount: usize, + stderr: io::Stderr, + stack: Mutex>, + spans: Mutex>, + ids: AtomicUsize, +} + +struct Span { + parent: Option, + kvs: Vec<(&'static str, String)>, +} + +struct Event<'a> { + stderr: io::StderrLock<'a>, + comma: bool, +} + +struct ColorLevel<'a>(&'a Level); + +impl<'a> fmt::Display for ColorLevel<'a> { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + match self.0 { + &Level::TRACE => Color::Purple.paint("TRACE"), + &Level::DEBUG => Color::Blue.paint("DEBUG"), + &Level::INFO => Color::Green.paint("INFO "), + &Level::WARN => Color::Yellow.paint("WARN "), + &Level::ERROR => Color::Red.paint("ERROR"), + } + .fmt(f) + } +} + +impl Span { + fn new( + parent: Option, + _meta: &tokio_trace::Metadata, + values: &tokio_trace::field::ValueSet, + ) -> Self { + let mut span = Self { + parent, + kvs: Vec::new(), + }; + values.record(&mut span); + span + } +} + +impl Record for Span { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.kvs.push((field.name(), format!("{:?}", value))) + } +} + +impl<'a> Record for Event<'a> { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + write!( + &mut self.stderr, + "{comma} ", + comma = if self.comma { "," } else { "" }, + ) + .unwrap(); + let name = field.name(); + if name == "message" { + write!( + &mut self.stderr, + "{}", + // Have to alloc here due to `ansi_term`'s API... + Style::new().bold().paint(format!("{:?}", value)) + ) + .unwrap(); + self.comma = true; + } else { + write!( + &mut self.stderr, + "{}: {:?}", + Style::new().bold().paint(name), + value + ) + .unwrap(); + self.comma = true; + } + } +} + +impl SloggishSubscriber { + pub fn new(indent_amount: usize) -> Self { + Self { + current: CurrentSpanPerThread::new(), + indent_amount, + stderr: io::stderr(), + stack: Mutex::new(vec![]), + spans: Mutex::new(HashMap::new()), + ids: AtomicUsize::new(0), + } + } + + fn print_kvs<'a, I, K, V>( + &self, + writer: &mut impl Write, + kvs: I, + leading: &str, + ) -> io::Result<()> + where + I: IntoIterator, + K: AsRef + 'a, + V: fmt::Display + 'a, + { + let mut kvs = kvs.into_iter(); + if let Some((k, v)) = kvs.next() { + write!( + writer, + "{}{}: {}", + leading, + Style::new().bold().paint(k.as_ref()), + v + )?; + } + for (k, v) in kvs { + write!(writer, ", {}: {}", Style::new().bold().paint(k.as_ref()), v)?; + } + Ok(()) + } + + fn print_indent(&self, writer: &mut impl Write, indent: usize) -> io::Result<()> { + for _ in 0..(indent * self.indent_amount) { + write!(writer, " ")?; + } + Ok(()) + } +} + +impl Subscriber for SloggishSubscriber { + fn enabled(&self, _metadata: &tokio_trace::Metadata) -> bool { + true + } + + fn new_span( + &self, + span: &tokio_trace::Metadata, + values: &tokio_trace::field::ValueSet, + ) -> tokio_trace::Id { + let next = self.ids.fetch_add(1, Ordering::SeqCst) as u64; + let id = tokio_trace::Id::from_u64(next); + let span = Span::new(self.current.id(), span, values); + self.spans.lock().unwrap().insert(id.clone(), span); + id + } + + fn record(&self, span: &tokio_trace::Id, values: &tokio_trace::field::ValueSet) { + let mut spans = self.spans.lock().expect("mutex poisoned!"); + if let Some(span) = spans.get_mut(span) { + values.record(span); + } + } + + fn record_follows_from(&self, _span: &tokio_trace::Id, _follows: &tokio_trace::Id) { + // unimplemented + } + + fn enter(&self, span_id: &tokio_trace::Id) { + self.current.enter(span_id.clone()); + let mut stderr = self.stderr.lock(); + let mut stack = self.stack.lock().unwrap(); + let spans = self.spans.lock().unwrap(); + let data = spans.get(span_id); + let parent = data.and_then(|span| span.parent.as_ref()); + if stack.iter().any(|id| id == span_id) { + // We are already in this span, do nothing. + return; + } else { + let indent = if let Some(idx) = stack + .iter() + .position(|id| parent.map(|p| id == p).unwrap_or(false)) + { + let idx = idx + 1; + stack.truncate(idx); + idx + } else { + stack.clear(); + 0 + }; + self.print_indent(&mut stderr, indent).unwrap(); + stack.push(span_id.clone()); + if let Some(data) = data { + self.print_kvs(&mut stderr, data.kvs.iter().map(|(k, v)| (k, v)), "") + .unwrap(); + } + write!(&mut stderr, "\n").unwrap(); + } + } + + fn event(&self, event: &tokio_trace::Event) { + let mut stderr = self.stderr.lock(); + let indent = self.stack.lock().unwrap().len(); + self.print_indent(&mut stderr, indent).unwrap(); + write!( + &mut stderr, + "{timestamp} {level} {target}", + timestamp = humantime::format_rfc3339_seconds(SystemTime::now()), + level = ColorLevel(event.metadata().level()), + target = &event.metadata().target(), + ) + .unwrap(); + let mut recorder = Event { + stderr, + comma: false, + }; + event.record(&mut recorder); + write!(&mut recorder.stderr, "\n").unwrap(); + } + + #[inline] + fn exit(&self, _span: &tokio_trace::Id) { + // TODO: unify stack with current span + self.current.exit(); + } + + fn drop_span(&self, _id: tokio_trace::Id) { + // TODO: GC unneeded spans. + } +} diff --git a/src/field.rs b/src/field.rs new file mode 100644 index 0000000000..9f8fdad978 --- /dev/null +++ b/src/field.rs @@ -0,0 +1,54 @@ +//! Structured data associated with `Span`s and `Event`s. +pub use tokio_trace_core::field::*; + +use Metadata; + +/// Trait implemented to allow a type to be used as a field key. +/// +/// **Note**: Although this is implemented for both the [`Field`] type *and* any +/// type that can be borrowed as an `&str`, only `Field` allows _O_(1) access. +/// Indexing a field with a string results in an iterative search that performs +/// string comparisons. Thus, if possible, once the key for a field is known, it +/// should be used whenever possible. +pub trait AsField: ::sealed::Sealed { + /// Attempts to convert `&self` into a `Field` with the specified `metadata`. + /// + /// If `metadata` defines this field, then the field is returned. Otherwise, + /// this returns `None`. + fn as_field(&self, metadata: &Metadata) -> Option; +} + +// ===== impl AsField ===== + +impl AsField for Field { + #[inline] + fn as_field(&self, metadata: &Metadata) -> Option { + if self.callsite() == metadata.callsite() { + Some(self.clone()) + } else { + None + } + } +} + +impl<'a> AsField for &'a Field { + #[inline] + fn as_field(&self, metadata: &Metadata) -> Option { + if self.callsite() == metadata.callsite() { + Some((*self).clone()) + } else { + None + } + } +} + +impl AsField for str { + #[inline] + fn as_field(&self, metadata: &Metadata) -> Option { + metadata.fields().field(&self) + } +} + +impl ::sealed::Sealed for Field {} +impl<'a> ::sealed::Sealed for &'a Field {} +impl ::sealed::Sealed for str {} diff --git a/src/lib.rs b/src/lib.rs new file mode 100644 index 0000000000..631d0e3b67 --- /dev/null +++ b/src/lib.rs @@ -0,0 +1,983 @@ +//! A scoped, structured logging and diagnostics system. +//! +//! # Overview +//! +//! `tokio-trace` is a framework for instrumenting Rust programs to collect +//! structured, event-based diagnostic information. +//! +//! 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. `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` crate provides the APIs necessary for instrumenting libraries +//! and applications to emit trace data. +//! +//! # Core Concepts +//! +//! The core of `tokio-trace`'s API is composed of `Event`s, `Span`s, and +//! `Subscriber`s. We'll cover these in turn. +//! +//! ## `Span`s +//! +//! A [`Span`] represents a _period of time_ during which a program was executing +//! in some context. A thread of execution is said to _enter_ a span when it +//! begins executing in that context, and to _exit_ the span when switching to +//! another context. The span in which a thread is currently executing is +//! referred to as the _current_ span. +//! +//! Spans form a tree structure — unless it is a root span, all spans have a +//! _parent_, and may have one or more _children_. When a new span is created, +//! the current span becomes the new span's parent. The total execution time of +//! a span consists of the time spent in that span and in the entire subtree +//! represented by its children. Thus, a parent span always lasts for at least +//! as long as the longest-executing span in its subtree. +//! +//! In addition, data may be associated with spans. A span may have _fields_ — +//! a set of key-value pairs describing the state of the program during that +//! span; an optional name, and metadata describing the source code location +//! where the span was originally entered. +//! +//! ### When to use spans +//! +//! As a rule of thumb, spans should be used to represent discrete units of work +//! (e.g., a given request's lifetime in a server) or periods of time spent in a +//! given context (e.g., time spent interacting with an instance of an external +//! system, such as a database). +//! +//! Which scopes in a program correspond to new spans depend somewhat on user +//! intent. For example, consider the case of a loop in a program. Should we +//! construct one span and perform the entire loop inside of that span, like: +//! ```rust +//! # #[macro_use] extern crate tokio_trace; +//! # fn main() { +//! # let n = 1; +//! span!("my loop").enter(|| { +//! for i in 0..n { +//! # let _ = i; +//! // ... +//! } +//! }) +//! # } +//! ``` +//! Or, should we create a new span for each iteration of the loop, as in: +//! ```rust +//! # #[macro_use] extern crate tokio_trace; +//! # fn main() { +//! # let n = 1u64; +//! for i in 0..n { +//! # let _ = i; +//! span!("my loop", iteration = i).enter(|| { +//! // ... +//! }) +//! } +//! # } +//! ``` +//! +//! Depending on the circumstances, we might want to do either, or both. For +//! example, if we want to know how long was spent in the loop overall, we would +//! create a single span around the entire loop; whereas if we wanted to know how +//! much time was spent in each individual iteration, we would enter a new span +//! on every iteration. +//! +//! ## Events +//! +//! An [`Event`] represents a _point_ in time. It signifies something that +//! happened while the trace was executing. `Event`s are comparable to the log +//! records emitted by unstructured logging code, but unlike a typical log line, +//! an `Event` may occur within the context of a `Span`. Like a `Span`, it +//! may have fields, and implicitly inherits any of the fields present on its +//! parent span, and it may be linked with one or more additional +//! spans that are not its parent; in this case, the event is said to _follow +//! from_ those spans. +//! +//! Essentially, `Event`s exist to bridge the gap between traditional +//! unstructured logging and span-based tracing. Similar to log records, they +//! may be recorded at a number of levels, and can have unstructured, +//! human-readable messages; however, they also carry key-value data and exist +//! within the context of the tree of spans that comprise a trace. Thus, +//! individual log record-like events can be pinpointed not only in time, but +//! in the logical execution flow of the system. +//! +//! Events are represented as a special case of spans — they are created, they +//! may have fields added, and then they close immediately, without being +//! entered. +//! +//! In general, events should be used to represent points in time _within_ a +//! span — a request returned with a given status code, _n_ new items were +//! taken from a queue, and so on. +//! +//! ## `Subscriber`s +//! +//! As `Span`s and `Event`s occur, they are recorded or aggregated by +//! implementations of the [`Subscriber`] trait. `Subscriber`s are notified +//! when an `Event` takes place and when a `Span` is entered or exited. These +//! notifications are represented by the following `Subscriber` trait methods: +//! + [`observe_event`], called when an `Event` takes place, +//! + [`enter`], called when execution enters a `Span`, +//! + [`exit`], called when execution exits a `Span` +//! +//! In addition, subscribers may implement the [`enabled`] function to _filter_ +//! the notifications they receive based on [metadata] describing each `Span` +//! or `Event`. If a call to `Subscriber::enabled` returns `false` for a given +//! set of metadata, that `Subscriber` will *not* be notified about the +//! corresponding `Span` or `Event`. For performance reasons, if no currently +//! active subscribers express interest in a given set of metadata by returning +//! `true`, then the corresponding `Span` or `Event` will never be constructed. +//! +//! # Usage +//! +//! First, add this to your `Cargo.toml`: +//! +//! ```toml +//! [dependencies] +//! tokio-trace = { git = "https://github.com/tokio-rs/tokio" } +//! ``` +//! +//! Next, add this to your crate: +//! +//! ```rust +//! #[macro_use] +//! extern crate tokio_trace; +//! # fn main() {} +//! ``` +//! +//! `Span`s are constructed using the `span!` macro, and then _entered_ +//! to indicate that some code takes place within the context of that `Span`: +//! +//! ```rust +//! # #[macro_use] +//! # extern crate tokio_trace; +//! # fn main() { +//! // Construct a new span named "my span". +//! let mut span = span!("my span"); +//! span.enter(|| { +//! // Any trace events in this closure or code called by it will occur within +//! // the span. +//! }); +//! // Dropping the span will close it, indicating that it has ended. +//! # } +//! ``` +//! +//! `Event`s are created using the `event!` macro, and are recorded when the +//! event is dropped: +//! +//! ```rust +//! # #[macro_use] +//! # extern crate tokio_trace; +//! # fn main() { +//! use tokio_trace::Level; +//! event!(Level::INFO, "something has happened!"); +//! # } +//! ``` +//! +//! Users of the [`log`] crate should note that `tokio-trace` exposes a set of +//! macros for creating `Event`s (`trace!`, `debug!`, `info!`, `warn!`, and +//! `error!`) which may be invoked with the same syntax as the similarly-named +//! macros from the `log` crate. Often, the process of converting a project to +//! use `tokio-trace` can begin with a simple drop-in replacement. +//! +//! Let's consider the `log` crate's yak-shaving example: +//! +//! ```rust +//! #[macro_use] +//! extern crate tokio_trace; +//! use tokio_trace::field; +//! # #[derive(Debug)] pub struct Yak(String); +//! # impl Yak { fn shave(&mut self, _: u32) {} } +//! # fn find_a_razor() -> Result { Ok(1) } +//! # fn main() { +//! pub fn shave_the_yak(yak: &mut Yak) { +//! // Create a new span for this invocation of `shave_the_yak`, annotated +//! // with the yak being shaved as a *field* on the span. +//! span!("shave_the_yak", yak = field::debug(&yak)).enter(|| { +//! // Since the span is annotated with the yak, it is part of the context +//! // for everything happening inside the span. Therefore, we don't need +//! // to add it to the message for this event, as the `log` crate does. +//! info!(target: "yak_events", "Commencing yak shaving"); +//! +//! loop { +//! match find_a_razor() { +//! Ok(razor) => { +//! // We can add the razor as a field rather than formatting it +//! // as part of the message, allowing subscribers to consume it +//! // in a more structured manner: +//! info!({ razor = field::display(razor) }, "Razor located"); +//! yak.shave(razor); +//! break; +//! } +//! Err(err) => { +//! // However, we can also create events with formatted messages, +//! // just as we would for log records. +//! warn!("Unable to locate a razor: {}, retrying", err); +//! } +//! } +//! } +//! }) +//! } +//! # } +//! ``` +//! +//! You can find examples showing how to use this crate in the examples +//! directory. +//! +//! ### In libraries +//! +//! Libraries should link only to the `tokio-trace` crate, and use the provided +//! macros to record whatever information will be useful to downstream +//! consumers. +//! +//! ### In executables +//! +//! In order to record trace events, executables have to use a `Subscriber` +//! implementation compatible with `tokio-trace`. A `Subscriber` implements a +//! way of collecting trace data, such as by logging it to standard output. +//! +//! Unlike the `log` crate, `tokio-trace` does *not* use a global `Subscriber` +//! which is initialized once. Instead, it follows the `tokio` pattern of +//! executing code in a context. For example: +//! +//! ```rust +//! #[macro_use] +//! extern crate tokio_trace; +//! # pub struct FooSubscriber; +//! # use tokio_trace::{span::Id, Metadata, field::ValueSet}; +//! # impl tokio_trace::Subscriber for FooSubscriber { +//! # fn new_span(&self, _: &Metadata, _: &ValueSet) -> Id { Id::from_u64(0) } +//! # fn record(&self, _: &Id, _: &ValueSet) {} +//! # fn event(&self, _: &tokio_trace::Event) {} +//! # fn record_follows_from(&self, _: &Id, _: &Id) {} +//! # fn enabled(&self, _: &Metadata) -> bool { false } +//! # fn enter(&self, _: &Id) {} +//! # fn exit(&self, _: &Id) {} +//! # } +//! # impl FooSubscriber { +//! # fn new() -> Self { FooSubscriber } +//! # } +//! # fn main() { +//! let my_subscriber = FooSubscriber::new(); +//! +//! tokio_trace::subscriber::with_default(my_subscriber, || { +//! // Any trace events generated in this closure or by functions it calls +//! // will be collected by `my_subscriber`. +//! }) +//! # } +//! ``` +//! +//! This approach allows trace data to be collected by multiple subscribers +//! within different contexts in the program. Alternatively, a single subscriber +//! may be constructed by the `main` function and all subsequent code executed +//! with that subscriber as the default. Any trace events generated outside the +//! context of a subscriber will not be collected. +//! +//! The executable itself may use the `tokio-trace` crate to instrument itself +//! as well. +//! +//! The [`tokio-trace-nursery`] repository contains less stable crates designed +//! to be used with the `tokio-trace` ecosystem. It includes a collection of +//! `Subscriber` implementations, as well as utility and adapter crates. +//! +//! [`log`]: https://docs.rs/log/0.4.6/log/ +//! [`Span`]: span/struct.Span +//! [`Event`]: struct.Event.html +//! [`Subscriber`]: subscriber/trait.Subscriber.html +//! [`observe_event`]: subscriber/trait.Subscriber.html#tymethod.observe_event +//! [`enter`]: subscriber/trait.Subscriber.html#tymethod.enter +//! [`exit`]: subscriber/trait.Subscriber.html#tymethod.exit +//! [`enabled`]: subscriber/trait.Subscriber.html#tymethod.enabled +//! [metadata]: struct.Metadata.html +//! [`tokio-trace-nursury`]: https://github.com/tokio-rs/tokio-trace-nursery +extern crate tokio_trace_core; + +// Somehow this `use` statement is necessary for us to re-export the `core` +// macros on Rust 1.26.0. I'm not sure how this makes it work, but it does. +#[allow(unused_imports)] +#[doc(hidden)] +use tokio_trace_core::*; + +pub use self::{ + dispatcher::Dispatch, + event::Event, + field::Value, + span::Span, + subscriber::Subscriber, + tokio_trace_core::{dispatcher, event, Level, Metadata}, +}; + +#[doc(hidden)] +pub use self::{ + span::Id, + tokio_trace_core::{ + callsite::{self, Callsite}, + metadata, + }, +}; + +/// Constructs a new static callsite for a span or event. +#[doc(hidden)] +#[macro_export] +macro_rules! callsite { + (name: $name:expr, fields: $( $field_name:expr ),* $(,)*) => ({ + callsite! { + name: $name, + target: module_path!(), + level: $crate::Level::TRACE, + fields: $( $field_name ),* + } + }); + (name: $name:expr, level: $lvl:expr, fields: $( $field_name:expr ),* $(,)*) => ({ + callsite! { + name: $name, + target: module_path!(), + level: $lvl, + fields: $( $field_name ),* + } + }); + ( + name: $name:expr, + target: $target:expr, + level: $lvl:expr, + fields: $( $field_name:expr ),* + $(,)* + ) => ({ + use std::sync::{Once, atomic::{self, AtomicUsize, Ordering}}; + use $crate::{callsite, Metadata, subscriber::Interest}; + struct MyCallsite; + static META: Metadata<'static> = { + metadata! { + name: $name, + target: $target, + level: $lvl, + fields: &[ $( stringify!($field_name) ),* ], + callsite: &MyCallsite, + } + }; + // FIXME: Rust 1.34 deprecated ATOMIC_USIZE_INIT. When Tokio's minimum + // supported version is 1.34, replace this with the const fn `::new`. + #[allow(deprecated)] + static INTEREST: AtomicUsize = atomic::ATOMIC_USIZE_INIT; + static REGISTRATION: Once = Once::new(); + impl MyCallsite { + #[inline] + fn interest(&self) -> Interest { + match INTEREST.load(Ordering::Relaxed) { + 0 => Interest::never(), + 2 => Interest::always(), + _ => Interest::sometimes(), + } + } + } + impl callsite::Callsite for MyCallsite { + fn add_interest(&self, interest: Interest) { + let current_interest = self.interest(); + let interest = match () { + // If the added interest is `never()`, don't change anything + // — either a different subscriber added a higher + // interest, which we want to preserve, or the interest is 0 + // anyway (as it's initialized to 0). + _ if interest.is_never() => return, + // If the interest is `sometimes()`, that overwrites a `never()` + // interest, but doesn't downgrade an `always()` interest. + _ if interest.is_sometimes() && current_interest.is_never() => 1, + // If the interest is `always()`, we overwrite the current + // interest, as always() is the highest interest level and + // should take precedent. + _ if interest.is_always() => 2, + _ => return, + }; + INTEREST.store(interest, Ordering::Relaxed); + } + fn clear_interest(&self) { + INTEREST.store(0, Ordering::Relaxed); + } + fn metadata(&self) -> &Metadata { + &META + } + } + REGISTRATION.call_once(|| { + callsite::register(&MyCallsite); + }); + &MyCallsite + }) +} + +/// Constructs a new span. +/// +/// # Examples +/// +/// Creating a new span with no fields: +/// ``` +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// let mut span = span!("my span"); +/// span.enter(|| { +/// // do work inside the span... +/// }); +/// # } +/// ``` +/// +/// Creating a span with fields: +/// ``` +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// span!("my span", foo = 2, bar = "a string").enter(|| { +/// // do work inside the span... +/// }); +/// # } +/// ``` +/// +/// Note that a trailing comma on the final field is valid: +/// ``` +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// span!( +/// "my span", +/// foo = 2, +/// bar = "a string", +/// ); +/// # } +/// ``` +/// +/// Creating a span with custom target and log level: +/// ``` +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// span!( +/// target: "app_span", +/// level: tokio_trace::Level::TRACE, +/// "my span", +/// foo = 3, +/// bar = "another string" +/// ); +/// # } +/// ``` +/// +/// Field values may be recorded after the span is created: +/// ``` +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// let mut my_span = span!("my span", foo = 2, bar); +/// my_span.record("bar", &7); +/// # } +/// ``` +/// +/// Note that a span may have up to 32 fields. The following will not compile: +/// ```rust,compile_fail +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// span!( +/// "too many fields!", +/// a = 1, b = 2, c = 3, d = 4, e = 5, f = 6, g = 7, h = 8, i = 9, +/// j = 10, k = 11, l = 12, m = 13, n = 14, o = 15, p = 16, q = 17, +/// r = 18, s = 19, t = 20, u = 21, v = 22, w = 23, x = 24, y = 25, +/// z = 26, aa = 27, bb = 28, cc = 29, dd = 30, ee = 31, ff = 32, gg = 33 +/// ); +/// # } +/// ``` +#[macro_export] +macro_rules! span { + (target: $target:expr, level: $lvl:expr, $name:expr, $($k:ident $( = $val:expr )* ),*,) => { + span!(target: $target, level: $lvl, $name, $($k $( = $val)*),*) + }; + (target: $target:expr, level: $lvl:expr, $name:expr, $($k:ident $( = $val:expr )* ),*) => { + { + use $crate::{callsite, field::{Value, ValueSet, AsField}, Span}; + use $crate::callsite::Callsite; + let callsite = callsite! { + name: $name, + target: $target, + level: $lvl, + fields: $($k),* + }; + if is_enabled!(callsite) { + let meta = callsite.metadata(); + Span::new(meta, &valueset!(meta.fields(), $($k $( = $val)*),*)) + } else { + Span::new_disabled() + } + } + }; + (target: $target:expr, level: $lvl:expr, $name:expr) => { + span!(target: $target, level: $lvl, $name,) + }; + (level: $lvl:expr, $name:expr, $($k:ident $( = $val:expr )* ),*,) => { + span!(target: module_path!(), level: $lvl, $name, $($k $( = $val)*),*) + }; + (level: $lvl:expr, $name:expr, $($k:ident $( = $val:expr )* ),*) => { + span!(target: module_path!(), level: $lvl, $name, $($k $( = $val)*),*) + }; + (level: $lvl:expr, $name:expr) => { + span!(target: module_path!(), level: $lvl, $name,) + }; + ($name:expr, $($k:ident $( = $val:expr)*),*,) => { + span!(target: module_path!(), level: $crate::Level::TRACE, $name, $($k $( = $val)*),*) + }; + ($name:expr, $($k:ident $( = $val:expr)*),*) => { + span!(target: module_path!(), level: $crate::Level::TRACE, $name, $($k $( = $val)*),*) + }; + ($name:expr) => { span!(target: module_path!(), level: $crate::Level::TRACE, $name,) }; +} + +/// Constructs a new `Event`. +/// +/// # Examples +/// +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace; +/// use tokio_trace::{Level, field}; +/// +/// # fn main() { +/// let data = (42, "fourty-two"); +/// let private_data = "private"; +/// let error = "a bad error"; +/// +/// event!(Level::ERROR, { error = field::display(error) }, "Received error"); +/// event!(target: "app_events", Level::WARN, { +/// private_data = private_data, +/// data = field::debug(data), +/// }, +/// "App warning: {}", error +/// ); +/// event!(Level::INFO, the_answer = data.0); +/// # } +/// ``` +/// +/// Note that *unlike `span!`*, `event!` requires a value for all fields. As +/// events are recorded immediately when the macro is invoked, there is no +/// opportunity for fields to be recorded later. A trailing comma on the final +/// field is valid. +/// +/// For example, the following does not compile: +/// ```rust,compile_fail +/// # #[macro_use] +/// # extern crate tokio_trace; +/// use tokio_trace::{Level, field}; +/// +/// # fn main() { +/// event!(Level::Info, foo = 5, bad_field, bar = field::display("hello")) +/// #} +/// ``` +/// +/// Events may have up to 32 fields. The following will not compile: +/// ```rust,compile_fail +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// event!(tokio_trace::Level::INFO, +/// a = 1, b = 2, c = 3, d = 4, e = 5, f = 6, g = 7, h = 8, i = 9, +/// j = 10, k = 11, l = 12, m = 13, n = 14, o = 15, p = 16, q = 17, +/// r = 18, s = 19, t = 20, u = 21, v = 22, w = 23, x = 24, y = 25, +/// z = 26, aa = 27, bb = 28, cc = 29, dd = 30, ee = 31, ff = 32, gg = 33 +/// ); +/// # } +/// ``` +#[macro_export] +macro_rules! event { + (target: $target:expr, $lvl:expr, { $( $k:ident = $val:expr ),* $(,)*} )=> ({ + { + #[allow(unused_imports)] + use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}}; + use $crate::callsite::Callsite; + let callsite = callsite! { + name: concat!("event ", file!(), ":", line!()), + target: $target, + level: $lvl, + fields: $( $k ),* + }; + if is_enabled!(callsite) { + let meta = callsite.metadata(); + Event::observe(meta, &valueset!(meta.fields(), $( $k = $val),* )); + } + } + }); + (target: $target:expr, $lvl:expr, { $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ({ + event!(target: $target, $lvl, { message = format_args!($($arg)+), $( $k = $val ),* }) + }); + (target: $target:expr, $lvl:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ({ + event!(target: $target, $lvl, { message = format_args!($($arg)+), $( $k = $val ),* }) + }); + (target: $target:expr, $lvl:expr, $( $k:ident = $val:expr ),+, ) => ( + event!(target: $target, $lvl, { $($k = $val),+ }) + ); + (target: $target:expr, $lvl:expr, $( $k:ident = $val:expr ),+ ) => ( + event!(target: $target, $lvl, { $($k = $val),+ }) + ); + (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ( + event!(target: $target, $lvl, { }, $($arg)+) + ); + ( $lvl:expr, { $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $lvl, { message = format_args!($($arg)+), $($k = $val),* }) + ); + ( $lvl:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $lvl, { message = format_args!($($arg)+), $($k = $val),* }) + ); + ( $lvl:expr, $( $k:ident = $val:expr ),*, ) => ( + event!(target: module_path!(), $lvl, { $($k = $val),* }) + ); + ( $lvl:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $lvl, { $($k = $val),* }) + ); + ( $lvl:expr, $($arg:tt)+ ) => ( + event!(target: module_path!(), $lvl, { }, $($arg)+) + ); +} + +/// Constructs an event at the trace level. +/// +/// When both a message and fields are included, curly braces (`{` and `}`) are +/// used to delimit the list of fields from the format string for the message. +/// A trailing comma on the final field is valid. +/// +/// # Examples +/// +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # use std::time::SystemTime; +/// # #[derive(Debug, Copy, Clone)] struct Position { x: f32, y: f32 } +/// # impl Position { +/// # const ORIGIN: Self = Self { x: 0.0, y: 0.0 }; +/// # fn dist(&self, other: Position) -> f32 { +/// # let x = (other.x - self.x).exp2(); let y = (self.y - other.y).exp2(); +/// # (x + y).sqrt() +/// # } +/// # } +/// # fn main() { +/// use tokio_trace::field; +/// +/// let pos = Position { x: 3.234, y: -1.223 }; +/// let origin_dist = pos.dist(Position::ORIGIN); +/// +/// trace!(position = field::debug(pos), origin_dist = field::debug(origin_dist)); +/// trace!(target: "app_events", +/// { position = field::debug(pos) }, +/// "x is {} and y is {}", +/// if pos.x >= 0.0 { "positive" } else { "negative" }, +/// if pos.y >= 0.0 { "positive" } else { "negative" }); +/// # } +/// ``` +#[macro_export] +macro_rules! trace { + (target: $target:expr, { $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::TRACE, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::TRACE, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, $( $k:ident = $val:expr ),*, ) => ( + event!(target: $target, $crate::Level::TRACE, { $($k = $val),* }) + ); + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::TRACE, { $($k = $val),* }) + ); + (target: $target:expr, $($arg:tt)+ ) => ( + // When invoking this macro with `log`-style syntax (no fields), we + // drop the event immediately — the `log` crate's macros don't + // expand to an item, and if this did, it would break drop-in + // compatibility with `log`'s macros. Since it defines no fields, + // the handle won't be used later to add values to them. + drop(event!(target: $target, $crate::Level::TRACE, {}, $($arg)+)); + ); + ({ $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::TRACE, { $($k = $val),* }, $($arg)+) + ); + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::TRACE, { $($k = $val),* }, $($arg)+) + ); + ($( $k:ident = $val:expr ),*, ) => ( + event!(target: module_path!(), $crate::Level::TRACE, { $($k = $val),* }) + ); + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::TRACE, { $($k = $val),* }) + ); + ($($arg:tt)+ ) => ( + drop(event!(target: module_path!(), $crate::Level::TRACE, {}, $($arg)+)); + ); +} + +/// Constructs an event at the debug level. +/// +/// When both a message and fields are included, curly braces (`{` and `}`) are +/// used to delimit the list of fields from the format string for the message. +/// A trailing comma on the final field is valid. +/// +/// # Examples +/// +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// # #[derive(Debug)] struct Position { x: f32, y: f32 } +/// use tokio_trace::field; +/// +/// let pos = Position { x: 3.234, y: -1.223 }; +/// +/// debug!(x = field::debug(pos.x), y = field::debug(pos.y)); +/// debug!(target: "app_events", { position = field::debug(pos) }, "New position"); +/// # } +/// ``` +#[macro_export] +macro_rules! debug { + (target: $target:expr, { $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::DEBUG, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::DEBUG, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, $( $k:ident = $val:expr ),*, ) => ( + event!(target: $target, $crate::Level::DEBUG, { $($k = $val),* }) + ); + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::DEBUG, { $($k = $val),* }) + ); + (target: $target:expr, $($arg:tt)+ ) => ( + drop(event!(target: $target, $crate::Level::DEBUG, {}, $($arg)+)); + ); + ({ $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::DEBUG, { $($k = $val),* }, $($arg)+) + ); + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::DEBUG, { $($k = $val),* }, $($arg)+) + ); + ($( $k:ident = $val:expr ),*, ) => ( + event!(target: module_path!(), $crate::Level::DEBUG, { $($k = $val),* }) + ); + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::DEBUG, { $($k = $val),* }) + ); + ($($arg:tt)+ ) => ( + drop(event!(target: module_path!(), $crate::Level::DEBUG, {}, $($arg)+)); + ); +} + +/// Constructs an event at the info level. +/// +/// When both a message and fields are included, curly braces (`{` and `}`) are +/// used to delimit the list of fields from the format string for the message. +/// A trailing comma on the final field is valid. +/// +/// # Examples +/// +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # use std::net::Ipv4Addr; +/// # fn main() { +/// # struct Connection { port: u32, speed: f32 } +/// use tokio_trace::field; +/// +/// let addr = Ipv4Addr::new(127, 0, 0, 1); +/// let conn_info = Connection { port: 40, speed: 3.20 }; +/// +/// info!({ port = conn_info.port }, "connected to {}", addr); +/// info!( +/// target: "connection_events", +/// ip = field::display(addr), +/// port = conn_info.port, +/// speed = field::debug(conn_info.speed) +/// ); +/// # } +/// ``` +#[macro_export] +macro_rules! info { + (target: $target:expr, { $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::INFO, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::INFO, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, $( $k:ident = $val:expr ),*, ) => ( + event!(target: $target, $crate::Level::INFO, { $($k = $val),* }) + ); + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::INFO, { $($k = $val),* }) + ); + (target: $target:expr, $($arg:tt)+ ) => ( + drop(event!(target: $target, $crate::Level::INFO, {}, $($arg)+)); + ); + ({ $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::INFO, { $($k = $val),* }, $($arg)+) + ); + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::INFO, { $($k = $val),* }, $($arg)+) + ); + ($( $k:ident = $val:expr ),*, ) => ( + event!(target: module_path!(), $crate::Level::INFO, { $($k = $val),* }) + ); + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::INFO, { $($k = $val),* }) + ); + ($($arg:tt)+ ) => ( + drop(event!(target: module_path!(), $crate::Level::INFO, {}, $($arg)+)); + ); +} + +/// Constructs an event at the warn level. +/// +/// When both a message and fields are included, curly braces (`{` and `}`) are +/// used to delimit the list of fields from the format string for the message. +/// A trailing comma on the final field is valid. +/// +/// # Examples +/// +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// use tokio_trace::field; +/// +/// let warn_description = "Invalid Input"; +/// let input = &[0x27, 0x45]; +/// +/// warn!(input = field::debug(input), warning = warn_description); +/// warn!( +/// target: "input_events", +/// { warning = warn_description }, +/// "Received warning for input: {:?}", input, +/// ); +/// # } +/// ``` +#[macro_export] +macro_rules! warn { + (target: $target:expr, { $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::WARN, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::WARN, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, $( $k:ident = $val:expr ),*, ) => ( + event!(target: $target, $crate::Level::WARN, { $($k = $val),* }) + ); + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::WARN, { $($k = $val),* }) + ); + (target: $target:expr, $($arg:tt)+ ) => ( + drop(event!(target: $target, $crate::Level::WARN, {}, $($arg)+)); + ); + ({ $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::WARN, { $($k = $val),* }, $($arg)+) + ); + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::WARN, { $($k = $val),* }, $($arg)+) + ); + ($( $k:ident = $val:expr ),*, ) => ( + event!(target: module_path!(), $crate::Level::WARN,{ $($k = $val),* }) + ); + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::WARN,{ $($k = $val),* }) + ); + ($($arg:tt)+ ) => ( + drop(event!(target: module_path!(), $crate::Level::WARN, {}, $($arg)+)); + ); +} + +/// Constructs an event at the error level. +/// +/// When both a message and fields are included, curly braces (`{` and `}`) are +/// used to delimit the list of fields from the format string for the message. +/// A trailing comma on the final field is valid. +/// +/// # Examples +/// +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace; +/// # fn main() { +/// use tokio_trace::field; +/// let (err_info, port) = ("No connection", 22); +/// +/// error!(port = port, error = field::display(err_info)); +/// error!(target: "app_events", "App Error: {}", err_info); +/// error!({ info = err_info }, "error on port: {}", port); +/// # } +/// ``` +#[macro_export] +macro_rules! error { + (target: $target:expr, { $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::ERROR, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::ERROR, { $($k = $val),* }, $($arg)+) + ); + (target: $target:expr, $( $k:ident = $val:expr ),*, ) => ( + event!(target: $target, $crate::Level::ERROR, { $($k = $val),* }) + ); + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::ERROR, { $($k = $val),* }) + ); + (target: $target:expr, $($arg:tt)+ ) => ( + drop(event!(target: $target, $crate::Level::ERROR, {}, $($arg)+)); + ); + ({ $( $k:ident = $val:expr ),*, }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::ERROR, { $($k = $val),* }, $($arg)+) + ); + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::ERROR, { $($k = $val),* }, $($arg)+) + ); + ($( $k:ident = $val:expr ),*, ) => ( + event!(target: module_path!(), $crate::Level::ERROR, { $($k = $val),* }) + ); + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::ERROR, { $($k = $val),* }) + ); + ($($arg:tt)+ ) => ( + drop(event!(target: module_path!(), $crate::Level::ERROR, {}, $($arg)+)); + ); +} + +#[macro_export] +// TODO: determine if this ought to be public API? +#[doc(hidden)] +macro_rules! is_enabled { + ($callsite:expr) => {{ + let interest = $callsite.interest(); + if interest.is_never() { + false + } else if interest.is_always() { + true + } else { + let meta = $callsite.metadata(); + $crate::dispatcher::with(|current| current.enabled(meta)) + } + }}; +} + +#[doc(hidden)] +#[macro_export] +macro_rules! valueset { + ($fields:expr, $($k:ident $( = $val:expr )* ) ,*) => { + { + let mut iter = $fields.iter(); + $fields.value_set(&[ + $(( + &iter.next().expect("FieldSet corrupted (this is a bug)"), + valueset!(@val $k $(= $val)*) + )),* + ]) + } + }; + (@val $k:ident = $val:expr) => { + Some(&$val as &$crate::field::Value) + }; + (@val $k:ident) => { None }; +} +pub mod field; +pub mod span; +pub mod subscriber; + +mod sealed { + pub trait Sealed {} +} diff --git a/src/span.rs b/src/span.rs new file mode 100644 index 0000000000..af098bdc41 --- /dev/null +++ b/src/span.rs @@ -0,0 +1,495 @@ +//! Spans represent periods of time in the execution of a program. +//! +//! # Entering a Span +//! +//! A thread of execution is said to _enter_ a span when it begins executing, +//! and _exit_ the span when it switches to another context. Spans may be +//! entered through the [`enter`](`Span::enter`) method, which enters the target span, +//! performs a given function (either a closure or a function pointer), exits +//! the span, and then returns the result. +//! +//! Calling `enter` on a span handle enters the span that handle corresponds to, +//! if the span exists: +//! ``` +//! # #[macro_use] extern crate tokio_trace; +//! # fn main() { +//! let my_var: u64 = 5; +//! let mut my_span = span!("my_span", my_var = &my_var); +//! +//! my_span.enter(|| { +//! // perform some work in the context of `my_span`... +//! }); +//! +//! // Perform some work outside of the context of `my_span`... +//! +//! my_span.enter(|| { +//! // Perform some more work in the context of `my_span`. +//! }); +//! # } +//! ``` +//! +//! # The Span Lifecycle +//! +//! Execution may enter and exit a span multiple times before that +//! span is _closed_. Consider, for example, a future which has an associated +//! span and enters that span every time it is polled: +//! ```rust +//! # extern crate tokio_trace; +//! # extern crate futures; +//! # use futures::{Future, Poll, Async}; +//! struct MyFuture<'a> { +//! // data +//! span: tokio_trace::Span<'a>, +//! } +//! +//! impl<'a> Future for MyFuture<'a> { +//! type Item = (); +//! type Error = (); +//! +//! fn poll(&mut self) -> Poll { +//! self.span.enter(|| { +//! // Do actual future work +//! # Ok(Async::Ready(())) +//! }) +//! } +//! } +//! ``` +//! +//! If this future was spawned on an executor, it might yield one or more times +//! before `poll` returns `Ok(Async::Ready)`. If the future were to yield, then +//! the executor would move on to poll the next future, which may _also_ enter +//! an associated span or series of spans. Therefore, it is valid for a span to +//! be entered repeatedly before it completes. Only the time when that span or +//! one of its children was the current span is considered to be time spent in +//! that span. A span which is not executing and has not yet been closed is said +//! to be _idle_. +//! +//! Because spans may be entered and exited multiple times before they close, +//! [`Subscriber`]s have separate trait methods which are called to notify them +//! of span exits and when span handles are dropped. When execution exits a +//! span, [`exit`](::Subscriber::exit) will always be called with that span's ID +//! to notify the subscriber that the span has been exited. When span handles +//! are dropped, the [`drop_span`](::Subscriber::drop_span) method is called +//! with that span's ID. The subscriber may use this to determine whether or not +//! the span will be entered again. +//! +//! If there is only a single handle with the capacity to exit a span, dropping +//! that handle "close" the span, since the capacity to enter it no longer +//! exists. For example: +//! ``` +//! # #[macro_use] extern crate tokio_trace; +//! # fn main() { +//! { +//! span!("my_span").enter(|| { +//! // perform some work in the context of `my_span`... +//! }); // --> Subscriber::exit(my_span) +//! +//! // The handle to `my_span` only lives inside of this block; when it is +//! // dropped, the subscriber will be informed that `my_span` has closed. +//! +//! } // --> Subscriber::close(my_span) +//! # } +//! ``` +//! +//! A span may be explicitly closed before when the span handle is dropped by +//! calling the [`Span::close`] method. Doing so will drop that handle the next +//! time it is exited. For example: +//! ``` +//! # #[macro_use] extern crate tokio_trace; +//! # fn main() { +//! use tokio_trace::Span; +//! +//! let mut my_span = span!("my_span"); +//! // Signal to my_span that it should close when it exits +//! my_span.close(); +//! my_span.enter(|| { +//! // ... +//! }); // --> Subscriber::exit(my_span); Subscriber::drop_span(my_span) +//! +//! // The handle to `my_span` still exists, but it now knows that the span was +//! // closed while it was executing. +//! my_span.is_closed(); // ==> true +//! +//! // Attempting to enter the span using the handle again will do nothing. +//! my_span.enter(|| { +//! // no-op +//! }); +//! # } +//! ``` +//! However, if multiple handles exist, the span can still be re-entered even if +//! one or more is dropped. For determining when _all_ handles to a span have +//! been dropped, `Subscriber`s have a [`clone_span`](::Subscriber::clone_span) +//! method, which is called every time a span handle is cloned. Combined with +//! `drop_span`, this may be used to track the number of handles to a given span +//! — if `drop_span` has been called one more time than the number of calls to +//! `clone_span` for a given ID, then no more handles to the span with that ID +//! exist. The subscriber may then treat it as closed. +//! +//! # Accessing a Span's Attributes +//! +//! The [`Attributes`] type represents a *non-entering* reference to a `Span`'s data +//! — a set of key-value pairs (known as _fields_), a creation timestamp, +//! a reference to the span's parent in the trace tree, and metadata describing +//! the source code location where the span was created. This data is provided +//! to the [`Subscriber`] when the span is created; it may then choose to cache +//! the data for future use, record it in some manner, or discard it completely. +//! +//! [`Subscriber`]: ::Subscriber +// TODO: remove this re-export? +pub use tokio_trace_core::span::Span as Id; + +use std::{ + borrow::Borrow, + cmp, fmt, + hash::{Hash, Hasher}, +}; +use { + dispatcher::{self, Dispatch}, + field, Metadata, +}; + +/// A handle representing a span, with the capability to enter the span if it +/// exists. +/// +/// If the span was rejected by the current `Subscriber`'s filter, entering the +/// span will silently do nothing. Thus, the handle can be used in the same +/// manner regardless of whether or not the trace is currently being collected. +#[derive(Clone, PartialEq, Hash)] +pub struct Span<'a> { + /// A handle used to enter the span when it is not executing. + /// + /// If this is `None`, then the span has either closed or was never enabled. + inner: Option>, + + /// Set to `true` when the span closes. + /// + /// This allows us to distinguish if `inner` is `None` because the span was + /// never enabled (and thus the inner state was never created), or if the + /// previously entered, but it is now closed. + is_closed: bool, +} + +/// A handle representing the capacity to enter a span which is known to exist. +/// +/// Unlike `Span`, this type is only constructed for spans which _have_ been +/// enabled by the current filter. This type is primarily used for implementing +/// span handles; users should typically not need to interact with it directly. +#[derive(Debug)] +pub(crate) struct Inner<'a> { + /// The span's ID, as provided by `subscriber`. + id: Id, + + /// The subscriber that will receive events relating to this span. + /// + /// This should be the same subscriber that provided this span with its + /// `id`. + subscriber: Dispatch, + + /// A flag indicating that the span has been instructed to close when + /// possible. + closed: bool, + + meta: &'a Metadata<'a>, +} + +/// A guard representing a span which has been entered and is currently +/// executing. +/// +/// This guard may be used to exit the span, returning an `Enter` to +/// re-enter it. +/// +/// This type is primarily used for implementing span handles; users should +/// typically not need to interact with it directly. +#[derive(Debug)] +#[must_use = "once a span has been entered, it should be exited"] +struct Entered<'a> { + inner: Inner<'a>, +} + +// ===== impl Span ===== + +impl<'a> Span<'a> { + /// Constructs a new `Span` with the given [metadata] and set of [field values]. + /// + /// The new span will be constructed by the currently-active [`Subscriber`], + /// with the current span as its parent (if one exists). + /// + /// After the span is constructed, [field values] and/or [`follows_from`] + /// annotations may be added to it. + /// + /// [metadata]: ::metadata::Metadata + /// [`Subscriber`]: ::subscriber::Subscriber + /// [field values]: ::field::ValueSet + /// [`follows_from`]: ::span::Span::follows_from + #[inline] + pub fn new(meta: &'a Metadata<'a>, values: &field::ValueSet) -> Span<'a> { + let inner = dispatcher::with(move |dispatch| { + let id = dispatch.new_span(meta, values); + Some(Inner::new(id, dispatch, meta)) + }); + Self { + inner, + is_closed: false, + } + } + + /// Constructs a new disabled span. + #[inline(always)] + pub fn new_disabled() -> Span<'a> { + Span { + inner: None, + is_closed: false, + } + } + + /// Executes the given function in the context of this span. + /// + /// If this span is enabled, then this function enters the span, invokes + /// and then exits the span. If the span is disabled, `f` will still be + /// invoked, but in the context of the currently-executing span (if there is + /// one). + /// + /// Returns the result of evaluating `f`. + pub fn enter T, T>(&mut self, f: F) -> T { + match self.inner.take() { + Some(inner) => dispatcher::with_default(inner.subscriber.clone(), || { + let guard = inner.enter(); + let result = f(); + self.inner = guard.exit(); + result + }), + None => f(), + } + } + + /// Returns a [`Field`](::field::Field) for the field with the given `name`, if + /// one exists, + pub fn field(&self, name: &Q) -> Option + where + Q: Borrow, + { + self.inner + .as_ref() + .and_then(|inner| inner.meta.fields().field(name)) + } + + /// Returns true if this `Span` has a field for the given + /// [`Field`](::field::Field) or field name. + pub fn has_field(&self, field: &Q) -> bool + where + Q: field::AsField, + { + self.metadata() + .and_then(|meta| field.as_field(meta)) + .is_some() + } + + /// Records that the field described by `field` has the value `value`. + pub fn record(&mut self, field: &Q, value: &V) -> &mut Self + where + Q: field::AsField, + V: field::Value, + { + if let Some(ref mut inner) = self.inner { + let meta = inner.metadata(); + if let Some(field) = field.as_field(meta) { + inner.record( + &meta + .fields() + .value_set(&[(&field, Some(value as &field::Value))]), + ) + } + } + self + } + + /// Record all the fields in the span + pub fn record_all(&mut self, values: &field::ValueSet) -> &mut Self { + if let Some(ref mut inner) = self.inner { + inner.record(&values); + } + self + } + + /// Closes this span handle, dropping its internal state. + /// + /// Once this function has been called, subsequent calls to `enter` on this + /// handle will no longer enter the span. If this is the final handle with + /// the potential to enter that span, the subscriber may consider the span to + /// have ended. + pub fn close(&mut self) { + if let Some(mut inner) = self.inner.take() { + inner.close(); + } + self.is_closed = true; + } + + /// Returns `true` if this span is closed. + pub fn is_closed(&self) -> bool { + self.is_closed + } + + /// Returns `true` if this span was disabled by the subscriber and does not + /// exist. + #[inline] + pub fn is_disabled(&self) -> bool { + self.inner.is_none() && !self.is_closed + } + + /// Indicates that the span with the given ID has an indirect causal + /// relationship with this span. + /// + /// This relationship differs somewhat from the parent-child relationship: a + /// span may have any number of prior spans, rather than a single one; and + /// spans are not considered to be executing _inside_ of the spans they + /// follow from. This means that a span may close even if subsequent spans + /// that follow from it are still open, and time spent inside of a + /// subsequent span should not be included in the time its precedents were + /// executing. This is used to model causal relationships such as when a + /// single future spawns several related background tasks, et cetera. + /// + /// If this span is disabled, or the resulting follows-from relationship + /// would be invalid, this function will do nothing. + pub fn follows_from(&self, from: &Id) -> &Self { + if let Some(ref inner) = self.inner { + inner.follows_from(from); + } + self + } + + /// Returns this span's `Id`, if it is enabled. + pub fn id(&self) -> Option { + self.inner.as_ref().map(Inner::id) + } + + /// Returns this span's `Metadata`, if it is enabled. + pub fn metadata(&self) -> Option<&'a Metadata<'a>> { + self.inner.as_ref().map(Inner::metadata) + } +} + +impl<'a> fmt::Debug for Span<'a> { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + let mut span = f.debug_struct("Span"); + if let Some(ref inner) = self.inner { + span.field("id", &inner.id()) + } else { + span.field("disabled", &true) + } + .finish() + } +} + +// ===== impl Inner ===== + +impl<'a> Inner<'a> { + /// Indicates that this handle will not be reused to enter the span again. + /// + /// After calling `close`, the `Entered` guard returned by `self.enter()` + /// will _drop_ this handle when it is exited. + fn close(&mut self) { + self.closed = true; + } + + /// Enters the span, returning a guard that may be used to exit the span and + /// re-enter the prior span. + /// + /// This is used internally to implement `Span::enter`. It may be used for + /// writing custom span handles, but should generally not be called directly + /// when entering a span. + fn enter(self) -> Entered<'a> { + self.subscriber.enter(&self.id); + Entered { inner: self } + } + + /// Indicates that the span with the given ID has an indirect causal + /// relationship with this span. + /// + /// This relationship differs somewhat from the parent-child relationship: a + /// span may have any number of prior spans, rather than a single one; and + /// spans are not considered to be executing _inside_ of the spans they + /// follow from. This means that a span may close even if subsequent spans + /// that follow from it are still open, and time spent inside of a + /// subsequent span should not be included in the time its precedents were + /// executing. This is used to model causal relationships such as when a + /// single future spawns several related background tasks, et cetera. + /// + /// If this span is disabled, this function will do nothing. Otherwise, it + /// returns `Ok(())` if the other span was added as a precedent of this + /// span, or an error if this was not possible. + fn follows_from(&self, from: &Id) { + self.subscriber.record_follows_from(&self.id, &from) + } + + /// Returns the span's ID. + fn id(&self) -> Id { + self.id.clone() + } + + /// Returns the span's metadata. + fn metadata(&self) -> &'a Metadata<'a> { + self.meta + } + + fn record(&mut self, values: &field::ValueSet) { + if values.callsite() == self.meta.callsite() { + self.subscriber.record(&self.id, &values) + } + } + + fn new(id: Id, subscriber: &Dispatch, meta: &'a Metadata<'a>) -> Self { + Inner { + id, + subscriber: subscriber.clone(), + closed: false, + meta, + } + } +} + +impl<'a> cmp::PartialEq for Inner<'a> { + fn eq(&self, other: &Self) -> bool { + self.id == other.id + } +} + +impl<'a> Hash for Inner<'a> { + fn hash(&self, state: &mut H) { + self.id.hash(state); + } +} + +impl<'a> Drop for Inner<'a> { + fn drop(&mut self) { + self.subscriber.drop_span(self.id.clone()); + } +} + +impl<'a> Clone for Inner<'a> { + fn clone(&self) -> Self { + Inner { + id: self.subscriber.clone_span(&self.id), + subscriber: self.subscriber.clone(), + closed: self.closed, + meta: self.meta, + } + } +} + +// ===== impl Entered ===== + +impl<'a> Entered<'a> { + /// Exit the `Entered` guard, returning an `Inner` handle that may be used + /// to re-enter the span, or `None` if the span closed while performing the + /// exit. + fn exit(self) -> Option> { + self.inner.subscriber.exit(&self.inner.id); + if self.inner.closed { + // Dropping `inner` will allow it to perform the closure if + // able. + None + } else { + Some(self.inner) + } + } +} diff --git a/src/subscriber.rs b/src/subscriber.rs new file mode 100644 index 0000000000..e1c8c457bf --- /dev/null +++ b/src/subscriber.rs @@ -0,0 +1,19 @@ +//! Collects and records trace data. +pub use tokio_trace_core::subscriber::*; + +/// Sets this dispatch as the default for the duration of a closure. +/// +/// The default dispatcher is used when creating a new [`Span`] or +/// [`Event`], _if no span is currently executing_. If a span is currently +/// executing, new spans or events are dispatched to the subscriber that +/// tagged that span, instead. +/// +/// [`Span`]: ::span::Span +/// [`Subscriber`]: ::Subscriber +/// [`Event`]: ::Event +pub fn with_default(subscriber: S, f: impl FnOnce() -> T) -> T +where + S: Subscriber + Send + Sync + 'static, +{ + ::dispatcher::with_default(::Dispatch::new(subscriber), f) +} diff --git a/tests/dispatcher.rs b/tests/dispatcher.rs new file mode 100644 index 0000000000..816968f2bc --- /dev/null +++ b/tests/dispatcher.rs @@ -0,0 +1,73 @@ +#[macro_use] +extern crate tokio_trace; +mod support; + +use self::support::*; +use tokio_trace::{dispatcher, Dispatch}; + +#[test] +fn dispatcher_is_sticky() { + // Test ensuring that entire trace trees are collected by the same + // dispatcher, even across dispatcher context switches. + let (subscriber1, handle1) = subscriber::mock() + .enter(span::mock().named("foo")) + .exit(span::mock().named("foo")) + .enter(span::mock().named("foo")) + .enter(span::mock().named("bar")) + .exit(span::mock().named("bar")) + .drop_span(span::mock().named("bar")) + .exit(span::mock().named("foo")) + .drop_span(span::mock().named("foo")) + .done() + .run_with_handle(); + let mut foo = dispatcher::with_default(Dispatch::new(subscriber1), || { + let mut foo = span!("foo"); + foo.enter(|| {}); + foo + }); + dispatcher::with_default(Dispatch::new(subscriber::mock().done().run()), move || { + foo.enter(|| span!("bar").enter(|| {})) + }); + + handle1.assert_finished(); +} + +#[test] +fn dispatcher_isnt_too_sticky() { + // Test ensuring that new trace trees are collected by the current + // dispatcher. + let (subscriber1, handle1) = subscriber::mock() + .enter(span::mock().named("foo")) + .exit(span::mock().named("foo")) + .enter(span::mock().named("foo")) + .enter(span::mock().named("bar")) + .exit(span::mock().named("bar")) + .drop_span(span::mock().named("bar")) + .exit(span::mock().named("foo")) + .drop_span(span::mock().named("foo")) + .done() + .run_with_handle(); + let (subscriber2, handle2) = subscriber::mock() + .enter(span::mock().named("baz")) + .enter(span::mock().named("quux")) + .exit(span::mock().named("quux")) + .drop_span(span::mock().named("quux")) + .exit(span::mock().named("baz")) + .drop_span(span::mock().named("baz")) + .done() + .run_with_handle(); + + let mut foo = dispatcher::with_default(Dispatch::new(subscriber1), || { + let mut foo = span!("foo"); + foo.enter(|| {}); + foo + }); + let mut baz = dispatcher::with_default(Dispatch::new(subscriber2), || span!("baz")); + dispatcher::with_default(Dispatch::new(subscriber::mock().done().run()), move || { + foo.enter(|| span!("bar").enter(|| {})); + baz.enter(|| span!("quux").enter(|| {})) + }); + + handle1.assert_finished(); + handle2.assert_finished(); +} diff --git a/tests/event.rs b/tests/event.rs new file mode 100644 index 0000000000..e5fcd81812 --- /dev/null +++ b/tests/event.rs @@ -0,0 +1,169 @@ +#[macro_use] +extern crate tokio_trace; +mod support; + +use self::support::*; + +use tokio_trace::{ + field::{debug, display}, + subscriber::with_default, + Level, +}; + +#[test] +fn event_without_message() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock().with_fields( + field::mock("answer") + .with_value(&42) + .and( + field::mock("to_question") + .with_value(&"life, the universe, and everything"), + ) + .only(), + ), + ) + .done() + .run_with_handle(); + + with_default(subscriber, || { + info!( + answer = 42, + to_question = "life, the universe, and everything" + ); + }); + + handle.assert_finished(); +} + +#[test] +fn event_with_message() { + let (subscriber, handle) = subscriber::mock() + .event(event::mock().with_fields(field::mock("message").with_value( + &tokio_trace::field::debug(format_args!( + "hello from my event! yak shaved = {:?}", + true + )), + ))) + .done() + .run_with_handle(); + + with_default(subscriber, || { + debug!("hello from my event! yak shaved = {:?}", true); + }); + + handle.assert_finished(); +} + +#[test] +fn one_with_everything() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock() + .with_fields( + field::mock("message") + .with_value(&tokio_trace::field::debug(format_args!( + "{:#x} make me one with{what:.>20}", + 4277009102u64, + what = "everything" + ))) + .and(field::mock("foo").with_value(&666)) + .and(field::mock("bar").with_value(&false)) + .only(), + ) + .at_level(tokio_trace::Level::ERROR) + .with_target("whatever"), + ) + .done() + .run_with_handle(); + + with_default(subscriber, || { + event!( + target: "whatever", + tokio_trace::Level::ERROR, + { foo = 666, bar = false }, + "{:#x} make me one with{what:.>20}", 4277009102u64, what = "everything" + ); + }); + + handle.assert_finished(); +} + +#[test] +fn moved_field() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock().with_fields( + field::mock("foo") + .with_value(&display("hello from my event")) + .only(), + ), + ) + .done() + .run_with_handle(); + with_default(subscriber, || { + let from = "my event"; + event!(Level::INFO, foo = display(format!("hello from {}", from))) + }); + + handle.assert_finished(); +} + +#[test] +fn borrowed_field() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock().with_fields( + field::mock("foo") + .with_value(&display("hello from my event")) + .only(), + ), + ) + .done() + .run_with_handle(); + with_default(subscriber, || { + let from = "my event"; + let mut message = format!("hello from {}", from); + event!(Level::INFO, foo = display(&message)); + message.push_str(", which happened!"); + }); + + 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() + .event( + event::mock().with_fields( + field::mock("x") + .with_value(&debug(3.234)) + .and(field::mock("y").with_value(&debug(-1.223))) + .only(), + ), + ) + .event(event::mock().with_fields(field::mock("position").with_value(&debug(&pos)))) + .done() + .run_with_handle(); + + with_default(subscriber, || { + let pos = Position { + x: 3.234, + y: -1.223, + }; + debug!(x = debug(pos.x), y = debug(pos.y)); + debug!(target: "app_events", { position = debug(pos) }, "New position"); + }); + handle.assert_finished(); +} diff --git a/tests/macros.rs b/tests/macros.rs new file mode 100644 index 0000000000..002b787c68 --- /dev/null +++ b/tests/macros.rs @@ -0,0 +1,145 @@ +#[macro_use] +extern crate tokio_trace; +// Tests that macros work across various invocation syntax. +// +// These are quite repetitive, and _could_ be generated by a macro. However, +// they're compile-time tests, so I want to get line numbers etc out of +// failures, and producing them with a macro would muddy the waters a bit. + +#[test] +fn span() { + span!(target: "foo_events", level: tokio_trace::Level::DEBUG, "foo", bar = 2, baz = 3); + span!(target: "foo_events", level: tokio_trace::Level::DEBUG, "foo", bar = 2, baz = 4,); + span!(target: "foo_events", level: tokio_trace::Level::DEBUG, "foo"); + span!(target: "foo_events", level: tokio_trace::Level::DEBUG, "bar",); + span!(level: tokio_trace::Level::DEBUG, "foo", bar = 2, baz = 3); + span!(level: tokio_trace::Level::DEBUG, "foo", bar = 2, baz = 4,); + span!(level: tokio_trace::Level::DEBUG, "foo"); + span!(level: tokio_trace::Level::DEBUG, "bar",); + span!("foo", bar = 2, baz = 3); + span!("foo", bar = 2, baz = 4,); + span!("foo"); + span!("bar",); +} + +#[test] +fn event() { + event!(tokio_trace::Level::DEBUG, foo = 3, bar = 2, baz = false); + event!(tokio_trace::Level::DEBUG, foo = 3, bar = 3,); + event!(tokio_trace::Level::DEBUG, "foo"); + event!(tokio_trace::Level::DEBUG, "foo: {}", 3); + event!(tokio_trace::Level::DEBUG, { foo = 3, bar = 80 }, "baz"); + event!(tokio_trace::Level::DEBUG, { foo = 2, bar = 79 }, "baz {:?}", true); + event!(tokio_trace::Level::DEBUG, { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + event!(tokio_trace::Level::DEBUG, { foo = 2, bar = 78, }, "baz"); + event!(target: "foo_events", tokio_trace::Level::DEBUG, foo = 3, bar = 2, baz = false); + event!(target: "foo_events", tokio_trace::Level::DEBUG, foo = 3, bar = 3,); + event!(target: "foo_events", tokio_trace::Level::DEBUG, "foo"); + event!(target: "foo_events", tokio_trace::Level::DEBUG, "foo: {}", 3); + event!(target: "foo_events", tokio_trace::Level::DEBUG, { foo = 3, bar = 80 }, "baz"); + event!(target: "foo_events", tokio_trace::Level::DEBUG, { foo = 2, bar = 79 }, "baz {:?}", true); + event!(target: "foo_events", tokio_trace::Level::DEBUG, { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + event!(target: "foo_events", tokio_trace::Level::DEBUG, { foo = 2, bar = 78, }, "baz"); +} + +#[test] +fn trace() { + trace!(foo = 3, bar = 2, baz = false); + trace!(foo = 3, bar = 3,); + trace!("foo"); + trace!("foo: {}", 3); + trace!({ foo = 3, bar = 80 }, "baz"); + trace!({ foo = 2, bar = 79 }, "baz {:?}", true); + trace!({ foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + trace!({ foo = 2, bar = 78, }, "baz"); + trace!(target: "foo_events", foo = 3, bar = 2, baz = false); + trace!(target: "foo_events", foo = 3, bar = 3,); + trace!(target: "foo_events", "foo"); + trace!(target: "foo_events", "foo: {}", 3); + trace!(target: "foo_events", { foo = 3, bar = 80 }, "baz"); + trace!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}", true); + trace!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + trace!(target: "foo_events", { foo = 2, bar = 78, }, "baz"); +} + +#[test] +fn debug() { + debug!(foo = 3, bar = 2, baz = false); + debug!(foo = 3, bar = 3,); + debug!("foo"); + debug!("foo: {}", 3); + debug!({ foo = 3, bar = 80 }, "baz"); + debug!({ foo = 2, bar = 79 }, "baz {:?}", true); + debug!({ foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + debug!({ foo = 2, bar = 78, }, "baz"); + debug!(target: "foo_events", foo = 3, bar = 2, baz = false); + debug!(target: "foo_events", foo = 3, bar = 3,); + debug!(target: "foo_events", "foo"); + debug!(target: "foo_events", "foo: {}", 3); + debug!(target: "foo_events", { foo = 3, bar = 80 }, "baz"); + debug!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}", true); + debug!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + debug!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + debug!(target: "foo_events", { foo = 2, bar = 78, }, "baz"); +} + +#[test] +fn info() { + info!(foo = 3, bar = 2, baz = false); + info!(foo = 3, bar = 3,); + info!("foo"); + info!("foo: {}", 3); + info!({ foo = 3, bar = 80 }, "baz"); + info!({ foo = 2, bar = 79 }, "baz {:?}", true); + info!({ foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + info!({ foo = 2, bar = 78, }, "baz"); + info!(target: "foo_events", foo = 3, bar = 2, baz = false); + info!(target: "foo_events", foo = 3, bar = 3,); + info!(target: "foo_events", "foo"); + info!(target: "foo_events", "foo: {}", 3); + info!(target: "foo_events", { foo = 3, bar = 80 }, "baz"); + info!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}", true); + info!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + info!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + info!(target: "foo_events", { foo = 2, bar = 78, }, "baz"); +} + +#[test] +fn warn() { + warn!(foo = 3, bar = 2, baz = false); + warn!(foo = 3, bar = 3,); + warn!("foo"); + warn!("foo: {}", 3); + warn!({ foo = 3, bar = 80 }, "baz"); + warn!({ foo = 2, bar = 79 }, "baz {:?}", true); + warn!({ foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + warn!({ foo = 2, bar = 78 }, "baz"); + warn!(target: "foo_events", foo = 3, bar = 2, baz = false); + warn!(target: "foo_events", foo = 3, bar = 3,); + warn!(target: "foo_events", "foo"); + warn!(target: "foo_events", "foo: {}", 3); + warn!(target: "foo_events", { foo = 3, bar = 80 }, "baz"); + warn!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}", true); + warn!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + warn!(target: "foo_events", { foo = 2, bar = 78, }, "baz"); +} + +#[test] +fn error() { + error!(foo = 3, bar = 2, baz = false); + error!(foo = 3, bar = 3,); + error!("foo"); + error!("foo: {}", 3); + error!({ foo = 3, bar = 80 }, "baz"); + error!({ foo = 2, bar = 79 }, "baz {:?}", true); + error!({ foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + error!({ foo = 2, bar = 78, }, "baz"); + error!(target: "foo_events", foo = 3, bar = 2, baz = false); + error!(target: "foo_events", foo = 3, bar = 3,); + error!(target: "foo_events", "foo"); + error!(target: "foo_events", "foo: {}", 3); + error!(target: "foo_events", { foo = 3, bar = 80 }, "baz"); + error!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}", true); + error!(target: "foo_events", { foo = 2, bar = 79 }, "baz {:?}, {quux}", true, quux = false); + error!(target: "foo_events", { foo = 2, bar = 78, }, "baz"); +} diff --git a/tests/span.rs b/tests/span.rs new file mode 100644 index 0000000000..45c192982b --- /dev/null +++ b/tests/span.rs @@ -0,0 +1,478 @@ +#[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(); +} diff --git a/tests/subscriber.rs b/tests/subscriber.rs new file mode 100644 index 0000000000..21a8a480bd --- /dev/null +++ b/tests/subscriber.rs @@ -0,0 +1,170 @@ +#[macro_use] +extern crate tokio_trace; +mod support; + +use self::support::*; +use tokio_trace::{dispatcher, Dispatch}; + +use std::sync::{ + atomic::{AtomicUsize, Ordering}, + Arc, +}; + +#[test] +fn filters_are_not_reevaluated_for_the_same_span() { + // Asserts that the `span!` macro caches the result of calling + // `Subscriber::enabled` for each span. + let alice_count = Arc::new(AtomicUsize::new(0)); + let bob_count = Arc::new(AtomicUsize::new(0)); + let alice_count2 = alice_count.clone(); + let bob_count2 = bob_count.clone(); + + let (subscriber, handle) = subscriber::mock() + .with_filter(move |meta| match meta.name { + "alice" => { + alice_count2.fetch_add(1, Ordering::Relaxed); + false + } + "bob" => { + bob_count2.fetch_add(1, Ordering::Relaxed); + true + } + _ => false, + }) + .run_with_handle(); + + dispatcher::with_default(Dispatch::new(subscriber), move || { + // Enter "alice" and then "bob". The dispatcher expects to see "bob" but + // not "alice." + let mut alice = span!("alice"); + let mut bob = alice.enter(|| { + let mut bob = span!("bob"); + bob.enter(|| ()); + bob + }); + + // The filter should have seen each span a single time. + assert_eq!(alice_count.load(Ordering::Relaxed), 1); + assert_eq!(bob_count.load(Ordering::Relaxed), 1); + + alice.enter(|| bob.enter(|| {})); + + // The subscriber should see "bob" again, but the filter should not have + // been called. + assert_eq!(alice_count.load(Ordering::Relaxed), 1); + assert_eq!(bob_count.load(Ordering::Relaxed), 1); + + bob.enter(|| {}); + assert_eq!(alice_count.load(Ordering::Relaxed), 1); + assert_eq!(bob_count.load(Ordering::Relaxed), 1); + }); + handle.assert_finished(); +} + +#[test] +fn filters_are_reevaluated_for_different_call_sites() { + // Asserts that the `span!` macro caches the result of calling + // `Subscriber::enabled` for each span. + let charlie_count = Arc::new(AtomicUsize::new(0)); + let dave_count = Arc::new(AtomicUsize::new(0)); + let charlie_count2 = charlie_count.clone(); + let dave_count2 = dave_count.clone(); + + let subscriber = subscriber::mock() + .with_filter(move |meta| { + println!("Filter: {:?}", meta.name); + match meta.name { + "charlie" => { + charlie_count2.fetch_add(1, Ordering::Relaxed); + false + } + "dave" => { + dave_count2.fetch_add(1, Ordering::Relaxed); + true + } + _ => false, + } + }) + .run(); + + dispatcher::with_default(Dispatch::new(subscriber), move || { + // Enter "charlie" and then "dave". The dispatcher expects to see "dave" but + // not "charlie." + let mut charlie = span!("charlie"); + let mut dave = charlie.enter(|| { + let mut dave = span!("dave"); + dave.enter(|| {}); + dave + }); + + // The filter should have seen each span a single time. + assert_eq!(charlie_count.load(Ordering::Relaxed), 1); + assert_eq!(dave_count.load(Ordering::Relaxed), 1); + + charlie.enter(|| dave.enter(|| {})); + + // The subscriber should see "dave" again, but the filter should not have + // been called. + assert_eq!(charlie_count.load(Ordering::Relaxed), 1); + assert_eq!(dave_count.load(Ordering::Relaxed), 1); + + // A different span with the same name has a different call site, so it + // should cause the filter to be reapplied. + let mut charlie2 = span!("charlie"); + charlie.enter(|| {}); + assert_eq!(charlie_count.load(Ordering::Relaxed), 2); + assert_eq!(dave_count.load(Ordering::Relaxed), 1); + + // But, the filter should not be re-evaluated for the new "charlie" span + // when it is re-entered. + charlie2.enter(|| span!("dave").enter(|| {})); + assert_eq!(charlie_count.load(Ordering::Relaxed), 2); + assert_eq!(dave_count.load(Ordering::Relaxed), 2); + }); +} + +#[test] +fn filter_caching_is_lexically_scoped() { + pub fn my_great_function() -> bool { + span!("emily").enter(|| true) + } + + pub fn my_other_function() -> bool { + span!("frank").enter(|| true) + } + + let count = Arc::new(AtomicUsize::new(0)); + let count2 = count.clone(); + + let subscriber = subscriber::mock() + .with_filter(move |meta| match meta.name { + "emily" | "frank" => { + count2.fetch_add(1, Ordering::Relaxed); + true + } + _ => false, + }) + .run(); + + dispatcher::with_default(Dispatch::new(subscriber), || { + // Call the function once. The filter should be re-evaluated. + assert!(my_great_function()); + assert_eq!(count.load(Ordering::Relaxed), 1); + + // Call the function again. The cached result should be used. + assert!(my_great_function()); + assert_eq!(count.load(Ordering::Relaxed), 1); + + assert!(my_other_function()); + assert_eq!(count.load(Ordering::Relaxed), 2); + + assert!(my_great_function()); + assert_eq!(count.load(Ordering::Relaxed), 2); + + assert!(my_other_function()); + assert_eq!(count.load(Ordering::Relaxed), 2); + + assert!(my_great_function()); + assert_eq!(count.load(Ordering::Relaxed), 2); + }); +} diff --git a/tests/support/event.rs b/tests/support/event.rs new file mode 100644 index 0000000000..5dbe2b235f --- /dev/null +++ b/tests/support/event.rs @@ -0,0 +1,92 @@ +#![allow(missing_docs)] +use super::{field, metadata}; + +use std::fmt; + +/// A mock event. +/// +/// This is intended for use with the mock subscriber API in the +/// `subscriber` module. +#[derive(Debug, Default, Eq, PartialEq)] +pub struct MockEvent { + pub fields: Option, + metadata: metadata::Expect, +} + +pub fn mock() -> MockEvent { + MockEvent { + ..Default::default() + } +} + +impl MockEvent { + pub fn named(self, name: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + name: Some(name.into()), + ..self.metadata + }, + ..self + } + } + + pub fn with_fields(self, fields: I) -> Self + where + I: Into, + { + Self { + fields: Some(fields.into()), + ..self + } + } + + pub fn at_level(self, level: tokio_trace::Level) -> Self { + Self { + metadata: metadata::Expect { + level: Some(level), + ..self.metadata + }, + ..self + } + } + + pub fn with_target(self, target: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + target: Some(target.into()), + ..self.metadata + }, + ..self + } + } + + pub(in support) fn check(self, event: &tokio_trace::Event) { + let meta = event.metadata(); + let name = meta.name(); + self.metadata.check(meta, format_args!("event {}", name)); + if let Some(mut expected_fields) = self.fields { + let mut checker = expected_fields.checker(format!("{}", name)); + event.record(&mut checker); + checker.finish(); + } + } +} + +impl fmt::Display for MockEvent { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "an event")?; + if let Some(ref name) = self.metadata.name { + write!(f, " named {:?}", name)?; + } + if let Some(ref fields) = self.fields { + write!(f, " with {}", fields)? + } + Ok(()) + } +} diff --git a/tests/support/field.rs b/tests/support/field.rs new file mode 100644 index 0000000000..578452b0b9 --- /dev/null +++ b/tests/support/field.rs @@ -0,0 +1,224 @@ +use tokio_trace::{ + callsite::Callsite, + field::{self, Field, Record, Value}, +}; + +use std::{collections::HashMap, fmt}; + +#[derive(Default, Debug, Eq, PartialEq)] +pub struct Expect { + fields: HashMap, + only: bool, +} + +#[derive(Debug)] +pub struct MockField { + name: String, + value: MockValue, +} + +#[derive(Debug, Eq, PartialEq)] +pub enum MockValue { + I64(i64), + U64(u64), + Bool(bool), + Str(String), + Debug(String), + Any, +} + +pub fn mock(name: K) -> MockField +where + String: From, +{ + MockField { + name: name.into(), + value: MockValue::Any, + } +} + +impl MockField { + /// Expect a field with the given name and value. + pub fn with_value(self, value: &Value) -> Self { + Self { + value: MockValue::from(value), + ..self + } + } + + pub fn and(self, other: MockField) -> Expect { + Expect { + fields: HashMap::new(), + only: false, + } + .and(self) + .and(other) + } + + pub fn only(self) -> Expect { + Expect { + fields: HashMap::new(), + only: true, + } + .and(self) + } +} + +impl Into for MockField { + fn into(self) -> Expect { + Expect { + fields: HashMap::new(), + only: false, + } + .and(self) + } +} + +impl Expect { + pub fn and(mut self, field: MockField) -> Self { + self.fields.insert(field.name, field.value); + self + } + + /// Indicates that no fields other than those specified should be expected. + pub fn only(self) -> Self { + Self { only: true, ..self } + } + + fn compare_or_panic(&mut self, name: &str, value: &Value, ctx: &str) { + let value = value.into(); + match self.fields.remove(name) { + Some(MockValue::Any) => {} + Some(expected) => assert!( + expected == value, + "\nexpected `{}` to contain:\n\t`{}{}`\nbut got:\n\t`{}{}`", + ctx, + name, + expected, + name, + value + ), + None if self.only => panic!( + "\nexpected `{}` to contain only:\n\t`{}`\nbut got:\n\t`{}{}`", + ctx, self, name, value + ), + _ => {} + } + } + + pub fn checker<'a>(&'a mut self, ctx: String) -> CheckRecorder<'a> { + CheckRecorder { expect: self, ctx } + } + + pub fn is_empty(&self) -> bool { + self.fields.is_empty() + } +} + +impl fmt::Display for MockValue { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + match self { + MockValue::I64(v) => write!(f, ": i64 = {:?}", v), + MockValue::U64(v) => write!(f, ": u64 = {:?}", v), + MockValue::Bool(v) => write!(f, ": bool = {:?}", v), + MockValue::Str(v) => write!(f, ": &str = {:?}", v), + MockValue::Debug(v) => write!(f, ": &fmt::Debug = {:?}", v), + MockValue::Any => write!(f, ": _ = _"), + } + } +} + +pub struct CheckRecorder<'a> { + expect: &'a mut Expect, + ctx: String, +} + +impl<'a> Record for CheckRecorder<'a> { + fn record_i64(&mut self, field: &Field, value: i64) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_u64(&mut self, field: &Field, value: u64) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_bool(&mut self, field: &Field, value: bool) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.expect + .compare_or_panic(field.name(), &field::debug(value), &self.ctx) + } +} + +impl<'a> CheckRecorder<'a> { + pub fn finish(self) { + assert!( + self.expect.fields.is_empty(), + "{}missing {}", + self.expect, + self.ctx + ); + } +} + +impl<'a> From<&'a Value> for MockValue { + fn from(value: &'a Value) -> Self { + struct MockValueBuilder { + value: Option, + } + + impl Record for MockValueBuilder { + fn record_i64(&mut self, _: &Field, value: i64) { + self.value = Some(MockValue::I64(value)); + } + + fn record_u64(&mut self, _: &Field, value: u64) { + self.value = Some(MockValue::U64(value)); + } + + fn record_bool(&mut self, _: &Field, value: bool) { + self.value = Some(MockValue::Bool(value)); + } + + fn record_str(&mut self, _: &Field, value: &str) { + self.value = Some(MockValue::Str(value.to_owned())); + } + + fn record_debug(&mut self, _: &Field, value: &fmt::Debug) { + self.value = Some(MockValue::Debug(format!("{:?}", value))); + } + } + + let fake_field = callsite!(name: "fake", fields: fake_field) + .metadata() + .fields() + .field("fake_field") + .unwrap(); + let mut builder = MockValueBuilder { value: None }; + value.record(&fake_field, &mut builder); + builder + .value + .expect("finish called before a value was recorded") + } +} + +impl fmt::Display for Expect { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "fields ")?; + let entries = self + .fields + .iter() + .map(|(k, v)| (field::display(k), field::display(v))); + f.debug_map().entries(entries).finish() + } +} diff --git a/tests/support/metadata.rs b/tests/support/metadata.rs new file mode 100644 index 0000000000..502c04e44e --- /dev/null +++ b/tests/support/metadata.rs @@ -0,0 +1,64 @@ +use std::fmt; +use tokio_trace::Metadata; + +#[derive(Debug, Eq, PartialEq, Default)] +pub struct Expect { + pub name: Option, + pub level: Option, + pub target: Option, +} + +impl Expect { + pub(in support) fn check(&self, actual: &Metadata, ctx: fmt::Arguments) { + if let Some(ref expected_name) = self.name { + let name = actual.name(); + assert!( + expected_name == name, + "expected {} to be named `{}`, but got one named `{}`", + ctx, + expected_name, + name + ) + } + + if let Some(ref expected_level) = self.level { + let level = actual.level(); + assert!( + expected_level == level, + "expected {} to be at level `{:?}`, but it was at level `{:?}` instead", + ctx, + expected_level, + level, + ) + } + + if let Some(ref expected_target) = self.target { + let target = actual.target(); + assert!( + expected_target == &target, + "expected {} to have target `{}`, but it had target `{}` instead", + ctx, + expected_target, + target, + ) + } + } +} + +impl fmt::Display for Expect { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + if let Some(ref name) = self.name { + write!(f, "named `{}`", name)?; + } + + if let Some(ref level) = self.level { + write!(f, " at the `{:?}` level", level)?; + } + + if let Some(ref target) = self.target { + write!(f, " with target `{}`", target)?; + } + + Ok(()) + } +} diff --git a/tests/support/mod.rs b/tests/support/mod.rs new file mode 100644 index 0000000000..b8f78cc7a2 --- /dev/null +++ b/tests/support/mod.rs @@ -0,0 +1,6 @@ +#![allow(dead_code)] +pub mod event; +pub mod field; +mod metadata; +pub mod span; +pub mod subscriber; diff --git a/tests/support/span.rs b/tests/support/span.rs new file mode 100644 index 0000000000..e1e738780c --- /dev/null +++ b/tests/support/span.rs @@ -0,0 +1,109 @@ +#![allow(missing_docs)] +use super::{field, metadata}; +use std::fmt; + +/// A mock span. +/// +/// This is intended for use with the mock subscriber API in the +/// `subscriber` module. +#[derive(Debug, Default, Eq, PartialEq)] +pub struct MockSpan { + pub(in support) metadata: metadata::Expect, +} + +#[derive(Debug, Default, Eq, PartialEq)] +pub struct NewSpan { + pub(in support) span: MockSpan, + pub(in support) fields: field::Expect, +} + +pub fn mock() -> MockSpan { + MockSpan { + ..Default::default() + } +} + +impl MockSpan { + pub fn named(self, name: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + name: Some(name.into()), + ..self.metadata + }, + ..self + } + } + + pub fn at_level(self, level: tokio_trace::Level) -> Self { + Self { + metadata: metadata::Expect { + level: Some(level), + ..self.metadata + }, + ..self + } + } + + pub fn with_target(self, target: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + target: Some(target.into()), + ..self.metadata + }, + ..self + } + } + + pub fn name(&self) -> Option<&str> { + self.metadata.name.as_ref().map(String::as_ref) + } + + pub fn with_field(self, fields: I) -> NewSpan + where + I: Into, + { + NewSpan { + span: self, + fields: fields.into(), + } + } + + pub(in support) fn check_metadata(&self, actual: &tokio_trace::Metadata) { + self.metadata.check(actual, format_args!("span {}", self)) + } +} + +impl fmt::Display for MockSpan { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + if self.metadata.name.is_some() { + write!(f, "a span{}", self.metadata) + } else { + write!(f, "any span{}", self.metadata) + } + } +} + +impl Into for MockSpan { + fn into(self) -> NewSpan { + NewSpan { + span: self, + ..Default::default() + } + } +} + +impl fmt::Display for NewSpan { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "a new span{}", self.span.metadata)?; + if !self.fields.is_empty() { + write!(f, " with {}", self.fields)?; + } + Ok(()) + } +} diff --git a/tests/support/subscriber.rs b/tests/support/subscriber.rs new file mode 100644 index 0000000000..662e0cc397 --- /dev/null +++ b/tests/support/subscriber.rs @@ -0,0 +1,337 @@ +#![allow(missing_docs)] +use super::{ + event::MockEvent, + field as mock_field, + span::{MockSpan, NewSpan}, +}; +use std::{ + collections::{HashMap, VecDeque}, + fmt, + sync::{ + atomic::{AtomicUsize, Ordering}, + Arc, Mutex, + }, +}; +use tokio_trace::{field, Event, Id, Metadata, Subscriber}; + +#[derive(Debug, Eq, PartialEq)] +enum Expect { + Event(MockEvent), + Enter(MockSpan), + Exit(MockSpan), + CloneSpan(MockSpan), + DropSpan(MockSpan), + Record(MockSpan, mock_field::Expect), + NewSpan(NewSpan), + Nothing, +} + +struct SpanState { + name: &'static str, + refs: usize, +} + +struct Running bool> { + spans: Mutex>, + expected: Arc>>, + ids: AtomicUsize, + filter: F, +} + +pub struct MockSubscriber bool> { + expected: VecDeque, + filter: F, +} + +pub struct MockHandle(Arc>>); + +pub fn mock() -> MockSubscriber bool> { + MockSubscriber { + expected: VecDeque::new(), + filter: (|_: &Metadata| true) as for<'r, 's> fn(&'r Metadata<'s>) -> _, + } +} + +impl bool> MockSubscriber { + pub fn enter(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::Enter(span)); + self + } + + pub fn event(mut self, event: MockEvent) -> Self { + self.expected.push_back(Expect::Event(event)); + self + } + + pub fn exit(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::Exit(span)); + self + } + + pub fn clone_span(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::CloneSpan(span)); + self + } + + pub fn drop_span(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::DropSpan(span)); + self + } + + pub fn done(mut self) -> Self { + self.expected.push_back(Expect::Nothing); + self + } + + pub fn record(mut self, span: MockSpan, fields: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::Record(span, fields.into())); + self + } + + pub fn new_span(mut self, new_span: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::NewSpan(new_span.into())); + self + } + + pub fn with_filter(self, filter: G) -> MockSubscriber + where + G: Fn(&Metadata) -> bool, + { + MockSubscriber { + filter, + expected: self.expected, + } + } + + pub fn run(self) -> impl Subscriber { + let (subscriber, _) = self.run_with_handle(); + subscriber + } + + pub fn run_with_handle(self) -> (impl Subscriber, MockHandle) { + let expected = Arc::new(Mutex::new(self.expected)); + let handle = MockHandle(expected.clone()); + let subscriber = Running { + spans: Mutex::new(HashMap::new()), + expected, + ids: AtomicUsize::new(0), + filter: self.filter, + }; + (subscriber, handle) + } +} + +impl bool> Subscriber for Running { + fn enabled(&self, meta: &Metadata) -> bool { + (self.filter)(meta) + } + + fn record(&self, id: &Id, values: &field::ValueSet) { + let spans = self.spans.lock().unwrap(); + let mut expected = self.expected.lock().unwrap(); + let span = spans + .get(id) + .unwrap_or_else(|| panic!("no span for ID {:?}", id)); + println!("record: {}; id={:?}; values={:?};", span.name, id, values); + let was_expected = if let Some(Expect::Record(_, _)) = expected.front() { + true + } else { + false + }; + if was_expected { + if let Expect::Record(expected_span, mut expected_values) = + expected.pop_front().unwrap() + { + if let Some(name) = expected_span.name() { + assert_eq!(name, span.name); + } + let mut checker = expected_values.checker(format!("span {}: ", span.name)); + values.record(&mut checker); + checker.finish(); + } + } + } + + fn event(&self, event: &Event) { + let name = event.metadata().name(); + println!("event: {};", name); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Event(expected)) => expected.check(event), + Some(ex) => ex.bad(format_args!("observed event {:?}", event)), + } + } + + fn record_follows_from(&self, _span: &Id, _follows: &Id) { + // TODO: it should be possible to expect spans to follow from other spans + } + + fn new_span(&self, meta: &Metadata, values: &field::ValueSet) -> Id { + let id = self.ids.fetch_add(1, Ordering::SeqCst); + let id = Id::from_u64(id as u64); + println!( + "new_span: name={:?}; target={:?}; id={:?};", + meta.name(), + meta.target(), + id + ); + let mut expected = self.expected.lock().unwrap(); + let was_expected = match expected.front() { + Some(Expect::NewSpan(_)) => true, + _ => false, + }; + if was_expected { + if let Expect::NewSpan(mut expected) = expected.pop_front().unwrap() { + let name = meta.name(); + expected + .span + .metadata + .check(meta, format_args!("span `{}`", name)); + let mut checker = expected.fields.checker(format!("{}", name)); + values.record(&mut checker); + checker.finish(); + } + } + self.spans.lock().unwrap().insert( + id.clone(), + SpanState { + name: meta.name(), + refs: 1, + }, + ); + id + } + + fn enter(&self, id: &Id) { + let spans = self.spans.lock().unwrap(); + if let Some(span) = spans.get(id) { + println!("enter: {}; id={:?};", span.name, id); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Enter(ref expected_span)) => { + if let Some(name) = expected_span.name() { + assert_eq!(name, span.name); + } + } + Some(ex) => ex.bad(format_args!("entered span {:?}", span.name)), + } + }; + } + + fn exit(&self, id: &Id) { + let spans = self.spans.lock().unwrap(); + let span = spans + .get(id) + .unwrap_or_else(|| panic!("no span for ID {:?}", id)); + println!("exit: {}; id={:?};", span.name, id); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Exit(ref expected_span)) => { + if let Some(name) = expected_span.name() { + assert_eq!(name, span.name); + } + } + Some(ex) => ex.bad(format_args!("exited span {:?}", span.name)), + }; + } + + fn clone_span(&self, id: &Id) -> Id { + let name = self.spans.lock().unwrap().get_mut(id).map(|span| { + let name = span.name; + println!("clone_span: {}; id={:?}; refs={:?};", name, id, span.refs); + span.refs += 1; + name + }); + if name.is_none() { + println!("clone_span: id={:?};", id); + } + let mut expected = self.expected.lock().unwrap(); + let was_expected = if let Some(Expect::CloneSpan(ref span)) = expected.front() { + assert_eq!(name, span.name()); + true + } else { + false + }; + if was_expected { + expected.pop_front(); + } + id.clone() + } + + fn drop_span(&self, id: Id) { + let mut is_event = false; + let name = if let Ok(mut spans) = self.spans.try_lock() { + spans.get_mut(&id).map(|span| { + let name = span.name; + if name.contains("event") { + is_event = true; + } + println!("drop_span: {}; id={:?}; refs={:?};", name, id, span.refs); + span.refs -= 1; + name + }) + } else { + None + }; + if name.is_none() { + println!("drop_span: id={:?}", id); + } + if let Ok(mut expected) = self.expected.try_lock() { + let was_expected = match expected.front() { + Some(Expect::DropSpan(ref span)) => { + // Don't assert if this function was called while panicking, + // as failing the assertion can cause a double panic. + if !::std::thread::panicking() { + assert_eq!(name, span.name()); + } + true + } + Some(Expect::Event(_)) => { + if !::std::thread::panicking() { + assert!(is_event); + } + true + } + _ => false, + }; + if was_expected { + expected.pop_front(); + } + } + } +} + +impl MockHandle { + pub fn assert_finished(&self) { + if let Ok(ref expected) = self.0.lock() { + assert!( + !expected.iter().any(|thing| thing != &Expect::Nothing), + "more notifications expected: {:?}", + **expected + ); + } + } +} + +impl Expect { + fn bad<'a>(&self, what: fmt::Arguments<'a>) { + match self { + Expect::Event(e) => panic!("expected event {}, but {} instead", e, what,), + Expect::Enter(e) => panic!("expected to enter {} but {} instead", e, what,), + Expect::Exit(e) => panic!("expected to exit {} but {} instead", e, what,), + Expect::CloneSpan(e) => panic!("expected to clone {} but {} instead", e, what,), + Expect::DropSpan(e) => panic!("expected to drop {} but {} instead", e, what,), + Expect::Record(e, fields) => { + panic!("expected {} to record {} but {} instead", e, fields, what,) + } + Expect::NewSpan(e) => panic!("expected {} but {} instead", e, what), + Expect::Nothing => panic!("expected nothing else to happen, but {} instead", what,), + } + } +} diff --git a/tokio-trace-core/Cargo.toml b/tokio-trace-core/Cargo.toml new file mode 100644 index 0000000000..7c36498f0c --- /dev/null +++ b/tokio-trace-core/Cargo.toml @@ -0,0 +1,18 @@ +[package] +name = "tokio-trace-core" +version = "0.1.0" +authors = ["Eliza Weisman "] +license = "MIT" +repository = "https://github.com/tokio-rs/tokio" +homepage = "https://tokio.rs" +description = """ +Core primitives for tokio-trace. +""" +categories = ["development-tools::debugging"] +keywords = ["logging", "tracing"] + +# Not yet ready for production. +publish = false + +[dependencies] +lazy_static = "1.0.0" diff --git a/tokio-trace-core/LICENSE b/tokio-trace-core/LICENSE new file mode 100644 index 0000000000..cdb28b4b56 --- /dev/null +++ b/tokio-trace-core/LICENSE @@ -0,0 +1,25 @@ +Copyright (c) 2019 Tokio Contributors + +Permission is hereby granted, free of charge, to any +person obtaining a copy of this software and associated +documentation files (the "Software"), to deal in the +Software without restriction, including without +limitation the rights to use, copy, modify, merge, +publish, distribute, sublicense, and/or sell copies of +the Software, and to permit persons to whom the Software +is furnished to do so, subject to the following +conditions: + +The above copyright notice and this permission notice +shall be included in all copies or substantial portions +of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF +ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED +TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A +PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT +SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY +CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION +OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR +IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER +DEALINGS IN THE SOFTWARE. diff --git a/tokio-trace-core/README.md b/tokio-trace-core/README.md new file mode 100644 index 0000000000..9fab742971 --- /dev/null +++ b/tokio-trace-core/README.md @@ -0,0 +1,42 @@ +# tokio-trace-core + +Core primitives for `tokio-trace`. + +## Overview + +`tokio-trace` is a framework for instrumenting Rust programs to collect +structured, event-based diagnostic information. This crate defines the core +primitives of `tokio-trace`. + +The crate provides: + +* `Span` identifies a span within the execution of a program. + +* `Subscriber`, the trait implemented to collect trace data. + +* `Metadata` and `Callsite` provide information describing `Span`s. + +* `Field` and `FieldSet` describe and access the structured data attached to a + `Span`. + +* `Dispatch` allows span events to be dispatched to `Subscriber`s. + +In addition, it defines the global callsite registry and per-thread current +dispatcher which other components of the tracing system rely on. + +Application authors will typically not use this crate directly. Instead, they +will use the [`tokio-trace`] crate, which provides a much more fully-featured +API. However, this crate's API will change very infrequently, so it may be used +when dependencies must be very stable. + +[`tokio-trace`]: ../ + +## License + +This project is licensed under the [MIT license](LICENSE). + +### Contribution + +Unless you explicitly state otherwise, any contribution intentionally submitted +for inclusion in Tokio by you, shall be licensed as MIT, without any additional +terms or conditions. diff --git a/tokio-trace-core/src/callsite.rs b/tokio-trace-core/src/callsite.rs new file mode 100644 index 0000000000..4b45aa0e43 --- /dev/null +++ b/tokio-trace-core/src/callsite.rs @@ -0,0 +1,121 @@ +//! Callsites represent the source locations from which spans or events +//! originate. +use std::{ + fmt, + hash::{Hash, Hasher}, + ptr, + sync::Mutex, +}; +use { + dispatcher::{self, Dispatch}, + subscriber::Interest, + Metadata, +}; + +lazy_static! { + static ref REGISTRY: Mutex = Mutex::new(Registry { + callsites: Vec::new(), + dispatchers: Vec::new(), + }); +} + +struct Registry { + callsites: Vec<&'static Callsite>, + dispatchers: Vec, +} + +/// Trait implemented by callsites. +pub trait Callsite: Sync { + /// Adds the [`Interest`] returned by [registering] the callsite with a + /// [dispatcher]. + /// + /// If the interest is greater than or equal to the callsite's current + /// interest, this should change whether or not the callsite is enabled. + /// + /// [`Interest`]: ::subscriber::Interest + /// [registering]: ::subscriber::Subscriber::register_callsite + /// [dispatcher]: ::Dispatch + fn add_interest(&self, interest: Interest); + + /// Remove _all_ [`Interest`] from the callsite, disabling it. + /// + /// [`Interest`]: ::subscriber::Interest + fn clear_interest(&self); + + /// Returns the [metadata] associated with the callsite. + /// + /// [metadata]: ::Metadata + fn metadata(&self) -> &Metadata; +} + +/// Uniquely identifies a [`Callsite`](::callsite::Callsite). +/// +/// Two `Identifier`s are equal if they both refer to the same callsite. +#[derive(Clone)] +pub struct Identifier( + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Identifier`. When + /// constructing new `Identifier`s, use the `identify_callsite!` macro or + /// the `Callsite::id` function instead. + // TODO: When `Callsite::id` is a const fn, this need no longer be `pub`. + #[doc(hidden)] + pub &'static Callsite, +); + +/// Register a new `Callsite` with the global registry. +/// +/// This should be called once per callsite after the callsite has been +/// constructed. +pub fn register(callsite: &'static Callsite) { + let mut registry = REGISTRY.lock().unwrap(); + let meta = callsite.metadata(); + registry.dispatchers.retain(|registrar| { + match registrar.try_register(meta) { + Some(interest) => { + callsite.add_interest(interest); + true + } + // TODO: if the dispatcher has been dropped, should we invalidate + // any callsites that it previously enabled? + None => false, + } + }); + registry.callsites.push(callsite); +} + +pub(crate) fn register_dispatch(dispatch: &Dispatch) { + let mut registry = REGISTRY.lock().unwrap(); + registry.dispatchers.push(dispatch.registrar()); + for callsite in ®istry.callsites { + let interest = dispatch.register_callsite(callsite.metadata()); + callsite.add_interest(interest); + } +} + +// ===== impl Identifier ===== + +impl PartialEq for Identifier { + fn eq(&self, other: &Identifier) -> bool { + ptr::eq(self.0, other.0) + } +} + +impl Eq for Identifier {} + +impl fmt::Debug for Identifier { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "Identifier({:p})", self.0) + } +} + +impl Hash for Identifier { + fn hash(&self, state: &mut H) + where + H: Hasher, + { + (self.0 as *const Callsite).hash(state) + } +} diff --git a/tokio-trace-core/src/dispatcher.rs b/tokio-trace-core/src/dispatcher.rs new file mode 100644 index 0000000000..05d35fdf39 --- /dev/null +++ b/tokio-trace-core/src/dispatcher.rs @@ -0,0 +1,252 @@ +//! Dispatches trace events to `Subscriber`s. +use { + callsite, field, + subscriber::{self, Subscriber}, + Event, Metadata, Span, +}; + +use std::{ + cell::RefCell, + fmt, + sync::{Arc, Weak}, +}; + +/// `Dispatch` trace data to a [`Subscriber`](::Subscriber). +#[derive(Clone)] +pub struct Dispatch { + subscriber: Arc, +} + +thread_local! { + static CURRENT_DISPATCH: RefCell = RefCell::new(Dispatch::none()); +} + +/// Sets this dispatch as the default for the duration of a closure. +/// +/// The default dispatcher is used when creating a new [`Span`] or +/// [`Event`], _if no span is currently executing_. If a span is currently +/// executing, new spans or events are dispatched to the subscriber that +/// tagged that span, instead. +/// +/// [`Span`]: ::span::Span +/// [`Subscriber`]: ::Subscriber +/// [`Event`]: ::Event +pub fn with_default(dispatcher: Dispatch, f: impl FnOnce() -> T) -> T { + // A drop guard that resets CURRENT_DISPATCH to the prior dispatcher. + // Using this (rather than simply resetting after calling `f`) ensures + // that we always reset to the prior dispatcher even if `f` panics. + struct ResetGuard(Option); + impl Drop for ResetGuard { + fn drop(&mut self) { + if let Some(dispatch) = self.0.take() { + let _ = CURRENT_DISPATCH.try_with(|current| { + *current.borrow_mut() = dispatch; + }); + } + } + } + + let prior = CURRENT_DISPATCH.try_with(|current| current.replace(dispatcher)); + let _guard = ResetGuard(prior.ok()); + f() +} + +/// Executes a closure with a reference to this thread's current dispatcher. +pub fn with(mut f: F) -> T +where + F: FnMut(&Dispatch) -> T, +{ + CURRENT_DISPATCH + .try_with(|current| f(&*current.borrow())) + .unwrap_or_else(|_| f(&Dispatch::none())) +} + +pub(crate) struct Registrar(Weak); + +impl Dispatch { + /// Returns a new `Dispatch` that discards events and spans. + pub fn none() -> Self { + Dispatch { + subscriber: Arc::new(NoSubscriber), + } + } + + /// Returns a `Dispatch` to the given [`Subscriber`](::Subscriber). + pub fn new(subscriber: S) -> Self + where + S: Subscriber + Send + Sync + 'static, + { + let me = Dispatch { + subscriber: Arc::new(subscriber), + }; + callsite::register_dispatch(&me); + me + } + + pub(crate) fn registrar(&self) -> Registrar { + Registrar(Arc::downgrade(&self.subscriber)) + } + + /// Registers a new callsite with this subscriber, returning whether or not + /// the subscriber is interested in being notified about the callsite. + /// + /// This calls the [`register_callsite`](::Subscriber::register_callsite) + /// function on the `Subscriber` that this `Dispatch` forwards to. + #[inline] + pub fn register_callsite(&self, metadata: &Metadata) -> subscriber::Interest { + self.subscriber.register_callsite(metadata) + } + + /// Record the construction of a new [`Span`], returning a new ID for the + /// span being constructed. + /// + /// This calls the [`new_span`](::Subscriber::new_span) + /// function on the `Subscriber` that this `Dispatch` forwards to. + /// + /// [`Span`]: ::span::Span + #[inline] + pub fn new_span(&self, metadata: &Metadata, values: &field::ValueSet) -> Span { + self.subscriber.new_span(metadata, values) + } + + /// Record a set of values on a span. + /// + /// This calls the [`record`](::Subscriber::record) + /// function on the `Subscriber` that this `Dispatch` forwards to. + #[inline] + pub fn record(&self, span: &Span, values: &field::ValueSet) { + self.subscriber.record(span, &values) + } + + /// Adds an indication that `span` follows from the span with the id + /// `follows`. + /// + /// This calls the [`record_follows_from`](::Subscriber::record_follows_from) + /// function on the `Subscriber` that this `Dispatch` forwards to. + #[inline] + pub fn record_follows_from(&self, span: &Span, follows: &Span) { + self.subscriber.record_follows_from(span, follows) + } + + /// Returns true if a span with the specified [metadata] would be + /// recorded. + /// + /// This calls the [`enabled`](::Subscriber::enabled) function on + /// the `Subscriber` that this `Dispatch` forwards to. + /// + /// [metadata]: ::Metadata + #[inline] + pub fn enabled(&self, metadata: &Metadata) -> bool { + self.subscriber.enabled(metadata) + } + + /// Records that an [`Event`] has occurred. + /// + /// This calls the [`event`](::Subscriber::event) function on + /// the `Subscriber` that this `Dispatch` forwards to. + /// + /// [`Event`]: ::event::Event + #[inline] + pub fn event(&self, event: &Event) { + self.subscriber.event(event) + } + + /// Records that a [`Span`] has been entered. + /// + /// This calls the [`enter`](::Subscriber::enter) function on the + /// `Subscriber` that this `Dispatch` forwards to. + /// + /// [`Span`]: ::span::Span + #[inline] + pub fn enter(&self, span: &Span) { + self.subscriber.enter(span) + } + + /// Records that a [`Span`] has been exited. + /// + /// This calls the [`exit`](::Subscriber::exit) function on the `Subscriber` + /// that this `Dispatch` forwards to. + /// + /// [`Span`]: ::span::Span + #[inline] + pub fn exit(&self, span: &Span) { + self.subscriber.exit(span) + } + + /// Notifies the subscriber that a [`Span`] has been cloned. + /// + /// This function is guaranteed to only be called with span IDs that were + /// returned by this `Dispatch`'s `new_span` function. + /// + /// This calls the [`clone_span`](::Subscriber::clone_span) function on + /// the `Subscriber` that this `Dispatch` forwards to. + /// + /// [`Span`]: ::span::Span + #[inline] + pub fn clone_span(&self, id: &Span) -> Span { + self.subscriber.clone_span(&id) + } + + /// Notifies the subscriber that a [`Span`] handle with the given [`Id`] has + /// been dropped. + /// + /// This function is guaranteed to only be called with span IDs that were + /// returned by this `Dispatch`'s `new_span` function. + /// + /// This calls the [`drop_span`](::Subscriber::drop_span) function on + /// the `Subscriber` that this `Dispatch` forwards to. + /// + /// [`Span`]: ::span::Span + #[inline] + pub fn drop_span(&self, id: Span) { + self.subscriber.drop_span(id) + } +} + +impl fmt::Debug for Dispatch { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + f.pad("Dispatch(...)") + } +} + +impl From for Dispatch +where + S: Subscriber + Send + Sync + 'static, +{ + #[inline] + fn from(subscriber: S) -> Self { + Dispatch::new(subscriber) + } +} + +struct NoSubscriber; +impl Subscriber for NoSubscriber { + #[inline] + fn register_callsite(&self, _: &Metadata) -> subscriber::Interest { + subscriber::Interest::never() + } + + fn new_span(&self, _meta: &Metadata, _vals: &field::ValueSet) -> Span { + Span::from_u64(0) + } + + fn event(&self, _event: &Event) {} + + fn record(&self, _span: &Span, _values: &field::ValueSet) {} + + fn record_follows_from(&self, _span: &Span, _follows: &Span) {} + + #[inline] + fn enabled(&self, _metadata: &Metadata) -> bool { + false + } + + fn enter(&self, _span: &Span) {} + fn exit(&self, _span: &Span) {} +} + +impl Registrar { + pub(crate) fn try_register(&self, metadata: &Metadata) -> Option { + self.0.upgrade().map(|s| s.register_callsite(metadata)) + } +} diff --git a/tokio-trace-core/src/event.rs b/tokio-trace-core/src/event.rs new file mode 100644 index 0000000000..e3c868b161 --- /dev/null +++ b/tokio-trace-core/src/event.rs @@ -0,0 +1,55 @@ +//! Events represent single points in time during the execution of a program. +use {field, Metadata}; + +/// `Event`s represent single points in time where something occurred during the +/// execution of a program. +/// +/// An `Event` can be compared to a log record in unstructured logging, but with +/// two key differences: +/// - `Event`s exist _within the context of a [`Span`]_. Unlike log lines, they +/// may be located within the trace tree, allowing visibility into the +/// _temporal_ context in which the event occurred, as well as the source +/// code location. +/// - Like spans, `Event`s have structured key-value data known as _fields_, +/// which may include textual message. In general, a majority of the data +/// associated with an event should be in the event's fields rather than in +/// the textual message, as the fields are more structed. +/// +/// [`Span`]: ::span::Span +#[derive(Debug)] +pub struct Event<'a> { + fields: &'a field::ValueSet<'a>, + metadata: &'a Metadata<'a>, +} + +impl<'a> Event<'a> { + /// Constructs a new `Event` with the specified metadata and set of values, + /// and observes it with the current subscriber. + #[inline] + pub fn observe(metadata: &'a Metadata<'a>, fields: &'a field::ValueSet) { + let event = Event { metadata, fields }; + ::dispatcher::with(|current| { + current.event(&event); + }); + } + + /// Records all the fields on this `Event` with the specified [recorder]. + /// + /// [recorder]: ::field::Record + #[inline] + pub fn record(&self, recorder: &mut field::Record) { + self.fields.record(recorder); + } + + /// Returns a reference to the set of values on this `Event`. + pub fn fields(&self) -> field::Iter { + self.fields.field_set().iter() + } + + /// Returns [metadata] describing this `Event`. + /// + /// [metadata]: ::metadata::Metadata + pub fn metadata(&self) -> &Metadata { + self.metadata + } +} diff --git a/tokio-trace-core/src/field.rs b/tokio-trace-core/src/field.rs new file mode 100644 index 0000000000..3a366e423a --- /dev/null +++ b/tokio-trace-core/src/field.rs @@ -0,0 +1,740 @@ +//! `Span` and `Event` key-value data. +//! +//! Spans and events may be annotated with key-value data, referred to as known +//! as _fields_. These fields consist of a mapping from a key (corresponding to +//! a `&str` but represented internally as an array index) to a `Value`. +//! +//! # `Value`s and `Subscriber`s +//! +//! `Subscriber`s consume `Value`s as fields attached to `Span`s or `Event`s. +//! The set of field keys on a given `Span` or is defined on its `Metadata`. +//! When a `Span` is created, it provides a `ValueSet` to the `Subscriber`'s +//! [`new_span`] method, containing any fields whose values were provided when +//! the span was created; and may call the `Subscriber`'s [`record`] method +//! with additional `ValueSet`s if values are added for more of its fields. +//! Similarly, the [`Event`] type passed to the subscriber's [`event`] method +//! will contain any fields attached to each event. +//! +//! `tokio_trace` represents values as either one of a set of Rust primitives +//! (`i64`, `u64`, `bool`, and `&str`) or using a `fmt::Display` or `fmt::Debug` +//! implementation. The `record_` trait functions on the `Subscriber` trait +//! allow `Subscriber` implementations to provide type-specific behaviour for +//! consuming values of each type. +//! +//! Instances of the `Record` trait are provided by `Subscriber`s to record the +//! values attached to `Span`s and `Event`. This trait represents the behavior +//! used to record values of various types. For example, we might record +//! integers by incrementing counters for their field names, rather than printing +//! them. +//! +//! [`new_span`]: ::subscriber::Subscriber::new_span +//! [`record`]: ::subscriber::Subscriber::record +//! [`Event`]: ::event::Event +//! [`event`]: ::subscriber::Subscriber::event +use callsite; +use std::{ + borrow::Borrow, + fmt, + hash::{Hash, Hasher}, + ops::Range, +}; + +/// An opaque key allowing _O_(1) access to a field in a `Span`'s key-value +/// data. +/// +/// As keys are defined by the _metadata_ of a span, rather than by an +/// individual instance of a span, a key may be used to access the same field +/// across all instances of a given span with the same metadata. Thus, when a +/// subscriber observes a new span, it need only access a field by name _once_, +/// and use the key for that name for all other accesses. +#[derive(Debug)] +pub struct Field { + i: usize, + fields: FieldSet, +} + +/// Describes the fields present on a span. +// TODO: When `const fn` is stable, make this type's fields private. +pub struct FieldSet { + /// The names of each field on the described span. + /// + /// **Warning**: The fields on this type are currently `pub` because it must be able + /// to be constructed statically by macros. However, when `const fn`s are + /// available on stable Rust, this will no longer be necessary. Thus, these + /// fields are *not* considered stable public API, and they may change + /// warning. Do not rely on any fields on `FieldSet`! + #[doc(hidden)] + pub names: &'static [&'static str], + /// The callsite where the described span originates. + /// + /// **Warning**: The fields on this type are currently `pub` because it must be able + /// to be constructed statically by macros. However, when `const fn`s are + /// available on stable Rust, this will no longer be necessary. Thus, these + /// fields are *not* considered stable public API, and they may change + /// warning. Do not rely on any fields on `FieldSet`! + #[doc(hidden)] + pub callsite: callsite::Identifier, +} + +/// A set of fields and values for a span. +pub struct ValueSet<'a> { + values: &'a [(&'a Field, Option<&'a (Value + 'a)>)], + fields: &'a FieldSet, +} + +/// An iterator over a set of fields. +#[derive(Debug)] +pub struct Iter { + idxs: Range, + fields: FieldSet, +} + +/// Records typed values. +/// +/// An instance of `Record` ("a recorder") represents the logic necessary to +/// record field values of various types. When an implementor of [`Value`] is +/// [recorded], it calls the appropriate method on the provided recorder to +/// indicate the type that value should be recorded as. +/// +/// When a [`Subscriber`] implementation [records an `Event`] or a +/// [set of `Value`s added to a `Span`], it can pass an `&mut Record` to the +/// `record` method on the provided [`ValueSet`] or [`Event`]. This recorder +/// will then be used to record all the field-value pairs present on that +/// `Event` or `ValueSet`. +/// +/// # Examples +/// +/// A simple recorder that writes to a string might be implemented like so: +/// ``` +/// # extern crate tokio_trace_core as tokio_trace; +/// use std::fmt::{self, Write}; +/// use tokio_trace::field::{Value, Record, Field}; +/// # fn main() { +/// pub struct StringRecorder<'a> { +/// string: &'a mut String, +/// } +/// +/// impl<'a> Record for StringRecorder<'a> { +/// fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { +/// write!(self.string, "{} = {:?}; ", field.name(), value).unwrap(); +/// } +/// } +/// # } +/// ``` +/// This recorder will format each recorded value using `fmt::Debug`, and +/// append the field name and formatted value to the provided string, +/// regardless of the type of the recorded value. When all the values have +/// been recorded, the `StringRecorder` may be dropped, allowing the string +/// to be printed or stored in some other data structure. +/// +/// The `Record` trait provides default implementations for `record_i64`, +/// `record_u64`, `record_bool`, and `record_str` which simply forward the +/// recorded value to `record_debug`. Thus, `record_debug` is the only method +/// which a `Record` implementation *must* implement. However, recorders may +/// override the default implementations of these functions in order to +/// implement type-specific behavior. +/// +/// Additionally, when a recorder recieves a value of a type it does not care +/// about, it is free to ignore those values completely. For example, a +/// recorder which only records numeric data might look like this: +/// +/// ``` +/// # extern crate tokio_trace_core as tokio_trace; +/// # use std::fmt::{self, Write}; +/// # use tokio_trace::field::{Value, Record, Field}; +/// # fn main() { +/// pub struct SumRecorder { +/// sum: i64, +/// } +/// +/// impl Record for SumRecorder { +/// fn record_i64(&mut self, _field: &Field, value: i64) { +/// self.sum += value; +/// } +/// +/// fn record_u64(&mut self, _field: &Field, value: u64) { +/// self.sum += value as i64; +/// } +/// +/// fn record_debug(&mut self, _field: &Field, _value: &fmt::Debug) { +/// // Do nothing +/// } +/// } +/// # } +/// ``` +/// +/// This recorder (which is probably not particularly useful) keeps a running +/// sum of all the numeric values it records, and ignores all other values. A +/// more practical example of recording typed values is presented in +/// `examples/counters.rs`, which demonstrates a very simple metrics system +/// implemented using `tokio-trace`. +/// +/// [`Value`]: ::field::Value +/// [recorded]: ::field::Value::record +/// [`Subscriber`]: ::subscriber::Subscriber +/// [records an `Event`]: ::subscriber::Subscriber::event +/// [set of `Value`s added to a `Span`]: ::subscriber::Subscriber::record +/// [`Event`]: ::event::Event +/// [`ValueSet`]: ::field::ValueSet +pub trait Record { + /// Record a signed 64-bit integer value. + fn record_i64(&mut self, field: &Field, value: i64) { + self.record_debug(field, &value) + } + + /// Record an umsigned 64-bit integer value. + fn record_u64(&mut self, field: &Field, value: u64) { + self.record_debug(field, &value) + } + + /// Record a boolean value. + fn record_bool(&mut self, field: &Field, value: bool) { + self.record_debug(field, &value) + } + + /// Record a string value. + fn record_str(&mut self, field: &Field, value: &str) { + self.record_debug(field, &value) + } + + /// Record a value implementing `fmt::Debug`. + fn record_debug(&mut self, field: &Field, value: &fmt::Debug); +} + +/// A field value of an erased type. +/// +/// Implementors of `Value` may call the appropriate typed recording methods on +/// the [recorder] passed to their `record` method in order to indicate how +/// their data should be recorded. +/// +/// [recorder]: ::field::Record +pub trait Value: ::sealed::Sealed { + /// Records this value with the given `Recorder`. + fn record(&self, key: &Field, recorder: &mut Record); +} + +/// A `Value` which serializes as a string using `fmt::Display`. +#[derive(Debug, Clone)] +pub struct DisplayValue(T); + +/// A `Value` which serializes as a string using `fmt::Debug`. +#[derive(Debug, Clone)] +pub struct DebugValue(T); + +/// Marker trait implemented by arrays which are of valid length to +/// construct a `ValueSet`. +/// +/// `ValueSet`s may only be constructed from arrays containing 32 or fewer +/// elements, to ensure the array is small enough to always be allocated on the +/// stack. This trait is only implemented by arrays of an appropriate length, +/// ensuring that the correct size arrays are used at compile-time. +pub trait ValidLen<'a>: ::sealed::Sealed + Borrow<[(&'a Field, Option<&'a (Value + 'a)>)]> {} + +/// Wraps a type implementing `fmt::Display` as a `Value` that can be +/// recorded using its `Display` implementation. +pub fn display(t: T) -> DisplayValue +where + T: fmt::Display, +{ + DisplayValue(t) +} + +/// Wraps a type implementing `fmt::Debug` as a `Value` that can be +/// recorded using its `Debug` implementation. +pub fn debug(t: T) -> DebugValue +where + T: fmt::Debug, +{ + DebugValue(t) +} + +// ===== impl Record ===== + +impl<'a, 'b> Record for fmt::DebugStruct<'a, 'b> { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.field(field.name(), value); + } +} + +impl<'a, 'b> Record for fmt::DebugMap<'a, 'b> { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.entry(&format_args!("{}", field), value); + } +} + +impl Record for F +where + F: FnMut(&Field, &fmt::Debug), +{ + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + (self)(field, value) + } +} + +// ===== impl Value ===== + +macro_rules! impl_values { + ( $( $record:ident( $( $whatever:tt)+ ) ),+ ) => { + $( + impl_value!{ $record( $( $whatever )+ ) } + )+ + } +} +macro_rules! impl_value { + ( $record:ident( $( $value_ty:ty ),+ ) ) => { + $( + impl $crate::sealed::Sealed for $value_ty {} + impl $crate::field::Value for $value_ty { + fn record( + &self, + key: &$crate::field::Field, + recorder: &mut $crate::field::Record, + ) { + recorder.$record(key, *self) + } + } + )+ + }; + ( $record:ident( $( $value_ty:ty ),+ as $as_ty:ty) ) => { + $( + impl $crate::sealed::Sealed for $value_ty {} + impl Value for $value_ty { + fn record( + &self, + key: &$crate::field::Field, + recorder: &mut $crate::field::Record, + ) { + recorder.$record(key, *self as $as_ty) + } + } + )+ + }; +} + +// ===== impl Value ===== + +impl_values! { + record_u64(u64), + record_u64(usize, u32, u16 as u64), + record_i64(i64), + record_i64(isize, i32, i16, i8 as i64), + record_bool(bool) +} + +impl ::sealed::Sealed for str {} + +impl Value for str { + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_str(key, &self) + } +} + +impl<'a, T: ?Sized> ::sealed::Sealed for &'a T where T: Value + ::sealed::Sealed + 'a {} + +impl<'a, T: ?Sized> Value for &'a T +where + T: Value + 'a, +{ + fn record(&self, key: &Field, recorder: &mut Record) { + (*self).record(key, recorder) + } +} + +impl<'a> ::sealed::Sealed for fmt::Arguments<'a> {} + +impl<'a> Value for fmt::Arguments<'a> { + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_debug(key, self) + } +} + +// ===== impl DisplayValue ===== + +impl ::sealed::Sealed for DisplayValue {} + +impl Value for DisplayValue +where + T: fmt::Display, +{ + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_debug(key, &format_args!("{}", self.0)) + } +} + +// ===== impl DebugValue ===== + +impl ::sealed::Sealed for DebugValue {} + +impl Value for DebugValue +where + T: fmt::Debug, +{ + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_debug(key, &self.0) + } +} + +// ===== impl Field ===== + +impl Field { + /// Returns an [`Identifier`](::metadata::Identifier) that uniquely + /// identifies the callsite that defines the field this key refers to. + #[inline] + pub fn callsite(&self) -> callsite::Identifier { + self.fields.callsite() + } + + /// Returns a string representing the name of the field. + pub fn name(&self) -> &'static str { + self.fields.names[self.i] + } +} + +impl fmt::Display for Field { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + f.pad(self.name()) + } +} + +impl AsRef for Field { + fn as_ref(&self) -> &str { + self.name() + } +} + +impl PartialEq for Field { + fn eq(&self, other: &Self) -> bool { + self.callsite() == other.callsite() && self.i == other.i + } +} + +impl Eq for Field {} + +impl Hash for Field { + fn hash(&self, state: &mut H) + where + H: Hasher, + { + self.callsite().hash(state); + self.i.hash(state); + } +} + +impl Clone for Field { + fn clone(&self) -> Self { + Field { + i: self.i, + fields: FieldSet { + names: self.fields.names, + callsite: self.fields.callsite(), + }, + } + } +} + +// ===== impl FieldSet ===== + +impl FieldSet { + pub(crate) fn callsite(&self) -> callsite::Identifier { + callsite::Identifier(self.callsite.0) + } + + /// Returns the [`Field`](::field::Field) named `name`, or `None` if no such + /// field exists. + pub fn field(&self, name: &Q) -> Option + where + Q: Borrow, + { + let name = &name.borrow(); + self.names.iter().position(|f| f == name).map(|i| Field { + i, + fields: FieldSet { + names: self.names, + callsite: self.callsite(), + }, + }) + } + + /// Returns `true` if `self` contains the given `field`. + /// + /// **Note**: If `field` shares a name with a field in this `FieldSet`, but + /// was created by a `FieldSet` with a different callsite, this `FieldSet` + /// does _not_ contain it. This is so that if two separate span callsites + /// define a field named "foo", the `Field` corresponding to "foo" for each + /// of those callsites are not equivalent. + pub fn contains(&self, field: &Field) -> bool { + field.callsite() == self.callsite() && field.i <= self.len() + } + + /// Returns an iterator over the `Field`s in this `FieldSet`. + pub fn iter(&self) -> Iter { + let idxs = 0..self.len(); + Iter { + idxs, + fields: FieldSet { + names: self.names, + callsite: self.callsite(), + }, + } + } + + /// Returns a new `ValueSet` with entries for this `FieldSet`'s values. + /// + /// Note that a `ValueSet` may not be constructed with arrays of over 32 + /// elements. + #[doc(hidden)] + pub fn value_set<'v, V>(&'v self, values: &'v V) -> ValueSet<'v> + where + V: ValidLen<'v>, + { + ValueSet { + fields: self, + values: &values.borrow()[..], + } + } + + /// Returns the number of fields in this `FieldSet`. + #[inline] + pub fn len(&self) -> usize { + self.names.len() + } +} + +impl<'a> IntoIterator for &'a FieldSet { + type IntoIter = Iter; + type Item = Field; + #[inline] + fn into_iter(self) -> Self::IntoIter { + self.iter() + } +} + +impl fmt::Debug for FieldSet { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + f.debug_struct("FieldSet") + .field("names", &self.names) + .field("callsite", &self.callsite) + .finish() + } +} + +// ===== impl Iter ===== + +impl Iterator for Iter { + type Item = Field; + fn next(&mut self) -> Option { + let i = self.idxs.next()?; + Some(Field { + i, + fields: FieldSet { + names: self.fields.names, + callsite: self.fields.callsite(), + }, + }) + } +} + +// ===== impl ValueSet ===== + +impl<'a> ValueSet<'a> { + /// Returns an [`Identifier`](::metadata::Identifier) that uniquely + /// identifies the callsite that defines the fields this `ValueSet` refers to. + #[inline] + pub fn callsite(&self) -> callsite::Identifier { + self.fields.callsite() + } + + /// Records all the fields in this `ValueSet` with the provided [recorder]. + /// + /// [recorder]: ::field::Record + pub fn record(&self, recorder: &mut Record) { + let my_callsite = self.callsite(); + for (field, value) in self.values { + if field.callsite() != my_callsite { + continue; + } + if let Some(value) = value { + value.record(field, recorder); + } + } + } + + /// Returns `true` if this `ValueSet` contains a value for the given `Field`. + pub fn contains(&self, field: &Field) -> bool { + field.callsite() == self.callsite() + && self + .values + .iter() + .any(|(key, val)| *key == field && val.is_some()) + } + + /// Returns true if this `ValueSet` contains _no_ values. + pub fn is_empty(&self) -> bool { + let my_callsite = self.callsite(); + self.values + .iter() + .all(|(key, val)| val.is_none() || key.callsite() != my_callsite) + } + + pub(crate) fn field_set(&self) -> &FieldSet { + self.fields + } +} + +impl<'a> fmt::Debug for ValueSet<'a> { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + self.values + .iter() + .fold(&mut f.debug_struct("ValueSet"), |dbg, (key, v)| { + if let Some(val) = v { + val.record(key, dbg); + } + dbg + }) + .finish() + } +} + +// ===== impl ValidLen ===== + +macro_rules! impl_valid_len { + ( $( $len:tt ),+ ) => { + $( + impl<'a> ::sealed::Sealed for + [(&'a Field, Option<&'a (Value + 'a)>); $len] {} + impl<'a> ValidLen<'a> for + [(&'a Field, Option<&'a (Value + 'a)>); $len] {} + )+ + } +} + +impl_valid_len! { + 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, + 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32 +} + +#[cfg(test)] +mod test { + use super::*; + use {Level, Metadata}; + + struct TestCallsite1; + static TEST_CALLSITE_1: TestCallsite1 = TestCallsite1; + static TEST_META_1: Metadata<'static> = metadata! { + name: "field_test1", + target: module_path!(), + level: Level::INFO, + fields: &["foo", "bar", "baz"], + callsite: &TEST_CALLSITE_1, + }; + + impl ::callsite::Callsite for TestCallsite1 { + fn add_interest(&self, _: ::subscriber::Interest) {} + fn clear_interest(&self) {} + + fn metadata(&self) -> &Metadata { + &TEST_META_1 + } + } + + struct TestCallsite2; + static TEST_CALLSITE_2: TestCallsite2 = TestCallsite2; + static TEST_META_2: Metadata<'static> = metadata! { + name: "field_test2", + target: module_path!(), + level: Level::INFO, + fields: &["foo", "bar", "baz"], + callsite: &TEST_CALLSITE_2, + }; + + impl ::callsite::Callsite for TestCallsite2 { + fn add_interest(&self, _: ::subscriber::Interest) {} + fn clear_interest(&self) {} + + fn metadata(&self) -> &Metadata { + &TEST_META_2 + } + } + + #[test] + fn value_set_with_no_values_is_empty() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), None), + (&fields.field("bar").unwrap(), None), + (&fields.field("baz").unwrap(), None), + ]; + let valueset = fields.value_set(values); + assert!(valueset.is_empty()); + } + + #[test] + fn empty_value_set_is_empty() { + let fields = TEST_META_1.fields(); + let valueset = fields.value_set(&[]); + assert!(valueset.is_empty()); + } + + #[test] + fn value_sets_with_fields_from_other_callsites_are_empty() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), Some(&1 as &Value)), + (&fields.field("bar").unwrap(), Some(&2 as &Value)), + (&fields.field("baz").unwrap(), Some(&3 as &Value)), + ]; + let valueset = TEST_META_2.fields().value_set(values); + assert!(valueset.is_empty()) + } + + #[test] + fn sparse_value_sets_are_not_empty() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), None), + (&fields.field("bar").unwrap(), Some(&57 as &Value)), + (&fields.field("baz").unwrap(), None), + ]; + let valueset = fields.value_set(values); + assert!(!valueset.is_empty()); + } + + #[test] + fn fields_from_other_callsets_are_skipped() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), None), + ( + &TEST_META_2.fields().field("bar").unwrap(), + Some(&57 as &Value), + ), + (&fields.field("baz").unwrap(), None), + ]; + + struct MyRecorder; + impl Record for MyRecorder { + fn record_debug(&mut self, field: &Field, _: &::std::fmt::Debug) { + assert_eq!(field.callsite(), TEST_META_1.callsite()) + } + } + let valueset = fields.value_set(values); + valueset.record(&mut MyRecorder); + } + + #[test] + fn record_debug_fn() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), Some(&1 as &Value)), + (&fields.field("bar").unwrap(), Some(&2 as &Value)), + (&fields.field("baz").unwrap(), Some(&3 as &Value)), + ]; + let valueset = fields.value_set(values); + let mut result = String::new(); + valueset.record(&mut |_: &Field, value: &fmt::Debug| { + use std::fmt::Write; + write!(&mut result, "{:?}", value).unwrap(); + }); + assert_eq!(result, "123".to_owned()); + } +} diff --git a/tokio-trace-core/src/lib.rs b/tokio-trace-core/src/lib.rs new file mode 100644 index 0000000000..965aaea238 --- /dev/null +++ b/tokio-trace-core/src/lib.rs @@ -0,0 +1,177 @@ +#![deny(missing_debug_implementations, missing_docs, unreachable_pub)] +#![cfg_attr(test, deny(warnings))] + +//! Core primitives for `tokio-trace`. +//! +//! `tokio-trace` is a framework for instrumenting Rust programs to collect +//! structured, event-based diagnostic information. This crate defines the core +//! primitives of `tokio-trace`. +//! +//! The crate provides: +//! +//! * [`Span`] identifies a span within the execution of a program. +//! +//! * [`Subscriber`], the trait implemented to collect trace data. +//! +//! * [`Metadata`] and [`Callsite`] provide information describing `Span`s. +//! +//! * [`Field`] and [`FieldSet`] describe and access the structured data attached to +//! a `Span`. +//! +//! * [`Dispatch`] allows span events to be dispatched to `Subscriber`s. +//! +//! In addition, it defines the global callsite registry and per-thread current +//! dispatcher which other components of the tracing system rely on. +//! +//! Application authors will typically not use this crate directly. Instead, +//! they will use the `tokio-trace` crate, which provides a much more +//! fully-featured API. However, this crate's API will change very infrequently, +//! so it may be used when dependencies must be very stable. +//! +//! [`Span`]: ::span::Span +//! [`Subscriber`]: ::subscriber::Subscriber +//! [`Metadata`]: ::metadata::Metadata +//! [`Callsite`]: ::callsite::Callsite +//! [`Field`]: ::field::Field +//! [`FieldSet`]: ::field::FieldSet +//! [`Dispatch`]: ::dispatcher::Dispatch +//! + +#[macro_use] +extern crate lazy_static; + +/// Statically constructs an [`Identifier`] for the provided [`Callsite`]. +/// +/// This may be used in contexts, such as static initializers, where the +/// [`Callsite::id`] function is not currently usable. +/// +/// For example: +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace_core; +/// use tokio_trace_core::callsite; +/// # use tokio_trace_core::{Metadata, subscriber::Interest}; +/// # fn main() { +/// pub struct MyCallsite { +/// // ... +/// } +/// impl callsite::Callsite for MyCallsite { +/// # fn add_interest(&self, _: Interest) { unimplemented!() } +/// # fn clear_interest(&self) {} +/// # fn metadata(&self) -> &Metadata { unimplemented!() } +/// // ... +/// } +/// +/// static CALLSITE: MyCallsite = MyCallsite { +/// // ... +/// }; +/// +/// static CALLSITE_ID: callsite::Identifier = identify_callsite!(&CALLSITE); +/// # } +/// ``` +/// +/// [`Identifier`]: ::callsite::Identifier +/// [`Callsite`]: ::callsite::Callsite +/// [`Callsite::id`]: ::callsite::Callsite::id +#[macro_export] +macro_rules! identify_callsite { + ($callsite:expr) => { + $crate::callsite::Identifier($callsite) + }; +} + +/// Statically constructs new span [metadata]. +/// +/// This may be used in contexts, such as static initializers, where the +/// [`Metadata::new`] function is not currently usable. +/// +/// /// For example: +/// ```rust +/// # #[macro_use] +/// # extern crate tokio_trace_core; +/// # use tokio_trace_core::{callsite::Callsite, subscriber::Interest}; +/// use tokio_trace_core::{Metadata, Level}; +/// # fn main() { +/// # pub struct MyCallsite { } +/// # impl Callsite for MyCallsite { +/// # fn add_interest(&self, _: Interest) { unimplemented!() } +/// # fn clear_interest(&self) {} +/// # fn metadata(&self) -> &Metadata { unimplemented!() } +/// # } +/// # +/// static FOO_CALLSITE: MyCallsite = MyCallsite { +/// // ... +/// }; +/// +/// static FOO_METADATA: Metadata = metadata!{ +/// name: "foo", +/// target: module_path!(), +/// level: Level::DEBUG, +/// fields: &["bar", "baz"], +/// callsite: &FOO_CALLSITE, +/// }; +/// # } +/// ``` +/// +/// [metadata]: ::metadata::Metadata +/// [`Metadata::new`]: ::metadata::Metadata::new +#[macro_export] +macro_rules! metadata { + ( + name: $name:expr, + target: $target:expr, + level: $level:expr, + fields: $fields:expr, + callsite: $callsite:expr + ) => { + metadata! { + name: $name, + target: $target, + level: $level, + fields: $fields, + callsite: $callsite, + } + }; + ( + name: $name:expr, + target: $target:expr, + level: $level:expr, + fields: $fields:expr, + callsite: $callsite:expr, + ) => { + $crate::metadata::Metadata { + name: $name, + target: $target, + level: $level, + file: Some(file!()), + line: Some(line!()), + module_path: Some(module_path!()), + fields: $crate::field::FieldSet { + names: $fields, + callsite: identify_callsite!($callsite), + }, + } + }; +} + +pub mod callsite; +pub mod dispatcher; +pub mod event; +pub mod field; +pub mod metadata; +pub mod span; +pub mod subscriber; + +pub use self::{ + callsite::Callsite, + dispatcher::Dispatch, + event::Event, + field::Field, + metadata::{Level, Metadata}, + span::Span, + subscriber::{Interest, Subscriber}, +}; + +mod sealed { + pub trait Sealed {} +} diff --git a/tokio-trace-core/src/metadata.rs b/tokio-trace-core/src/metadata.rs new file mode 100644 index 0000000000..154e537507 --- /dev/null +++ b/tokio-trace-core/src/metadata.rs @@ -0,0 +1,272 @@ +//! Metadata describing trace data. +use super::{ + callsite::{self, Callsite}, + field, +}; +use std::fmt; + +/// Metadata describing a [`Span`]. +/// +/// This includes the source code location where the span occurred, the names of +/// its fields, et cetera. +/// +/// Metadata is used by [`Subscriber`]s when filtering spans and events, and it +/// may also be used as part of their data payload. +/// +/// When created by the `event!` or `span!` macro, the metadata describing a +/// particular event or span is constructed statically and exists as a single +/// static instance. Thus, the overhead of creating the metadata is +/// _significantly_ lower than that of creating the actual span. Therefore, +/// filtering is based on metadata, rather than on the constructed span. +/// +/// **Note**: Although instances of `Metadata` cannot be compared directly, they +/// provide a method [`Metadata::id()`] which returns an an opaque [callsite +/// identifier] which uniquely identifies the callsite where the metadata +/// originated. This can be used for determining if two Metadata correspond to +/// the same callsite. +/// +/// [`Span`]: ::span::Span +/// [`Subscriber`]: ::Subscriber +/// [`Metadata::id()`]: ::metadata::Metadata::id +/// [callsite identifier]: ::callsite::Identifier +// TODO: When `const fn` is stable, make this type's fields private. +pub struct Metadata<'a> { + /// The name of the span described by this metadata. + /// + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Metadata`. When + /// constructing new `Metadata`, use the `metadata!` macro or the + /// `Metadata::new` constructor instead! + #[doc(hidden)] + pub name: &'static str, + + /// The part of the system that the span that this metadata describes + /// occurred in. + /// + /// Typically, this is the module path, but alternate targets may be set + /// when spans or events are constructed. + /// + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Metadata`. When + /// constructing new `Metadata`, use the `metadata!` macro or the + /// `Metadata::new` constructor instead! + #[doc(hidden)] + pub target: &'a str, + + /// The level of verbosity of the described span. + /// + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Metadata`. When + /// constructing new `Metadata`, use the `metadata!` macro or the + /// `Metadata::new` constructor instead! + #[doc(hidden)] + pub level: Level, + + /// The name of the Rust module where the span occurred, or `None` if this + /// could not be determined. + /// + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Metadata`. When + /// constructing new `Metadata`, use the `metadata!` macro or the + /// `Metadata::new` constructor instead! + #[doc(hidden)] + pub module_path: Option<&'a str>, + + /// The name of the source code file where the span occurred, or `None` if + /// this could not be determined. + /// + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Metadata`. When + /// constructing new `Metadata`, use the `metadata!` macro or the + /// `Metadata::new` constructor instead! + #[doc(hidden)] + pub file: Option<&'a str>, + + /// The line number in the source code file where the span occurred, or + /// `None` if this could not be determined. + /// + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Metadata`. When + /// constructing new `Metadata`, use the `metadata!` macro or the + /// `Metadata::new` constructor instead! + #[doc(hidden)] + pub line: Option, + + /// The names of the key-value fields attached to the described span or + /// event. + /// + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Metadata`. When + /// constructing new `Metadata`, use the `metadata!` macro or the + /// `Metadata::new` constructor instead! + #[doc(hidden)] + pub fields: field::FieldSet, +} + +/// Describes the level of verbosity of a `Span`. +#[derive(Clone, Debug, Eq, PartialEq, Ord, PartialOrd)] +pub struct Level(LevelInner); + +// ===== impl Metadata ===== + +impl<'a> Metadata<'a> { + /// Construct new metadata for a span, with a name, target, level, field + /// names, and optional source code location. + pub fn new( + name: &'static str, + target: &'a str, + level: Level, + module_path: Option<&'a str>, + file: Option<&'a str>, + line: Option, + field_names: &'static [&'static str], + callsite: &'static Callsite, + ) -> Self { + Metadata { + name, + target, + level, + module_path, + file, + line, + fields: field::FieldSet { + names: field_names, + callsite: callsite::Identifier(callsite), + }, + } + } + + /// Returns the set of fields on the described span. + pub fn fields(&self) -> &field::FieldSet { + &self.fields + } + + /// Returns the level of verbosity of the described span. + pub fn level(&self) -> &Level { + &self.level + } + + /// Returns the name of the span. + pub fn name(&self) -> &'static str { + self.name + } + + /// Returns a string describing the part of the system where the span or + /// event that this metadata describes occurred. + /// + /// Typically, this is the module path, but alternate targets may be set + /// when spans or events are constructed. + pub fn target(&self) -> &'a str { + self.target + } + + /// Returns the path to the Rust module where the span occurred, or + /// `None` if the module path is unknown. + pub fn module_path(&self) -> Option<&'a str> { + self.module_path + } + + /// Returns the name of the source code file where the span + /// occurred, or `None` if the file is unknown + pub fn file(&self) -> Option<&'a str> { + self.file + } + + /// Returns the line number in the source code file where the span + /// occurred, or `None` if the line number is unknown. + pub fn line(&self) -> Option { + self.line + } + + /// Returns an opaque `Identifier` that uniquely identifies the callsite + /// this `Metadata` originated from. + #[inline] + pub fn callsite(&self) -> callsite::Identifier { + self.fields.callsite() + } +} + +impl<'a> fmt::Debug for Metadata<'a> { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + f.debug_struct("Metadata") + .field("name", &self.name) + .field("target", &self.target) + .field("level", &self.level) + .field("module_path", &self.module_path) + .field("file", &self.file) + .field("line", &self.line) + .field("field_names", &self.fields) + .finish() + } +} + +// ===== impl Level ===== + +impl Level { + /// The "error" level. + /// + /// Designates very serious errors. + pub const ERROR: Level = Level(LevelInner::Error); + /// The "warn" level. + /// + /// Designates hazardous situations. + pub const WARN: Level = Level(LevelInner::Warn); + /// The "info" level. + /// + /// Designates useful information. + pub const INFO: Level = Level(LevelInner::Info); + /// The "debug" level. + /// + /// Designates lower priority information. + pub const DEBUG: Level = Level(LevelInner::Debug); + /// The "trace" level. + /// + /// Designates very low priority, often extremely verbose, information. + pub const TRACE: Level = Level(LevelInner::Trace); +} + +#[repr(usize)] +#[derive(Copy, Clone, Debug, Eq, PartialEq, Hash, Ord, PartialOrd)] +enum LevelInner { + /// The "error" level. + /// + /// Designates very serious errors. + Error = 1, + /// The "warn" level. + /// + /// Designates hazardous situations. + Warn, + /// The "info" level. + /// + /// Designates useful information. + Info, + /// The "debug" level. + /// + /// Designates lower priority information. + Debug, + /// The "trace" level. + /// + /// Designates very low priority, often extremely verbose, information. + Trace, +} diff --git a/tokio-trace-core/src/span.rs b/tokio-trace-core/src/span.rs new file mode 100644 index 0000000000..1ad66a5542 --- /dev/null +++ b/tokio-trace-core/src/span.rs @@ -0,0 +1,22 @@ +//! Spans represent periods of time in the execution of a program. + +/// Identifies a span within the context of a process. +/// +/// Span IDs are used primarily to determine of two handles refer to the same +/// span, without requiring the comparison of the span's fields. +/// +/// They are generated by [`Subscriber`](::Subscriber)s for each span as it is +/// created, through the [`new_id`](::Subscriber::new_span_id) trait +/// method. See the documentation for that method for more information on span +/// ID generation. +#[derive(Clone, Debug, PartialEq, Eq, Hash)] +pub struct Span(u64); + +// ===== impl Id ===== + +impl Span { + /// Constructs a new span ID from the given `u64`. + pub fn from_u64(u: u64) -> Self { + Span(u) + } +} diff --git a/tokio-trace-core/src/subscriber.rs b/tokio-trace-core/src/subscriber.rs new file mode 100644 index 0000000000..8d381e6fa0 --- /dev/null +++ b/tokio-trace-core/src/subscriber.rs @@ -0,0 +1,318 @@ +//! Subscribers collect and record trace data. +use {field, Event, Metadata, Span}; + +/// Trait representing the functions required to collect trace data. +/// +/// Crates that provide implementations of methods for collecting or recording +/// trace data should implement the `Subscriber` interface. This trait is +/// intended to represent fundamental primitives for collecting trace events and +/// spans — other libraries may offer utility functions and types to make +/// subscriber implementations more modular or improve the ergonomics of writing +/// subscribers. +/// +/// A subscriber is responsible for the following: +/// - Registering new spans as they are created, and providing them with span +/// IDs. Implicitly, this means the subscriber may determine the strategy for +/// determining span equality. +/// - Recording the attachment of field values and follows-from annotations to +/// spans. +/// - Filtering spans and events, and determining when those filters must be +/// invalidated. +/// - Observing spans as they are entered, exited, and closed, and events as +/// they occur. +/// +/// When a span is entered or exited, the subscriber is provided only with the +/// [ID] with which it tagged that span when it was created. This means +/// that it is up to the subscriber to determine whether and how span _data_ — +/// the fields and metadata describing the span — should be stored. The +/// [`new_span`] function is called when a new span is created, and at that +/// point, the subscriber _may_ choose to store the associated data if it will +/// be referenced again. However, if the data has already been recorded and will +/// not be needed by the implementations of `enter` and `exit`, the subscriber +/// may freely discard that data without allocating space to store it. +/// +/// [ID]: ::span::Span +/// [`new_span`]: ::Span::new_span +pub trait Subscriber { + // === Span registry methods ============================================== + + /// Registers a new callsite with this subscriber, returning whether or not + /// the subscriber is interested in being notified about the callsite. + /// + /// By default, this function assumes that the subscriber's filter + /// represents an unchanging view of its interest in the callsite. However, + /// if this is not the case, subscribers may override this function to + /// indicate different interests, or to implement behaviour that should run + /// once for every callsite. + /// + /// This function is guaranteed to be called exactly once per callsite on + /// every active subscriber. The subscriber may store the keys to fields it + /// cares in order to reduce the cost of accessing fields by name, + /// preallocate storage for that callsite, or perform any other actions it + /// wishes to perform once for each callsite. + /// + /// The subscriber should then return an [`Interest`](Interest), indicating + /// whether it is interested in being notified about that callsite in the + /// future. This may be `Always` indicating that the subscriber always + /// wishes to be notified about the callsite, and its filter need not be + /// re-evaluated; `Sometimes`, indicating that the subscriber may sometimes + /// care about the callsite but not always (such as when sampling), or + /// `Never`, indicating that the subscriber never wishes to be notified about + /// that callsite. If all active subscribers return `Never`, a callsite will + /// never be enabled unless a new subscriber expresses interest in it. + /// + /// `Subscriber`s which require their filters to be run every time an event + /// occurs or a span is entered/exited should return `Interest::Sometimes`. + /// + /// For example, suppose a sampling subscriber is implemented by + /// incrementing a counter every time `enabled` is called and only returning + /// `true` when the counter is divisible by a specified sampling rate. If + /// that subscriber returns `Interest::Always` from `register_callsite`, then + /// the filter will not be re-evaluated once it has been applied to a given + /// set of metadata. Thus, the counter will not be incremented, and the span + /// or event that correspands to the metadata will never be `enabled`. + /// + /// Similarly, if a `Subscriber` has a filtering strategy that can be + /// changed dynamically at runtime, it would need to re-evaluate that filter + /// if the cached results have changed. + /// + /// A subscriber which manages fanout to multiple other subscribers + /// should proxy this decision to all of its child subscribers, + /// returning `Interest::Never` only if _all_ such children return + /// `Interest::Never`. If the set of subscribers to which spans are + /// broadcast may change dynamically, the subscriber should also never + /// return `Interest::Never`, as a new subscriber may be added that _is_ + /// interested. + /// + /// **Note**: If a subscriber returns `Interest::Never` for a particular + /// callsite, it _may_ still see spans and events originating from that + /// callsite, if another subscriber expressed interest in it. + /// + /// [metadata]: ::Metadata + /// [`enabled`]: ::Subscriber::enabled + fn register_callsite(&self, metadata: &Metadata) -> Interest { + match self.enabled(metadata) { + true => Interest::always(), + false => Interest::never(), + } + } + + /// Returns true if a span with the specified [metadata] would be + /// recorded. + /// + /// This is used by the dispatcher to avoid allocating for span construction + /// if the span would be discarded anyway. + /// + /// [metadata]: ::Metadata + fn enabled(&self, metadata: &Metadata) -> bool; + + /// Record the construction of a new [`Span`], returning a new ID for the + /// span being constructed. + /// + /// The provided `ValueSet` contains any field values that were provided + /// when the span was created. The subscriber may pass a [recorder] to the + /// `ValueSet`'s [`record` method] to record these values. + /// + /// IDs are used to uniquely identify spans and events within the context of a + /// subscriber, so span equality will be based on the returned ID. Thus, if + /// the subscriber wishes for all spans with the same metadata to be + /// considered equal, it should return the same ID every time it is given a + /// particular set of metadata. Similarly, if it wishes for two separate + /// instances of a span with the same metadata to *not* be equal, it should + /// return a distinct ID every time this function is called, regardless of + /// the metadata. + /// + /// [`Span`]: ::span::Span + /// [recorder]: ::field::Record + /// [`record` method]: ::field::ValueSet::record + fn new_span(&self, metadata: &Metadata, values: &field::ValueSet) -> Span; + + // === Notification methods =============================================== + + /// Record a set of values on a span. + /// + /// The subscriber is expected to provide a [recorder] to the `ValueSet`'s + /// [`record` method] in order to record the added values. + /// + /// [recorder]: ::field::Record + /// [`record` method]: ::field::ValueSet::record + fn record(&self, span: &Span, values: &field::ValueSet); + + /// Adds an indication that `span` follows from the span with the id + /// `follows`. + /// + /// This relationship differs somewhat from the parent-child relationship: a + /// span may have any number of prior spans, rather than a single one; and + /// spans are not considered to be executing _inside_ of the spans they + /// follow from. This means that a span may close even if subsequent spans + /// that follow from it are still open, and time spent inside of a + /// subsequent span should not be included in the time its precedents were + /// executing. This is used to model causal relationships such as when a + /// single future spawns several related background tasks, et cetera. + /// + /// If the subscriber has spans corresponding to the given IDs, it should + /// record this relationship in whatever way it deems necessary. Otherwise, + /// if one or both of the given span IDs do not correspond to spans that the + /// subscriber knows about, or if a cyclical relationship would be created + /// (i.e., some span _a_ which proceeds some other span _b_ may not also + /// follow from _b_), it may silently do nothing. + fn record_follows_from(&self, span: &Span, follows: &Span); + + /// Records that an [`Event`] has occurred. + /// + /// The provided `Event` struct contains any field values attached to the + /// event. The subscriber may pass a [recorder] to the `Event`'s + /// [`record` method] to record these values. + /// + /// [`Event`]: ::event::Event + /// [recorder]: ::field::Record + /// [`record` method]: ::event::Event::record + fn event(&self, event: &Event); + + /// Records that a [`Span`] has been entered. + /// + /// When entering a span, this method is called to notify the subscriber + /// that the span has been entered. The subscriber is provided with the ID + /// of the entered span, and should update any internal state tracking the + /// current span accordingly. + /// + /// [`Span`]: ::span::Span + fn enter(&self, span: &Span); + + /// Records that a [`Span`] has been exited. + /// + /// When entering a span, this method is called to notify the subscriber + /// that the span has been exited. The subscriber is provided with the ID + /// of the exited span, and should update any internal state tracking the + /// current span accordingly. + /// + /// Exiting a span does not imply that the span will not be re-entered. + /// + /// [`Span`]: ::span::Span + fn exit(&self, span: &Span); + + /// Notifies the subscriber that a [`Span`] has been cloned. + /// + /// This function is guaranteed to only be called with span IDs that were + /// returned by this subscriber's `new_span` function. + /// + /// Note that the default implementation of this function this is just the + /// identity function, passing through the identifier. However, it can be + /// used in conjunction with [`drop_span`] to track the number of handles + /// capable of `enter`ing a span. When all the handles have been dropped + /// (i.e., `drop_span` has been called one more time than `clone_span` for a + /// given ID), the subscriber may assume that the span will not be entered + /// again. It is then free to deallocate storage for data associated with + /// that span, write data from that span to IO, and so on. + /// + /// For more unsafe situations, however, if `id` is itself a pointer of some + /// kind this can be used as a hook to "clone" the pointer, depending on + /// what that means for the specified pointer. + /// + /// [`Span`]: ::span::Span, + /// [`drop_span`]: ::subscriber::Subscriber::drop_span + fn clone_span(&self, id: &Span) -> Span { + id.clone() + } + + /// Notifies the subscriber that a [`Span`] has been dropped. + /// + /// This function is guaranteed to only be called with span IDs that were + /// returned by this subscriber's `new_span` function. + /// + /// It's guaranteed that if this function has been called once more than the + /// number of times `clone_span` was called with the same `id`, then no more + /// `Span`s using that `id` exist. This means that it can be used in + /// conjunction with [`clone_span`] to track the number of handles + /// capable of `enter`ing a span. When all the handles have been dropped + /// (i.e., `drop_span` has been called one more time than `clone_span` for a + /// given ID), the subscriber may assume that the span will not be entered + /// again. It is then free to deallocate storage for data associated with + /// that span, write data from that span to IO, and so on. + /// + /// **Note**: since this function is called when spans are dropped, + /// implementations should ensure that they are unwind-safe. Panicking from + /// inside of a `drop_span` function may cause a double panic, if the span + /// was dropped due to a thread unwinding. + /// + /// [`Span`]: ::span::Span, + /// [`drop_span`]: ::subscriber::Subscriber::drop_span + fn drop_span(&self, id: Span) { + let _ = id; + } +} + +/// Indicates a `Subscriber`'s interest in a particular callsite. +#[derive(Clone, Debug)] +pub struct Interest(InterestKind); + +#[derive(Copy, Clone, Debug, Eq, PartialEq, Ord, PartialOrd)] +enum InterestKind { + Never = 0, + Sometimes = 1, + Always = 2, +} + +impl Interest { + /// Returns an `Interest` indicating that the subscriber is never interested + /// in being notified about a callsite. + /// + /// If all active subscribers are `never()` interested in a callsite, it will + /// be completely disabled unless a new subscriber becomes active. + #[inline] + pub fn never() -> Self { + Interest(InterestKind::Never) + } + + /// Returns an `Interest` indicating the subscriber is sometimes interested + /// in being notified about a callsite. + /// + /// If all active subscribers are `sometimes` or `never` interested in a + /// callsite, the currently active subscriber will be asked to filter that + /// callsite every time it creates a span. This will be the case until a + /// subscriber expresses that it is `always` interested in the callsite. + #[inline] + pub fn sometimes() -> Self { + Interest(InterestKind::Sometimes) + } + + /// Returns an `Interest` indicating the subscriber is always interested in + /// being notified about a callsite. + /// + /// If any subscriber expresses that it is `always()` interested in a given + /// callsite, then the callsite will always be enabled. + #[inline] + pub fn always() -> Self { + Interest(InterestKind::Always) + } + + /// Returns `true` if the subscriber is never interested in being notified + /// about this callsite. + #[inline] + pub fn is_never(&self) -> bool { + match self.0 { + InterestKind::Never => true, + _ => false, + } + } + + /// Returns `true` if the subscriber is sometimes interested in being notified + /// about this callsite. + #[inline] + pub fn is_sometimes(&self) -> bool { + match self.0 { + InterestKind::Sometimes => true, + _ => false, + } + } + + /// Returns `true` if the subscriber is always interested in being notified + /// about this callsite. + #[inline] + pub fn is_always(&self) -> bool { + match self.0 { + InterestKind::Always => true, + _ => false, + } + } +}