🎓 A1Learner
🔍

Rust Tracing in Async Code

Tracing ties each log span to its future, not to a thread. Async tasks take turns on shared threads.

instrument an async fn

The same attribute works. The span wakes and sleeps with the future. This is its first line in the closing program:

#[instrument]
async fn wash(order_id: u32, millis: u64) {
    info!("wash started");
    tokio::time::sleep(Duration::from_millis(millis)).await;

Two tasks, two contexts

While wash sleeps at its await, dry runs on the same thread. Read the middle of the closing output. Dry's lines sit between wash's pair, and each keeps its own span:

tokio::join!(wash(1, 30), dry(2));

Attach a span to any future

No function of your own to annotate? The Instrument trait wraps any future. This job has no attribute at all:

job().instrument(info_span!("job", id = 7)).await;

The guard trap

A held guard belongs to the moment, not to the future. Hold one across an await in a spawned task, and other work can run under your span. Attach the span to the future instead, as the snippet above does:

let _guard = span.enter();
some_async_work().await; // the guard is still held here

Example

// Cargo.toml: tracing = "0.1" (resolved 0.1.44), tracing-subscriber = "0.3" (resolved 0.3.23),
// tokio = { version = "1", features = ["full"] } (resolved 1.54.1)
use std::time::Duration;
use tracing::{info, instrument};

#[instrument]
async fn wash(order_id: u32, millis: u64) {
    info!("wash started");
    tokio::time::sleep(Duration::from_millis(millis)).await;
    info!("wash finished");
}

#[instrument]
async fn dry(order_id: u32) {
    info!("dry started");
    info!("dry finished");
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_target(false)
        .without_time()
        .with_ansi(false)
        .init();

    tokio::join!(wash(1, 30), dry(2));
    info!("both orders done");
}

Key points

  • A span on a future is entered on every poll and left at every await.
  • The context follows the work, not the thread
  • Two tasks can share one thread and never mix contexts.
  • Each event prints the span of the future that wrote it
  • instrument works on an async fn unchanged.
  • The Instrument trait covers futures you did not write
  • A spawned task starts with no span.
  • Hand the span over with .instrument(...) on the spawned future when the child work belongs to the parent span
  • EnvFilter sees async spans exactly like sync ones.
  • The span rules from the EnvFilter lesson work across awaits
  • Threads swap under async code; ownership does not.

In this example, join! runs two instrumented jobs together. Read the output as a timeline. wash starts, then sleeps for 30 milliseconds at its await. dry takes the thread and runs to the end. wash wakes and finishes. Now look at the spans. The dry lines never borrow the wash span, even though dry ran while wash was half done. And the last wash line still carries wash and order_id 1, after a sleep and a possible thread swap. That is the span doing its job. It was entered again when the future was polled again. This output was run three times during the writing of this lesson. It came out identical every time.

Note

Rust ties the span to the future value, so the context survives every swap.

Try it Yourself

Edit the code, then press Run.

Running is simulated · Rust Playground

Exercise

wash sleeps at an await. dry runs on the same thread and writes a log line. Which span does dry's line carry?