Structured Logging in Rust with tracing

TL;DR — tracing is the de facto structured logging + spans crate for Rust. Spans add context that nests through async calls. Events are individual log lines. tracing-subscriber wires it up: JSON in prod, pretty console in dev. Request-scoped fields via #[instrument].

After Axum, sqlx, and serde, the last piece for a production-shaped backend service is observability. In Rust 2022 that means tracing.

tracing is more than logging — it’s a tree-of-spans model where each operation can carry contextual fields (request_id, user_id) that automatically attach to every log event emitted inside it. Same idea as Go’s request-scoped logger middleware from the Zap post, more natural to express.

Setup

[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }

tracing is the API your code uses. tracing-subscriber is the part that decides what to do with the events (write to stdout? in what format?). Other subscribers exist (tracing-opentelemetry for exporting to Jaeger, tracing-bunyan-formatter, etc.).

Initialization

use tracing_subscriber::{fmt, EnvFilter};

fn init_logging(env: &str) {
    let filter = EnvFilter::try_from_default_env()
        .or_else(|_| EnvFilter::try_new("info"))
        .unwrap();

    if env == "production" || env == "staging" {
        tracing_subscriber::fmt()
            .with_env_filter(filter)
            .json()
            .with_current_span(true)
            .with_span_list(true)
            .init();
    } else {
        tracing_subscriber::fmt()
            .with_env_filter(filter)
            .pretty()
            .init();
    }
}

Prod = JSON to stdout for log aggregators. Dev = pretty-printed colorful output. EnvFilter reads RUST_LOG env var so you can crank to debug ad-hoc.

In main:

#[tokio::main]
async fn main() -> anyhow::Result<()> {
    init_logging(&std::env::var("APP_ENV").unwrap_or_else(|_| "development".into()));
    tracing::info!("starting service");
    // ...
    Ok(())
}

Events: the log lines

Five log levels: trace, debug, info, warn, error. Macro-call form:

tracing::info!(user_id = %user.id, "user logged in");
tracing::warn!(retries = 3, "operation slow");
tracing::error!(error = ?err, customer_id = %cust.id, "refund failed");

Field syntax:

• %value uses Display
• ?value uses Debug
• name = value records an arbitrary field

The JSON output for the first one:

{
  "timestamp": "2022-03-23T09:14:33.812Z",
  "level": "INFO",
  "fields": {
    "user_id": "42",
    "message": "user logged in"
  },
  "target": "myapp::auth"
}

Parseable, indexable, greppable. Same shape as our Go services Zap setup, different code.

Spans: request-scoped context

The killer feature. A span is a region of execution with attached fields. Events emitted inside the span automatically include those fields.

use tracing::{info_span, Instrument};

async fn handle_request(user_id: u64) {
    let span = info_span!("request", user_id);
    async move {
        tracing::info!("starting");
        do_work().await;
        tracing::info!("done");
    }.instrument(span).await;
}

Both starting and done events carry user_id automatically. No manual threading. The span context propagates through .await boundaries because Tokio’s executor preserves it.

The cleaner form: #[tracing::instrument] macro:

#[tracing::instrument(skip(state), fields(user_id))]
async fn handle_request(user_id: u64, state: AppState) -> Result<(), AppError> {
    tracing::info!("starting");
    do_work().await?;
    tracing::info!("done");
    Ok(())
}

Every event inside handle_request has user_id attached. The skip(state) excludes state from the span fields (it’s a connection pool, not something to log).

Request-scoped logger pattern (Axum)

In the Axum post we mentioned middleware. Here’s the tracing one:

use tower_http::trace::TraceLayer;

let app = Router::new()
    .route("/users/:id", get(get_user))
    .layer(TraceLayer::new_for_http()
        .make_span_with(|req: &Request<_>| {
            let request_id = req.headers()
                .get("x-request-id")
                .and_then(|v| v.to_str().ok())
                .map(String::from)
                .unwrap_or_else(|| uuid::Uuid::new_v4().to_string());
            tracing::info_span!(
                "http",
                method = %req.method(),
                path = %req.uri().path(),
                request_id = %request_id,
            )
        })
    );

Every request gets a span with method, path, request_id. Every event inside any handler that runs in that request inherits those fields automatically.

TraceLayer::new_for_http() from tower-http also emits standard start/end/duration events out of the box.

What sqlx logs

If you enable the sqlx tracing feature, every query is logged as an event with timing and SQL text (configurable). Drop into your subscriber automatically. Useful in dev; turn down to warn in prod or you’ll log every query.

EnvFilter::new("info,sqlx::query=warn")

Common Pitfalls

Using println! in production code. No structure, no level, no aggregator. Always tracing::info!.

Logging huge JSON bodies. Costs money on per-GB log services and pollutes signal. Log structured fields, not raw payloads.

Forgetting #[instrument(skip(...))] for big args. Without skip, every arg gets logged. A DbPool arg printed as Debug is multi-KB of noise per call.

Calling .init() twice. Subscriber init is global; second call panics. If your tests need a subscriber, use tracing_subscriber::fmt::try_init() and ignore the error.

Logging in hot loops at info level. Even structured logging has cost. trace for tight loops; promote to info only when meaningful.

Forgetting with_env_filter so RUST_LOG doesn’t work. You’ll wonder why setting RUST_LOG=debug does nothing. Always wire EnvFilter in.

Not propagating spans across spawn. A spawned task starts a new context. Use tokio::task::spawn(future.instrument(Span::current())) if you want to keep the current span’s fields.

Wrapping Up

tracing makes structured logging + request context idiomatic in Rust. Spans + #[instrument] + JSON output + RUST_LOG filtering covers most production needs. With this in place we have a full backend service shape: Axum + sqlx + serde + tracing. Friday: containerizing the Rust service into a sub-25 MB production image.