Introduce tokio-trace (#827)

<!-- Thank you for your Pull Request. Please provide a description above
and review the requirements below.

Bug fixes and new features should include tests.

Contributors guide:
https://github.com/tokio-rs/tokio/blob/master/CONTRIBUTING.md -->

## Motivation

In asynchronous systems like Tokio, interpreting traditional log
messages can often be quite challenging. Since individual tasks are
multiplexed on the same thread, associated events and log lines are
intermixed making it difficult to trace the logic flow. Currently, none
of the available logging frameworks or libraries in Rust offer the
ability to trace logical paths through a futures-based program.

There also are complementary goals that can be accomplished with such a
system. For example, metrics / instrumentation can be tracked by
observing emitted events, or trace data can be exported to a distributed
tracing or event processing system.

In addition, it can often be useful to generate this diagnostic data in
a structured manner that can be consumed programmatically. While prior
art for structured logging in Rust exists, it is not currently
standardized, and is not "Tokio-friendly".

## Solution

This branch adds a new library to the tokio project, `tokio-trace`.
`tokio-trace` expands upon logging-style diagnostics by allowing
libraries and applications to record structured events with additional
information about *temporality* and *causality* --- unlike a log
message, a span in `tokio-trace` has a beginning and end time, may be
entered and exited by the flow of execution, and may exist within a
nested tree of similar spans. In addition, `tokio-trace` spans are
*structured*, with the ability to record typed data as well as textual
messages.

The `tokio-trace-core` crate contains the core primitives for this
system, which are expected to remain stable, while `tokio-trace` crate
provides a more "batteries-included" API. In particular, it provides
macros which are a superset of the `log` crate's `error!`, `warn!`,
`info!`, `debug!`, and `trace!` macros, allowing users to begin the
process of adopting `tokio-trace` by performing a drop-in replacement.

## Notes

Work on this project had previously been carried out in the
[tokio-trace-prototype] repository. In addition to the `tokio-trace` and
`tokio-trace-core` crates, the `tokio-trace-prototype` repo also
contains prototypes or sketches of adapter, compatibility, and utility
crates which provide useful functionality for `tokio-trace`, but these
crates are not yet ready for a release. When this branch is merged, that
repository will be archived, and the remaining unstable crates will be
moved to a new `tokio-trace-nursery` repository. Remaining issues on the
`tokio-trace-prototype` repo will be moved to the appropriate new repo.

The crates added in this branch are not _identical_ to the current head
of the `tokio-trace-prototype` repo, as I did some final clean-up and docs
polish in this branch prior to merging this PR.

[tokio-trace-prototype]: https://github.com/hawkw/tokio-trace-prototype

Closes: #561

Signed-off-by: Eliza Weisman <[email protected]>

tokio-trace/examples/counters.rs

@@ -0,0 +1,138 @@
+#[macro_use]
+extern crate tokio_trace;
+
+use tokio_trace::{
+    field::{self, Field, Record},
+    span,
+    subscriber::{self, Subscriber},
+    Event, Id, Metadata,
+};
+
+use std::{
+    collections::HashMap,
+    fmt,
+    sync::{
+        atomic::{AtomicUsize, Ordering},
+        Arc, RwLock, RwLockReadGuard,
+    },
+};
+
+#[derive(Clone)]
+struct Counters(Arc<RwLock<HashMap<String, AtomicUsize>>>);
+
+struct CounterSubscriber {
+    ids: AtomicUsize,
+    counters: Counters,
+}
+
+struct Count<'a> {
+    counters: RwLockReadGuard<'a, HashMap<String, AtomicUsize>>,
+}
+
+impl<'a> Record for Count<'a> {
+    fn record_i64(&mut self, field: &Field, value: i64) {
+        if let Some(counter) = self.counters.get(field.name()) {
+            if value > 0 {
+                counter.fetch_add(value as usize, Ordering::Release);
+            } else {
+                counter.fetch_sub((value * -1) as usize, Ordering::Release);
+            }
+        };
+    }
+
+    fn record_u64(&mut self, field: &Field, value: u64) {
+        if let Some(counter) = self.counters.get(field.name()) {
+            counter.fetch_add(value as usize, Ordering::Release);
+        };
+    }
+
+    fn record_bool(&mut self, _: &Field, _: bool) {}
+    fn record_str(&mut self, _: &Field, _: &str) {}
+    fn record_debug(&mut self, _: &Field, _: &fmt::Debug) {}
+}
+
+impl CounterSubscriber {
+    fn recorder(&self) -> Count {
+        Count {
+            counters: self.counters.0.read().unwrap(),
+        }
+    }
+}
+
+impl Subscriber for CounterSubscriber {
+    fn register_callsite(&self, meta: &Metadata) -> subscriber::Interest {
+        let mut interest = subscriber::Interest::never();
+        for key in meta.fields() {
+            let name = key.name();
+            if name.contains("count") {
+                self.counters
+                    .0
+                    .write()
+                    .unwrap()
+                    .entry(name.to_owned())
+                    .or_insert_with(|| AtomicUsize::new(0));
+                interest = subscriber::Interest::always();
+            }
+        }
+        interest
+    }
+
+    fn new_span(&self, _new_span: &Metadata, values: &field::ValueSet) -> Id {
+        values.record(&mut self.recorder());
+        let id = self.ids.fetch_add(1, Ordering::SeqCst);
+        Id::from_u64(id as u64)
+    }
+
+    fn record_follows_from(&self, _span: &Id, _follows: &Id) {
+        // unimplemented
+    }
+
+    fn record(&self, _: &Id, values: &field::ValueSet) {
+        values.record(&mut self.recorder())
+    }
+
+    fn event(&self, event: &Event) {
+        event.record(&mut self.recorder())
+    }
+
+    fn enabled(&self, metadata: &Metadata) -> bool {
+        metadata.fields().iter().any(|f| f.name().contains("count"))
+    }
+
+    fn enter(&self, _span: &Id) {}
+    fn exit(&self, _span: &Id) {}
+}
+
+impl Counters {
+    fn print_counters(&self) {
+        for (k, v) in self.0.read().unwrap().iter() {
+            println!("{}: {}", k, v.load(Ordering::Acquire));
+        }
+    }
+
+    fn new() -> (Self, CounterSubscriber) {
+        let counters = Counters(Arc::new(RwLock::new(HashMap::new())));
+        let subscriber = CounterSubscriber {
+            ids: AtomicUsize::new(0),
+            counters: counters.clone(),
+        };
+        (counters, subscriber)
+    }
+}
+
+fn main() {
+    let (counters, subscriber) = Counters::new();
+
+    tokio_trace::subscriber::with_default(subscriber, || {
+        let mut foo: u64 = 2;
+        span!("my_great_span", foo_count = &foo).enter(|| {
+            foo += 1;
+            info!({ yak_shaved = true, yak_count = 1 }, "hi from inside my span");
+            span!("my other span", foo_count = &foo, baz_count = 5).enter(|| {
+                warn!({ yak_shaved = false, yak_count = -1 }, "failed to shave yak");
+            });
+        });
+    });
+
+    counters.print_counters();
+}

tokio-trace/examples/sloggish/main.rs

@@ -0,0 +1,53 @@
+//! A simple example demonstrating how one might implement a custom
+//! subscriber.
+//!
+//! This subscriber implements a tree-structured logger similar to
+//! the "compact" formatter in [`slog-term`]. The demo mimicks the
+//! example output in the screenshot in the [`slog` README].
+//!
+//! Note that this logger isn't ready for actual production use.
+//! Several corners were cut to make the example simple.
+//!
+//! [`slog-term`]: https://docs.rs/slog-term/2.4.0/slog_term/
+//! [`slog` README]: https://github.com/slog-rs/slog#terminal-output-example
+#[macro_use]
+extern crate tokio_trace;
+
+use tokio_trace::field;
+
+mod sloggish_subscriber;
+use self::sloggish_subscriber::SloggishSubscriber;
+
+fn main() {
+    let subscriber = SloggishSubscriber::new(2);
+
+    tokio_trace::dispatcher::with_default(tokio_trace::Dispatch::new(subscriber), || {
+        span!("", version = &field::display(5.0)).enter(|| {
+            span!("server", host = "localhost", port = 8080).enter(|| {
+                info!("starting");
+                info!("listening");
+                let mut peer1 = span!("conn", peer_addr = "82.9.9.9", port = 42381);
+                peer1.enter(|| {
+                    debug!("connected");
+                    debug!({ length = 2 }, "message received");
+                });
+                let mut peer2 = span!("conn", peer_addr = "8.8.8.8", port = 18230);
+                peer2.enter(|| {
+                    debug!("connected");
+                });
+                peer1.enter(|| {
+                    warn!({ algo = "xor" }, "weak encryption requested");
+                    debug!({ length = 8 }, "response sent");
+                    debug!("disconnected");
+                });
+                peer2.enter(|| {
+                    debug!({ length = 5 }, "message received");
+                    debug!({ length = 8 }, "response sent");
+                    debug!("disconnected");
+                });
+                warn!("internal error");
+                info!("exit");
+            })
+        });
+    });
+}

tokio-trace/examples/sloggish/sloggish_subscriber.rs

@@ -0,0 +1,293 @@
+//! A simple example demonstrating how one might implement a custom
+//! subscriber.
+//!
+//! This subscriber implements a tree-structured logger similar to
+//! the "compact" formatter in [`slog-term`]. The demo mimicks the
+//! example output in the screenshot in the [`slog` README].
+//!
+//! Note that this logger isn't ready for actual production use.
+//! Several corners were cut to make the example simple.
+//!
+//! [`slog-term`]: https://docs.rs/slog-term/2.4.0/slog_term/
+//! [`slog` README]: https://github.com/slog-rs/slog#terminal-output-example
+extern crate ansi_term;
+extern crate humantime;
+use self::ansi_term::{Color, Style};
+use super::tokio_trace::{
+    self,
+    field::{Field, Record},
+    Id, Level, Subscriber,
+};
+
+use std::{
+    cell::RefCell,
+    collections::HashMap,
+    fmt,
+    io::{self, Write},
+    sync::{
+        atomic::{AtomicUsize, Ordering},
+        Mutex,
+    },
+    thread,
+    time::SystemTime,
+};
+
+/// Tracks the currently executing span on a per-thread basis.
+#[derive(Clone)]
+pub struct CurrentSpanPerThread {
+    current: &'static thread::LocalKey<RefCell<Vec<Id>>>,
+}
+
+impl CurrentSpanPerThread {
+    pub fn new() -> Self {
+        thread_local! {
+            static CURRENT: RefCell<Vec<Id>> = RefCell::new(vec![]);
+        };
+        Self { current: &CURRENT }
+    }
+
+    /// Returns the [`Id`](::Id) of the span in which the current thread is
+    /// executing, or `None` if it is not inside of a span.
+    pub fn id(&self) -> Option<Id> {
+        self.current
+            .with(|current| current.borrow().last().cloned())
+    }
+
+    pub fn enter(&self, span: Id) {
+        self.current.with(|current| {
+            current.borrow_mut().push(span);
+        })
+    }
+
+    pub fn exit(&self) {
+        self.current.with(|current| {
+            let _ = current.borrow_mut().pop();
+        })
+    }
+}
+
+pub struct SloggishSubscriber {
+    // TODO: this can probably be unified with the "stack" that's used for
+    // printing?
+    current: CurrentSpanPerThread,
+    indent_amount: usize,
+    stderr: io::Stderr,
+    stack: Mutex<Vec<Id>>,
+    spans: Mutex<HashMap<Id, Span>>,
+    ids: AtomicUsize,
+}
+
+struct Span {
+    parent: Option<Id>,
+    kvs: Vec<(&'static str, String)>,
+}
+
+struct Event<'a> {
+    stderr: io::StderrLock<'a>,
+    comma: bool,
+}
+
+struct ColorLevel<'a>(&'a Level);
+
+impl<'a> fmt::Display for ColorLevel<'a> {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match self.0 {
+            &Level::TRACE => Color::Purple.paint("TRACE"),
+            &Level::DEBUG => Color::Blue.paint("DEBUG"),
+            &Level::INFO => Color::Green.paint("INFO "),
+            &Level::WARN => Color::Yellow.paint("WARN "),
+            &Level::ERROR => Color::Red.paint("ERROR"),
+        }
+        .fmt(f)
+    }
+}
+
+impl Span {
+    fn new(
+        parent: Option<Id>,
+        _meta: &tokio_trace::Metadata,
+        values: &tokio_trace::field::ValueSet,
+    ) -> Self {
+        let mut span = Self {
+            parent,
+            kvs: Vec::new(),
+        };
+        values.record(&mut span);
+        span
+    }
+}
+
+impl Record for Span {
+    fn record_debug(&mut self, field: &Field, value: &fmt::Debug) {
+        self.kvs.push((field.name(), format!("{:?}", value)))
+    }
+}
+
+impl<'a> Record for Event<'a> {
+    fn record_debug(&mut self, field: &Field, value: &fmt::Debug) {
+        write!(
+            &mut self.stderr,
+            "{comma} ",
+            comma = if self.comma { "," } else { "" },
+        )
+        .unwrap();
+        let name = field.name();
+        if name == "message" {
+            write!(
+                &mut self.stderr,
+                "{}",
+                // Have to alloc here due to `ansi_term`'s API...
+                Style::new().bold().paint(format!("{:?}", value))
+            )
+            .unwrap();
+            self.comma = true;
+        } else {
+            write!(
+                &mut self.stderr,
+                "{}: {:?}",
+                Style::new().bold().paint(name),
+                value
+            )
+            .unwrap();
+            self.comma = true;
+        }
+    }
+}
+
+impl SloggishSubscriber {
+    pub fn new(indent_amount: usize) -> Self {
+        Self {
+            current: CurrentSpanPerThread::new(),
+            indent_amount,
+            stderr: io::stderr(),
+            stack: Mutex::new(vec![]),
+            spans: Mutex::new(HashMap::new()),
+            ids: AtomicUsize::new(0),
+        }
+    }
+
+    fn print_kvs<'a, I, K, V>(
+        &self,
+        writer: &mut impl Write,
+        kvs: I,
+        leading: &str,
+    ) -> io::Result<()>
+    where
+        I: IntoIterator<Item = (K, V)>,
+        K: AsRef<str> + 'a,
+        V: fmt::Display + 'a,
+    {
+        let mut kvs = kvs.into_iter();
+        if let Some((k, v)) = kvs.next() {
+            write!(
+                writer,
+                "{}{}: {}",
+                leading,
+                Style::new().bold().paint(k.as_ref()),
+                v
+            )?;
+        }
+        for (k, v) in kvs {
+            write!(writer, ", {}: {}", Style::new().bold().paint(k.as_ref()), v)?;
+        }
+        Ok(())
+    }
+
+    fn print_indent(&self, writer: &mut impl Write, indent: usize) -> io::Result<()> {
+        for _ in 0..(indent * self.indent_amount) {
+            write!(writer, " ")?;
+        }
+        Ok(())
+    }
+}
+
+impl Subscriber for SloggishSubscriber {
+    fn enabled(&self, _metadata: &tokio_trace::Metadata) -> bool {
+        true
+    }
+
+    fn new_span(
+        &self,
+        span: &tokio_trace::Metadata,
+        values: &tokio_trace::field::ValueSet,
+    ) -> tokio_trace::Id {
+        let next = self.ids.fetch_add(1, Ordering::SeqCst) as u64;
+        let id = tokio_trace::Id::from_u64(next);
+        let span = Span::new(self.current.id(), span, values);
+        self.spans.lock().unwrap().insert(id.clone(), span);
+        id
+    }
+
+    fn record(&self, span: &tokio_trace::Id, values: &tokio_trace::field::ValueSet) {
+        let mut spans = self.spans.lock().expect("mutex poisoned!");
+        if let Some(span) = spans.get_mut(span) {
+            values.record(span);
+        }
+    }
+
+    fn record_follows_from(&self, _span: &tokio_trace::Id, _follows: &tokio_trace::Id) {
+        // unimplemented
+    }
+
+    fn enter(&self, span_id: &tokio_trace::Id) {
+        self.current.enter(span_id.clone());
+        let mut stderr = self.stderr.lock();
+        let mut stack = self.stack.lock().unwrap();
+        let spans = self.spans.lock().unwrap();
+        let data = spans.get(span_id);
+        let parent = data.and_then(|span| span.parent.as_ref());
+        if stack.iter().any(|id| id == span_id) {
+            // We are already in this span, do nothing.
+            return;
+        } else {
+            let indent = if let Some(idx) = stack
+                .iter()
+                .position(|id| parent.map(|p| id == p).unwrap_or(false))
+            {
+                let idx = idx + 1;
+                stack.truncate(idx);
+                idx
+            } else {
+                stack.clear();
+                0
+            };
+            self.print_indent(&mut stderr, indent).unwrap();
+            stack.push(span_id.clone());
+            if let Some(data) = data {
+                self.print_kvs(&mut stderr, data.kvs.iter().map(|(k, v)| (k, v)), "")
+                    .unwrap();
+            }
+            write!(&mut stderr, "\n").unwrap();
+        }
+    }
+
+    fn event(&self, event: &tokio_trace::Event) {
+        let mut stderr = self.stderr.lock();
+        let indent = self.stack.lock().unwrap().len();
+        self.print_indent(&mut stderr, indent).unwrap();
+        write!(
+            &mut stderr,
+            "{timestamp} {level} {target}",
+            timestamp = humantime::format_rfc3339_seconds(SystemTime::now()),
+            level = ColorLevel(event.metadata().level()),
+            target = &event.metadata().target(),
+        )
+        .unwrap();
+        let mut recorder = Event {
+            stderr,
+            comma: false,
+        };
+        event.record(&mut recorder);
+        write!(&mut recorder.stderr, "\n").unwrap();
+    }
+
+    #[inline]
+    fn exit(&self, _span: &tokio_trace::Id) {
+        // TODO: unify stack with current span
+        self.current.exit();
+    }
+
+    fn drop_span(&self, _id: tokio_trace::Id) {
+        // TODO: GC unneeded spans.
+    }
+}