Concept: tracing — Spans, instrument, and the Trace Layer

Kind: Concept. New crate: tracing — this chapter shows it working before you build with it.

Observability is not an afterthought

By the end of Part VI your coordinator is a running program: it claims a run, splits it into jobs, and dispatches them across a worker pool with bounded concurrency. That last phrase — bounded concurrency — is exactly what makes it hard to see what it is doing. At any instant four jobs are in flight, from different models and epochs, their await points interleaved on the runtime. When something goes wrong at two in the morning during a real eval, "add a println!" produces this:

processing order
processing order
reserved
processing order
reserved
reserved
order complete

Which run did the third reserved belong to? You cannot tell. The lines from independent concurrent tasks are shuffled together, none of them carries the id of the work it came from, and there is no way to filter to just the run you care about. A println! is a string with no structure and no context — and concurrency is precisely the setting where a string with no context is useless.

tracing exists to fix this. It is the observability layer the whole coordinator threads through, and the design goal is one sentence: every line of output should know which run produced it, and you should be able to ask for exactly the lines you want without recompiling. This chapter builds that machinery on a toy so that when you wire it into process_run, the run id follows every job through the entire dispatch — for free, because the span carries it.

Events and spans: the two primitives

tracing has exactly two things you emit, and the distinction is the whole idea.

An event is a single moment — a structured println!. Instead of formatting a string, you name a message and attach typed key/value fields:

tracing::info!(user = "ada", "logged in");

A span is a period of time with a name and its own fields. While a span is entered, every event — and every nested span — inherits its context automatically. You do not pass the context down by hand; entering the span is what attaches it.

Here are both, in a program that needs nothing but tracing and tracing-subscriber:

use tracing::{info, info_span};

fn main() {
    tracing_subscriber::fmt().with_target(false).init();

    // An EVENT: a single moment, like a structured println.
    info!(user = "ada", "logged in");

    // A SPAN: a period of time whose fields every event inside inherits.
    let span = info_span!("checkout", cart_id = 7);
    let _guard = span.enter();
    info!(item = "book", "added"); // inherits cart_id=7
    info!(item = "pen", "added");  // inherits cart_id=7
    // `_guard` drops here → the span closes
}

Run it and read the output closely (timestamps will differ each run):

2026-07-21T19:18:45.992143Z  INFO logged in user="ada"
2026-07-21T19:18:45.992312Z  INFO checkout{cart_id=7}: added item="book"
2026-07-21T19:18:45.992334Z  INFO checkout{cart_id=7}: added item="pen"

The first event has no span, so it prints bare. The two events inside the span are each prefixed with checkout{cart_id=7}: — the span's name and fields, stamped onto every line beneath it, without either info! mentioning cart_id. That prefix is the thing a println! can never give you: a way to know, from the line alone, what larger unit of work it belongs to. A span is entered when the guard is created and closed when the guard drops — the span's lifetime is a real Rust scope, which is why nesting Just Works.

#[tracing::instrument]: the span you don't write by hand

Entering a span manually is fine, but the common case is "wrap this whole function in a span named after it, with these arguments as fields." That is a macro: #[tracing::instrument]. Put it on a function and every call gets its own span, opened on entry and closed on return, with the function's arguments recorded as fields.

This is the toy that mirrors the build one-for-one. process_order takes an order, does some nested work per item, and we want the order id stamped on every line the call produces — including lines from the functions it calls:

use tracing::info;
use tracing_subscriber::EnvFilter;

#[derive(Debug)]
struct Order {
    id: u32,
    items: Vec<&'static str>,
}

#[tracing::instrument(skip(order), fields(order_id = order.id))]
fn process_order(order: &Order) {
    info!(items = order.items.len(), "processing order");
    for item in &order.items {
        reserve_item(item);
    }
    info!("order complete");
}

#[tracing::instrument]
fn reserve_item(item: &str) {
    info!("reserved");
}

fn main() {
    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
    tracing_subscriber::fmt()
        .with_env_filter(filter)
        .with_target(false) // trims the module-path column for readability
        .init();

    process_order(&Order { id: 42, items: vec!["widget", "gadget"] });
}

The real, captured output:

2026-07-21T19:20:40.618206Z  INFO process_order{order_id=42}: processing order items=2
2026-07-21T19:20:40.618404Z  INFO process_order{order_id=42}:reserve_item{item="widget"}: reserved
2026-07-21T19:20:40.618456Z  INFO process_order{order_id=42}:reserve_item{item="gadget"}: reserved
2026-07-21T19:20:40.618485Z  INFO process_order{order_id=42}: order complete

Read what the annotation bought us:

• order_id=42 is on every single line — including the two from reserve_item, which never saw the order. The nested spans render as process_order{order_id=42}:reserve_item{item="widget"}:, so a line tells you both the order it belongs to and the item being reserved inside it. That is the context a println! throws away.
• skip(order) tells the macro not to record the whole Order as a field. By default #[instrument] records every argument via its Debug, which for a big struct is noise (and for a secret would be a leak). skip opts a field out.
• fields(order_id = order.id) then adds back exactly the one piece we want — the id — pulled out of the skipped argument. skip the noisy whole, fields the useful part: that pairing is the idiom.

Now hold this next to the build. In process_run, the annotation is:

#[tracing::instrument(skip(self, run), fields(run_id = %run.id))]
async fn process_run(&self, run: Run) -> Result<(), ControlError> { ... }

Identical shape. skip(self, run) drops the two big arguments; fields(run_id = %run.id) records just the run id. From that point on, every log the scheduler emits while processing that run — planning jobs, dispatching, retrying, recording outcomes — is stamped with run_id, because all of it happens inside the process_run span. The % is one small new thing: it means "record this field using its Display (to_string) rather than its Debug." A RunId displays as the bare uuid, which is what you want in a log; %run.id gets you run_id=3f2a… instead of run_id=RunId(3f2a…). (instrument also handles async fn correctly — it re-enters the span every time the future is polled, so the context survives every .await.)

EnvFilter: turning the firehose up and down without recompiling

Structured lines are only half the win. The other half is choosing which lines you get — at startup, from the environment, without touching the code. That is EnvFilter.

An EnvFilter reads a directive string (conventionally from the RUST_LOG environment variable) and decides, per event, whether it passes. The directive can be as blunt as a level (info, warn) or as surgical as per-module (control_store=debug,info — debug for the store, info for everything else). The subscriber consults the filter for every event; anything below the threshold is dropped before it is ever formatted.

The construction you will use in the build is exactly the one in the toy above:

let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
tracing_subscriber::fmt().with_env_filter(filter).try_init();

try_from_default_env() reads RUST_LOG; if it is unset, the unwrap_or_else supplies a sensible default of "info". So the coordinator is talkative-enough out of the box, and an operator who wants more detail sets RUST_LOG=debug and reruns — no recompile. Run the process_order example with RUST_LOG=warn and all four info lines vanish, because none of them clears the warn bar; run it with nothing set and you get the full output above.

Two more details worth pinning now, because they surprise people:

• fmt() writes to stdout by default, not stderr. (Verified: redirecting stdout to /dev/null silences the logs; redirecting stderr does not.) That is fine for this course, but in a real service you often want logs on stderr so stdout stays clean for actual output — a one-liner, .with_writer(std::io::stderr), if you ever need it.
• try_init is idempotent-friendly. It returns a Result instead of panicking if a global subscriber is already set. That is why telemetry::init can be called from every test's setup without the second call blowing up — the first install wins and the rest quietly no-op. The panicking init() would make the second test crash.

One layer for every request: tower-http's TraceLayer

The API tier gets its telemetry almost for free. axum is built on tower, and tower middleware is composable Layers wrapped around your router. tower-http ships a ready-made one, TraceLayer, that opens a span for every incoming HTTP request and logs when it completes — method, path, status, latency — with no per-handler code at all.

use tower_http::trace::TraceLayer;

pub fn app(state: AppState) -> Router {
    Router::new()
        .route("/runs", post(create_run))
        .route("/stats", get(get_stats))
        // ... other routes ...
        .layer(TraceLayer::new_for_http()) // one line: every request now traced
        .with_state(state)
}

new_for_http() is a preset tuned for HTTP: it knows to pull method and path into the request span and to log the status and duration on the way out. Because it is a layer, it wraps all the routes uniformly — you do not, and must not, sprinkle logging into each handler. That is the same "one place" discipline you already applied to error mapping in Part V (IntoResponse turned the taxonomy into status codes in a single spot); here one layer turns every request into a traced span in a single spot.

tower-http and axum are not on the Rust playground, so the block above is marked ignore — there is no run button. To exercise it, add axum, tower-http (features ["trace"]), and tracing to a scratch crate, or just read it in place; you will build the real thing against the router in the next chapter.

One-for-one with the build

The toy maps onto the coordinator's telemetry exactly:

• #[instrument] on process_order ↔ #[instrument] on process_run (the span that wraps a whole unit of work)
• skip(order) + fields(order_id = order.id) ↔ skip(self, run) + fields(run_id = %run.id) (drop the big args, keep the id)
• order_id stamped on nested reserve_item lines ↔ run_id stamped on every dispatch/retry/record line inside the run
• info_span!("checkout", cart_id = 7) ↔ the request span TraceLayer opens per HTTP call
• EnvFilter from RUST_LOG, default "info" ↔ telemetry::init — the identical try_from_default_env/try_init pattern

Same two primitives, same one annotation, same one filter. Build the order tracer and you have built the run tracer with the labels changed.

Questions to lock

1. In a coordinator running four jobs concurrently, why does an unadorned println! fail to tell you which run a line came from — and what does a span give every line beneath it that fixes this?
2. What is the difference between an event and a span, and what does entering a span do to the events emitted inside it?
3. #[tracing::instrument(skip(self, run), fields(run_id = %run.id))] — say what each of skip(...), fields(...), and the % is doing, and why you would skip an argument only to add one field back.
4. You set RUST_LOG=warn but your info! lines still print. What is the single most likely cause, given how EnvFilter gets attached to a subscriber?
5. TraceLayer::new_for_http() is one line on the router. Why is a layer the right place for request logging rather than a log statement inside each handler?

Next chapter is the build: telemetry::init, the TraceLayer on the router, the run span on process_run, and the /stats endpoint that turns the tokens your workers already report into a cost per model.