Giter VIP home page Giter VIP logo

tracing's Introduction

Tracing — Structured, application-level diagnostics

Crates.io Documentation Documentation (master) MIT licensed Build Status Discord chat

Website | Chat | Documentation (master branch)

The master branch is the pre-release, development version of tracing. Please see the v0.1.x branch for the versions of tracing released to crates.io.

Overview

tracing is a framework for instrumenting Rust programs to collect structured, event-based diagnostic information. tracing is maintained by the Tokio project, but does not require the tokio runtime to be used.

Usage

In Applications

In order to record trace events, executables have to use a collector implementation compatible with tracing. A collector implements a way of collecting trace data, such as by logging it to standard output. tracing-subscriber's fmt module provides a collector for logging traces with reasonable defaults. Additionally, tracing-subscriber is able to consume messages emitted by log-instrumented libraries and modules.

To use tracing-subscriber, add the following to your Cargo.toml:

[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"

Then create and install a collector, for example using init():

use tracing::info;
use tracing_subscriber;

fn main() {
    // install global collector configured based on RUST_LOG env var.
    tracing_subscriber::fmt::init();

    let number_of_yaks = 3;
    // this creates a new event, outside of any spans.
    info!(number_of_yaks, "preparing to shave yaks");

    let number_shaved = yak_shave::shave_all(number_of_yaks);
    info!(
        all_yaks_shaved = number_shaved == number_of_yaks,
        "yak shaving completed."
    );
}

Using init() calls set_global_default() so this collector will be used as the default in all threads for the remainder of the duration of the program, similar to how loggers work in the log crate.

For more control, a collector can be built in stages and not set globally, but instead used to locally override the default collector. For example:

use tracing::{info, Level};
use tracing_subscriber;

fn main() {
    let collector = tracing_subscriber::fmt()
        // filter spans/events with level TRACE or higher.
        .with_max_level(Level::TRACE)
        // build but do not install the subscriber.
        .finish();

    tracing::collect::with_default(collector, || {
        info!("This will be logged to stdout");
    });
    info!("This will _not_ be logged to stdout");
}

Any trace events generated outside the context of a collector will not be collected.

This approach allows trace data to be collected by multiple collectors within different contexts in the program. Note that the override only applies to the currently executing thread; other threads will not see the change from with_default.

Once a collector has been set, instrumentation points may be added to the executable using the tracing crate's macros.

In Libraries

Libraries should only rely on the tracing crate and use the provided macros and types to collect whatever information might be useful to downstream consumers.

use std::{error::Error, io};
use tracing::{debug, error, info, span, warn, Level};

// the `#[tracing::instrument]` attribute creates and enters a span
// every time the instrumented function is called. The span is named after
// the function or method. Parameters passed to the function are recorded as fields.
#[tracing::instrument]
pub fn shave(yak: usize) -> Result<(), Box<dyn Error + 'static>> {
    // this creates an event at the DEBUG level with two fields:
    // - `excitement`, with the key "excitement" and the value "yay!"
    // - `message`, with the key "message" and the value "hello! I'm gonna shave a yak."
    //
    // unlike other fields, `message`'s shorthand initialization is just the string itself.
    debug!(excitement = "yay!", "hello! I'm gonna shave a yak.");
    if yak == 3 {
        warn!("could not locate yak!");
        // note that this is intended to demonstrate `tracing`'s features, not idiomatic
        // error handling! in a library or application, you should consider returning
        // a dedicated `YakError`. libraries like snafu or thiserror make this easy.
        return Err(io::Error::new(io::ErrorKind::Other, "shaving yak failed!").into());
    } else {
        debug!("yak shaved successfully");
    }
    Ok(())
}

pub fn shave_all(yaks: usize) -> usize {
    // Constructs a new span named "shaving_yaks" at the TRACE level,
    // and a field whose key is "yaks". This is equivalent to writing:
    //
    // let span = span!(Level::TRACE, "shaving_yaks", yaks = yaks);
    //
    // local variables (`yaks`) can be used as field values
    // without an assignment, similar to struct initializers.
    let span = span!(Level::TRACE, "shaving_yaks", yaks);
    let _enter = span.enter();

    info!("shaving yaks");

    let mut yaks_shaved = 0;
    for yak in 1..=yaks {
        let res = shave(yak);
        debug!(yak, shaved = res.is_ok());

        if let Err(ref error) = res {
            // Like spans, events can also use the field initialization shorthand.
            // In this instance, `yak` is the field being initialized.
            error!(yak, error = error.as_ref(), "failed to shave yak!");
        } else {
            yaks_shaved += 1;
        }
        debug!(yaks_shaved);
    }

    yaks_shaved
}
[dependencies]
tracing = "0.1"

Note: Libraries should NOT install a collector by using a method that calls set_global_default(), as this will cause conflicts when executables try to set the default later.

In Asynchronous Code

To trace async fns, the preferred method is using the #[instrument] attribute:

use tracing::{info, instrument};
use tokio::{io::AsyncWriteExt, net::TcpStream};
use std::io;

#[instrument]
async fn write(stream: &mut TcpStream) -> io::Result<usize> {
    let result = stream.write(b"hello world\n").await;
    info!("wrote to stream; success={:?}", result.is_ok());
    result
}

Special handling is needed for the general case of code using std::future::Future or blocks with async/await, as the following example will not work:

async {
    let _s = span.enter();
    // ...
}

The span guard _s will not exit until the future generated by the async block is complete. Since futures and spans can be entered and exited multiple times without them completing, the span remains entered for as long as the future exists, rather than being entered only when it is polled, leading to very confusing and incorrect output. For more details, see the documentation on closing spans.

This problem can be solved using the Future::instrument combinator:

use tracing::Instrument;

let my_future = async {
    // ...
};

my_future
    .instrument(tracing::info_span!("my_future"))
    .await

Future::instrument attaches a span to the future, ensuring that the span's lifetime is as long as the future's.

Under the hood, the #[instrument] macro performs the same explicit span attachment that Future::instrument does.

Supported Rust Versions

Tracing is built against the latest stable release. The minimum supported version is 1.63. The current Tracing version is not guaranteed to build on Rust versions earlier than the minimum supported version.

Tracing follows the same compiler support policies as the rest of the Tokio project. The current stable Rust compiler and the three most recent minor versions before it will always be supported. For example, if the current stable compiler version is 1.69, the minimum supported version will not be increased past 1.66, three minor versions prior. Increasing the minimum supported compiler version is not considered a semver breaking change as long as doing so complies with this policy.

Getting Help

First, see if the answer to your question can be found in the API documentation. If the answer is not there, there is an active community in the Tracing Discord channel. We would be happy to try to answer your question. Last, if that doesn't work, try opening an issue with the question.

Contributing

🎈 Thanks for your help improving the project! We are so happy to have you! We have a contributing guide to help you get involved in the Tracing project.

Project layout

The tracing crate contains the primary instrumentation API, used for instrumenting libraries and applications to emit trace data. The tracing-core crate contains the core API primitives on which the rest of tracing is instrumented. Authors of trace subscribers may depend on tracing-core, which guarantees a higher level of stability.

Additionally, this repository contains several compatibility and utility libraries built on top of tracing. Some of these crates are in a pre-release state, and are less stable than the tracing and tracing-core crates.

The crates included as part of Tracing are:

Related Crates

In addition to this repository, here are also several third-party crates which are not maintained by the tokio project. These include:

  • tracing-timing implements inter-event timing metrics on top of tracing. It provides a subscriber that records the time elapsed between pairs of tracing events and generates histograms.
  • tracing-honeycomb Provides a layer that reports traces spanning multiple machines to honeycomb.io. Backed by tracing-distributed.
  • tracing-distributed Provides a generic implementation of a layer that reports traces spanning multiple machines to some backend.
  • tracing-actix-web provides tracing integration for the actix-web web framework.
  • tracing-actix provides tracing integration for the actix actor framework.
  • axum-insights provides tracing integration and Application insights export for the axum web framework.
  • tracing-gelf implements a subscriber for exporting traces in Greylog GELF format.
  • tracing-coz provides integration with the coz causal profiler (Linux-only).
  • tracing-bunyan-formatter provides a layer implementation that reports events and spans in bunyan format, enriched with timing information.
  • tide-tracing provides a tide middleware to trace all incoming requests and responses.
  • color-spantrace provides a formatter for rendering span traces in the style of color-backtrace
  • color-eyre provides customized panic and eyre report handlers for eyre::Report for capturing span traces and backtraces with new errors and pretty printing them.
  • spandoc provides a proc macro for constructing spans from doc comments inside of functions.
  • tracing-wasm provides a Collector/Subscriber implementation that reports events and spans via browser console.log and User Timing API (window.performance).
  • tracing-web provides a layer implementation of level-aware logging of events to web browsers' console.* and span events to the User Timing API (window.performance).
  • test-log takes care of initializing tracing for tests, based on environment variables with an env_logger compatible syntax.
  • tracing-unwrap provides convenience methods to report failed unwraps on Result or Option types to a Collector.
  • diesel-tracing provides integration with diesel database connections.
  • tracing-tracy provides a way to collect Tracy profiles in instrumented applications.
  • tracing-elastic-apm provides a layer for reporting traces to Elastic APM.
  • tracing-etw provides a layer for emitting Windows ETW events.
  • sentry-tracing provides a layer for reporting events and traces to Sentry.
  • tracing-forest provides a subscriber that preserves contextual coherence by grouping together logs from the same spans during writing.
  • tracing-loki provides a layer for shipping logs to Grafana Loki.
  • tracing-logfmt provides a layer that formats events and spans into the logfmt format.
  • tracing-chrome provides a layer that exports trace data that can be viewed in chrome://tracing.
  • reqwest-tracing provides a middleware to trace reqwest HTTP requests.
  • tracing-cloudwatch provides a layer that sends events to AWS CloudWatch Logs.
  • clippy-tracing provides a tool to add, remove and check for tracing::instrument.

(if you're the maintainer of a tracing ecosystem crate not in this list, please let us know!)

Note: that some of the ecosystem crates are currently unreleased and undergoing active development. They may be less stable than tracing and tracing-core.

External Resources

This is a list of links to blog posts, conference talks, and tutorials about Tracing.

Blog Posts

Talks

Help us expand this list! If you've written or spoken about Tracing, or know of resources that aren't listed, please open a pull request adding them.

License

This project is licensed under the MIT license.

Contribution

Unless you explicitly state otherwise, any contribution intentionally submitted for inclusion in Tracing by you, shall be licensed as MIT, without any additional terms or conditions.

tracing's People

Contributors

amousset avatar baloo avatar cad97 avatar davidbarsky avatar dependabot-preview[bot] avatar dependabot[bot] avatar dvdplm avatar emschwartz avatar folyd avatar guswynn avatar hawkw avatar hds avatar jarrodldavis avatar jonhoo avatar jswrenn avatar jtescher avatar jyn514 avatar kaffarell avatar kleimkuhler avatar lenaschoenburg avatar luciofranco avatar lukemathwalker avatar nightmared avatar salewski avatar samscott89 avatar swsnr avatar taiki-e avatar waywardmonkeys avatar yaahc avatar zekisherif avatar

Stargazers

 avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar

Watchers

 avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar

tracing's Issues

The fmt subscriber should include timestamps by default

Feature Request

Crates

tokio-trace-fmt

Motivation

Currently there is no good way to get timestamped log entries with the tokio-trace-fmt subscriber. Even with full, timestamps are not included. This is surprising to those coming from other logging crates. It is also inconvenient to work around, as you would either need to add a custom field to all spans and events across all your crates, or write your own subscriber which sort of reduces the usefulness of fmt.

Proposal

full should include timestamps in logging output. It should be possible to turn timestamps on/off on the Builder. If we wanted to be fancy, it should also show the duration of spans, perhaps using something fast like quanta, but that's low priority.

trace [docs]: explain field vs attribute/meta syntax

The docs don't currently explain the difference between x: y and x = y syntax in span! and event! macros. It would be useful if that existed, and also told you what possible xs you can set in x: context for both span and event.

tracing-core: Replace macros with `const fn`s

Feature Request

Crates

tracing-core

Motivation

Since the minimum Rust version we support is now 1.34, we can now use const fn, which stabilized in Rust 1.31. There are a few types in tracing-core, such as Metadata, which have #[doc(hidden)] pub fields and are constructed by macros, but could be changed to have const fn constructors and private fields.

We should change this before releasing tracing-core 0.1

Ensure #[trace] macro works correctly for async functions.

copied from hawkw/tokio-trace-prototype#54:

Original discussion.

@hawkw

Also for potential future work: it would be cool to allow things that aren't functions to be traced. At the very least, it would be nice to detect if we're annotating a future, and instrument it in the "right way" --- by constructing the span once and wrapping the future in a tokio_trace_futures::Instrumented future.
The naïve approach—just putting the #[trace] macro on the implementation of Future::poll for that future—wouldn't do the Right Thing; it would instead create a new span that's entered for every individual time that future is polled. This could potentially be a big enough gotcha that I think it's probably worthwhile to special-case this.
We'd probably want to figure out a similar approach for async fns as well...
[my comment redacted]
Yes, but I think we'd want to make sure we do the right thing for async fns --- namely, I think we'd want to make sure that the future created by that async fn is instrumented by that span, rather than just the initial call to the async fn that returns the future. This may require some testing.

tokio-trace: how to use Spans to represent concurrency?

I've been reading the code for tokio-trace, and I've got some questions about Spans and how they're intended to be used.

It looks like they're pretty good at representing strictly nested time-periods, as you'd get with a function call tree. But its unclear to me if the direct children of a parent Span can overlap with each other (ie, representing long-term concurrent operations).

For example, if I have a Future which is managing 10 concurrent connections which it initiates at once and then waits for each of them to produce a result, could I represent that as a parent Span with 10 sub-Span representing each connection (which in turn may have sub-spans, etc)? It seems like that would't work because there's always a notion of "the" current Span.

Or is this not the intended level of granularity? Should I be using Span just to track specific calls to Future/Stream::poll and derive tracing at that level? I can see how that would be possible, but it seems like it would be hard to reconstruct application-level states from that level of granularity.

The example doesn't really help clarify this, because it omits all actual async behaviour.

On a more general level, is there a way to represent a dependency relationship in the trace? For example, if task A is waiting for something from task B, can that be recorded?

Add ignored parameters with `#[trace_ignore]`

As mentioned in #5:

...
Since some parameters may not be valid span fields, we might consider adding an additional attribute (#[trace_ignore]?) to annotate those fields that should be skipped.

I think this could be easier to add now that parameters are passed into span!. @hawkw was what you had in mind for this something like this?

#[trace]
#[trace_ignore(bar, baz)]
fn example(foo: t1, bar: t2, bar: t3) -> t4 {
    ...
}

fmt: Consider storing fields in a more structured way

Currently, the tokio-trace-fmt crate stores each span's fields as a single String in the span store. The intention is to improve performance by allowing the fields to be formatted a single time, and avoid making multiple allocations by reusing the string. When a span is formatted in order to print an event inside that span, we can simply write the string to the formatter's output.

However, there are some issues with this approach:

  • It doesn't play nice with field value replacement: tokio-trace-core does not prohibit code like this:

    let mut my_span = span!("my_span", my_field = "foo");
    span.record("my_field", &"bar");
    span.record("my_field", &"baz");

    Code like this could be useful in cases where there is a single logical span corresponding to some operation, but a value that span records changes dynamically.

    Currently, the above code will result in tokio-trace-fmt formatting my_span like this:

    my_span{my_field="foo" my_field="bar" my_field="baz"}
    

    which is probably not the desired output.

  • It makes filtering on span fields difficult: @LucioFranco is implementing a filter that allows conditionally enabling events and spans only when inside of a span where a field has a particular value. In the current approach, this would require searching the string. It would be nice if the filter could look up the specified field instead.

If we end up making this change, we'll probably want the span store to continue allowing allocation reuse. Thus, we could replace the string that lives in each slab slot and is re-used across spans with a collection type for storing field key-value pairs. When the span is closed, we could clear that collection (as we currently do with strings), allowing the allocation to be re-used.

Since the formatted representation of field values are typically fairly short, we might also want to look into using small-string optimization, to avoid having to allocate a whole bunch of strings like "1" and "false" on the heap. If we do this, we should try to measure the performance with and without SSO.

Distributed tracing

I saw a little bit of discussion of this in tokio-rs/tokio#561, but there aren't currently any open issues for it, so I figured I'd start one.

Distributed tracing is like tokio-trace but extended for distributed systems; instead of tracing only within a single process, you can trace code execution of code across process boundaries, machines, data centers, continents... There are a number of systems for this, e.g. Jaeger, zipkin, a bunch of others. Tokio-trace is perfectly set up to support distributed tracing, only the actual glue code needs to be written.

  1. Trace propagation -- in a distributed tracing system, incoming and outgoing requests to a process are annotated with some form of ID, so that they can be collated later. In the past, tracing systems defined their own bespoke propagation formats, but going forward it looks like people are standardizing on the W3C Trace Context Recommendation.

  2. Trace export -- after traces are recorded, they need to be sent to a central location for viewing. This can be done push-style (having your application connect somewhere and send data) or pull-style (exposing data on some port that can later be scraped). There are open APIs for doing this -- OpenTracing and OpenCensus, which are currently merging into OpenTelemetry.

I think the simplest path forward on this is to build:

  • A parser for W3C TraceContext
  • Integrations of that parser with various ecosystem libraries (http, hyper, grpc, actix, rocket, reqwests, ...).
  • An exporter for the OpenCensus service. That service acts as basically a multiplexer - you run a little daemon on your server and send traces to it, then it can send them to jaeger, zipkin, etc for you. OpenTelemetry will be backwards-compatible with this.

Ideally end users should be able to do:

fn main() {
    opencensus::export();
    actix_web::App::new()
       .middleware(TraceContextMiddleware::new())
       /* ... */
       .finish();
}

and have things just work ✨

tower_grpc compatibility with tokio_trace_tower_http

Can't seem to get it to work with latest tower_grpc:

let new_service = server::FooServer::new(handler);

let new_service =
            tokio_trace_tower_http::InstrumentedMakeService::new::<http::Request<tower_grpc::BoxBody>>>(new_service, serve_span.clone());

let mut server = Server::new(new_service);
error[E0369]: binary operation `>` cannot be applied to type `fn(_, tokio_trace::Span) -> tokio_trace_tower_http::InstrumentedMakeService<_, _> {tokio_trace_tower_http::InstrumentedMakeService::<_, _>::new::<http::request::Request<tower_grpc::body::BoxBody>>}`
   --> src/bin/server.rs:164:103
    |
164 |             tokio_trace_tower_http::InstrumentedMakeService::new::<http::Request<tower_grpc::BoxBody>>>(new_service, serve_span.clone());
    |             ------------------------------------------------------------------------------------------^--------------------------------- (foo::grpc::server::FooServer<Foo>, tokio_trace::Span)
    |             |
    |             fn(_, tokio_trace::Span) -> tokio_trace_tower_http::InstrumentedMakeService<_, _> {tokio_trace_tower_http::InstrumentedMakeService::<_, _>::new::<http::request::Request<tower_grpc::body::BoxBody>>}
    |
    = note: an implementation of `std::cmp::PartialOrd` might be missing for `fn(_, tokio_trace::Span) -> tokio_trace_tower_http::InstrumentedMakeService<_, _> {tokio_trace_tower_http::InstrumentedMakeService::<_, _>::new::<http::request::Request<tower_grpc::body::BoxBody>>}

It refuses to compile without the type annotation, so I've specified the one above, but I'm not sure it's correct. The following three were available:

tower_service::Service<()>>
tower_service::Service<http::request::Request<tower_grpc::body::BoxBody>>>
tower_service::Service<http::request::Request<tower_hyper::body::Body>>>

subscriber: High performance span store

Feature Request

Crates

tracing-subscriber

Motivation

In many use cases, Subscriber implementations will need to store data for each span over the course of that span's lifetime. Since the Subscriber interface is based on &self references, and a single subscriber is shared across multiple threads, storing mutable per-span data requires some kind of locking.

The naïve approach is to store spans in a RwLock<HashMap<Id, PerSpanData>> or similar structure, but this is not ideal; introducing a global lock means that any access to the span store by the subscriber is a global synchronization point. Instead, it's almost certainly better to use more granular locking, so that modifying the data for unrelated spans on two different threads need not cause the whole program to synchronize.

More granular approaches can be more complex to implement than using a simple global lock. So that subscriber implementations need not reinvent the wheel, the tracing-subscriber crate ought to provide batteries-included structures for storing per-span data.

Proposal

The tokio threadpool (and other work-stealing executors) try hard to ensure that individual tasks remain on the same worker thread, and that spans are often attached to a task, we should consider optimizing for a case where span accesses from the same thread are common but spans move across threads infrequently. Given this, a good approach might be one where the locking of span data is sharded by the thread where the span was created, in order to make access fast in the common case. When a span's data is used from another thread, we can "steal" the span from the thread where its data was previously used, a slower operation that's okay for the less common case.

Alternatives

There are other potential solutions to a fast span store. For example, tracing-fmt uses a slab where each entry (span) has its own lock. This may also be worth investigating.

tracing: Replace macro-rules with procedural macros

Feature Request

Crates

tracing

Motivation

Now that we are not supporting Rust 1.26.0 as our minimum compatible version, we can ship procedural macros in tracing. Replacing the existing macro_rules macros should improve user-facing error messages, make the macros more maintainable, and make it easier to add new features to them in the future (such as #83).

Proposal

The macros should be in a separate crate, but they should be re-exported by tracing. We should re-implement the existing macro syntax prior to adding any new features, and do that separately as a follow-up.

I think the new macros could live in the existingtracing-proc-macros or tracing-macros crates. Perhaps we should use tracing-macros and move everything currently in tracing-proc-macros there (and rewrite or remove the macros currently in tracing-macros, which are very experimental).

Clarify licensing?

Hi! I can't find any licensing information in the repository so far. Are you planning to license these crates under an MIT license, as tokio itself has? If so, it'd be awesome if one were added ASAP with the sign-off of existing contributors so that new contributions are appropriately licensed.

tracing: possible bug in when setting event parents

Bug Report

Crates

tracing

Description

When running tests that set explicit parents using the Event macros, the compiler emits warnings that the parent span is unused:

warning: unused variable: `p`
   --> tracing/tests/macros.rs:536:9
    |
536 |     let p = span!(Level::TRACE, "im_a_parent!");
    |         ^ help: consider prefixing with an underscore: `_p`
    |
    = note: #[warn(unused_variables)] on by default

warning: unused variable: `p`
   --> tracing/tests/macros.rs:558:9
    |
558 |     let p = span!(Level::TRACE, "im_a_parent!");
    |         ^ help: consider prefixing with an underscore: `_p`

warning: unused variable: `p`
   --> tracing/tests/macros.rs:581:9
    |
581 |     let p = span!(Level::TRACE, "im_a_parent!");
    |         ^ help: consider prefixing with an underscore: `_p`

warning: unused variable: `p`
   --> tracing/tests/macros.rs:604:9
    |
604 |     let p = span!(Level::TRACE, "im_a_parent!");
    |         ^ help: consider prefixing with an underscore: `_p`

warning: unused variable: `p`
   --> tracing/tests/macros.rs:627:9
    |
627 |     let p = span!(Level::TRACE, "im_a_parent!");
    |         ^ help: consider prefixing with an underscore: `_p`

warning: unused variable: `p`
   --> tracing/tests/macros.rs:650:9
    |
650 |     let p = span!(Level::TRACE, "im_a_parent!");
    |         ^ help: consider prefixing with an underscore: `_p`

This implies to me that the bug where the $LEVEL_span! macros didn't actually propagate parents to the span! macro parents, fixed in tokio-rs/tokio#1167, may also apply to the event macros, since support for setting explicit parents for events was merged after that fix.

If that's the case, we should fix this.

trace: Determine new syntax for uninitialized fields

Followup from #1062 and tokio-rs/tokio#1103 (comment).

Prior to #1103, the syntax field, was used by the tokio-trace macros to indicate span fields which have yet to have a value recorded. In order to support shorthand for using local variables as fields, we changed the meaning of this syntax, since local variable shorthand is likely to be a more common use-case (see #1103).

This leaves uninitialized fields without an appropriate macro syntax. There have been some suggestions, of which I think the strongest thus far are let field, and field = _,.

let field nicely mirrors the way let bindings with unset values are created in Rust; it does, however, seem somewhat inconsistent with the existing syntax, since other fields do not begin with let. On the other hand, field = _ fits in with the existing field syntax, but @carllerche has pointed out that it uses the assignment syntax to indicate something which is unassigned, which seems confusing.

We should try to agree on a new syntax for uninitialized fields, and re-enable support for them in the macros.

trace: Consider committing to 'static Span metadata

Subcrates

tokio-trace-core

Motivation

Currently, the span::Attributes type in tokio-trace-core contains a reference to Metadata with a generic lifetime 'a. This means that if a Subscriber wishes to store span metadata, it cannot simply store a &'static Metadata<'static>. Instead, it must extract the individual components from the metadata and store them in its own structure. In addition, while the name and FieldSet in a Metadata are always 'static, the target and file path are not. If the Subscriber needs to store those values, they must be cloned into a String on the heap.

This is somewhat unergonomic for subscriber implementors, in comparison to being able to use a &'static Metadata<'static> reference. In addition, it implies additional overhead when using certain parts of a span's metadata.

Proposal

It's necessary to have Metadata with a generic lifetime, in order to allow constructing Events from short-lived log records. However, this constraint does not apply to Spans, and in practice, spans always originate from static callsites. Thus, we should consider changing the Attributes type so that the 'a lifetime is only the lifetime of the ValueSet, and not the Metadata. The Attributes::metadata function could then return &'static Metadata<'static>, which subscribers could store as a reference rather than by copying fields out of it.

This would require changing the Attributes constructors to only accept 'static metadata, which is a breaking change. AFAICT, there isn't any way to make this change without breaking existing APIs. Thus, we should wait to actually make this change until a breaking core release is planned.

trace: Non-contextual span enter/leave

I am currently instrumenting tokio-tower, and am running into a use-case that I don't think tokio-trace really supports. I want to trace the full path of a given request through the system, so the request is given its own Span. That Span should be entered once when the request is first issued, and not be left again until the request eventually resolves, potentially much later and in some other context.

More concretely, the flow looks a little like this:

  • User wants to issue a request, and passes it to the client library.
  • The library creates a oneshot channel tx/rx pair and a Span.
  • The library enters the Span.
  • The library sends all these three over a channel to a spawned worker.
  • The worker does a bunch of asynchronous work, including handling other requests.
    As part of doing so, it also emits events related to each request's Span (if any).
  • Eventually, the request finishes, and a response is sent on the oneshot channel.
  • The library emits a final event for the request's Span marking its completion, and then leaves the Span.

#1109 is need to allow the worker to explicitly log events as part of a request's Span, since it is not executing "in the context of" any given Span. Beyond that however, there is no way to have the Span::enter and Span::leave as disjoint as this flow requires. Span::in_scope immediately leaves the span's scope, and Span::enter returns a guard that is tied to the lifetime of the Span.

There are a couple of options here as far as I can see:

  • Make Span::enter return an owned guard that increments the ref count of the Span. This has the upside of leaving the API simple, but increases the cost of Span::enter for everyone, even when it is not necessary.
  • Add Span::enter_owned (under some other name probably) alongside Span::enter, and have that return an owned guard which increments the ref count. This still ensures that the Span is entered and left correctly and isolates the cost to when it is needed, but complicates the API.
  • Add Span::emit_enter and Span::emit_leave which emit the Span's "enter" and "leave" events without returning a guard. This API can be mis-used so that multiple enter/leaves are emitted, but would be more efficient than incrementing the ref count for a guard.
  • Add Span::guard which consumes the Span and returns an owned guard. This is probably the nicest API, as it cannot be mis-used, doesn't increment the ref count, and adds only a single API method.

Reloading an EnvFilter in tokio-trace-fmt

I'm trying to use the filter reloading introduced in #45, but get stuck with cannot infer type for N, for example with:

let subscriber = FmtSubscriber::builder().with_filter_reloading().full().finish();
let reload_handle = subscriber.reload_handle();
reload_handle.reload(EnvFilter::from_default_env())

which gives:

|                     match reload_handle.reload(EnvFilter::from_default_env()) {
|                                         ^^^^^^ cannot infer type for `N`

(But N cannot be specified because of impl Into)
Am I missing something?

subscriber: Rewrite the subscriber-util crate

This is a tracking issue for getting the subscriber crate into an actually usable state.

  • generalize the Store/Context types from the fmt crate into something reusable
  • better registry/context trait, and have the store impl it
  • update the teeable traits (currently Observe) to be compatible with the current API
  • update the filtering traits to be more like the ones in fmt
  • downcasting story (see tokio-rs/tokio#974)

Tracking issue for composing multiple subscribers

Feature Request

Crates

tracing-subscriber

Motivation

In many cases, it is valuable to compose multiple consumers for trace events. However, certain aspects of tracing's design --- in particular, that span IDs are assigned by the subscriber, and that a single subscriber collects events from multiple threads --- make it difficult to compose the Subscriber trait directly.

Proposal

I think it should be possible to implement subscriber composition in the tracing-subscriber crate without making changes to tracing-core. Here's how I think we should do this:

  • Provide a Layer/Middleware-like approach for composing multiple consumers (which don't get to assign span IDs) around a single core subscriber that does assign IDs. I have a work in progress implementation of this, and will open a draft PR for discussion.
  • Provide a similar interface for composing filters, based on logical combinators, that slots into the Layer interface.
  • Provide an optimized concurrent structure for subscriber implementations to use for storing span data. I have some thoughts on this, which I described in #157. This will give subscriber layers an alternative to Mutex<HashMap<Id, MyPerSpanData>> and similar bad ideas.
  • Update existing subscriber implementations to be compatible with this API.
  • Investigate combinators like tees as well.

Alternatives

There are other potential ways to implement subscriber fan-out.

In the past, I've considered an approach where there is a central registry that manages per-span data and provides it to multiple consumers. I think this introduces a lot of complexity and is hard to come up with a design that satisfies the needs of various subscribers --- this is a big part of why tools for subscriber composition haven't landed sooner.

@davidbarsky proposed modifying the Dispatch type in tracing-core to take a slice of subscribers and iterate over them. I don't think this is the right approach for the following reasons:

  • It's a change in tracing-core, which I really don't think is necessary to implement this. IMO, if we can do it in a crate on top of -core, we should.
  • This approach does not solve the problem that all spans must have a single ID. If the dispatcher iterates over multiple implementations of the Subscriber trait, we would need a method for determining whose ID is the authoritative one. This could lead to very surprising behaviour when implementations expect their IDs to be used.
  • Similarly, it is difficult to reason about whether or not a span is enabled in such a world.

Finally, we could do nothing. Many implementations are already writing ad-hoc versions of the layered/stacked subscriber I described above (@LucioFranco's experiments w/ this was part of the inspiration behind the design I proposed). However there are several pitfalls/gotchas that ad-hoc implementations need to avoid, while if we provide a principled implementation in a library, it is only necessary to solve these problems once.

Void spans

Feature Request

Crates

tracing

Motivation

In tokio-tower, and elsewhere, I have cases where I may or may not want to include a Span with something like a request. For example, I want to trace only a certain subset of the requests. To do that, I currently have to keep an Option<Span> along with some code like:

let _guard = self.span.map(Span::enter);

Proposal

The solution outlined above works okay, but it'd be nicer if there existed a sort of "void" Span that was free to produce, and that did nothing when entered. Ideally I would also not need to give Metadata for it, since it shouldn't ever be used.

trace: Support setting event parent events explicitly

Motivation

Currently, the tokio-trace span macros allow setting the parent span explicitly as a parameter of the macro, as well as contextually. However, events created via the event macros always have their parents determined contextually. It would be nice to allow setting explicit parents for events as well (as @jonhoo mentioned in #1065).

Implementation

Making this change will require changes in both tokio-trace and tokio-trace-core. I believe we can do this somewhat like so:

  1. In the tokio-trace-core crate, move the Parent type out of the span module, and make it pub(crate), so that it can be used in the event module as well.
  2. Add a parent: Parent field to the Event type.
  3. Add a new variant1 of the Event::dispatch function to construct and observe an event with an explicit parent, similar to span::Attributes::child_of. I'm not sure whether or not we also want to allow events to be created without parents (similar to span::Attributes::new_root), but if so, we can add an explicit no parent function as well.
  4. Add the parent accessor methods from span::Attributes to Event as well. We could consider factoring out the logic to the Parent type and have Event and Attributes call those functions on Parent, in order to reduce repetition, but the implementation is simple enough that I'm not sure if that's strictly necessary.
  5. In the tokio-trace crate, add match arms to the event! macro that accept a parent: field and construct new events with parents. These will look similar to this match arm from the span! macro, but changed to construct events.
  6. Add similar match arms to the error!, warn!, info!, debug!, and trace! macros that expand to the appropriate invocations of the event! macro. The similarly-named leveled span macros can be used as a guide.

This should not require a breaking change.


1We will want to create a new function rather than add a new parameter to the existing Event::dispatch function, as adding a new parameter is a breaking change in tokio-trace-core.

trace: When a span's explicit parent is disabled, the parent should probably be contextual

In tokio-trace, when constructing a span using Span::child_of, we accept a type that can provide us an Option<&Id> as the span's parent. This allows writing code like this:

let foo = span!(Level::TRACE, ...);
let bar = span!(Level::INFO, parent: &foo, ...);

It's necessary to take an Option<&Id> here rather than just &Id, as the parent span may not be enabled --- for example, in the snippet above, we might have a filter set that accepts spans with Level::DEBUG and lower, so foo would be disabled.

Currently, if the parent span is disabled, we call Attributes::new_root:
https://github.com/tokio-rs/tokio/blob/84d5a7f5a0660dbe1e2be0e831e715f13cb59a2b/tokio-trace/src/span.rs#L251-L254

I think this behaviour is fairly surprising. Consider the following:

let foo = info_span!(...);
let _guard = foo.enter();

let bar = trace_span!(...);
let baz = info_span!(parent: &bar, ...);

If we run this code with the max verbosity level set to INFO, bar is disabled, so baz's parent is None, making it the root of a new trace tree. This seems incorrect to me --- I'd only expect a span to be a root if I explicitly set it to not have a parent. Instead, in the case where the explicitly set parent is disabled, I'd expect the span to have a contextual parent.

trace-core: Support creating an event outside of a subscriber context

During my implementation of a rate limiter subscriber that wraps another subscriber like tokio-trace-fmt I ran into the want to create a custom rollup event within the Subscriber::event trait fn. Since we are outside of a subscriber context we can not use Event::dispatch but I want an Event that I can pass to the inner subscriber that contains custom attributes and a custom message.

The proposed solution is to create a Event::new that takes a Metadata and FieldSet and returns a new Event.

cc @hawkw

tracing 0.1 fails to compile with `log` feature enabled

Hello! I am very excited to switch from tokio-trace 0.1 to tracing 0.1! Sadly I appear to be unable to compile the new release with the log feature enabled.

Platform

Windows 64-bit

Crates

Cargo.toml:

tracing = { version = "0.1", features = ["log"] }

Compiler error:

   Compiling tracing v0.1.0
       Fresh syn v0.15.39
     Running `rustc --crate-name tracing C:\Users\adam\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.0\src\lib.rs --color always --crate-type lib --emit=dep-info,metadata,link -C debuginfo=2 --cfg "feature=\"log\"" -C metadata=22d8d61eee879087 -C extra-filename=-22d8d61eee879087 --out-dir C:\Users\adam\Documents\GitHub\moxie\target\debug\deps -L dependency=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps --extern cfg_if=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\libcfg_if-43544de485dae8ac.rlib --extern log=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\liblog-78ad9be729e51666.rlib --extern tracing_core=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\libtracing_core-db15944ba314627e.rlib --cap-lints allow`
       Fresh proc-macro-hack v0.5.7
       Fresh topo-macro v0.8.0 (C:\Users\adam\Documents\GitHub\moxie\topo\macro)
       Fresh futures-select-macro-preview v0.3.0-alpha.16
   Compiling topo v0.8.0 (C:\Users\adam\Documents\GitHub\moxie\topo)
     Running `rustc --edition=2018 --crate-name topo topo\src\lib.rs --color always --crate-type lib --emit=dep-info,metadata,link -C debuginfo=2 -C metadata=f800424da5f8c4bc -C extra-filename=-f800424da5f8c4bc --out-dir C:\Users\adam\Documents\GitHub\moxie\target\debug\deps -C incremental=C:\Users\adam\Documents\GitHub\moxie\target\debug\incremental -L dependency=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps --extern owning_ref=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\libowning_ref-4e7c10f045132e25.rlib --extern scopeguard=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\libscopeguard-6b874d16a23e70b9.rlib --extern topo_macro=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\topo_macro-584f7209c63cec74.dll`
error[E0616]: field `level` of struct `tracing_core::Metadata` is private
   --> C:\Users\adam\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.0\src\span.rs:678:34
    |
678 |             .level(level_to_log!(self.meta.level))
    |                                  ^^^^^^^^^^-----
    |                                            |
    |                                            help: a method `level` also exists, call it with parentheses: `level()`

error[E0616]: field `target` of struct `tracing_core::Metadata` is private   --> C:\Users\adam\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.0\src\span.rs:679:21
    |
679 |             .target(self.meta.target)
    |                     ^^^^^^^^^^------
    |                               |
    |                               help: a method `target` also exists, call it with parentheses: `target()`

error[E0616]: field `module_path` of struct `tracing_core::Metadata` is private
   --> C:\Users\adam\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.0\src\span.rs:685:34
    |
685 |                     .module_path(self.meta.module_path)
    |                                  ^^^^^^^^^^-----------
    |                                            |
    |                                            help: a method `module_path` also exists, call it with parentheses: `module_path()`

error[E0616]: field `file` of struct `tracing_core::Metadata` is private
   --> C:\Users\adam\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.0\src\span.rs:686:27
    |
686 |                     .file(self.meta.file)
    |                           ^^^^^^^^^^----
    |                                     |
    |                                     help: a method `file` also exists, call it with parentheses: `file()`

error[E0616]: field `line` of struct `tracing_core::Metadata` is private
   --> C:\Users\adam\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.0\src\span.rs:687:27
    |
687 |                     .line(self.meta.line)
    |                           ^^^^^^^^^^----
    |                                     |
    |                                     help: a method `line` also exists, call it with parentheses: `line()`

error: aborting due to 5 previous errors

For more information about this error, try `rustc --explain E0616`.
error: Could not compile `tracing`.

Caused by:
  process didn't exit successfully: `rustc --crate-name tracing C:\Users\adam\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.0\src\lib.rs --color always --crate-type lib --emit=dep-info,metadata,link -C debuginfo=2 --cfg "feature=\"log\"" -C metadata=22d8d61eee879087 -C extra-filename=-22d8d61eee879087 --out-dir C:\Users\adam\Documents\GitHub\moxie\target\debug\deps -L dependency=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps --extern cfg_if=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\libcfg_if-43544de485dae8ac.rlib --extern log=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\liblog-78ad9be729e51666.rlib --extern tracing_core=C:\Users\adam\Documents\GitHub\moxie\target\debug\deps\libtracing_core-db15944ba314627e.rlib --cap-lints allow` (exit code: 1)

Cargo.lock:

# This file is automatically @generated by Cargo. # It is not intended for manual editing. [[package]] name = "cfg-if" version = "0.1.9" source = "registry+https://github.com/rust-lang/crates.io-index"

[[package]]
name = "lazy_static"
version = "1.3.0"
source = "registry+https://github.com/rust-lang/crates.io-index"

[[package]]
name = "log"
version = "0.4.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
dependencies = [
"cfg-if 0.1.9 (registry+https://github.com/rust-lang/crates.io-index)",
]

[[package]]
name = "test-tracing"
version = "0.1.0"
dependencies = [
"tracing 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)",
]

[[package]]
name = "tracing"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
dependencies = [
"cfg-if 0.1.9 (registry+https://github.com/rust-lang/crates.io-index)",
"log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)",
"tracing-core 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)",
]

[[package]]
name = "tracing-core"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
dependencies = [
"lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)",
]

[metadata]
"checksum cfg-if 0.1.9 (registry+https://github.com/rust-lang/crates.io-index)" = "b486ce3ccf7ffd79fdeb678eac06a9e6c09fc88d33836340becb8fffe87c5e33"
"checksum lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)" = "bc5729f27f159ddd61f4df6228e827e86643d4d3e7c32183cb30a1c08f604a14"
"checksum log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)" = "c84ec4b527950aa83a329754b01dbe3f58361d1c5efacd1f6d68c494d08a17c6"
"checksum tracing 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "ff6ff2664f0b91870d297cd3e51be6980057273998844578fb392487cb93cfc1"
"checksum tracing-core 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "7d5f34cae5ddd9e2dab25f17ff18acec0832b35c8d0ef9a9528737da74370b4b"

tokio-trace-futures' instrument can be a little clunky for functions that return a Future but do other work first

With a lot of help from @hawkw I've got a branch that uses tokio-trace for logging in sccache. I used a span to instrument a Future but was confused by the fact that some of my log messages didn't have the span fields attached. As it turns out it's because the function being called does some immediate work (including logging some messages) before it returns a Future to do the rest of the work, so only the work within the Future gets instrumented. I was able to work around this by doing something like:

let mut span = span!("compile");
let task = span.enter(|| {
  do_some_work()
});
spawn(Box::new(task.instrument(span)));

It might be nice to have a better API to support this use case. Perhaps a utility method on Span like enter_instrument that calls enter but expects the block to produce a Future which it will then instrument before returning? Then that code could instead look like:

let task = span!("compile").enter_instrument(|| {
  do_some_work()
});
spawn(Box::new(task));

Set up CI

We can probably base our config on the .travis.yml from the tokio-trace-prototype repo, modulo the following:

  • remove tokio-trace and tokio-trace-core crates from the tests (as they live in the tokio-rs/tokio repo)
  • add tokio-trace-macros to the crates tested in the main script
  • change the "test proc macros" step to test tokio-trace-proc-macros instead of tokio-trace-macros

Add span and event macros that are only enabled in debug mode

See also tokio-rs/tokio#827 (review).

It would be nice to have debug_span! and debug_event! macros in the tokio-trace-macros crate which are only enabled in debug mode builds.

We can detect debug mode with

#[cfg(debug_assertions)]

In debug mode, these macros would behave identically to the tokio_trace crate's span! and debug! macros. In release mode (i.e. #[cfg(not(debug_assertions))]) the debug_span! macro would always evaluate to a disabled span struct (Span::new_disabled()) while debug_event! would do nothing.

Rename to tracing

Crates

all

Motivation

As described in tokio-rs/tokio#1159 (comment), the name tokio-trace has created the incorrect impression that using this library requires the tokio runtime.

Proposal

We are in the process of moving the main crates from the tokio repository to this repository, and have renamed the repository to tracing. At the same time, we will rename the nursery crates as well.

  • Rename repository
  • Move core crates (tokio-rs/tokio#1159)
  • Rename core crates
  • Rename nursery crates
  • Update README, CONTRIBUTING, and RustDocs
  • Update any links

Alternatives

We may also want to rename some of the compatibility crates to use a different format --- I'm considering renaming tokio-trace-tower to tower-tracing instead of tracing-tower.

Explore whether to use syn-md

syn-mid seems like an interesting library that provides constructs such as “functions whose bodies aren't parsed” and “blocks whose bodies aren't parsed”. This might help with some of the attribute macros.

trace-core: Consider adding follows_from to `Attributes`

It might be worthwhile to consider adding a set of span IDs that a span follows from to the span::Attributes type in tokio-trace-core.

Currently, when a span is created with field values already specified, it provides those values in the Attributes struct passed to Subscriber::new_span, rather than calling Subscriber::record multiple times after the call to new_span returns. This avoids taking another trip through the dispatcher for each field. In contrast, if we wish to create a span and know the other span IDs it follows from up front, it is still necessary to create the span and then call record_follows_from on it for each span ID it follows from.

The nice thing about using an opaque args struct such as Attributes is that we can add more arguments to new_span without changing the method's signature. So, we could add follows-from IDs to it without a breaking change.

metrics: Introduce `tracing-metrics` subscriber/crate

This is a tracking issue for introducing a new tokio-trace-metrics crate that will contain a metrics-based subscriber and traits that metrics providers can implement:

  • Create a Metrics subscriber
  • Provide a Metrics agnostic backend trait

trace_span no longer compiles in 0.1.1

Bug Report

Version

tracing: 0.1.1

Description

Attempt to compile this program with tracing = "0.1.1" in Cargo.toml:

fn main() {
    tracing::trace_span!("foo");
}

It fails to compile on both rustc 1.35.0 and 1.36.0 with

error: cannot find macro `trace_span!` in this scope
 --> src/main.rs:2:5
  |
2 |     tracing::trace_span!("foo");
  |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  |
  = note: this error originates in a macro outside of the current crate (in Nightly builds, run with -Z external-macro-backtrace for more info)

It compiles fine with tracing = "=0.1.0"

trace: support string interpolation

Log readability is significantly improved by interleaving information with text, rather than supplying a static string followed by a set of key-value pairs. tokio-trace's macros should support constructing such interpolated strings while preserving the interpolated data as structured fields.

Additionally, any out-of-the-box subscribers targeting direct human consumption (such as by printing to stdout) should not duplicate interpolated values in its output. This could be accomplished without compromising support for users that prefer not to use interpolation by using a distinct field name for message strings that include interpolated data, and establishing that human-oriented subscribers should only display unrecognized key-value pairs if an interpolated message field is not present.

log: Cache interests

Feature Request

Crates

tokio-trace-log

Motivation

Currently, after #70, the LogTracer struct in tokio-trace-log will call Subscriber::enabled every time an event occurs. This is not great. It would be nice if we could register callsites for these events with the subscriber, and cache interests for them.

Proposal

Unfortunately, we cannot call Subscriber::enabled in our implementation of Log::enabled, since we don't have enough information to construct a tokio_trace::Metadata. However, I think we could use a hash of the log::Record's location data to key a map of Interests for each log record, which would allow us to call register_callsite once for each record. When the Callsite::clear_interest method is called on our fake static callsite from which all log events originate, we can blow away this cache.

Tokio-trace docs

It might be helpful to have:

  • a link to tokio-trace in the main tokio README
  • links to the various tokio-trace subscribers in the tokio-trace README, similar to how log lists loggers
  • a README for tokio-trace-nursery and its various subcrates
  • docs for how to setup tokio-trace across a whole program, instead of just on a single thread. (I honestly don't know how to do this, e.g. if i'm using runtime and want the executor threads instrumented.)

fmt: EnvFilter should allow `off` directives

The env_logger crate allows log directives ending in off to disable all logging from a matching target. However, tokio-trace-fmt's EnvFilter does not:

ignoring invalid log directive 'linkerd2_proxy::proxy::canonicalize=off'
ignoring invalid log directive 'linkerd2_proxy::proxy::http::router=off'
ignoring invalid log directive 'linkerd2_proxy::proxy::tcp=off'

We should add support for off directives.

Utility for filtering fields at the visitor level

Feature Request

Crates

  • tokio-trace-subscriber
  • possibly tokio-trace-fmt

Motivation

Spans and events may be created with up to 32 fields. In many cases, these fields will provide fairly verbose diagnostic information about the program. Sometimes, users may wish to record data about a span or event, but exclude particularly verbose data attached to it (such as fields provided by libraries).

For example, tokio-trace-futures currently adds fields describing the task to spans generated by the spawn! macro. In the future, the tokio runtime will likely enrich these spans with additional information about the task's state in the executor. It's likely that this additional information will only be necessary when diagnosing issues involving the executor or the application's interaction with it, so users probably will not typically want to display them by default. Fortunately, the introduction of . into the permissible field name characters allows "namespacing" these fields; for example, task-specific data is currently in fields with names such as tokio.task.$FIELD.

Proposal

I propose adding a utility for wrapping a Visit implementation with a FieldFilter (or similar) struct. This wrapper would implement Visit by checking if field names match a filter, and if they do not, it would do nothing. Otherwise, it would forward to the wrapped visitor. This could live in tokio-trace-subscriber, as it's primarily a tool for subscriber implementors to use.

Additionally, we'd have functions for constructing a "field filter" from various types, such as a Fn(&Field) -> bool, and a list of allowed or denied patterns.

As a proposal, I suggest a grammar for constructing allow/deny lists from strings similar to the EnvFilter in tokio-trace-fmt. A single filter pattern would consist of:

  • a field name: matches that field name exactly.
    • for example, tokio.task.is_spawned, message, user.email
  • single globs: a single asterisk * should match up to the next . character.
    • for example:
      • tokio.task.* would match any field name beginning with tokio.task. followed by one more Rust identifier
      • tokio.*.is_spawned: matches any field name beginning with tokio., followed by a single rust identifier segment, followed by .is_spawned
      • tokio.task.is_*: matches tokio.task.is_spawned, tokio.task.is_blocking, tokio.task.is_parked, and so on.
      • *.*.* matches any field name consisting of exactly three dotted segments
  • ** double globs**: two asterisks (**) would match any number of characters.
    • for example:
      • tokio.** would match tokio.task.is_spawned,tokio.runtime, tokio.task.state.is_blocked, and so on
      • **.is_spawned: matches tokio.task.is_spawned, romio.is_spawned, foo.executor.state.is_spawned, std.thread.is_spawned, and so on
      • **: matches anything

We could parse an allow/deny list from a comma separated list of the above patterns.

Additionally, we could add syntax to filters that are dependent on the name of the span/event the field is on, as well as the field name itself. I think that should probably be a follow-up issue, since it requires an API for informing the visitor what the span's name is.

Alternatives

Rather than implementing our own globbing syntax, we could use regular expressions. This might be simpler to implement, since we can use existing regex libraries, and would allow more flexible filters.

However, since we have a much more restricted grammar for field names than "all UTF-8 characters", there are advantages for not allowing full regular expressions. For example, since , is not a valid field name character, we can parse a list of patterns from a comma-separated string. However, if we accept arbitrary regexen, , may be part of a regex, rather than a separator between regexen.

Similarly, . is a special character with a defined meaning in most regex implementations. This means that regexen that match tokio-trace field names with .s would need to escape every . character. This would lead to regexen like foo\..+.bar, which is awkward and hard to parse.

Finally, it would be possible to construct a regex that matches only field names that are invalid and will never occur. Allowing such a regex and testing all field names against it seems inefficient. Using our own globbing syntax would allow us to reject patterns that will never match a field.

Update to 2018 edition

Now that the minimum Rust version is 1.34.0, we should consider migrating all tracing crates to the 2018 edition.

Serde compatibility crate

There ought to be a compatibility crate allowing fields to be recorded using serde.

I think we could do this by having a newtype that wraps a type implementing serde's Serializer trait and implements the tokio-trace-core's Visit trait by dispatching to the appropriate Serializer trait methods.

Then, we could have newtypes that wrap tokio-trace-core's Event, Attributes, and Record types and implement the Serialize trait from serde by wrapping the passed in serializer with the newtype that implements Visit and using it to record the fields on the event or span. We should probably also serialize span IDs and metadata as well. I think we would probably want to serialize the metadata using serialize_struct and the fields using serialize_map.

trace [docs]: docs should make clear what a "target" is

Maybe I missed it, but it wasn't clear to me what a "target" was, or what I might set it to. @hawkw pointed me to the log docs, which say:

A log request consists of a target, a level, and a body. A target is a string which defaults to the module path of the location of the log request, though that default may be overridden. Logger implementations typically use the target to filter requests based on some user configuration.

Having something similar, maybe with some more context, would be helpful.

tracing: span! and event! macros are inconsistent

Bug Report

Crates

tracing

Description

The span! and event! macros in tracing are inconsistent. span! takes attribute arguments (target:, parent:) after the verbosity level, while event! puts them before. We should make both macros consistent.

The format used by event! is closer to the log crate's log! macro, so personally, I think we should change span!.

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.