diff --git a/Cargo.toml b/Cargo.toml index 97f3b128bb1..5811bd276b3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -38,6 +38,8 @@ members = [ "tokio-timer", "tokio-tcp", "tokio-tls", + "tokio-trace", + "tokio-trace/tokio-trace-core", "tokio-udp", "tokio-uds", ] diff --git a/tokio-trace/Cargo.toml b/tokio-trace/Cargo.toml new file mode 100644 index 00000000000..b66ac607a74 --- /dev/null +++ b/tokio-trace/Cargo.toml @@ -0,0 +1,30 @@ +[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/tokio-trace/LICENSE b/tokio-trace/LICENSE new file mode 100644 index 00000000000..cdb28b4b56a --- /dev/null +++ b/tokio-trace/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/README.md b/tokio-trace/README.md new file mode 100644 index 00000000000..a21905141e7 --- /dev/null +++ b/tokio-trace/README.md @@ -0,0 +1,168 @@ +# tokio-trace + +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. + +## 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 + +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/benches/no_subscriber.rs b/tokio-trace/benches/no_subscriber.rs new file mode 100644 index 00000000000..84a5bc428a2 --- /dev/null +++ b/tokio-trace/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/tokio-trace/benches/subscriber.rs b/tokio-trace/benches/subscriber.rs new file mode 100644 index 00000000000..fd60979b1b1 --- /dev/null +++ b/tokio-trace/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/tokio-trace/examples/counters.rs b/tokio-trace/examples/counters.rs new file mode 100644 index 00000000000..9c617c4c6dc --- /dev/null +++ b/tokio-trace/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/tokio-trace/examples/sloggish/main.rs b/tokio-trace/examples/sloggish/main.rs new file mode 100644 index 00000000000..fb26a83503c --- /dev/null +++ b/tokio-trace/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/tokio-trace/examples/sloggish/sloggish_subscriber.rs b/tokio-trace/examples/sloggish/sloggish_subscriber.rs new file mode 100644 index 00000000000..4a93f93533a --- /dev/null +++ b/tokio-trace/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/tokio-trace/src/field.rs b/tokio-trace/src/field.rs new file mode 100644 index 00000000000..9f8fdad9788 --- /dev/null +++ b/tokio-trace/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/tokio-trace/src/lib.rs b/tokio-trace/src/lib.rs new file mode 100644 index 00000000000..631d0e3b678 --- /dev/null +++ b/tokio-trace/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/tokio-trace/src/span.rs b/tokio-trace/src/span.rs new file mode 100644 index 00000000000..af098bdc415 --- /dev/null +++ b/tokio-trace/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/tokio-trace/src/subscriber.rs b/tokio-trace/src/subscriber.rs new file mode 100644 index 00000000000..e1c8c457bfa --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/dispatcher.rs b/tokio-trace/tests/dispatcher.rs new file mode 100644 index 00000000000..816968f2bc6 --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/event.rs b/tokio-trace/tests/event.rs new file mode 100644 index 00000000000..e5fcd81812f --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/macros.rs b/tokio-trace/tests/macros.rs new file mode 100644 index 00000000000..002b787c68e --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/span.rs b/tokio-trace/tests/span.rs new file mode 100644 index 00000000000..45c192982bf --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/subscriber.rs b/tokio-trace/tests/subscriber.rs new file mode 100644 index 00000000000..21a8a480bd7 --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/support/event.rs b/tokio-trace/tests/support/event.rs new file mode 100644 index 00000000000..5dbe2b235f3 --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/support/field.rs b/tokio-trace/tests/support/field.rs new file mode 100644 index 00000000000..578452b0b96 --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/support/metadata.rs b/tokio-trace/tests/support/metadata.rs new file mode 100644 index 00000000000..502c04e44e8 --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/support/mod.rs b/tokio-trace/tests/support/mod.rs new file mode 100644 index 00000000000..b8f78cc7a29 --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/support/span.rs b/tokio-trace/tests/support/span.rs new file mode 100644 index 00000000000..e1e738780c3 --- /dev/null +++ b/tokio-trace/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/tokio-trace/tests/support/subscriber.rs b/tokio-trace/tests/support/subscriber.rs new file mode 100644 index 00000000000..662e0cc3979 --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/Cargo.toml b/tokio-trace/tokio-trace-core/Cargo.toml new file mode 100644 index 00000000000..7c36498f0c2 --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/LICENSE b/tokio-trace/tokio-trace-core/LICENSE new file mode 100644 index 00000000000..cdb28b4b56a --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/README.md b/tokio-trace/tokio-trace-core/README.md new file mode 100644 index 00000000000..9fab7429714 --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/callsite.rs b/tokio-trace/tokio-trace-core/src/callsite.rs new file mode 100644 index 00000000000..4b45aa0e43c --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/dispatcher.rs b/tokio-trace/tokio-trace-core/src/dispatcher.rs new file mode 100644 index 00000000000..05d35fdf39d --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/event.rs b/tokio-trace/tokio-trace-core/src/event.rs new file mode 100644 index 00000000000..e3c868b161a --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/field.rs b/tokio-trace/tokio-trace-core/src/field.rs new file mode 100644 index 00000000000..3a366e423a8 --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/lib.rs b/tokio-trace/tokio-trace-core/src/lib.rs new file mode 100644 index 00000000000..965aaea2381 --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/metadata.rs b/tokio-trace/tokio-trace-core/src/metadata.rs new file mode 100644 index 00000000000..154e5375079 --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/span.rs b/tokio-trace/tokio-trace-core/src/span.rs new file mode 100644 index 00000000000..1ad66a5542b --- /dev/null +++ b/tokio-trace/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/tokio-trace-core/src/subscriber.rs b/tokio-trace/tokio-trace-core/src/subscriber.rs new file mode 100644 index 00000000000..8d381e6fa0b --- /dev/null +++ b/tokio-trace/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, + } + } +}