Crate tracing_forest

Preserve contextual coherence among trace data from concurrent tasks.

Overview

tracing is a framework for instrumenting programs to collect structured and async-aware diagnostics via the Subscriber trait. The tracing-subscriber crate provides tools for composing Subscribers from smaller units. This crate extends tracing-subscriber by providing ForestLayer, a Layer that preserves contextual coherence of trace data from concurrent tasks when logging.

This crate is intended for programs running many nontrivial and disjoint tasks concurrently, like server backends. Unlike other Subscribers which simply keep track of the context of an event, tracing-forest preserves the contextual coherence when writing logs even in parallel contexts, allowing readers to easily trace a sequence of events from the same task.

tracing-forest is intended for authoring applications.

Getting started

The easiest way to get started is to enable all features. Do this by adding the following to your Cargo.toml file:

tracing-forest = { version = "0.1.6", features = ["full"] }

Then, add tracing_forest::init to your main function:

fn main() {
    // Initialize a default `ForestLayer` subscriber
    tracing_forest::init();
    // ...
}

This crate also provides tools for much more advanced configurations:

use tracing_forest::{traits::*, util::*};

#[tokio::main]
async fn main() {
    tracing_forest::worker_task()
        .set_global(true)
        .map_sender(|sender| sender.or_stderr())
        .build_on(|subscriber| subscriber
            .with(EnvFilter::from_default_env())
            .with(LevelFilter::INFO)
        )
        .on(async {
            // -- snip --
        })
        .await;
}

For useful configuration abstractions, see the runtime module documentation.

Contextual coherence in action

Similar to this crate, the tracing-tree crate collects and writes trace data as a tree. Unlike this crate, it doesn’t maintain contextual coherence in parallel contexts.

Observe the below program, which simulates serving multiple clients concurrently.

use tracing::info;
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, Registry};
use tracing_tree::HierarchicalLayer;

#[tracing::instrument]
async fn conn(id: u32) {
    for i in 0..3 {
        some_expensive_operation().await;
        info!(id, "step {}", i);
    }
}

#[tokio::main(flavor = "multi_thread")]
async fn main() {
    // Use a `tracing-tree` subscriber
    Registry::default()
        .with(HierarchicalLayer::default())
        .init();

    let connections: Vec<_> = (0..3)
        .map(|id| tokio::spawn(conn(id)))
        .collect();

    for conn in connections {
        conn.await.unwrap();
    }
}

tracing-tree isn’t intended for concurrent use, and this is demonstrated by the output of the program:

conn id=2
conn id=0
conn id=1
  23ms  INFO step 0, id=2
  84ms  INFO step 0, id=1
  94ms  INFO step 1, id=2
  118ms  INFO step 0, id=0
  130ms  INFO step 1, id=1
  193ms  INFO step 2, id=2

  217ms  INFO step 1, id=0
  301ms  INFO step 2, id=1

  326ms  INFO step 2, id=0

We can instead use tracing-forest as a drop-in replacement for tracing-tree.

use tracing::info;
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, Registry};
use tracing_forest::ForestLayer;

#[tracing::instrument]
async fn conn(id: u32) {
    // -- snip --
}

#[tokio::main(flavor = "multi_thread")]
async fn main() {
    // Use a `tracing-forest` subscriber
    Registry::default()
        .with(ForestLayer::default())
        .init();

    // -- snip --
}

Now we can easily trace what happened:

INFO     conn [ 150µs | 100.00% ] id: 1
INFO     ┝━ ｉ [info]: step 0 | id: 1
INFO     ┝━ ｉ [info]: step 1 | id: 1
INFO     ┕━ ｉ [info]: step 2 | id: 1
INFO     conn [ 343µs | 100.00% ] id: 0
INFO     ┝━ ｉ [info]: step 0 | id: 0
INFO     ┝━ ｉ [info]: step 1 | id: 0
INFO     ┕━ ｉ [info]: step 2 | id: 0
INFO     conn [ 233µs | 100.00% ] id: 2
INFO     ┝━ ｉ [info]: step 0 | id: 2
INFO     ┝━ ｉ [info]: step 1 | id: 2
INFO     ┕━ ｉ [info]: step 2 | id: 2

Categorizing events with tags

This crate allows attaching supplemental categorical information to events with Tags.

Without tags, it’s difficult to distinguish where events are occurring in a system.

INFO     ｉ [info]: some info for the admin
ERROR    🚨 [error]: the request timed out
ERROR    🚨 [error]: the db has been breached

Tags help make this distinction more visible.

INFO     ｉ [admin.info]: some info for the admin
ERROR    🚨 [request.error]: the request timed out
ERROR    🔐 [security.critical]: the db has been breached

See the tag module-level documentation for details.

Attaching Uuids to trace data

When the uuid feature is enabled, the ForestLayer will automatically attach Uuids to trace data. Events will adopt the UUID of their span, or the “nil” UUID at the root level. Spans will adopt the UUID of parent spans, or generate a new UUID at the root level.

A span’s Uuid can also be passed in manually to override adopting the parent’s Uuid by passing it in as a field named uuid:

let id = Uuid::new_v4();

let span = info_span!("my_span", uuid = %id);

It can also be retreived from the most recently entered span with tracing_forest::id:

let id = Uuid::new_v4();

info_span!("my_span", uuid = %id).in_scope(|| {
    let current_id = tracing_forest::id();

    assert!(id == current_id);
});

Immediate logs

Since tracing-forest stores trace data in memory until the root span finishes, it can be a long time until a log is written. This may not be acceptable in certain use cases.

To resolve this, the immediate field can be used on an event to print the event and its parent spans to stderr. Unlike eprintln!, the event will still appear in the trace tree written once the root span closes.

Example

use tracing::{info, trace_span};

tracing_forest::init();

trace_span!("my_span").in_scope(|| {
    info!("first");
    info!("second");
    info!(immediate = true, "third, but immediately");
});

INFO     ｉ IMMEDIATE ｉ my_span > third, but immediately
TRACE    my_span [ 125µs | 100.000% ]
INFO     ┝━ ｉ [info]: first
INFO     ┝━ ｉ [info]: second
INFO     ┕━ ｉ [info]: third, but immediately

Feature flags

This crate uses feature flags to reduce dependency bloat.

• full: Enables all features listed below.
• uuid: Enables spans to carry operation IDs.
• chrono: Enables timestamps on trace data.
• ansi: Enables ANSI terminal colors.
• smallvec: Enables some performance optimizations.
• tokio: Enables worker_task and capture.
• serde: Enables log trees to be serialized, which is useful for formatting.
• env-filter: Re-exports EnvFilter from the util module.

By default, only smallvec in enabled.

Re-exports

• pub use printer::Formatter;
• pub use printer::PrettyPrinter;
• pub use printer::Printer;
• pub use processor::Processor;
• pub use tag::Tag;
• pub use runtime::capture;
• pub use runtime::worker_task;

Modules

• printer
  Utilities for formatting and writing trace trees.
• processor
  Trait for processing log trees on completion.
• runtime
  Run asynchronous code in the context of a tracing-forest subscriber.
• tag
  Supplement events with categorical information.
• traits
  Bring traits from this crate, tracing, and tracing_subscriber into scope anonymously.
• tree
  The core tree structure of tracing-forest.
• util
  Bring Tracing’s event and span macros into scope, along with other sensible defaults.

Structs

• ForestLayer
  A Layer that collects and processes trace data while preserving contextual coherence.

Functions

• id
  Gets the current Uuid of an entered span within a tracing-forest subscriber.
• init
  Initializes a global subscriber with a ForestLayer using the default configuration.
• test_init
  Initializes a global subscriber for cargo tests with a ForestLayer using the default configuration.