trace: Add shorthand for field::display and field::debug (#1088)

## Motivation

In `tokio-trace`, field values may be recorded as either a subset of
Rust primitive types or as `fmt::Display` and `fmt::Debug`
implementations. Currently, `tokio-trace` provides the `field::display`
and `field::debug` functions which wrap a type with a type that
implements `Value` using the wrapped type's `fmt::Display` or
`fmt::Debug` implementation. However, importing and using these
functions adds unnecessary boilerplate. 

In #1081, @jonhoo suggested adding shorthand syntax to the macros,
similar to that used by the `slog` crate, as a solution for the
wordiness of the current API.

## Solution

This branch adds `?` and `%` sigils to field values in the span and
event macros, which expand to the `field::debug` and `field::display`
wrappers, respectively. The shorthand sigils may be used in any position
where the macros take a field value.

For example:
```rust
trace_span!("foo", my_field = ?something, ...); // shorthand for `debug`
info!(foo = %value, bar = false, ...) // shorthand for `display`
```

Adding this shorthand required a fairly large change to how field
key-value pairs are handled by the macros --- since `%foo` and `%foo`
are not valid Rust expressions, we can no longer match repeated 
`$ident = $expr` patterns, and must now match field lists as repeated
token trees. The inner helper macros for constructing `FieldSet`s and
`ValueSet`s have to parse the token trees recursively. This added a
decent chunk of complexity, but fortunately we have a large number of
compile tests for the macros and I'm quite confident that all existing
invocations will still work.

Closes #1081

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

tokio-trace/src/lib.rs

@@ -94,6 +94,40 @@
 //! # }
 //!```
 //!
+//! The [`field::display`] and [`field::debug`] functions are used to record
+//! fields on spans or events using their `fmt::Display` and `fmt::Debug`
+//! implementations (rather than as typed data). This may be used in lieu of
+//! custom `Value` implementations for complex or user-defined types.
+//!
+//! In addition, the span and event macros permit the use of the `%` and `?`
+//! sigils as shorthand for `field::display` and `field::debug`, respectively.
+//! For example:
+//!
+//! ```
+//! # #[macro_use]
+//! # extern crate tokio_trace;
+//! # use tokio_trace::Level;
+//! # fn main() {
+//! #[derive(Debug)]
+//! struct MyStruct {
+//!     my_field: &'static str,
+//! }
+//!
+//! let my_struct = MyStruct {
+//!     my_field: "Hello world!"
+//! };
+//!
+//! let my_span = span!(
+//!     Level::TRACE,
+//!     "my_span",
+//!     // `my_struct` will be recorded using its `fmt::Debug` implementation.
+//!     my_struct = ?my_struct,
+//!     // `my_field` will be recorded using the implementation of `fmt::Display` for `&str`.
+//!     my_struct.my_field = %my_struct.my_field,
+//! );
+//! # }
+//!```
+//!
 //! ### When to use spans
 //!
 //! As a rule of thumb, spans should be used to represent discrete units of work
@@ -254,7 +288,8 @@
 //! ```rust
 //! #[macro_use]
 //! extern crate tokio_trace;
-//! use tokio_trace::{field, Level};
+//! use tokio_trace::Level;
+//!
 //! # #[derive(Debug)] pub struct Yak(String);
 //! # impl Yak { fn shave(&mut self, _: u32) {} }
 //! # fn find_a_razor() -> Result<u32, u32> { Ok(1) }
@@ -262,7 +297,7 @@
 //! pub fn shave_the_yak(yak: &mut Yak) {
 //!     // Create a new span for this invocation of `shave_the_yak`, annotated
 //!     // with  the yak being shaved as a *field* on the span.
-//!     span!(Level::TRACE, "shave_the_yak", yak = field::debug(&yak)).enter(|| {
+//!     span!(Level::TRACE, "shave_the_yak", yak = ?yak).enter(|| {
 //!         // Since the span is annotated with the yak, it is part of the context
 //!         // for everything happening inside the span. Therefore, we don't need
 //!         // to add it to the message for this event, as the `log` crate does.
@@ -274,7 +309,7 @@
 //!                     // We can add the razor as a field rather than formatting it
 //!                     // as part of the message, allowing subscribers to consume it
 //!                     // in a more structured manner:
-//!                     info!({ razor = field::display(razor) }, "Razor located");
+//!                     info!({ razor = %razor }, "Razor located");
 //!                     yak.shave(razor);
 //!                     break;
 //!                 }
@@ -387,6 +422,8 @@
 //! [`exit`]: subscriber/trait.Subscriber.html#tymethod.exit
 //! [`enabled`]: subscriber/trait.Subscriber.html#tymethod.enabled
 //! [metadata]: struct.Metadata.html
+//! [`field::display`]: field/fn.display.html
+//! [`field::debug`]: field/fn.debug.html
 //! [`tokio-trace-nursery`]: https://github.com/tokio-rs/tokio-trace-nursery
 //! [`tokio-trace-futures`]: https://github.com/tokio-rs/tokio-trace-nursery/tree/master/tokio-trace-futures
 //! [`tokio-trace-fmt`]: https://github.com/tokio-rs/tokio-trace-nursery/tree/master/tokio-trace-fmt

tokio-trace/tests/event.rs

@@ -4,7 +4,11 @@ mod support;
 
 use self::support::*;
 
-use tokio_trace::{field::display, subscriber::with_default, Level};
+use tokio_trace::{
+    field::{debug, display},
+    subscriber::with_default,
+    Level,
+};
 
 #[test]
 fn event_without_message() {
@@ -187,3 +191,61 @@ fn move_field_out_of_struct() {
     });
     handle.assert_finished();
 }
+
+#[test]
+fn display_shorthand() {
+    let (subscriber, handle) = subscriber::mock()
+        .event(
+            event::mock().with_fields(
+                field::mock("my_field")
+                    .with_value(&display("hello world"))
+                    .only(),
+            ),
+        )
+        .done()
+        .run_with_handle();
+    with_default(subscriber, || {
+        event!(Level::TRACE, my_field = %"hello world");
+    });
+
+    handle.assert_finished();
+}
+
+#[test]
+fn debug_shorthand() {
+    let (subscriber, handle) = subscriber::mock()
+        .event(
+            event::mock().with_fields(
+                field::mock("my_field")
+                    .with_value(&debug("hello world"))
+                    .only(),
+            ),
+        )
+        .done()
+        .run_with_handle();
+    with_default(subscriber, || {
+        event!(Level::TRACE, my_field = ?"hello world");
+    });
+
+    handle.assert_finished();
+}
+
+#[test]
+fn both_shorthands() {
+    let (subscriber, handle) = subscriber::mock()
+        .event(
+            event::mock().with_fields(
+                field::mock("display_field")
+                    .with_value(&display("hello world"))
+                    .and(field::mock("debug_field").with_value(&debug("hello world")))
+                    .only(),
+            ),
+        )
+        .done()
+        .run_with_handle();
+    with_default(subscriber, || {
+        event!(Level::TRACE, display_field = %"hello world", debug_field = ?"hello world");
+    });
+
+    handle.assert_finished();
+}

tokio-trace/tests/macros.rs

@@ -10,6 +10,7 @@ extern crate tokio_trace;
 
 #[test]
 fn span() {
+    span!(Level::DEBUG, target: "foo_events", "foo", bar.baz = ?2, quux = %3, quuux = 4);
     span!(Level::DEBUG, target: "foo_events", "foo", bar.baz = 2, quux = 3);
     span!(Level::DEBUG, target: "foo_events", "foo", bar.baz = 2, quux = 4,);
     span!(Level::DEBUG, target: "foo_events", "foo");
@@ -18,72 +19,90 @@ fn span() {
     span!(Level::DEBUG, "foo", bar.baz = 2, quux = 4,);
     span!(Level::TRACE, "foo", bar.baz = 2, quux = 3);
     span!(Level::TRACE, "foo", bar.baz = 2, quux = 4,);
+    span!(Level::TRACE, "foo", bar.baz = ?2);
+    span!(Level::TRACE, "foo", bar.baz = %2);
     span!(Level::TRACE, "foo");
     span!(Level::TRACE, "bar",);
 }
 
 #[test]
 fn trace_span() {
+    trace_span!(target: "foo_events", "foo", bar.baz = ?2, quux = %3, quuux = 4);
     trace_span!(target: "foo_events", "foo", bar.baz = 2, quux = 3);
     trace_span!(target: "foo_events", "foo", bar.baz = 2, quux = 4,);
     trace_span!(target: "foo_events", "foo");
     trace_span!(target: "foo_events", "bar",);
     trace_span!("foo", bar.baz = 2, quux = 3);
     trace_span!("foo", bar.baz = 2, quux = 4,);
+    trace_span!("foo", bar.baz = ?2);
+    trace_span!("foo", bar.baz = %2);
     trace_span!("bar");
     trace_span!("bar",);
 }
 
 #[test]
 fn debug_span() {
+    debug_span!(target: "foo_events", "foo", bar.baz = ?2, quux = %3, quuux = 4);
     debug_span!(target: "foo_events", "foo", bar.baz = 2, quux = 3);
     debug_span!(target: "foo_events", "foo", bar.baz = 2, quux = 4,);
     debug_span!(target: "foo_events", "foo");
     debug_span!(target: "foo_events", "bar",);
     debug_span!("foo", bar.baz = 2, quux = 3);
     debug_span!("foo", bar.baz = 2, quux = 4,);
+    debug_span!("foo", bar.baz = ?2);
+    debug_span!("foo", bar.baz = %2);
     debug_span!("bar");
     debug_span!("bar",);
 }
 
 #[test]
 fn info_span() {
+    info_span!(target: "foo_events", "foo", bar.baz = ?2, quux = %3, quuux = 4);
     info_span!(target: "foo_events", "foo", bar.baz = 2, quux = 3);
     info_span!(target: "foo_events", "foo", bar.baz = 2, quux = 4,);
     info_span!(target: "foo_events", "foo");
     info_span!(target: "foo_events", "bar",);
     info_span!("foo", bar.baz = 2, quux = 3);
     info_span!("foo", bar.baz = 2, quux = 4,);
+    info_span!("foo", bar.baz = ?2);
+    info_span!("foo", bar.baz = %2);
     info_span!("bar");
     info_span!("bar",);
 }
 
 #[test]
 fn warn_span() {
+    warn_span!(target: "foo_events", "foo", bar.baz = ?2, quux = %3, quuux = 4);
     warn_span!(target: "foo_events", "foo", bar.baz = 2, quux = 3);
     warn_span!(target: "foo_events", "foo", bar.baz = 2, quux = 4,);
     warn_span!(target: "foo_events", "foo");
     warn_span!(target: "foo_events", "bar",);
     warn_span!("foo", bar.baz = 2, quux = 3);
     warn_span!("foo", bar.baz = 2, quux = 4,);
+    warn_span!("foo", bar.baz = ?2);
+    warn_span!("foo", bar.baz = %2);
     warn_span!("bar");
     warn_span!("bar",);
 }
 
 #[test]
 fn error_span() {
+    error_span!(target: "foo_events", "foo", bar.baz = ?2, quux = %3, quuux = 4);
     error_span!(target: "foo_events", "foo", bar.baz = 2, quux = 3);
     error_span!(target: "foo_events", "foo", bar.baz = 2, quux = 4,);
     error_span!(target: "foo_events", "foo");
     error_span!(target: "foo_events", "bar",);
     error_span!("foo", bar.baz = 2, quux = 3);
     error_span!("foo", bar.baz = 2, quux = 4,);
+    error_span!("foo", bar.baz = ?2);
+    error_span!("foo", bar.baz = %2);
     error_span!("bar");
     error_span!("bar",);
 }
 
 #[test]
 fn span_root() {
+    span!(Level::DEBUG, target: "foo_events", parent: None, "foo", bar.baz = 2, quux = 3);
     span!(Level::DEBUG, target: "foo_events", parent: None, "foo", bar.baz = 2, quux = 3);
     span!(Level::DEBUG, target: "foo_events", parent: None, "foo", bar.baz = 2, quux = 4,);
     span!(Level::DEBUG, target: "foo_events", parent: None, "foo");
@@ -246,6 +265,7 @@ fn error_span_with_parent() {
 
 #[test]
 fn event() {
+    event!(Level::DEBUG, foo = ?3, bar.baz = %2, quux = false);
     event!(Level::DEBUG, foo = 3, bar.baz = 2, quux = false);
     event!(Level::DEBUG, foo = 3, bar.baz = 3,);
     event!(Level::DEBUG, "foo");
@@ -253,7 +273,7 @@ fn event() {
     event!(Level::DEBUG, { foo = 3, bar.baz = 80 }, "quux");
     event!(Level::DEBUG, { foo = 2, bar.baz = 79 }, "quux {:?}", true);
     event!(Level::DEBUG, { foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
-    event!(Level::DEBUG, { foo = 2, bar.baz = 78, }, "quux");
+    event!(Level::DEBUG, { foo = ?2, bar.baz = %78 }, "quux");
     event!(target: "foo_events", Level::DEBUG, foo = 3, bar.baz = 2, quux = false);
     event!(target: "foo_events", Level::DEBUG, foo = 3, bar.baz = 3,);
     event!(target: "foo_events", Level::DEBUG, "foo");
@@ -266,6 +286,7 @@ fn event() {
 
 #[test]
 fn trace() {
+    trace!(foo = ?3, bar.baz = %2, quux = false);
     trace!(foo = 3, bar.baz = 2, quux = false);
     trace!(foo = 3, bar.baz = 3,);
     trace!("foo");
@@ -273,7 +294,8 @@ fn trace() {
     trace!({ foo = 3, bar.baz = 80 }, "quux");
     trace!({ foo = 2, bar.baz = 79 }, "quux {:?}", true);
     trace!({ foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
-    trace!({ foo = 2, bar.baz = 78, }, "quux");
+    trace!({ foo = 2, bar.baz = 78 }, "quux");
+    trace!({ foo = ?2, bar.baz = %78 }, "quux");
     trace!(target: "foo_events", foo = 3, bar.baz = 2, quux = false);
     trace!(target: "foo_events", foo = 3, bar.baz = 3,);
     trace!(target: "foo_events", "foo");
@@ -286,6 +308,7 @@ fn trace() {
 
 #[test]
 fn debug() {
+    debug!(foo = ?3, bar.baz = %2, quux = false);
     debug!(foo = 3, bar.baz = 2, quux = false);
     debug!(foo = 3, bar.baz = 3,);
     debug!("foo");
@@ -293,7 +316,8 @@ fn debug() {
     debug!({ foo = 3, bar.baz = 80 }, "quux");
     debug!({ foo = 2, bar.baz = 79 }, "quux {:?}", true);
     debug!({ foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
-    debug!({ foo = 2, bar.baz = 78, }, "quux");
+    debug!({ foo = 2, bar.baz = 78 }, "quux");
+    debug!({ foo = ?2, bar.baz = %78 }, "quux");
     debug!(target: "foo_events", foo = 3, bar.baz = 2, quux = false);
     debug!(target: "foo_events", foo = 3, bar.baz = 3,);
     debug!(target: "foo_events", "foo");
@@ -301,12 +325,12 @@ fn debug() {
     debug!(target: "foo_events", { foo = 3, bar.baz = 80 }, "quux");
     debug!(target: "foo_events", { foo = 2, bar.baz = 79 }, "quux {:?}", true);
     debug!(target: "foo_events", { foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
-    debug!(target: "foo_events", { foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
     debug!(target: "foo_events", { foo = 2, bar.baz = 78, }, "quux");
 }
 
 #[test]
 fn info() {
+    info!(foo = ?3, bar.baz = %2, quux = false);
     info!(foo = 3, bar.baz = 2, quux = false);
     info!(foo = 3, bar.baz = 3,);
     info!("foo");
@@ -314,7 +338,8 @@ fn info() {
     info!({ foo = 3, bar.baz = 80 }, "quux");
     info!({ foo = 2, bar.baz = 79 }, "quux {:?}", true);
     info!({ foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
-    info!({ foo = 2, bar.baz = 78, }, "quux");
+    info!({ foo = 2, bar.baz = 78 }, "quux");
+    info!({ foo = ?2, bar.baz = %78 }, "quux");
     info!(target: "foo_events", foo = 3, bar.baz = 2, quux = false);
     info!(target: "foo_events", foo = 3, bar.baz = 3,);
     info!(target: "foo_events", "foo");
@@ -322,12 +347,12 @@ fn info() {
     info!(target: "foo_events", { foo = 3, bar.baz = 80 }, "quux");
     info!(target: "foo_events", { foo = 2, bar.baz = 79 }, "quux {:?}", true);
     info!(target: "foo_events", { foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
-    info!(target: "foo_events", { foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
     info!(target: "foo_events", { foo = 2, bar.baz = 78, }, "quux");
 }
 
 #[test]
 fn warn() {
+    warn!(foo = ?3, bar.baz = %2, quux = false);
     warn!(foo = 3, bar.baz = 2, quux = false);
     warn!(foo = 3, bar.baz = 3,);
     warn!("foo");
@@ -336,6 +361,7 @@ fn warn() {
     warn!({ foo = 2, bar.baz = 79 }, "quux {:?}", true);
     warn!({ foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
     warn!({ foo = 2, bar.baz = 78 }, "quux");
+    warn!({ foo = ?2, bar.baz = %78 }, "quux");
     warn!(target: "foo_events", foo = 3, bar.baz = 2, quux = false);
     warn!(target: "foo_events", foo = 3, bar.baz = 3,);
     warn!(target: "foo_events", "foo");
@@ -348,6 +374,7 @@ fn warn() {
 
 #[test]
 fn error() {
+    error!(foo = ?3, bar.baz = %2, quux = false);
     error!(foo = 3, bar.baz = 2, quux = false);
     error!(foo = 3, bar.baz = 3,);
     error!("foo");
@@ -356,6 +383,7 @@ fn error() {
     error!({ foo = 2, bar.baz = 79 }, "quux {:?}", true);
     error!({ foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false);
     error!({ foo = 2, bar.baz = 78, }, "quux");
+    error!({ foo = ?2, bar.baz = %78 }, "quux");
     error!(target: "foo_events", foo = 3, bar.baz = 2, quux = false);
     error!(target: "foo_events", foo = 3, bar.baz = 3,);
     error!(target: "foo_events", "foo");

tokio-trace/tests/span.rs

@@ -4,7 +4,11 @@ mod support;
 
 use self::support::*;
 use std::thread;
-use tokio_trace::{field::display, subscriber::with_default, Level, Span};
+use tokio_trace::{
+    field::{debug, display},
+    subscriber::with_default,
+    Level, Span,
+};
 
 #[test]
 fn handles_to_the_same_span_are_equal() {
@@ -547,3 +551,61 @@ fn contextual_child() {
 
     handle.assert_finished();
 }
+
+#[test]
+fn display_shorthand() {
+    let (subscriber, handle) = subscriber::mock()
+        .new_span(
+            span::mock().named("my_span").with_field(
+                field::mock("my_field")
+                    .with_value(&display("hello world"))
+                    .only(),
+            ),
+        )
+        .done()
+        .run_with_handle();
+    with_default(subscriber, || {
+        span!(Level::TRACE, "my_span", my_field = %"hello world");
+    });
+
+    handle.assert_finished();
+}
+
+#[test]
+fn debug_shorthand() {
+    let (subscriber, handle) = subscriber::mock()
+        .new_span(
+            span::mock().named("my_span").with_field(
+                field::mock("my_field")
+                    .with_value(&debug("hello world"))
+                    .only(),
+            ),
+        )
+        .done()
+        .run_with_handle();
+    with_default(subscriber, || {
+        span!(Level::TRACE, "my_span", my_field = ?"hello world");
+    });
+
+    handle.assert_finished();
+}
+
+#[test]
+fn both_shorthands() {
+    let (subscriber, handle) = subscriber::mock()
+        .new_span(
+            span::mock().named("my_span").with_field(
+                field::mock("display_field")
+                    .with_value(&display("hello world"))
+                    .and(field::mock("debug_field").with_value(&debug("hello world")))
+                    .only(),
+            ),
+        )
+        .done()
+        .run_with_handle();
+    with_default(subscriber, || {
+        span!(Level::TRACE, "my_span", display_field = %"hello world", debug_field = ?"hello world");
+    });
+
+    handle.assert_finished();
+}