Logging and Tracing

When something goes wrong in production, the errors from Error Libraries — thiserror and anyhow tell you what failed; logs and traces tell you how the program got there. Rust's observability story has two layers worth understanding: the simple log facade for basic line-oriented logging, and the richer tracing ecosystem built for structured, span-based diagnostics, which is what you want for async and concurrent code. This tutorial covers when each fits and how to use tracing well.

The `log` Facade: Decoupling Calls from Output

The log crate is a facade: it defines the logging macros (error!, warn!, info!, debug!, trace!) but deliberately does not decide where the output goes. A separate implementation crate (like env_logger) is installed once at startup to actually print the records. This split mirrors thiserror defining error types while the application chooses how to report them, libraries log against the facade, and the final binary picks the backend.

// in a library: just emit records, no opinion on where they go
log::info!("cache miss for key {key}");
log::warn!("retrying after {attempts} failed attempts");

// in the binary, once, at startup:
fn main() {
    env_logger::init();   // now log records print to stderr, filtered by RUST_LOG
    run();
}

The five levels are ordered by severity (error > warn > info > debug > trace), and the backend filters by a threshold, usually set via the RUST_LOG environment variable (RUST_LOG=info shows info and above; RUST_LOG=my_crate=debug scopes it per-module). The key design point: a library should never call env_logger::init() or pick a backend, that's the application's single decision, exactly like the anyhow-at-the-top rule.

Why `tracing`: Spans, Not Just Lines

Plain log lines have a structural problem in concurrent code: when two requests interleave, their log lines mix together in the output with no reliable way to tell which line belongs to which request. tracing solves this with spans, a span represents a period of time with a context (a request, a transaction, an operation), and every event emitted while that span is active is tagged with it.

use tracing::{info, info_span};

fn handle_request(req_id: u64) {
    let span = info_span!("request", id = req_id);
    let _guard = span.enter();   // span is active until _guard drops (RAII, from the Drop tutorial)

    info!("started");            // automatically tagged with request id = req_id
    do_work();
    info!("completed");          // also tagged — same span context
}

Entering a span returns a guard whose Drop (from Drop, RAII, and Resource Cleanup) exits the span, so the span's scope is tied to the guard's lifetime. Now every event between enter and drop carries id = req_id, so even with a hundred requests interleaved, you can filter the output down to one request's complete story. This is the capability plain log fundamentally can't provide.

Structured Fields Over String Interpolation

Both log and tracing let you interpolate values into a message, but tracing encourages attaching them as structured fields instead, key-value pairs the output backend can render as JSON, index, and query, rather than baking them into an opaque string.

use tracing::info;

// interpolated: the values are trapped inside a string, hard to query later
info!("processed order {order_id} for {amount} cents");

// structured: order_id and amount are real fields a log aggregator can filter on
info!(order_id, amount_cents = amount, "processed order");

The structured form matters most in production with a log aggregator (Elasticsearch, Loki, a cloud logging service): you can query order_id = 4815 directly instead of grepping substrings out of message text. The bare order_id is shorthand for order_id = order_id, and name = value adds a renamed or computed field. The trailing string literal is still the human-readable message; the fields ride alongside it.

`#[instrument]`: Spans Without the Boilerplate

Manually creating and entering a span in every function gets repetitive. The #[instrument] attribute macro wraps an entire function in a span automatically, recording its arguments as fields, which is both less code and the idiomatic way to trace async functions.

use tracing::instrument;

#[instrument]
async fn fetch_user(user_id: u64) -> Result<User, DbError> {
    // a span named "fetch_user" with field user_id is active for the whole call,
    // correctly following the future across .await points and across threads
    let user = query_db(user_id).await?;
    Ok(user)
}

// skip large or sensitive args; add explicit fields
#[instrument(skip(db), fields(request_id = %req.id))]
async fn handle(db: &Database, req: Request) -> Result<Response, Error> { /* ... */ }

For async code (from Async/Await with Tokio), #[instrument] is essential, not optional: a manually enter()ed span guard held across an .await would be wrong, because the task can be suspended and resumed on a different thread while the guard sits there. #[instrument] handles the future correctly, the span follows the task wherever it's polled. Use skip(...) to omit arguments that are large, non-Debug, or sensitive, and fields(...) to add custom ones (% formats with Display, ? with Debug).

The Subscriber: Where Output Is Decided

Just as log needs a backend, tracing needs a subscriber to collect spans and events and do something with them. tracing-subscriber is the standard one, installed once at startup, and it controls formatting (human-readable vs JSON), filtering, and destination.

use tracing_subscriber::{fmt, EnvFilter};

fn main() {
    tracing_subscriber::fmt()
        .with_env_filter(EnvFilter::from_default_env())  // honors RUST_LOG, like env_logger
        .json()                                          // structured JSON output for aggregators
        .init();

    run();
}

The same separation-of-concerns principle holds: your library code emits spans and events with no knowledge of where they go; the binary installs exactly one subscriber and decides everything about output, pretty-printed to a terminal in development, JSON to a collector in production. Swapping that is a one-line change at startup, with zero changes to instrumented code. (A compatibility layer lets tracing also capture records from libraries that use the older log facade, so you don't have to choose only one across your dependency tree.)

Key Takeaways

log is a facade: libraries emit records via error!/warn!/info!/debug!/trace!, and the binary installs one backend (e.g. env_logger) to decide output. Libraries must never pick the backend themselves.
Levels are filtered by a threshold, typically RUST_LOG (RUST_LOG=my_crate=debug), so verbosity is a runtime/deployment decision, not a code change.
tracing adds spans, time-bounded contexts that tag every event within them, so interleaved concurrent/async work stays attributable to the right request or operation, which plain log lines can't do.
Prefer structured fields (info!(order_id, "processed")) over string interpolation so a log aggregator can query on values instead of grepping message text.
Use #[instrument] to span a whole function automatically; it's the correct way to trace async fns (a manual span guard held across .await is a bug). Use skip(...)/fields(...) to control recorded arguments.
tracing needs a subscriber (tracing-subscriber), installed once in the binary, controlling format/filter/destination, so production JSON vs dev pretty-printing is a one-line startup change with no edits to instrumented code.

Logging and Tracing

The log Facade: Decoupling Calls from Output

Why tracing: Spans, Not Just Lines