tracing: less noisy, more useful log records for spans

[hawkw]

Motivation

Currently, the tracing crate's "log" feature always logs span
lifecycle (creation/enter/exit/close) events, even when the span has no
fields. This can be quite noisy. Since the enter, exit, and close logs
don't include the span's fields, it doesn't add that much additional
context to the surrounding log records.

Additionally, when using tracing with the log-always feature and a
subscriber is active, the IDs of enabled spans are available, but not
included in the span lifecycle log records. These could be used to
enable tracking individual span's lifecycles via these log records, but
this is not currently possible.

Solution

In order to continue recording this data while improving the
signal-to-noise ratio of tracing-generated logs, this branch changes
the log integration to log span lifecycle events under a separate
target, "tracing::span". This way, log users can opt in to this data
when it is desired, but logs are generally much less noisy. Span
creation is still logged to the default target when the span has fields,
as this often provides useful information, but is sent to the
"tracing-span" target when there are no fields.

This branch also updates the log integration so that when a span is
enabled by a subscriber, and log integration is enabled, that span's
log records will include its ID. Now, when multiple spans with the
same name are in the logs, we have a rudimentary ability to correlate
those span's lifecycle events, without introducing so much complexity
that just using a tracing subscriber would be a better solution.

For example, when a subscriber is assigning IDs to spans, the logs look
like this:

ERROR log_with_trace foo=5
ERROR log_with_trace foo=42
ERROR log_with_trace foo=39
WARN  log_with_trace hello world;
INFO  log_with_trace hello world; thingy=42 other_thingy=666
TRACE tracing::span ++ foo; span=1
TRACE tracing::span -> foo; span=1
TRACE log_with_trace hello san francisco; foo=3 bar=4
TRACE tracing::span <- foo; span=1
TRACE tracing::span -- foo; span=1
TRACE log_with_trace ++ foo; bar=3 baz=false; span=2
TRACE tracing::span -- foo; span=2
TRACE log_with_trace hello world foo=1 bar=2

Finally, I've added a new section to the tracing crate's documentation
to provide details on using the log integration features.

Fixes #607

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

[hawkw]

cc @sagebind — this is what we discussed in #607

[sagebind]

Awesome! 🎉

[sagebind]

Sorry for the bump, any chance of getting a tracing 0.1.14 out there with this in it? It's sort of a blocker for me to adopt it in a public release of my own crate.

[hawkw]

@sagebind whoops, I forgot that this hadn't been published yet. Will get that out ASAP.