🎓 A1Learner
🔍

Rust Tracing Events and Spans

Tracing records events and groups them inside spans. An event is one moment in the program, and a span is a named stretch of work.

An event is one moment

The macros match the log crate. This line prints at once, with the level padded to five letters:

info!("till opened");

A span is a stretch of work

info_span! builds a span. enter() starts it. Events written while the guard lives carry the span and its field:

let span = info_span!("checkout", order_id = 42);
let _guard = span.enter();
info!("scanning items");

Spans nest

Start a second span inside the first. The event now carries both, outermost first:

let pay = info_span!("payment", method = "card");
let _pay_guard = pay.enter();
info!("card approved");

Drop the guard, end the span

The checkout guard drops here. The next event stands alone again:

drop(_guard);
info!("till closed");

entered() does both steps

span.entered() builds the span and enters it in one call. Most code uses this shorter form:

let _guard = info_span!("checkout", order_id = 42).entered();

Example

// Cargo.toml: tracing = "0.1" (resolved 0.1.44), tracing-subscriber = "0.3" (resolved 0.3.23)
use tracing::{debug, info, info_span, warn, Level};

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(Level::DEBUG)
        .with_target(false)
        .without_time()
        .with_ansi(false)
        .init();

    info!("till opened");
    let span = info_span!("checkout", order_id = 42);
    let _guard = span.enter();
    info!("scanning items");
    debug!("read barcode 987-1");
    {
        let pay = info_span!("payment", method = "card");
        let _g2 = pay.enter();
        info!("card approved");
    }
    warn!("receipt paper is low");
    drop(_guard);
    info!("till closed");
}

Key points

  • Event: one moment in the program, written with info!, debug!, warn!, error! or trace! — the same five levels as the log crate
  • Span: a stretch of work with a name and fields, like checkout with order_id 42.
  • Events inside it carry its name
  • Use span.enter() to start the context.
  • It hands back a guard, and the span ends when the guard drops
  • Spans nest: an event prints every span around it, outermost first
  • Nothing prints until the final program installs a subscriber.
  • Libraries add events and spans only, and never choose the printer

In this example, the fmt subscriber prints the events. with_target(false) hides module paths. without_time() hides the clock, and with_ansi(false) turns off the colours a terminal would add, so this output is exact. The first event stands alone. Then the checkout span starts, and every event until the drop carries checkout{order_id=42}. The payment span lives inside a block. So it ends at the closing brace. Its one event carries both spans. The warn line still sits inside checkout. After drop(_guard), the last event stands alone again. Notice what printed nothing: the spans themselves. A span prints no line of its own. It lends its name and fields to the events inside it.

Note

In Rust a span is a value you hold, not a block you mark.

The guard ties the span to ownership, so it ends exactly where the guard drops.

Try it Yourself

Edit the code, then press Run.

Running is simulated · Rust Playground

Exercise

An event prints as checkout{order_id=42}: payment taken. What does the first part tell you?