Observability: Tracing, Logging, and Metrics

Observability is the ability to explain what a running system is doing from the data it emits. The three signals are logs (events), traces (the path of one request through the system), and metrics (numbers aggregated over time). This lesson sets up all three for an Axum service with tracing, W3C trace context, and Prometheus.

Signal	Explains	Example
Log	What happened in one event	`order 42 payment declined`
Trace	Where the time went for one request	Spans across Orders, Inventory, Payments
Metric	Whether the system is healthy now	Requests per second, error ratio, p99 latency

Project setup

Cargo.toml

TOML

[package]
name = "storefront-observability"
version = "0.1.0"
edition = "2021"
default-run = "storefront-observability"

[dependencies]
axum = "0.8"
tokio = { version = "1", features = ["full"] }
tower = { version = "0.5", features = ["util"] }
tower-http = { version = "0.6", features = ["trace", "request-id", "propagate-header"] }
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }
metrics = "0.24"
metrics-exporter-prometheus = "0.16"
rand = "0.8"
serde_json = "1"

tracing-subscriber needs env-filter for EnvFilter and json for the JSON formatter.

Example 1: Spans and events

The tracing crate records events and spans. An event is a point in time with a level and fields. A span is a period of time with fields, and events emitted while it is entered belong to it. Fields are structured key-value pairs, so a backend can filter on order_id.

src/bin/basics.rs

Rust

use tracing::{info, instrument, warn};

#[instrument]
fn place_order(customer_id: i64, cents: u64) -> i64 {
    info!(cents, "creating order");
    let order_id = customer_id;
    if cents > 1_000_000 {
        warn!(order_id, "large order flagged");
    }
    order_id
}

fn main() {
    tracing_subscriber::fmt().with_target(false).without_time().init();
    place_order(7, 1250);
    place_order(8, 2_000_000);
}

Terminal

cargo run -q --bin basics

Output

 INFO place_order{customer_id=7 cents=1250}: creating order cents=1250
 INFO place_order{customer_id=8 cents=2000000}: creating order cents=2000000
 WARN place_order{customer_id=8 cents=2000000}: large order flagged order_id=8

#[instrument] wraps the function in a span named after it and records the arguments as fields. It also works on async functions and attaches the span to the future, so the span is entered on each poll.
skip(arg) and skip_all leave arguments out. Use them for values that do not implement Debug and for secrets. Never record passwords, tokens, or card numbers.
In field syntax, %value records with Display and ?value records with Debug.
tracing_subscriber::fmt() with without_time and with_target(false) gives stable output for this example.

Level conventions:

Level	Use
`error`	An operation failed and needs attention
`warn`	Unexpected condition the service handled
`info`	Business events: order created, service started
`debug`, `trace`	Diagnostic detail, usually off

A 404 or a validation failure is a client mistake. Logging it at error creates false alarms.

Example 2: A subscriber with JSON output

Events go nowhere until a subscriber is installed. EnvFilter selects levels from RUST_LOG. JSON output is parsed directly by log aggregators such as Loki or Elasticsearch, and the human-readable format suits local work.

src/telemetry.rs

Rust

use metrics_exporter_prometheus::{PrometheusBuilder, PrometheusHandle};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};

pub fn init_tracing() {
    tracing_subscriber::registry()
        .with(
            EnvFilter::try_from_default_env()
                .unwrap_or_else(|_| EnvFilter::new("info,tower_http=debug")),
        )
        .with(fmt::layer().json())
        .init();
}

pub fn init_metrics() -> PrometheusHandle {
    PrometheusBuilder::new()
        .install_recorder()
        .expect("the metrics recorder installs once")
}

With RUST_LOG=info,storefront_observability=debug, the service logs info for all crates and debug for its own. Each JSON line carries the level, target, message, event fields, and the fields of the enclosing spans. The exact layout depends on the formatter settings. init_metrics installs the Prometheus recorder used in Example 5.

Example 3: Request spans and propagated trace context

A distributed trace needs the same trace id in every service. The W3C Trace Context standard defines the traceparent header:

Text

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             |  |                                |                |
             |  trace id (32 hex)                span id (16 hex) flags (01 = sampled)
             version

The trace id stays constant across the request. The span id identifies the caller's span, which becomes the parent of the receiver's span. Two steps make it work: extract the header on an incoming call, and inject a header with the same trace id and a new span id on each outgoing call. The middleware below does this without an OpenTelemetry SDK. If the header is missing or malformed, it starts a new trace.

src/trace_context.rs

Rust

use axum::{extract::Request, middleware::Next, response::Response};

#[derive(Clone, Debug)]
pub struct TraceContext {
    pub trace_id: String,
    pub parent_id: String,
    pub flags: String,
}

fn new_span_id() -> String {
    format!("{:016x}", rand::random::<u64>())
}

fn is_hex(value: &str, len: usize) -> bool {
    value.len() == len && value.bytes().all(|b| b.is_ascii_hexdigit())
}

impl TraceContext {
    pub fn parse(header: &str) -> Option<Self> {
        let parts: Vec<&str> = header.split('-').collect();
        if parts.len() != 4 || parts[0] != "00" {
            return None;
        }
        let (trace_id, parent_id, flags) = (parts[1], parts[2], parts[3]);
        if !is_hex(trace_id, 32) || !is_hex(parent_id, 16) || !is_hex(flags, 2) {
            return None;
        }
        Some(Self {
            trace_id: trace_id.to_string(),
            parent_id: parent_id.to_string(),
            flags: flags.to_string(),
        })
    }

    pub fn new_root() -> Self {
        Self {
            trace_id: format!("{:032x}", rand::random::<u128>()),
            parent_id: new_span_id(),
            flags: "01".to_string(),
        }
    }

    /// The header value for an outgoing call: same trace id, new span id.
    pub fn outgoing(&self) -> String {
        format!("00-{}-{}-{}", self.trace_id, new_span_id(), self.flags)
    }
}

pub async fn trace_context(mut request: Request, next: Next) -> Response {
    let context = request
        .headers()
        .get("traceparent")
        .and_then(|value| value.to_str().ok())
        .and_then(TraceContext::parse)
        .unwrap_or_else(TraceContext::new_root);
    request.extensions_mut().insert(context);
    next.run(request).await
}

The TraceLayer in the complete example adds trace_id, request_id, and the route pattern to the span of every request, so each log line of the request carries them. The route comes from MatchedPath, which holds /orders/{id} and not /orders/42. Use the pattern for span names and metric labels, because concrete paths produce unbounded distinct values.

Example 4: Export traces with OpenTelemetry

OpenTelemetry (OTel) is a vendor-neutral standard for traces, metrics, and logs. The service sends spans over the OTLP protocol to a collector or directly to a backend such as Jaeger or Tempo. The tracing-opentelemetry crate adds a tracing subscriber layer that converts spans into OTel spans, and opentelemetry-otlp provides the exporter.

The builder APIs of the OpenTelemetry crates change between minor versions, so this lesson shows no SDK code. The structure is stable:

An exporter sends span batches to an OTLP endpoint, port 4317 for gRPC or 4318 for HTTP.
A batch processor exports spans in the background so requests do not wait on the network.
A resource attribute service.name = "storefront" groups spans per service in the backend.
A sampler keeps a fraction of traces. A parent-based sampler follows the caller's sampled flag, so a trace is never half recorded. Keeping traces that contain errors needs tail-based sampling in the collector.
The tracer provider must be flushed at shutdown, or the last spans are lost. See graceful shutdown.
With OTel, the propagator reads and writes traceparent. It replaces the hand-written middleware and works the same way. Message headers in Kafka messaging and gRPC metadata carry the same value.

A local backend for experiments:

Terminal

docker run --rm -e COLLECTOR_OTLP_ENABLED=true -p 16686:16686 -p 4317:4317 jaegertracing/all-in-one

Jaeger accepts OTLP on port 4317 and serves the UI on port 16686. The environment variable enables the OTLP receiver on releases where it is off by default.

Example 5: Prometheus metrics

A metric is a named numeric series with labels. Prometheus scrapes an HTTP endpoint, usually /metrics, on a schedule.

Type	Behavior	Example
Counter	Only increases (resets on restart)	`http_requests_total`
Gauge	Goes up and down	`db_pool_connections_in_use`
Histogram	Counts observations, giving percentiles	`http_request_duration_seconds`

The metrics crate provides the macros. metrics-exporter-prometheus installs the global recorder and renders the text format through PrometheusHandle::render. The middleware records a counter and a histogram per request after the handler returns.

src/metrics_mw.rs

Rust

use axum::{
    extract::{MatchedPath, Request},
    middleware::Next,
    response::Response,
};
use std::time::Instant;

pub async fn track_metrics(request: Request, next: Next) -> Response {
    let start = Instant::now();
    let method = request.method().to_string();
    let route = request
        .extensions()
        .get::<MatchedPath>()
        .map(|path| path.as_str().to_owned())
        .unwrap_or_else(|| "unmatched".to_owned());

    let response = next.run(request).await;

    let status = response.status().as_u16().to_string();
    let elapsed = start.elapsed().as_secs_f64();
    metrics::counter!(
        "http_requests_total",
        "method" => method.clone(),
        "route" => route.clone(),
        "status" => status.clone()
    )
    .increment(1);
    metrics::histogram!(
        "http_request_duration_seconds",
        "method" => method,
        "route" => route,
        "status" => status
    )
    .record(elapsed);
    response
}

Labels are "key" => value pairs.
Cardinality is the number of distinct label combinations, and each combination is a separate stored series. Route pattern, method, and status are safe. User ids, order ids, and raw paths make memory grow without bound.
Expose /metrics on an internal port or restrict it at the network level, because it reveals internal names and counts. The complete example serves it on the main port for simplicity.
By default the exporter renders histograms as summaries with quantiles. Explicit buckets are configured on PrometheusBuilder.

Example 6: What to measure

RED for request-driven services: Rate (requests per second), Errors (failed requests per second or ratio), Duration (latency distribution).
USE for resources such as CPU, database pools, and queues: Utilization, Saturation, Errors.

Metric	Type	Purpose
`http_requests_total{route,method,status}`	Counter	Rate and error ratio
`http_request_duration_seconds{route}`	Histogram	p50, p95, p99 latency
`db_pool_connections_in_use`	Gauge	Pool saturation
`outbox_pending_messages`	Gauge	Publisher lag, see SQL transactions
`cache_hits_total`, `cache_misses_total`	Counters	Cache effectiveness, see Redis caching
`downstream_request_duration_seconds{service}`	Histogram	Which dependency is slow

Read latency as percentiles, because an average hides slow requests. A page that makes ten calls meets the p99 of each one often. Alerts fire on user-visible symptoms (error ratio, latency percentiles) and on saturation that predicts failure. Each alert needs a defined response.

Example 7: Connect the signals

The request id and trace id join the signals.

An alert on the error ratio for route="/orders/{id}" fires.
A trace search for the same time range and route finds slow traces. One span shows a call to Payments taking 9 seconds.
The trace id filters the logs of every service, showing the timeout warning and the retry.

Requirements: every log line carries trace_id and request_id, the request id is returned in a response header, and metric route labels match the route names in traces. Redact personal data and secrets before emission, and set retention to match data policy.

Complete example

File tree:

Text

storefront-observability/
  Cargo.toml
  src/
    main.rs
    telemetry.rs
    trace_context.rs
    metrics_mw.rs
    bin/
      basics.rs

Cargo.toml

TOML

[package]
name = "storefront-observability"
version = "0.1.0"
edition = "2021"
default-run = "storefront-observability"

[dependencies]
axum = "0.8"
tokio = { version = "1", features = ["full"] }
tower = { version = "0.5", features = ["util"] }
tower-http = { version = "0.6", features = ["trace", "request-id", "propagate-header"] }
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }
metrics = "0.24"
metrics-exporter-prometheus = "0.16"
rand = "0.8"
serde_json = "1"

src/telemetry.rs

Rust

use metrics_exporter_prometheus::{PrometheusBuilder, PrometheusHandle};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};

pub fn init_tracing() {
    tracing_subscriber::registry()
        .with(
            EnvFilter::try_from_default_env()
                .unwrap_or_else(|_| EnvFilter::new("info,tower_http=debug")),
        )
        .with(fmt::layer().json())
        .init();
}

pub fn init_metrics() -> PrometheusHandle {
    PrometheusBuilder::new()
        .install_recorder()
        .expect("the metrics recorder installs once")
}

src/trace_context.rs

Rust

use axum::{extract::Request, middleware::Next, response::Response};

#[derive(Clone, Debug)]
pub struct TraceContext {
    pub trace_id: String,
    pub parent_id: String,
    pub flags: String,
}

fn new_span_id() -> String {
    format!("{:016x}", rand::random::<u64>())
}

fn is_hex(value: &str, len: usize) -> bool {
    value.len() == len && value.bytes().all(|b| b.is_ascii_hexdigit())
}

impl TraceContext {
    pub fn parse(header: &str) -> Option<Self> {
        let parts: Vec<&str> = header.split('-').collect();
        if parts.len() != 4 || parts[0] != "00" {
            return None;
        }
        let (trace_id, parent_id, flags) = (parts[1], parts[2], parts[3]);
        if !is_hex(trace_id, 32) || !is_hex(parent_id, 16) || !is_hex(flags, 2) {
            return None;
        }
        Some(Self {
            trace_id: trace_id.to_string(),
            parent_id: parent_id.to_string(),
            flags: flags.to_string(),
        })
    }

    pub fn new_root() -> Self {
        Self {
            trace_id: format!("{:032x}", rand::random::<u128>()),
            parent_id: new_span_id(),
            flags: "01".to_string(),
        }
    }

    /// The header value for an outgoing call: same trace id, new span id.
    pub fn outgoing(&self) -> String {
        format!("00-{}-{}-{}", self.trace_id, new_span_id(), self.flags)
    }
}

pub async fn trace_context(mut request: Request, next: Next) -> Response {
    let context = request
        .headers()
        .get("traceparent")
        .and_then(|value| value.to_str().ok())
        .and_then(TraceContext::parse)
        .unwrap_or_else(TraceContext::new_root);
    request.extensions_mut().insert(context);
    next.run(request).await
}

src/metrics_mw.rs

Rust

use axum::{
    extract::{MatchedPath, Request},
    middleware::Next,
    response::Response,
};
use std::time::Instant;

pub async fn track_metrics(request: Request, next: Next) -> Response {
    let start = Instant::now();
    let method = request.method().to_string();
    let route = request
        .extensions()
        .get::<MatchedPath>()
        .map(|path| path.as_str().to_owned())
        .unwrap_or_else(|| "unmatched".to_owned());

    let response = next.run(request).await;

    let status = response.status().as_u16().to_string();
    let elapsed = start.elapsed().as_secs_f64();
    metrics::counter!(
        "http_requests_total",
        "method" => method.clone(),
        "route" => route.clone(),
        "status" => status.clone()
    )
    .increment(1);
    metrics::histogram!(
        "http_request_duration_seconds",
        "method" => method,
        "route" => route,
        "status" => status
    )
    .record(elapsed);
    response
}

src/main.rs

The layer order is: request id, trace context, TraceLayer, request id propagation, metrics. Trace context comes before TraceLayer, so the span can read the trace id from the request extensions.

Rust

mod metrics_mw;
mod telemetry;
mod trace_context;

use axum::{
    body::Body,
    extract::{MatchedPath, Path, State},
    http::StatusCode,
    middleware::from_fn,
    routing::get,
    Extension, Json, Router,
};
use metrics_exporter_prometheus::PrometheusHandle;
use metrics_mw::track_metrics;
use serde_json::{json, Value};
use tower::ServiceBuilder;
use tower_http::{
    request_id::{MakeRequestUuid, PropagateRequestIdLayer, SetRequestIdLayer},
    trace::{DefaultOnResponse, TraceLayer},
};
use trace_context::{trace_context, TraceContext};
use tracing::{info, instrument, warn, Level};

#[instrument]
async fn find_order(id: u64) -> Option<u64> {
    info!(order_id = id, "loading order");
    if id < 1000 {
        Some(id * 100)
    } else {
        warn!(order_id = id, "order not found");
        None
    }
}

async fn get_order(Path(id): Path<u64>) -> Result<Json<Value>, StatusCode> {
    match find_order(id).await {
        Some(cents) => Ok(Json(json!({ "id": id, "cents": cents }))),
        None => Err(StatusCode::NOT_FOUND),
    }
}

async fn trace_info(Extension(context): Extension<TraceContext>) -> Json<Value> {
    let outgoing = context.outgoing();
    Json(json!({
        "trace_id": context.trace_id,
        "parent_id": context.parent_id,
        "outgoing_prefix": &outgoing[..36],
        "outgoing_length": outgoing.len(),
    }))
}

async fn metrics_endpoint(State(handle): State<PrometheusHandle>) -> String {
    handle.render()
}

#[tokio::main]
async fn main() {
    telemetry::init_tracing();
    let handle = telemetry::init_metrics();

    let x_request_id = axum::http::HeaderName::from_static("x-request-id");
    let trace = TraceLayer::new_for_http()
        .make_span_with(|request: &axum::http::Request<Body>| {
            let route = request
                .extensions()
                .get::<MatchedPath>()
                .map(MatchedPath::as_str)
                .unwrap_or("unmatched");
            let request_id = request
                .headers()
                .get("x-request-id")
                .and_then(|value| value.to_str().ok())
                .unwrap_or("none");
            let trace_id = request
                .extensions()
                .get::<TraceContext>()
                .map(|context| context.trace_id.as_str())
                .unwrap_or("none");
            tracing::info_span!(
                "http_request",
                method = %request.method(),
                route = %route,
                request_id = %request_id,
                trace_id = %trace_id,
            )
        })
        .on_response(DefaultOnResponse::new().level(Level::INFO));

    let app = Router::new()
        .route("/orders/{id}", get(get_order))
        .route("/trace", get(trace_info))
        .route("/metrics", get(metrics_endpoint))
        .layer(
            ServiceBuilder::new()
                .layer(SetRequestIdLayer::new(x_request_id.clone(), MakeRequestUuid))
                .layer(from_fn(trace_context))
                .layer(trace)
                .layer(PropagateRequestIdLayer::new(x_request_id))
                .layer(from_fn(track_metrics)),
        )
        .with_state(handle);

    let listener = tokio::net::TcpListener::bind("127.0.0.1:3000").await.unwrap();
    info!("listening on 127.0.0.1:3000");
    axum::serve(listener, app).await.unwrap();
}

src/bin/basics.rs

Rust

use tracing::{info, instrument, warn};

#[instrument]
fn place_order(customer_id: i64, cents: u64) -> i64 {
    info!(cents, "creating order");
    let order_id = customer_id;
    if cents > 1_000_000 {
        warn!(order_id, "large order flagged");
    }
    order_id
}

fn main() {
    tracing_subscriber::fmt().with_target(false).without_time().init();
    place_order(7, 1250);
    place_order(8, 2_000_000);
}

Run:

Terminal

cargo run --bin storefront-observability

Requests:

Terminal

curl -s -w ' [%{http_code}]\n' localhost:3000/orders/7
curl -s -w ' [%{http_code}]\n' localhost:3000/orders/5000
curl -s -w '\n' -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' localhost:3000/trace
curl -s localhost:3000/metrics | grep '^http_requests_total' | sort

Output

{"cents":700,"id":7} [200]
 [404]
{"outgoing_length":55,"outgoing_prefix":"00-4bf92f3577b34da6a3ce929d0e0e4736-","parent_id":"00f067aa0ba902b7","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736"}
http_requests_total{method="GET",route="/orders/{id}",status="200"} 1
http_requests_total{method="GET",route="/orders/{id}",status="404"} 1
http_requests_total{method="GET",route="/trace",status="200"} 1

The outgoing header keeps the trace id from the request and has a new random span id, so the response shows only its fixed prefix and length (55 characters).
The server log shows one JSON line per event. The line for /orders/5000 has level WARN, the message order not found, and the span fields route, request_id, and trace_id.
The /metrics request is counted after its own response, so it does not appear in the first scrape.

Summary

tracing provides structured events and spans. tracing-subscriber formats and filters them.
#[instrument] creates spans for sync and async functions. skip keeps secrets and large arguments out.
EnvFilter reads RUST_LOG. JSON output suits aggregators.
TraceLayer creates a span per request. Add the route pattern, request id, and trace id.
traceparent carries trace id, parent span id, and flags. Extract on incoming calls and inject on outgoing calls.
OpenTelemetry exports spans with OTLP. Sampling controls volume, and the provider is flushed at shutdown.
Prometheus scrapes counters, gauges, and histograms rendered by metrics-exporter-prometheus.
Metric label values stay bounded, and /metrics stays off the public interface.