diff --git a/tokio-trace/benches/subscriber.rs b/tokio-trace/benches/subscriber.rs index 5e2c22d0141..fd60979b1b1 100644 --- a/tokio-trace/benches/subscriber.rs +++ b/tokio-trace/benches/subscriber.rs @@ -5,23 +5,30 @@ extern crate tokio_trace; extern crate test; use test::Bencher; -use std::sync::Mutex; -use tokio_trace::{field, span, Id, Metadata}; +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) -> Id { - let _ = span; + fn new_span(&self, span: &Metadata, values: &field::ValueSet) -> Id { + let _ = (span, values); Id::from_u64(0) } - fn record_debug(&self, span: &Id, field: &field::Field, value: &::std::fmt::Debug) { - let _ = (span, field, value); + fn event(&self, event: &Event) { + let _ = event; + } + + fn record(&self, span: &Id, values: &field::ValueSet) { + let _ = (span, values); } - fn add_follows_from(&self, span: &Id, follows: Id) { + fn record_follows_from(&self, span: &Id, follows: &Id) { let _ = (span, follows); } @@ -40,19 +47,35 @@ impl tokio_trace::Subscriber for EnabledSubscriber { } /// Simulates a subscriber that records span data. -struct Record(Mutex>); +struct RecordingSubscriber(Mutex); -impl tokio_trace::Subscriber for Record { - fn new_span(&self, span: &Metadata) -> Id { - *self.0.lock().unwrap() = Some(span.name().to_string()); +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_debug(&self, _span: &Id, _field: &field::Field, value: &::std::fmt::Debug) { - *self.0.lock().unwrap() = Some(format!("{:?}", value)); + 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 add_follows_from(&self, span: &Id, follows: Id) { + fn record_follows_from(&self, span: &Id, follows: &Id) { let _ = (span, follows); } @@ -107,7 +130,8 @@ fn span_with_fields(b: &mut Bencher) { #[bench] fn span_with_fields_record(b: &mut Bencher) { - tokio_trace::subscriber::with_default(Record(Mutex::new(None)), || { + let subscriber = RecordingSubscriber(Mutex::new(String::from(""))); + tokio_trace::subscriber::with_default(subscriber, || { b.iter(|| { span!( "span", diff --git a/tokio-trace/examples/counters.rs b/tokio-trace/examples/counters.rs index 7304cd857b3..9c617c4c6dc 100644 --- a/tokio-trace/examples/counters.rs +++ b/tokio-trace/examples/counters.rs @@ -2,16 +2,18 @@ extern crate tokio_trace; use tokio_trace::{ - field, span, + field::{self, Field, Record}, + span, subscriber::{self, Subscriber}, - Id, Metadata, + Event, Id, Metadata, }; use std::{ collections::HashMap, + fmt, sync::{ atomic::{AtomicUsize, Ordering}, - Arc, RwLock, + Arc, RwLock, RwLockReadGuard, }, }; @@ -23,8 +25,42 @@ struct CounterSubscriber { 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: &tokio_trace::Metadata) -> subscriber::Interest { + fn register_callsite(&self, meta: &Metadata) -> subscriber::Interest { let mut interest = subscriber::Interest::never(); for key in meta.fields() { let name = key.name(); @@ -41,35 +77,24 @@ impl Subscriber for CounterSubscriber { interest } - fn new_span(&self, _new_span: &Metadata) -> Id { + 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 add_follows_from(&self, _span: &Id, _follows: Id) { + fn record_follows_from(&self, _span: &Id, _follows: &Id) { // unimplemented } - fn record_i64(&self, _id: &Id, field: &field::Field, value: i64) { - let registry = self.counters.0.read().unwrap(); - if let Some(counter) = registry.get(field.name()) { - if value > 0 { - counter.fetch_add(value as usize, Ordering::Release); - } else { - counter.fetch_sub(value as usize, Ordering::Release); - } - }; + fn record(&self, _: &Id, values: &field::ValueSet) { + values.record(&mut self.recorder()) } - fn record_u64(&self, _id: &Id, field: &field::Field, value: u64) { - let registry = self.counters.0.read().unwrap(); - if let Some(counter) = registry.get(field.name()) { - counter.fetch_add(value as usize, Ordering::Release); - }; + fn event(&self, event: &Event) { + event.record(&mut self.recorder()) } - fn record_debug(&self, _id: &Id, _field: &field::Field, _value: &::std::fmt::Debug) {} - fn enabled(&self, metadata: &Metadata) -> bool { metadata.fields().iter().any(|f| f.name().contains("count")) } diff --git a/tokio-trace/examples/sloggish/sloggish_subscriber.rs b/tokio-trace/examples/sloggish/sloggish_subscriber.rs index 720f92a5fb8..4a93f93533a 100644 --- a/tokio-trace/examples/sloggish/sloggish_subscriber.rs +++ b/tokio-trace/examples/sloggish/sloggish_subscriber.rs @@ -13,7 +13,11 @@ extern crate ansi_term; extern crate humantime; use self::ansi_term::{Color, Style}; -use super::tokio_trace::{self, Id, Level, Subscriber}; +use super::tokio_trace::{ + self, + field::{Field, Record}, + Id, Level, Subscriber, +}; use std::{ cell::RefCell, @@ -70,73 +74,83 @@ pub struct SloggishSubscriber { stderr: io::Stderr, stack: Mutex>, spans: Mutex>, - events: Mutex>, ids: AtomicUsize, } struct Span { parent: Option, - kvs: Vec<(String, String)>, + kvs: Vec<(&'static str, String)>, } -struct Event { - level: tokio_trace::Level, - target: String, - message: String, - kvs: Vec<(String, String)>, +struct Event<'a> { + stderr: io::StderrLock<'a>, + comma: bool, } -struct ColorLevel(Level); +struct ColorLevel<'a>(&'a Level); -impl fmt::Display for ColorLevel { +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"), + &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) -> Self { - Self { + fn new( + parent: Option, + _meta: &tokio_trace::Metadata, + values: &tokio_trace::field::ValueSet, + ) -> Self { + let mut span = Self { parent, kvs: Vec::new(), - } - } - - fn record(&mut self, key: &tokio_trace::field::Field, value: fmt::Arguments) { - // TODO: shouldn't have to alloc the key... - let k = key.name().to_owned(); - let v = fmt::format(value); - self.kvs.push((k, v)); + }; + values.record(&mut span); + span } } -impl Event { - fn new(meta: &tokio_trace::Metadata) -> Self { - Self { - target: meta.target.to_owned(), - level: meta.level.clone(), - message: String::new(), - kvs: Vec::new(), - } +impl Record for Span { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.kvs.push((field.name(), format!("{:?}", value))) } +} - fn record(&mut self, key: &tokio_trace::field::Field, value: fmt::Arguments) { - if key.name() == "message" { - self.message = fmt::format(value); - return; +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; } - - // TODO: shouldn't have to alloc the key... - let k = key.name().to_owned(); - let v = fmt::format(value); - self.kvs.push((k, v)); } } @@ -148,7 +162,6 @@ impl SloggishSubscriber { stderr: io::stderr(), stack: Mutex::new(vec![]), spans: Mutex::new(HashMap::new()), - events: Mutex::new(HashMap::new()), ids: AtomicUsize::new(0), } } @@ -193,39 +206,26 @@ impl Subscriber for SloggishSubscriber { true } - fn new_span(&self, span: &tokio_trace::Metadata) -> tokio_trace::Id { + 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); - if span.name.contains("event") { - self.events - .lock() - .unwrap() - .insert(id.clone(), Event::new(span)); - } else { - self.spans - .lock() - .unwrap() - .insert(id.clone(), Span::new(self.current.id(), span)); - } + let span = Span::new(self.current.id(), span, values); + self.spans.lock().unwrap().insert(id.clone(), span); id } - fn record_debug( - &self, - span: &tokio_trace::Id, - name: &tokio_trace::field::Field, - value: &fmt::Debug, - ) { - if let Some(event) = self.events.lock().expect("mutex poisoned!").get_mut(span) { - return event.record(name, format_args!("{:?}", value)); - }; + 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) { - span.record(name, format_args!("{:?}", value)) + values.record(span); } } - fn add_follows_from(&self, _span: &tokio_trace::Id, _follows: tokio_trace::Id) { + fn record_follows_from(&self, _span: &tokio_trace::Id, _follows: &tokio_trace::Id) { // unimplemented } @@ -261,34 +261,33 @@ impl Subscriber for SloggishSubscriber { } } + 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) { - if let Some(event) = self.events.lock().expect("mutex poisoned").remove(&id) { - 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} {message}", - timestamp = humantime::format_rfc3339_seconds(SystemTime::now()), - level = ColorLevel(event.level), - target = &event.target, - message = Style::new().bold().paint(event.message), - ) - .unwrap(); - self.print_kvs( - &mut stderr, - event.kvs.iter().map(|&(ref k, ref v)| (k, v)), - ", ", - ) - .unwrap(); - write!(&mut stderr, "\n").unwrap(); - } + 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 index 2c3b3e6b113..9f8fdad9788 100644 --- a/tokio-trace/src/field.rs +++ b/tokio-trace/src/field.rs @@ -1,7 +1,6 @@ //! Structured data associated with `Span`s and `Event`s. pub use tokio_trace_core::field::*; -use std::fmt; use Metadata; /// Trait implemented to allow a type to be used as a field key. @@ -19,120 +18,6 @@ pub trait AsField: ::sealed::Sealed { fn as_field(&self, metadata: &Metadata) -> Option; } -// If, in the future, there's a valid use-case for user-defined `Record` -// implementations, consider unsealing this trait. -pub trait Record: ::sealed::Sealed { - /// Record a signed 64-bit integer value. - fn record_i64(&mut self, field: &Q, value: i64) - where - Q: AsField; - - /// Record an umsigned 64-bit integer value. - fn record_u64(&mut self, field: &Q, value: u64) - where - Q: AsField; - - /// Record a boolean value. - fn record_bool(&mut self, field: &Q, value: bool) - where - Q: AsField; - - /// Record a string value. - fn record_str(&mut self, field: &Q, value: &str) - where - Q: AsField; - - /// Record a value implementing `fmt::Debug`. - fn record_debug(&mut self, field: &Q, value: &fmt::Debug) - where - Q: AsField; -} - -/// A field value of an erased type. -/// -/// Implementors of `Value` may call the appropriate typed recording methods on -/// the `Subscriber` passed to `record` in order to indicate how their data -/// should be recorded. -pub trait Value { - /// Records this value with the given `Subscriber`. - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record; -} - -/// A `Value` which serializes as a string using `fmt::Display`. -#[derive(Clone)] -pub struct DisplayValue(T); - -/// A `Value` which serializes as a string using `fmt::Debug`. -#[derive(Clone)] -pub struct DebugValue(T); - -/// 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) -} - -// ===== impl Value ===== - -/// 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) -} - -macro_rules! impl_values { - ( $( $record:ident( $( $whatever:tt)+ ) ),+ ) => { - $( - impl_value!{ $record( $( $whatever )+ ) } - )+ - } -} -macro_rules! impl_value { - ( $record:ident( $( $value_ty:ty ),+ ) ) => { - $( - impl $crate::field::Value for $value_ty { - fn record( - &self, - key: &Q, - recorder: &mut R, - ) - where - Q: $crate::field::AsField, - R: $crate::field::Record, - { - recorder.$record(key, *self) - } - } - )+ - }; - ( $record:ident( $( $value_ty:ty ),+ as $as_ty:ty) ) => { - $( - impl Value for $value_ty { - fn record( - &self, - key: &Q, - recorder: &mut R, - ) - where - Q: $crate::field::AsField, - R: $crate::field::Record, - { - recorder.$record(key, *self as $as_ty) - } - } - )+ - }; -} - // ===== impl AsField ===== impl AsField for Field { @@ -167,66 +52,3 @@ impl AsField for str { impl ::sealed::Sealed for Field {} impl<'a> ::sealed::Sealed for &'a Field {} impl ::sealed::Sealed for str {} - -// ===== 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 Value for str { - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - recorder.record_str(key, &self) - } -} - -impl<'a, T: ?Sized> Value for &'a T -where - T: Value + 'a, -{ - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - (*self).record(key, recorder) - } -} - -// ===== impl DisplayValue ===== - -impl Value for DisplayValue -where - T: fmt::Display, -{ - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - recorder.record_debug(key, &format_args!("{}", self.0)) - } -} - -// ===== impl DebugValue ===== - -impl Value for DebugValue -where - T: fmt::Debug, -{ - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - recorder.record_debug(key, &self.0) - } -} diff --git a/tokio-trace/src/lib.rs b/tokio-trace/src/lib.rs index 8bd3025cee9..e6a3d27d982 100644 --- a/tokio-trace/src/lib.rs +++ b/tokio-trace/src/lib.rs @@ -247,11 +247,12 @@ //! #[macro_use] //! extern crate tokio_trace; //! # pub struct FooSubscriber; -//! # use tokio_trace::{span::Id, field::Field, Metadata}; +//! # use tokio_trace::{span::Id, Metadata, field::ValueSet}; //! # impl tokio_trace::Subscriber for FooSubscriber { -//! # fn new_span(&self, _: &Metadata) -> Id { Id::from_u64(0) } -//! # fn record_debug(&self, _: &Id, _: &Field, _: &::std::fmt::Debug) {} -//! # fn add_follows_from(&self, _: &Id, _: Id) {} +//! # 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) {} @@ -302,10 +303,11 @@ use tokio_trace_core::*; pub use self::{ dispatcher::Dispatch, + event::Event, field::Value, - span::{Event, Span}, + span::Span, subscriber::Subscriber, - tokio_trace_core::{dispatcher, Level, Metadata}, + tokio_trace_core::{dispatcher, event, Level, Metadata}, }; #[doc(hidden)] @@ -321,31 +323,30 @@ pub use self::{ #[doc(hidden)] #[macro_export] macro_rules! callsite { - (span: $name:expr, $( $field_name:ident ),*) => ({ - callsite!(@ + (name: $name:expr, fields: $( $field_name:ident ),* $(,)*) => ({ + callsite! { name: $name, target: module_path!(), level: $crate::Level::TRACE, - fields: &[ $(stringify!($field_name)),* ] - ) + fields: $( $field_name ),* + } }); - (event: $lvl:expr, $( $field_name:ident ),*) => - (callsite!(event: $lvl, target: module_path!(), $( $field_name ),* )); - (event: $lvl:expr, target: $target:expr, $( $field_name:ident ),*) => ({ - callsite!(@ - name: concat!("event at ", file!(), ":", line!()), - target: $target, + (name: $name:expr, level: $lvl:expr, fields: $( $field_name:ident ),* $(,)*) => ({ + callsite! { + name: $name, + target: module_path!(), level: $lvl, - fields: &[ "message", $(stringify!($field_name)),* ] - ) + fields: $( $field_name ),* + } }); - (@ + ( name: $name:expr, target: $target:expr, level: $lvl:expr, - fields: $field_names:expr + fields: $( $field_name:ident ),* + $(,)* ) => ({ - use std::sync::{Once, atomic::{ATOMIC_USIZE_INIT, AtomicUsize, Ordering}}; + use std::sync::{Once, atomic::{self, AtomicUsize, Ordering}}; use $crate::{callsite, Metadata, subscriber::Interest}; struct MyCallsite; static META: Metadata<'static> = { @@ -353,11 +354,14 @@ macro_rules! callsite { name: $name, target: $target, level: $lvl, - fields: $field_names, + fields: &[ $( stringify!($field_name) ),* ], callsite: &MyCallsite, } }; - static INTEREST: AtomicUsize = ATOMIC_USIZE_INIT; + // 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] @@ -444,37 +448,17 @@ macro_rules! span { ($name:expr) => { span!($name,) }; ($name:expr, $($k:ident $( = $val:expr )* ) ,*) => { { - #[allow(unused_imports)] - use $crate::{callsite, field::{Value, AsField}, Span}; + use $crate::{callsite, field::{Value, ValueSet, AsField}, Span}; use $crate::callsite::Callsite; - let callsite = callsite! { span: $name, $( $k ),* }; - let interest = callsite.interest(); - if interest.is_never() { - Span::new_disabled() + let callsite = callsite! { name: $name, fields: $( $k ),* }; + if is_enabled!(callsite) { + let meta = callsite.metadata(); + Span::new(meta, &valueset!(meta.fields(), $($k $( = $val)*),*)) } else { - let mut span = Span::new(interest, callsite.metadata()); - // Depending on how many fields are generated, this may or may - // not actually be used, but it doesn't make sense to repeat it. - #[allow(unused_variables, unused_mut)] { - if !span.is_disabled() { - let mut keys = callsite.metadata().fields().into_iter(); - $( - let key = keys.next() - .expect(concat!("metadata should define a key for '", stringify!($k), "'")); - span!(@ record: span, $k, &key, $($val)*); - )* - }; - } - span + Span::new_disabled() } } }; - (@ record: $span:expr, $k:expr, $i:expr, $val:expr) => ( - $span.record($i, &$val) - ); - (@ record: $span:expr, $k:expr, $i:expr,) => ( - // skip - ); } /// Constructs a new `Event`. @@ -501,96 +485,58 @@ macro_rules! span { /// 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. +/// +/// 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")) +/// #} +/// ``` #[macro_export] macro_rules! event { - (target: $target:expr, $lvl:expr, $( $k:ident $( = $val:expr )* ),+ ) => ( - event!(target: $target, $lvl, { $( $k $( = $val)* ),+ }) - ); - (target: $target:expr, $lvl:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ({ + (target: $target:expr, $lvl:expr, { $( $k:ident = $val:expr ),* $(,)*} )=> ({ { #[allow(unused_imports)] - use $crate::{callsite, Id, Subscriber, Event, field::{Value, AsField}}; + use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}}; use $crate::callsite::Callsite; - let callsite = callsite! { event: - $lvl, - target: - $target, $( $k ),* + let callsite = callsite! { + name: concat!("event ", file!(), ":", line!()), + target: $target, + level: $lvl, + fields: $( $k ),* }; - let interest = callsite.interest(); - if interest.is_never() { - Event::new_disabled() - } else { - let mut event = Event::new(callsite.interest(), callsite.metadata()); - // Depending on how many fields are generated, this may or may - // not actually be used, but it doesn't make sense to repeat it. - #[allow(unused_variables, unused_mut)] { - if !event.is_disabled() { - let mut keys = callsite.metadata().fields().into_iter(); - let msg_key = keys.next() - .expect("event metadata should define a key for the message"); - event.message(&msg_key, format_args!( $($arg)+ )); - $( - let key = keys.next() - .expect(concat!("metadata should define a key for '", stringify!($k), "'")); - event!(@ record: event, $k, &key, $($val)*); - )* - } - } - event + 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 )* ),* } ) => ({ - { - #[allow(unused_imports)] - use $crate::{callsite, Id, Subscriber, Event, field::{Value, AsField}}; - use $crate::callsite::Callsite; - let callsite = callsite! { event: - $lvl, - target: - $target, $( $k ),* - }; - let interest = callsite.interest(); - if interest.is_never() { - Event::new_disabled() - } else { - let mut event = Event::new(callsite.interest(), callsite.metadata()); - // Depending on how many fields are generated, this may or may - // not actually be used, but it doesn't make sense to repeat it. - #[allow(unused_variables, unused_mut)] { - if !event.is_disabled() { - let mut keys = callsite.metadata().fields().into_iter(); - let msg_key = keys.next() - .expect("event metadata should define a key for the message"); - $( - let key = keys.next() - .expect(concat!("metadata should define a key for '", stringify!($k), "'")); - event!(@ record: event, $k, &key, $($val)*); - )* - } - } - event - } - } + (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, $($arg:tt)+ ) => ( event!(target: $target, $lvl, { }, $($arg)+) ); - ( $lvl:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: module_path!(), $lvl, { $($k $( = $val)* ),* }, $($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 )* ),* ) => ( - 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)+) ); - (@ record: $ev:expr, $k:expr, $i:expr, $val:expr) => ( - $ev.record($i, &$val); - ); - (@ record: $ev:expr, $k:expr, $i:expr,) => ( - // skip - ); } /// Constructs an event at the trace level. @@ -620,7 +566,7 @@ macro_rules! event { /// /// trace!(position = field::debug(pos), origin_dist = field::debug(origin_dist)); /// trace!(target: "app_events", -/// { pos = field::debug(pos) }, +/// { 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" }); @@ -628,11 +574,11 @@ macro_rules! event { /// ``` #[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 @@ -642,11 +588,11 @@ macro_rules! trace { // 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)+)); @@ -675,20 +621,20 @@ macro_rules! trace { /// ``` #[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)+)); @@ -724,20 +670,20 @@ macro_rules! debug { /// ``` #[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)+)); @@ -770,20 +716,20 @@ macro_rules! info { /// ``` #[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)+)); @@ -811,26 +757,62 @@ macro_rules! warn { /// ``` #[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; diff --git a/tokio-trace/src/span.rs b/tokio-trace/src/span.rs index 02f38bbe111..ceae403770e 100644 --- a/tokio-trace/src/span.rs +++ b/tokio-trace/src/span.rs @@ -145,9 +145,7 @@ use std::{ }; use { dispatcher::{self, Dispatch}, - field, - subscriber::Interest, - Metadata, + field, Metadata, }; /// A handle representing a span, with the capability to enter the span if it @@ -171,28 +169,6 @@ pub struct Span<'a> { is_closed: bool, } -/// `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: -/// - Events exist _within the context of a [`Span`]_. Unlike log lines, they may -/// be located within the trace tree, allowing visibility into the context in -/// which the event occurred. -/// - Events have structured key-value data known as _fields_, as well as a -/// 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(PartialEq, Hash)] -pub struct Event<'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>, -} - /// 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 @@ -233,39 +209,32 @@ struct Entered<'a> { // ===== impl Span ===== impl<'a> Span<'a> { - /// Constructs a new `Span` originating from the given [`Callsite`]. + /// 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). + /// 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. /// - /// [`Callsite`]: ::callsite::Callsite + /// [metadata]: ::metadata::Metadata /// [`Subscriber`]: ::subscriber::Subscriber - /// [current span]: ::span::Span::current - /// [field values]: ::span::Span::record + /// [field values]: ::field::ValueSet /// [`follows_from`]: ::span::Span::follows_from #[inline] - pub fn new(interest: Interest, meta: &'a Metadata<'a>) -> Span<'a> { - if interest.is_never() { - return Self::new_disabled(); + 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(Enter::new(id, dispatch, meta)) + }); + Self { + inner, + is_closed: false, } - dispatcher::with(|dispatch| { - if interest.is_sometimes() && !dispatch.enabled(meta) { - return Span::new_disabled(); - } - let id = dispatch.new_span(meta); - let inner = Some(Enter::new(id, dispatch, meta)); - Self { - inner, - is_closed: false, - } - }) } /// Constructs a new disabled span. - #[inline] + #[inline(always)] pub fn new_disabled() -> Span<'a> { Span { inner: None, @@ -316,13 +285,24 @@ impl<'a> Span<'a> { } /// Records that the field described by `field` has the value `value`. - pub fn record(&mut self, field: &Q, value: &V) -> &mut Self + 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 { - value.record(field, inner); + let meta = inner.metadata(); + if let Some(field) = field.as_field(meta) { + inner.record(&meta.fields().value_set(&[(&field, Some(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 } @@ -366,7 +346,7 @@ impl<'a> Span<'a> { /// /// 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 { + pub fn follows_from(&self, from: &Id) -> &Self { if let Some(ref inner) = self.inner { inner.follows_from(from); } @@ -396,125 +376,6 @@ impl<'a> fmt::Debug for Span<'a> { } } -// ===== impl Event ===== - -impl<'a> Event<'a> { - /// Constructs a new `Event` originating from the given [`Callsite`]. - /// - /// The new span will be constructed by the currently-active [`Subscriber`], - /// with the [current span] as its parent (if one exists). - /// - /// After the event is constructed, [field values] and/or [`follows_from`] - /// annotations may be added to it. - /// - /// [`Callsite`]: ::callsite::Callsite - /// [`Subscriber`]: ::subscriber::Subscriber - /// [current span]: ::span::Span::current - /// [field values]: ::span::Evemt::record - /// [`follows_from`]: ::span::Event::follows_from - #[inline] - pub fn new(interest: Interest, meta: &'a Metadata<'a>) -> Self { - if interest.is_never() { - return Self::new_disabled(); - } - dispatcher::with(|dispatch| { - if interest.is_sometimes() && !dispatch.enabled(meta) { - return Self::new_disabled(); - } - let id = dispatch.new_span(meta); - let inner = Enter::new(id, dispatch, meta); - Self { inner: Some(inner) } - }) - } - - /// Returns a new disabled `Event`. - #[inline] - pub fn new_disabled() -> Self { - Self { - inner: None, - } - } - - /// Adds a formattable message describing the event that occurred. - pub fn message(&mut self, key: &field::Field, message: fmt::Arguments) -> &mut Self { - if let Some(ref mut inner) = self.inner { - inner.subscriber.record_debug(&inner.id, key, &message); - } - self - } - - /// 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 `Event` 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 { - value.record(field, inner); - } - self - } - - /// Returns `true` if this span was disabled by the subscriber and does not - /// exist. - pub fn is_disabled(&self) -> bool { - self.inner.is_none() - } - - /// Indicates that the span with the given ID has an indirect causal - /// relationship with this event. - /// - /// 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 event 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(Enter::id) - } - - /// Returns this span's `Metadata`, if it is enabled. - pub fn metadata(&self) -> Option<&'a Metadata<'a>> { - self.inner.as_ref().map(|inner| inner.metadata()) - } -} - // ===== impl Enter ===== impl<'a> Enter<'a> { @@ -552,8 +413,8 @@ impl<'a> Enter<'a> { /// 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.add_follows_from(&self.id, from) + fn follows_from(&self, from: &Id) { + self.subscriber.record_follows_from(&self.id, &from) } /// Returns the span's ID. @@ -566,29 +427,10 @@ impl<'a> Enter<'a> { self.meta } - /// Record a signed 64-bit integer value. - fn record_value_i64(&self, field: &field::Field, value: i64) { - self.subscriber.record_i64(&self.id, field, value) - } - - /// Record an unsigned 64-bit integer value. - fn record_value_u64(&self, field: &field::Field, value: u64) { - self.subscriber.record_u64(&self.id, field, value) - } - - /// Record a boolean value. - fn record_value_bool(&self, field: &field::Field, value: bool) { - self.subscriber.record_bool(&self.id, field, value) - } - - /// Record a string value. - fn record_value_str(&self, field: &field::Field, value: &str) { - self.subscriber.record_str(&self.id, field, value) - } - - /// Record a value implementing `fmt::Debug`. - fn record_value_debug(&self, field: &field::Field, value: &fmt::Debug) { - self.subscriber.record_debug(&self.id, field, value) + 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 { @@ -630,60 +472,6 @@ impl<'a> Clone for Enter<'a> { } } -impl<'a> ::sealed::Sealed for Enter<'a> {} - -impl<'a> field::Record for Enter<'a> { - #[inline] - fn record_i64(&mut self, field: &Q, value: i64) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_i64(&key, value); - } - } - - #[inline] - fn record_u64(&mut self, field: &Q, value: u64) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_u64(&key, value); - } - } - - #[inline] - fn record_bool(&mut self, field: &Q, value: bool) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_bool(&key, value); - } - } - - #[inline] - fn record_str(&mut self, field: &Q, value: &str) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_str(&key, value); - } - } - - #[inline] - fn record_debug(&mut self, field: &Q, value: &fmt::Debug) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_debug(&key, value); - } - } -} - // ===== impl Entered ===== impl<'a> Entered<'a> { 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/span.rs b/tokio-trace/tests/span.rs index 4460790ec96..f7764cf9f2d 100644 --- a/tokio-trace/tests/span.rs +++ b/tokio-trace/tests/span.rs @@ -4,7 +4,11 @@ mod support; use self::support::*; use std::thread; -use tokio_trace::{dispatcher, Dispatch, Level, Span}; +use tokio_trace::{ + dispatcher, + field::{debug, display}, + Dispatch, Level, Span, +}; #[test] fn closed_handle_cannot_be_entered() { @@ -146,7 +150,7 @@ fn dropping_a_span_calls_drop_span() { fn span_closes_after_event() { let (subscriber, handle) = subscriber::mock() .enter(span::mock().named("foo")) - .event() + .event(event::mock()) .exit(span::mock().named("foo")) .drop_span(span::mock().named("foo")) .done() @@ -164,7 +168,7 @@ fn span_closes_after_event() { fn new_span_after_event() { let (subscriber, handle) = subscriber::mock() .enter(span::mock().named("foo")) - .event() + .event(event::mock()) .exit(span::mock().named("foo")) .drop_span(span::mock().named("foo")) .enter(span::mock().named("bar")) @@ -185,7 +189,7 @@ fn new_span_after_event() { #[test] fn event_outside_of_span() { let (subscriber, handle) = subscriber::mock() - .event() + .event(event::mock()) .enter(span::mock().named("foo")) .exit(span::mock().named("foo")) .drop_span(span::mock().named("foo")) @@ -303,3 +307,152 @@ fn entering_a_closed_span_again_is_a_no_op() { 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(); +} 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 index 919f6af49aa..b8f78cc7a29 100644 --- a/tokio-trace/tests/support/mod.rs +++ b/tokio-trace/tests/support/mod.rs @@ -1,3 +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 index f72e59f12df..e1e738780c3 100644 --- a/tokio-trace/tests/support/span.rs +++ b/tokio-trace/tests/support/span.rs @@ -1,4 +1,5 @@ #![allow(missing_docs)] +use super::{field, metadata}; use std::fmt; /// A mock span. @@ -7,8 +8,13 @@ use std::fmt; /// `subscriber` module. #[derive(Debug, Default, Eq, PartialEq)] pub struct MockSpan { - pub name: Option<&'static str>, - // TODO: more + 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 { @@ -18,19 +24,86 @@ pub fn mock() -> MockSpan { } impl MockSpan { - pub fn named(mut self, name: &'static str) -> Self { - self.name = Some(name); - self + 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 + } } - // TODO: fields, etc + 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 { - match self.name { - Some(name) => write!(f, "a span named {:?}", name), - None => write!(f, "any span"), + 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 index 3b4c10b69a0..662e0cc3979 100644 --- a/tokio-trace/tests/support/subscriber.rs +++ b/tokio-trace/tests/support/subscriber.rs @@ -1,5 +1,9 @@ #![allow(missing_docs)] -use super::span::MockSpan; +use super::{ + event::MockEvent, + field as mock_field, + span::{MockSpan, NewSpan}, +}; use std::{ collections::{HashMap, VecDeque}, fmt, @@ -8,21 +12,17 @@ use std::{ Arc, Mutex, }, }; -use tokio_trace::{field, Id, Metadata, Subscriber}; - -#[derive(Debug, Eq, PartialEq)] -struct ExpectEvent { - // TODO: implement -} +use tokio_trace::{field, Event, Id, Metadata, Subscriber}; #[derive(Debug, Eq, PartialEq)] enum Expect { - #[allow(dead_code)] // TODO: implement! - Event(ExpectEvent), + Event(MockEvent), Enter(MockSpan), Exit(MockSpan), CloneSpan(MockSpan), DropSpan(MockSpan), + Record(MockSpan, mock_field::Expect), + NewSpan(NewSpan), Nothing, } @@ -58,9 +58,8 @@ impl bool> MockSubscriber { self } - pub fn event(mut self) -> Self { - // TODO: expect message/fields! - self.expected.push_back(Expect::Event(ExpectEvent {})); + pub fn event(mut self, event: MockEvent) -> Self { + self.expected.push_back(Expect::Event(event)); self } @@ -84,6 +83,22 @@ impl bool> MockSubscriber { 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, @@ -117,15 +132,47 @@ impl bool> Subscriber for Running { (self.filter)(meta) } - fn record_debug(&self, _span: &Id, _field: &field::Field, _value: &fmt::Debug) { - // TODO: it would be nice to be able to expect field values... + 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 add_follows_from(&self, _span: &Id, _follows: Id) { + 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) -> Id { + 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!( @@ -134,6 +181,23 @@ impl bool> Subscriber for Running { 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 { @@ -150,32 +214,12 @@ impl bool> Subscriber for Running { println!("enter: {}; id={:?};", span.name, id); match self.expected.lock().unwrap().pop_front() { None => {} - Some(Expect::Event(_)) => panic!( - "expected an event, but entered span {:?} instead", - span.name - ), Some(Expect::Enter(ref expected_span)) => { - if let Some(name) = expected_span.name { + if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - // TODO: expect fields } - Some(Expect::Exit(ref expected_span)) => panic!( - "expected to exit {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::CloneSpan(ref expected_span)) => panic!( - "expected to clone {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::DropSpan(ref expected_span)) => panic!( - "expected to drop {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::Nothing) => panic!( - "expected nothing else to happen, but entered span {:?}", - span.name, - ), + Some(ex) => ex.bad(format_args!("entered span {:?}", span.name)), } }; } @@ -188,31 +232,12 @@ impl bool> Subscriber for Running { println!("exit: {}; id={:?};", span.name, id); match self.expected.lock().unwrap().pop_front() { None => {} - Some(Expect::Event(_)) => { - panic!("expected an event, but exited span {:?} instead", span.name) - } - Some(Expect::Enter(ref expected_span)) => panic!( - "expected to enter {}, but exited span {:?} instead", - expected_span, span.name - ), Some(Expect::Exit(ref expected_span)) => { - if let Some(name) = expected_span.name { + if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - // TODO: expect fields } - Some(Expect::CloneSpan(ref expected_span)) => panic!( - "expected to clone {}, but exited span {:?} instead", - expected_span, span.name - ), - Some(Expect::DropSpan(ref expected_span)) => panic!( - "expected to drop {}, but exited span {:?} instead", - expected_span, span.name - ), - Some(Expect::Nothing) => panic!( - "expected nothing else to happen, but exited span {:?}", - span.name, - ), + Some(ex) => ex.bad(format_args!("exited span {:?}", span.name)), }; } @@ -228,7 +253,7 @@ impl bool> Subscriber for Running { } let mut expected = self.expected.lock().unwrap(); let was_expected = if let Some(Expect::CloneSpan(ref span)) = expected.front() { - assert_eq!(name, span.name); + assert_eq!(name, span.name()); true } else { false @@ -263,7 +288,7 @@ impl bool> Subscriber for Running { // 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); + assert_eq!(name, span.name()); } true } @@ -293,3 +318,20 @@ impl MockHandle { } } } + +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/src/callsite.rs b/tokio-trace/tokio-trace-core/src/callsite.rs index 1401e84089d..4b45aa0e43c 100644 --- a/tokio-trace/tokio-trace-core/src/callsite.rs +++ b/tokio-trace/tokio-trace-core/src/callsite.rs @@ -107,7 +107,7 @@ impl Eq for Identifier {} impl fmt::Debug for Identifier { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - f.pad("Identifier(...)") + write!(f, "Identifier({:p})", self.0) } } diff --git a/tokio-trace/tokio-trace-core/src/dispatcher.rs b/tokio-trace/tokio-trace-core/src/dispatcher.rs index 798d4375947..14ac3478079 100644 --- a/tokio-trace/tokio-trace-core/src/dispatcher.rs +++ b/tokio-trace/tokio-trace-core/src/dispatcher.rs @@ -2,7 +2,7 @@ use { callsite, field, subscriber::{self, Subscriber}, - Metadata, Span, + Event, Metadata, Span, }; use std::{ @@ -106,63 +106,27 @@ impl Dispatch { /// /// [`Span`]: ::span::Span #[inline] - pub fn new_span(&self, metadata: &Metadata) -> Span { - self.subscriber.new_span(metadata) + pub fn new_span(&self, metadata: &Metadata, values: &field::ValueSet) -> Span { + self.subscriber.new_span(metadata, values) } - /// Record a signed 64-bit integer value. + /// Record a set of values on a span. /// - /// This calls the [`record_i64`](::Subscriber::record_i64) + /// This calls the [`record`](::Subscriber::record) /// function on the `Subscriber` that this `Dispatch` forwards to. #[inline] - pub fn record_i64(&self, span: &Span, field: &field::Field, value: i64) { - self.subscriber.record_i64(span, field, value) - } - - /// Record an unsigned 64-bit integer value. - /// - /// This calls the [`record_u64`](::Subscriber::record_u64) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_u64(&self, span: &Span, field: &field::Field, value: u64) { - self.subscriber.record_u64(span, field, value) - } - - /// Record a boolean value. - /// - /// This calls the [`record_bool`](::Subscriber::record_bool) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_bool(&self, span: &Span, field: &field::Field, value: bool) { - self.subscriber.record_bool(span, field, value) - } - - /// Record a string value. - /// - /// This calls the [`record_str`](::Subscriber::record_str) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_str(&self, span: &Span, field: &field::Field, value: &str) { - self.subscriber.record_str(span, field, value) - } - - /// Record a value implementing `fmt::Debug`. - /// - /// This calls the [`record_debug`](::Subscriber::record_debug) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_debug(&self, span: &Span, field: &field::Field, value: &fmt::Debug) { - self.subscriber.record_debug(span, field, value) + 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 [`add_follows_from`](::Subscriber::add_follows_from) + /// This calls the [`record_follows_from`](::Subscriber::record_follows_from) /// function on the `Subscriber` that this `Dispatch` forwards to. #[inline] - pub fn add_follows_from(&self, span: &Span, follows: Span) { - self.subscriber.add_follows_from(span, follows) + 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 @@ -177,6 +141,17 @@ impl Dispatch { 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 @@ -242,13 +217,15 @@ impl Subscriber for NoSubscriber { subscriber::Interest::never() } - fn new_span(&self, _meta: &Metadata) -> Span { + fn new_span(&self, _meta: &Metadata, _vals: &field::ValueSet) -> Span { Span::from_u64(0) } - fn record_debug(&self, _span: &Span, _field: &field::Field, _value: &fmt::Debug) {} + fn event(&self, _event: &Event) {} + + fn record(&self, _span: &Span, _values: &field::ValueSet) {} - fn add_follows_from(&self, _span: &Span, _follows: Span) {} + fn record_follows_from(&self, _span: &Span, _follows: &Span) {} #[inline] fn enabled(&self, _metadata: &Metadata) -> bool { 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..370260b5458 --- /dev/null +++ b/tokio-trace/tokio-trace-core/src/event.rs @@ -0,0 +1,58 @@ +//! 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 index a267b1a7a30..45ee028eabd 100644 --- a/tokio-trace/tokio-trace-core/src/field.rs +++ b/tokio-trace/tokio-trace-core/src/field.rs @@ -1,16 +1,19 @@ -//! `Span` key-value data. +//! `Span` and `Event` key-value data. //! -//! Spans 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`. +//! 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. The set of -//! field keys on a given `Span` or is defined on its `Metadata`. Once the span -//! has been created (i.e., the `new_id` or `new_span` methods on the -//! `Subscriber` have been called), field values may be added by calls to the -//! subscriber's `record_` methods. +//! `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` @@ -18,14 +21,16 @@ //! allow `Subscriber` implementations to provide type-specific behaviour for //! consuming values of each type. //! -//! The `Subscriber` trait provides default implementations of `record_u64`, -//! `record_i64`, `record_bool`, and `record_str` which call the `record_fmt` -//! function, so that only the `record_fmt` function must be implemented. -//! However, implementors of `Subscriber` that wish to consume these primitives -//! as their types may override the `record` methods for any types they care -//! about. For example, we might record integers by incrementing counters for -//! their field names, rather than printing them. +//! 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, @@ -71,6 +76,12 @@ pub struct FieldSet { 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 { @@ -78,6 +89,259 @@ pub struct Iter { 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); + +/// 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) +} + +// ===== impl Value ===== + +/// 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) +} + +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 { @@ -145,7 +409,7 @@ impl FieldSet { /// Returns the [`Field`](::field::Field) named `name`, or `None` if no such /// field exists. - pub fn field(&self, name: &Q) -> Option + pub fn field(&self, name: &Q) -> Option where Q: Borrow, { @@ -167,12 +431,12 @@ impl FieldSet { /// 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.names.len() + 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.names.len(); + let idxs = 0..self.len(); Iter { idxs, fields: FieldSet { @@ -181,6 +445,24 @@ impl FieldSet { }, } } + + /// Returns a new `ValueSet` with entries for this `FieldSet`'s values. + #[doc(hidden)] + pub fn value_set<'v>( + &'v self, + values: &'v [(&'v Field, Option<&'v (Value + 'v)>)], + ) -> ValueSet<'v> { + ValueSet { + fields: self, + values, + } + } + + /// Returns the number of fields in this `FieldSet`. + #[inline] + pub fn len(&self) -> usize { + self.names.len() + } } impl<'a> IntoIterator for &'a FieldSet { @@ -216,3 +498,175 @@ impl Iterator for Iter { }) } } + +// ===== 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 { + // TODO: this might be handy as a public impl? + impl<'a, 'b> Record for fmt::DebugStruct<'a, 'b> { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.field(field.name(), value); + } + } + self.values + .iter() + .fold(&mut f.debug_struct("ValueSet"), |dbg, (key, v)| { + if let Some(val) = v { + val.record(key, dbg); + } + dbg + }) + .finish() + } +} + +#[cfg(test)] +mod test { + use super::*; + use ::{Metadata, Level}; + + 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); + } +} diff --git a/tokio-trace/tokio-trace-core/src/lib.rs b/tokio-trace/tokio-trace-core/src/lib.rs index 21637b29b31..965aaea2381 100644 --- a/tokio-trace/tokio-trace-core/src/lib.rs +++ b/tokio-trace/tokio-trace-core/src/lib.rs @@ -156,6 +156,7 @@ macro_rules! metadata { pub mod callsite; pub mod dispatcher; +pub mod event; pub mod field; pub mod metadata; pub mod span; @@ -164,8 +165,13 @@ 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/subscriber.rs b/tokio-trace/tokio-trace-core/src/subscriber.rs index 412054608d8..8d381e6fa0b 100644 --- a/tokio-trace/tokio-trace-core/src/subscriber.rs +++ b/tokio-trace/tokio-trace-core/src/subscriber.rs @@ -1,7 +1,5 @@ //! Subscribers collect and record trace data. -use {field, Metadata, Span}; - -use std::fmt; +use {field, Event, Metadata, Span}; /// Trait representing the functions required to collect trace data. /// @@ -25,7 +23,7 @@ use std::fmt; /// /// 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 or not span _data_ — +/// 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 @@ -99,9 +97,22 @@ pub trait Subscriber { } } + /// 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 @@ -111,71 +122,21 @@ pub trait Subscriber { /// return a distinct ID every time this function is called, regardless of /// the metadata. /// - /// Subscribers which do not rely on the implementations of `PartialEq`, - /// `Eq`, and `Hash` for `Span`s are free to return span IDs with value 0 - /// from all calls to this function, if they so choose. - /// /// [`Span`]: ::span::Span - fn new_span(&self, metadata: &Metadata) -> Span; - - /// Record a signed 64-bit integer value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to signed integers may override the default - /// implementation. - /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_i64(&self, span: &Span, field: &field::Field, value: i64) { - self.record_debug(span, field, &value) - } - - /// Record an unsigned 64-bit integer value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to unsigned integers may override the default - /// implementation. - /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_u64(&self, span: &Span, field: &field::Field, value: u64) { - self.record_debug(span, field, &value) - } + /// [recorder]: ::field::Record + /// [`record` method]: ::field::ValueSet::record + fn new_span(&self, metadata: &Metadata, values: &field::ValueSet) -> Span; - /// Record a boolean value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to booleans may override the default - /// implementation. - /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_bool(&self, span: &Span, field: &field::Field, value: bool) { - self.record_debug(span, field, &value) - } + // === Notification methods =============================================== - /// Record a string value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to strings may override the default - /// implementation. + /// Record a set of values on a span. /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_str(&self, span: &Span, field: &field::Field, value: &str) { - self.record_debug(span, field, &value) - } - - /// Record a value implementing `fmt::Debug`. + /// The subscriber is expected to provide a [recorder] to the `ValueSet`'s + /// [`record` method] in order to record the added values. /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_debug(&self, span: &Span, field: &field::Field, value: &fmt::Debug); + /// [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`. @@ -195,20 +156,18 @@ pub trait Subscriber { /// 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 add_follows_from(&self, span: &Span, follows: Span); + fn record_follows_from(&self, span: &Span, follows: &Span); - // === Filtering methods ================================================== - - /// Returns true if a span with the specified [metadata] would be - /// recorded. + /// Records that an [`Event`] has occurred. /// - /// This is used by the dispatcher to avoid allocating for span construction - /// if the span would be discarded anyway. + /// 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. /// - /// [metadata]: ::Metadata - fn enabled(&self, metadata: &Metadata) -> bool; - - // === Notification methods =============================================== + /// [`Event`]: ::event::Event + /// [recorder]: ::field::Record + /// [`record` method]: ::event::Event::record + fn event(&self, event: &Event); /// Records that a [`Span`] has been entered. ///