Skip to content
Hacking with RustHacking with Rust
Select theme

Structured logging and request tracing

Step 13 of 15. Step 12 gave rate limiting a polite 429 and step 10 gave database errors a clean 500, and neither one can tell you it happened: the service has not logged a single line in twelve steps. This step wires tracing in, gives every request an id chosen at the edge, and puts that id on every line the request produces - including the two lines the last two steps earned their keep with, the 429 and the 500.

Start from step 12’s end state: git checkout api-ch12 in your clone of the examples repository, inside axum-sqlx-api/, with the Postgres container from step 5 running and DATABASE_URL and SHORTLINK_API_KEY exported as before. Three crates join Cargo.toml:

Terminal window
cargo add tracing
cargo add tracing-subscriber --features env-filter
cargo add tower-http --features trace,request-id
[dependencies]
axum = { version = "0.8", features = ["macros"] }
serde = { version = "1", features = ["derive"] }
serde_json = "1"
sqlx = { version = "0.9", features = ["runtime-tokio", "tls-rustls", "postgres", "macros"] }
thiserror = "2"
tokio = { version = "1", features = ["macros", "rt-multi-thread"] }
tower = "0.5"
tower-http = { version = "0.7.1", features = ["trace", "request-id"] }
tracing = "0.1.44"
tracing-subscriber = { version = "0.3.23", features = ["env-filter"] }
validator = { version = "0.21", features = ["derive"] }

The division of labour: tracing defines the macros and the span tree, tracing-subscriber decides what happens to the events - here, one line of text on stdout - and the env-filter feature is what makes RUST_LOG work. tower-http’s two features bring the pieces that live between the request and the logs: trace for the per-request span, request-id for the id itself.

The subscriber

Section titled “The subscriber”

Logging that nobody configured prints nothing, so the first lines of main build a subscriber. EnvFilter::try_from_default_env() reads RUST_LOG; without the variable, info and up:

src/main.rs
#[tokio::main]
async fn main() {
    // RUST_LOG picks the level, using the same syntax as env_logger. Without
    // it, info and up. The names are crate names, so `RUST_LOG=shortlink=debug`
    // turns up only this service's own lines and leaves the dependencies alone.
    // No colour: these lines are headed for files and aggregators, and the
    // escape codes would be noise there.
    tracing_subscriber::fmt()
        .with_ansi(false)
        .with_env_filter(
            EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")),
        )
        .init();


    let url = std::env::var("DATABASE_URL").expect("DATABASE_URL is not set");
    let pool = PgPoolOptions::new()
        .max_connections(5)
        .acquire_timeout(std::time::Duration::from_secs(3))
        .connect(&url)
        .await
        .expect("failed to connect to DATABASE_URL");


    sqlx::migrate!().run(&pool).await.expect("failed to run migrations");


    // The key lives in the environment, not in the source. The service
    // refuses to start without one - a missing key means every /links
    // request is rejected, which is better discovered at boot.
    let key = std::env::var("SHORTLINK_API_KEY").expect("SHORTLINK_API_KEY is not set");


    // Two routers, because the routes have different audiences: browsers
    // hitting /{code} send no headers, and a load balancer polling /health
    // has none to offer. Only /links - the routes that change or read data -
    // sit behind the layers. route_layer, not layer: it runs only once a
    // route has matched, so a typo like /foo/bar stays a 404 instead of
    // being told to authenticate against a path that does not exist.
    // Both route_layers wrap the same routes, and the last one added is the
    // outermost: a request meets auth before the limiter, because the
    // limiter needs the identity auth leaves in the extensions.
    let protected = Router::new()
        .route("/links", get(list_links).post(create_link))
        .route_layer(RateLimit::new(10.0, 5.0))
        .route_layer(RequireApiKey::new(key));


    let app = Router::new()
        .route("/health", get(health))
        .route("/{code}", get(resolve_link))
        .merge(protected)
        .layer(Extension(pool))
        // Step 12's rule again: the last layer added is the first to see the
        // request. Set runs outermost and gives every request an id - or
        // adopts the one in its x-request-id header. Propagate sits inside
        // it and reads the header back on its way through, so it can stamp
        // the response - a generated id included. The trace layer runs
        // inside both, so its span is made after the id exists and every
        // line carries it.
        .layer(
            TraceLayer::new_for_http()
                .make_span_with(RequestSpan)
                .on_response(DefaultOnResponse::new().level(Level::INFO)),
        )
        .layer(PropagateRequestIdLayer::x_request_id())
        .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid));


    let listener = tokio::net::TcpListener::bind("0.0.0.0:8000").await.unwrap();
    tracing::info!("listening on {}", listener.local_addr().unwrap());
    axum::serve(listener, app).await.unwrap();
}

(The block is unverified for the same reason as step 12’s: sqlx::migrate! reads migrations/ at compile time, which the verifier’s standalone sandbox does not have. The file is in the tag and cargo build proves it.)

Boot now prints two lines before the service accepts anything. The subscriber colours its output by default; .with_ansi(false) turns that off, which is what the log lines above show, byte for byte, in a terminal or in a file:

2026-10-18T18:18:01.282881Z  INFO sqlx::postgres::notice: relation "_sqlx_migrations" already exists, skipping
2026-10-18T18:18:01.287639Z  INFO shortlink: listening on 0.0.0.0:8000

The format is timestamp LEVEL target: message - the two spaces before INFO are the level column padded for ERROR. The first line is not ours: sqlx logs its migration notice at info too, under the target sqlx::postgres::notice. That is the price of an unfiltered default, and it shows why the target exists: RUST_LOG=shortlink=info,tower_http=info keeps exactly those two crates and silences the rest.

An id for every request

Section titled “An id for every request”

SetRequestIdLayer runs first on every request. If the request carries an x-request-id header, it adopts that value; otherwise MakeRequestUuid generates a uuid, and the id lands in the request extensions where anything downstream can read it. Adopting is deliberate - a gateway that already chose an id gets to keep it, and the docs are explicit that an existing id is never overwritten. It also means a client can pick its own id, which is fine for a service behind your own infrastructure and worth a second thought on the public internet.

Everything about a request that might need explaining - the slow one, the rejected one, the one that 500’d - now has a name. The remaining step is making sure the lines about it carry that name.

The span that carries it

Section titled “The span that carries it”

TraceLayer wraps every request in a span and logs one line when the response comes back. Which fields that span has is decided by the MakeSpan you hand it, and this is the whole trick of the step: make the span after the id layer has run, and read the id out of the extensions.

src/main.rs
use axum::{
    Json, Router,
    extract::{Extension, FromRequest, Path, Query, Request},
    http::{StatusCode, header, HeaderMap, HeaderValue},
    response::{IntoResponse, Response},
    routing::get,
};
use serde::{Deserialize, Serialize, de::DeserializeOwned};
use serde_json::json;
use sqlx::{PgPool, postgres::PgPoolOptions};
use std::{
    collections::HashMap,
    convert::Infallible,
    future::Future,
    pin::Pin,
    sync::{Arc, Mutex},
    task::{Context, Poll},
    time::Instant,
};
use thiserror::Error;
use tower::{Layer, Service};
use tower_http::{
    request_id::{MakeRequestUuid, PropagateRequestIdLayer, RequestId, SetRequestIdLayer},
    trace::{DefaultOnResponse, MakeSpan, TraceLayer},
};
use tracing::Level;
use tracing_subscriber::EnvFilter;
use validator::{Validate, ValidationErrors};


#[derive(Debug, Error)]
enum ApiError {
    // Extractor rejections carry their own status: 400 for malformed JSON,
    // 415 for a missing or wrong content-type.
    #[error("{1}")]
    BadBody(StatusCode, String),
    #[error("{0}")]
    Validation(#[from] ValidationErrors),
    #[error("{0}")]
    Unauthorized(&'static str),
    #[error("not found")]
    NotFound,
    #[error("rate limit exceeded")]
    TooManyRequests(u64),
    // The rate limiter reads the identity the auth layer left behind. This
    // variant means it found none - the two layers were wired in the wrong
    // order. That is a deployment bug, not a client's fault, so it maps to
    // 500 like the other internal errors.
    #[error("internal server error")]
    Miswired,
    // The sqlx error is kept as the source so into_response can log it -
    // the response body still only says "internal server error".
    #[error("internal server error")]
    Database(#[from] sqlx::Error),
    #[error("internal server error")]
    Exhausted,
}


impl IntoResponse for ApiError {
    fn into_response(self) -> Response {
        // Every rejected request passes through here once. The lines below
        // run inside the request's span, so each one carries the request id
        // - a 500 in the log can be traced to the exact request. 5xx errors
        // log their cause; a 429 is worth a warning; 401 and 404 are the
        // client's story, already told by the response line.
        match &self {
            ApiError::Database(source) => {
                tracing::error!(error = ?source, "database error");
            }
            ApiError::Miswired => {
                tracing::error!("rate limiter found no API user; the layer order is wrong");
            }
            ApiError::Exhausted => {
                tracing::error!("five code collisions in a row; refusing to retry again");
            }
            ApiError::TooManyRequests(_) => {
                tracing::warn!("rate limit exceeded");
            }
            _ => {}
        }
        let status = match &self {
            ApiError::BadBody(status, _) => *status,
            ApiError::Validation(_) => StatusCode::UNPROCESSABLE_ENTITY,
            ApiError::Unauthorized(_) => StatusCode::UNAUTHORIZED,
            ApiError::NotFound => StatusCode::NOT_FOUND,
            ApiError::TooManyRequests(_) => StatusCode::TOO_MANY_REQUESTS,
            ApiError::Miswired | ApiError::Database(_) | ApiError::Exhausted => {
                StatusCode::INTERNAL_SERVER_ERROR
            }
        };
        let mut res = (status, Json(json!({ "error": self.to_string() }))).into_response();
        if let ApiError::TooManyRequests(retry) = &self {
            // RFC 9110: Retry-After tells the client when to try again. The
            // bucket refills continuously, so this is a whole-second
            // estimate, rounded up.
            res.headers_mut().insert(
                header::RETRY_AFTER,
                HeaderValue::from_str(&retry.to_string()).expect("a u64 is a valid header value"),
            );
        }
        res
    }
}


// The span every log line of a request lands in. tower-http calls this once
// the request reaches the trace layer, and the request-id layer sits outside
// it, so the id is already in the extensions here. One id, chosen at the
// edge, printed on every line this request produces.
#[derive(Clone)]
struct RequestSpan;


impl<B> MakeSpan<B> for RequestSpan {
    fn make_span(&mut self, request: &axum::http::Request<B>) -> tracing::Span {
        let request_id = request
            .extensions()
            .get::<RequestId>()
            .map(|id| id.header_value().to_str().unwrap_or("-"))
            .unwrap_or("-");
        tracing::info_span!(
            "http_request",
            request_id = %request_id,
            method = %request.method(),
            path = %request.uri().path(),
        )
    }
}

Everything here is new or changed in src/main.rs; the handlers, the auth layer and the limiter are untouched and left out. The pieces:

RequestSpan is the MakeSpan. It reads the RequestId extension - inserted by the id layer, which sits outside the trace layer - and puts it in the span as a plain string, next to the method and the path. unwrap_or("-") covers the only case where the extension is missing: the layers wired in the wrong order, which the next request will tell on itself anyway.

The order of the three layer() calls is the one thing to get right, and it is step 12’s rule - last added, first seen - with one turn. SetRequestId is outermost because it must run first. PropagateRequestIdLayer sits inside it: on the way in it reads the x-request-id header, and on the way out it stamps that value on the response. Get this backwards - propagate outside, set inside, the order in the axum examples - and the id is still on every log line, but curl -i on a fresh request shows no x-request-id header at all, because the propagate layer read the request before the id existed. Generated ids would live in the logs only. With the order above, every response carries the id back:

Terminal window
curl -s -o /dev/null -D - http://127.0.0.1:8000/health | grep -i x-request
curl -s -o /dev/null -D - -H 'x-request-id: my-own-id-42' http://127.0.0.1:8000/nope | grep -i x-request
x-request-id: 08281203-07dd-427e-a1c0-78a310ad190f
x-request-id: my-own-id-42

A generated uuid on the first, the client’s own id echoed on the second - the id a client sees in the response header is the id every line about that request carries.

TraceLayer::new_for_http() gets two settings. make_span_with(RequestSpan) swaps in the span above. on_response(DefaultOnResponse::new().level(Level::INFO)) raises the response line from the default debug to info, so it survives the default filter - one line per request, with the status and the latency.

One request, end to end

Section titled “One request, end to end”

A 429 from step 12’s own volley, ten requests through and two over the limit:

2026-10-18T18:18:03.750858Z  WARN http_request{request_id=e58ce499-3372-439b-ac97-6cf93d6ec641 method=GET path=/links}: shortlink: rate limit exceeded
2026-10-18T18:18:03.750903Z  INFO http_request{request_id=e58ce499-3372-439b-ac97-6cf93d6ec641 method=GET path=/links}: tower_http::trace::on_response: finished processing request latency=0 ms status=429

Two lines, same id. The warn comes from into_response - the one place every rejected request passes through - and because that code runs inside the span the trace layer made, the id is on it without into_response knowing spans exist.

The other half of the bargain, with the database stopped. Four lines, one id:

2026-10-18T18:18:11.893971Z  INFO http_request{request_id=6ae16028-062b-4764-ac1f-393da78009f7 method=GET path=/links}: sqlx_core::pool::inner: ping on idle connection returned error error=error returned from database: terminating connection due to administrator command at line 3286
2026-10-18T18:18:14.894635Z ERROR http_request{request_id=6ae16028-062b-4764-ac1f-393da78009f7 method=GET path=/links}: shortlink: database error error=PoolTimedOut
2026-10-18T18:18:14.895022Z  INFO http_request{request_id=6ae16028-062b-4764-ac1f-393da78009f7 method=GET path=/links}: tower_http::trace::on_response: finished processing request latency=3001 ms status=500
2026-10-18T18:18:14.895184Z ERROR http_request{request_id=6ae16028-062b-4764-ac1f-393da78009f7 method=GET path=/links}: tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=3001 ms

Reading top to bottom: sqlx notices a pooled connection died when Postgres went away; three seconds pass - step 5’s acquire_timeout(3s) - while the pool tries to fill its quota; our line names the cause, PoolTimedOut, which is the sqlx error step 10 kept as the source for exactly this; the response line says 500; and on_failure fires because a 5xx counts as a failure to tower-http. Restart the container and the next request succeeds on its own - the pool reconnects - which the log also shows, 200 on the id that followed the outage.

Step 12’s comment on the Database variant said the sqlx error was “kept as the source for logging (step 13)”. The match in into_response is the fulfilment: error = ?source puts the real error in the line, while the response body still says only “internal server error”.

Dropping the level drops the id

Section titled “Dropping the level drops the id”

One default worth knowing before you ship. RUST_LOG=warn silences the per-request response lines, which sounds like pure win at peak traffic. What it also does is drop the span - the span is info-level, and a filtered span does not print its fields. The warn survives, the id does not:

2026-10-18T18:18:42.024664Z  WARN shortlink: rate limit exceeded
2026-10-18T18:18:42.030094Z  WARN shortlink: rate limit exceeded

Two rejections, no way to tell which request either one belongs to. The same two lines of code under the two filters, side by side and without the timestamps, so the output is stable:

use tracing::subscriber::with_default;
use tracing_subscriber::{EnvFilter, fmt};


fn main() {
    let emit = || {
        let span = tracing::info_span!(
            "http_request",
            request_id = %("b3d24a58-6c9e-4e0b-9a29-6f6f13a8a91e"),
            method = %("GET"),
            path = %("/links"),
        );
        let _enter = span.enter();
        tracing::warn!("rate limit exceeded");
        tracing::info!("finished processing request");
    };


    // The service's default filter: info and up.
    with_default(
        fmt()
            .without_time()
            .with_env_filter(EnvFilter::new("info"))
            .finish(),
        emit,
    );
    // What RUST_LOG=warn does to the same two events.
    with_default(
        fmt()
            .without_time()
            .with_env_filter(EnvFilter::new("warn"))
            .finish(),
        emit,
    );
}
 WARN http_request{request_id=b3d24a58-6c9e-4e0b-9a29-6f6f13a8a91e method=GET path=/links}: verify: rate limit exceeded
 INFO http_request{request_id=b3d24a58-6c9e-4e0b-9a29-6f6f13a8a91e method=GET path=/links}: verify: finished processing request
 WARN verify: rate limit exceeded

Under info, both events sit in the span and carry the id. Under warn, the span is disabled and the warn line is naked. The token between the brace and the message is the target - the crate that emitted the line, verify here because the site’s checker compiles this snippet under its own name; in the running service it is shortlink. If warn is the level you want in production, the fix is to keep the span: RUST_LOG=shortlink=info,tower_http=warn keeps the span for our lines while quieting the per-request noise from tower-http. Filtering, not levels, is where the real decisions are.

Where this leaves the service

Section titled “Where this leaves the service”

The service talks. Every request has an id from the moment it arrives, the id is on the response header the client sees, and the two error paths the last steps built - the 429 and the 500 - now explain themselves in lines that can be traced back to one request. What has not been tested is any of it: step 14 starts testing the service against a real database, per-test schema included.

The end state is tagged api-ch13 in the examples repository - git checkout api-ch13 inside axum-sqlx-api/. cargo test still runs the six tests offline; the log lines above need the container up and the curls from this page.

Next: integration tests against a real database. The service boots a pool and runs migrations on startup, and sqlx::test can hand every test a database of its own - the curl sequence from step 9 stops being manual. The track overview keeps the full list current as articles land.