Logging & Tracing

Logging in Rust is split into two parts: a facade that code writes to, and a backend chosen by the application. Libraries and applications write log events with the macros of the tracing crate, and the application installs a subscriber, usually from tracing-subscriber, that decides what to keep, how to format it, and where to write it. With no subscriber installed, events are discarded.

tracing goes beyond plain logging in two ways: every event can carry structured fields (user_id = 42) instead of text you parse later, and spans attach context to everything logged during a unit of work, such as a request ID, even across async code.

Terminal

cargo add tracing
cargo add tracing-subscriber --features env-filter,json

Task	tracing
Log a message	`info!("started")`
Log a value	`info!(user_id = id, "logged in")`
Configure output	building a subscriber in `main`
Set levels per module	`EnvFilter::new("info,shop::db=debug")` or `RUST_LOG`
Attach context to every line	a span: `info_span!("request", id)`
JSON output	`.json()`
Write to (rolling) files	`.with_writer(...)`, the `tracing-appender` crate
Capture events from the older `log` crate	`tracing-log`, built into `tracing-subscriber`

The examples call .without_time(), .with_ansi(false), and .with_target(false) so the output on this page is plain and stable. In a real program, keep the timestamps, and keep the colors when writing to a terminal.

Part 1: Events

1. Levels, macros, and a subscriber

The five macros match the familiar levels: error!, warn!, info!, debug!, and trace!. Nothing is printed until a subscriber is installed; tracing_subscriber::fmt().init() installs the default one, which writes human-readable lines to stdout and shows INFO and above.

Rust

use tracing::{debug, error, info, warn};

fn main() {
    info!("before a subscriber is installed: this goes nowhere");

    tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).init();

    info!("server starting on port {}", 8080);
    warn!("config file not found, using defaults");
    error!("could not connect to the database");
    debug!("not shown: below the default INFO level");
}

Output

 INFO server starting on port 8080
 WARN config file not found, using defaults
ERROR could not connect to the database

Libraries only ever use the macros; only the application's main installs a subscriber, once.

2. Structured fields

Instead of formatting values into the message, attach them as fields: name = value before the message. They appear as key=value in text output and as real JSON fields in JSON output (example 8), so log tools can filter on them without parsing text. %value records a value with Display, ?value with Debug, and a bare variable name records it under its own name.

Rust

use tracing::info;

#[derive(Debug)]
struct Cart {
    items: u32,
    total_cents: u64,
}

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

    let order_id = "A-1042";
    let cart = Cart { items: 3, total_cents: 4_990 };
    let user_id = 42;

    info!(user_id, order = %order_id, "order placed");
    info!(?cart, express = true, "checkout");
    info!(cart.items, cart.total_cents, "cart summary");
}

Output

 INFO order placed user_id=42 order=A-1042
 INFO checkout cart=Cart { items: 3, total_cents: 4990 } express=true
 INFO cart summary cart.items=3 cart.total_cents=4990

3. Choosing what to log with `EnvFilter`

An EnvFilter sets a default level and per-module overrides. EnvFilter::from_default_env() reads the RUST_LOG environment variable, so levels can change without recompiling: RUST_LOG=info,shop::db=debug cargo run. Each event's target defaults to its module path; here the target: argument sets it explicitly.

Rust

use tracing::{debug, info, trace, warn};
use tracing_subscriber::EnvFilter;

fn main() {
    // In a real program: EnvFilter::from_default_env(), set via RUST_LOG.
    let filter = EnvFilter::new("warn,shop::db=debug,shop::http=info");
    tracing_subscriber::fmt().without_time().with_ansi(false).with_env_filter(filter).init();

    debug!(target: "shop::db", "SELECT * FROM orders WHERE id = 7");
    trace!(target: "shop::db", "row decoded"); // below debug: filtered out
    info!(target: "shop::http", "GET /orders/7 -> 200");
    debug!(target: "shop::http", "headers parsed"); // below info: filtered out
    info!(target: "shop::billing", "invoice sent"); // default level is warn
    warn!(target: "shop::billing", "invoice 7 is overdue");
}

Output

DEBUG shop::db: SELECT * FROM orders WHERE id = 7
 INFO shop::http: GET /orders/7 -> 200
 WARN shop::billing: invoice 7 is overdue

A common setup reads RUST_LOG and falls back to a default: EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")).

Part 2: Spans

4. Spans: context for a unit of work

A span represents a period of time, such as handling one request. While a span is entered, every event includes its name and fields, which is how a request ID ends up on every line. Spans nest, and leaving the scope of the guard returned by enter() exits the span.

Rust

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

fn load_order(id: u32) {
    info!("loading from the database");
    if id == 13 {
        warn!("order is locked by another request");
    }
}

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

    for (request_id, order_id) in [(1, 7), (2, 13)] {
        let request = info_span!("request", request_id, path = "/orders");
        let _entered = request.enter();
        info!("received");
        {
            let _db = info_span!("db", order_id).entered();
            load_order(order_id);
        }
        info!("responded");
    } // `_entered` is dropped at the end of each iteration: the span is exited
    info!("outside any span");
}

Output

 INFO request{request_id=1 path="/orders"}: received
 INFO request{request_id=1 path="/orders"}:db{order_id=7}: loading from the database
 INFO request{request_id=1 path="/orders"}: responded
 INFO request{request_id=2 path="/orders"}: received
 INFO request{request_id=2 path="/orders"}:db{order_id=13}: loading from the database
 WARN request{request_id=2 path="/orders"}:db{order_id=13}: order is locked by another request
 INFO request{request_id=2 path="/orders"}: responded
 INFO outside any span

span.entered() enters and returns the guard in one step.

5. `#[instrument]`: a span per function call

The #[instrument] attribute wraps a function in a span named after it, with its arguments as fields. skip leaves out arguments that shouldn't be logged, such as passwords or large values, and fields adds more.

Rust

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

#[instrument(skip(password), fields(method = "password"))]
fn login(user: &str, password: &str) -> bool {
    let ok = password == "correct horse";
    if ok {
        info!("logged in");
    } else {
        warn!(len = password.len(), "wrong password");
    }
    ok
}

#[instrument]
fn charge(order_id: u32, cents: u64) {
    info!("charging card");
}

fn main() {
    tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).init();
    login("ana", "hunter2");
    login("ana", "correct horse");
    charge(7, 4_990);
}

Output

 WARN login{user="ana" method="password"}: wrong password len=7
 INFO login{user="ana" method="password"}: logged in
 INFO charge{order_id=7 cents=4990}: charging card

6. Spans across async code

A span entered with enter() would stay entered while the task sleeps at an .await, and other tasks running on the same thread would appear to be inside it. For async code, attach the span to the future with .instrument(span) instead: it's entered each time the future runs and exited each time it pauses. #[instrument] on an async fn does this automatically.

Rust

use std::time::Duration;
use tracing::{Instrument, info, info_span, instrument};

#[instrument]
async fn fetch(url: &str, delay_ms: u64) -> usize {
    info!("start");
    tokio::time::sleep(Duration::from_millis(delay_ms)).await;
    info!("done");
    url.len()
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).init();

    let a = fetch("https://a.example", 30);
    let b = fetch("https://b.example/slow", 60);
    let (x, y) = tokio::join!(a, b); // both run at the same time; each line still names its own call
    info!(total = x + y, "both finished");

    async { info!("inside a manually instrumented block") }.instrument(info_span!("job", id = 9)).await;
}

Output

 INFO fetch{url="https://a.example" delay_ms=30}: start
 INFO fetch{url="https://b.example/slow" delay_ms=60}: start
 INFO fetch{url="https://a.example" delay_ms=30}: done
 INFO fetch{url="https://b.example/slow" delay_ms=60}: done
 INFO both finished total=39
 INFO job{id=9}: inside a manually instrumented block

Part 3: Output

7. Logging errors

Record an error as a field with %, so its Display text appears. When the error has a chain of causes, as anyhow errors do, {:#} formats the whole chain on one line (thiserror & anyhow).

Rust

use anyhow::Context;
use tracing::{error, warn};

fn read_config(path: &str) -> anyhow::Result<String> {
    std::fs::read_to_string(path).with_context(|| format!("reading {path}"))
}

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

    let parse_error = "12x".parse::<u32>().unwrap_err();
    warn!(error = %parse_error, input = "12x", "ignoring bad quantity");

    if let Err(e) = read_config("missing.toml") {
        error!(error = format!("{e:#}"), "startup failed");
    }
}

Output

 WARN ignoring bad quantity error=invalid digit found in string input="12x"
ERROR startup failed error="reading missing.toml: No such file or directory (os error 2)"

8. JSON logs for production

Log collectors such as Elasticsearch, Loki, or CloudWatch prefer one JSON object per line. .json() switches the format; fields become JSON fields and the current spans are included.

Rust

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

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

    let span = info_span!("request", request_id = 81, path = "/checkout");
    let _entered = span.enter();
    info!(user_id = 42, total_cents = 4_990, "order placed");
    warn!(retry_in_ms = 250, "payment provider slow");
}

Output

{"level":"INFO","fields":{"message":"order placed","user_id":42,"total_cents":4990},"span":{"path":"/checkout","request_id":81,"name":"request"},"spans":[{"path":"/checkout","request_id":81,"name":"request"}]}
{"level":"WARN","fields":{"message":"payment provider slow","retry_in_ms":250},"span":{"path":"/checkout","request_id":81,"name":"request"},"spans":[{"path":"/checkout","request_id":81,"name":"request"}]}

With timestamps enabled, each object also has a "timestamp" field. .flatten_event(true) moves the fields to the top level if your log collector prefers that.

9. Writing logs to a file

with_writer chooses where the output goes. It accepts anything that can produce writers: std::io::stderr (the usual choice for command-line tools, so logs don't mix with the program's output), or a Mutex<File>. For rolling daily files and writing on a background thread, use the tracing-appender crate.

Rust

use std::fs::{self, File};
use std::sync::Mutex;
use tracing::info;

fn main() -> std::io::Result<()> {
    let file = File::create("app.log")?;
    tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).with_writer(Mutex::new(file)).init();

    info!(version = "1.4.2", "service started");
    info!(jobs = 3, "queue drained");

    print!("app.log contains:\n{}", fs::read_to_string("app.log")?);
    Ok(())
}

Output

app.log contains:
 INFO service started version="1.4.2"
 INFO queue drained jobs=3

10. A subscriber for one scope

init() sets the global subscriber and can only be called once per program. tracing::subscriber::with_default installs one just for the duration of a closure on the current thread. Tests use it to capture or silence logs, and it's handy for showing two formats side by side.

Rust

use tracing::info;

fn work() {
    info!(step = 1, "doing work");
}

fn main() {
    let plain = tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).finish();
    tracing::subscriber::with_default(plain, work);

    let json = tracing_subscriber::fmt().json().without_time().with_target(false).finish();
    tracing::subscriber::with_default(json, work);

    work(); // no subscriber here: nothing is printed
}

Output

 INFO doing work step=1
{"level":"INFO","fields":{"message":"doing work","step":1}}

11. Disabled levels cost almost nothing

A debug! call below the active level checks the level and returns: its arguments aren't even evaluated. Leaving detailed debug! and trace! calls in production code is therefore cheap, and they can be switched on with RUST_LOG when needed.

Rust

use std::sync::atomic::{AtomicU32, Ordering};
use tracing::{debug, info};
use tracing_subscriber::EnvFilter;

static CALLS: AtomicU32 = AtomicU32::new(0);

fn expensive_summary() -> String {
    CALLS.fetch_add(1, Ordering::Relaxed);
    "a very long report".to_string()
}

fn main() {
    tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).with_env_filter(EnvFilter::new("info")).init();

    for _ in 0..1_000 {
        debug!(summary = %expensive_summary(), "tick"); // disabled: never evaluated
    }
    info!(summary = %expensive_summary(), "done");
    println!("expensive_summary ran {} time(s)", CALLS.load(Ordering::Relaxed));
}

Output

 INFO done summary=a very long report
expensive_summary ran 1 time(s)

12. Libraries that use the `log` crate

Before tracing, the ecosystem's logging facade was the log crate, and many libraries still use it. tracing-subscriber's init() also captures log events, so they appear in the same output.

Rust

use tracing::info;

mod legacy_library {
    pub fn connect() {
        log::info!("connected via the log crate");
        log::debug!("not shown at INFO level");
    }
}

fn main() {
    tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).init();
    info!("from tracing");
    legacy_library::connect();
}

Output

 INFO from tracing
 INFO connected via the log crate

Part 4: Putting it together

13. Realistic example: an instrumented order service

A request handler with the patterns a real service uses: a span per request with a request ID, #[instrument] on the steps, structured fields everywhere, warnings for recoverable problems, errors with their cause, and one summary event per request. The filter comes from RUST_LOG with a default.

Rust

use tracing::{debug, error, info, info_span, instrument, warn};
use tracing_subscriber::EnvFilter;

#[derive(Debug)]
struct Order {
    id: u32,
    items: u32,
    cents: u64,
}

#[instrument(skip(order), fields(order_id = order.id))]
fn reserve_stock(order: &Order) -> Result<(), String> {
    debug!(items = order.items, "reserving");
    if order.items > 10 {
        return Err(format!("only 10 in stock, {} requested", order.items));
    }
    Ok(())
}

#[instrument(skip(order), fields(order_id = order.id))]
fn charge(order: &Order, attempt: u32) -> Result<(), String> {
    if order.cents > 50_000 && attempt == 1 {
        warn!("provider timeout, retrying");
        return charge(order, attempt + 1);
    }
    info!(cents = order.cents, "charged");
    Ok(())
}

fn handle(request_id: u32, order: Order) {
    let _span = info_span!("request", request_id).entered();
    let result = reserve_stock(&order).and_then(|()| charge(&order, 1));
    match result {
        Ok(()) => info!(order_id = order.id, status = 201, "request complete"),
        Err(e) => error!(order_id = order.id, status = 409, error = %e, "request failed"),
    }
}

fn main() {
    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
    tracing_subscriber::fmt().without_time().with_ansi(false).with_target(false).with_env_filter(filter).init();

    handle(1, Order { id: 7, items: 2, cents: 4_990 });
    handle(2, Order { id: 8, items: 12, cents: 9_000 });
    handle(3, Order { id: 9, items: 1, cents: 72_000 });
}

Output

 INFO request{request_id=1}:charge{attempt=1 order_id=7}: charged cents=4990
 INFO request{request_id=1}: request complete order_id=7 status=201
ERROR request{request_id=2}: request failed order_id=8 status=409 error=only 10 in stock, 12 requested
 WARN request{request_id=3}:charge{attempt=1 order_id=9}: provider timeout, retrying
 INFO request{request_id=3}:charge{attempt=1 order_id=9}:charge{attempt=2 order_id=9}: charged cents=72000
 INFO request{request_id=3}: request complete order_id=9 status=201

Where to go from here

Distributed tracing: tracing-opentelemetry exports spans to Jaeger, Zipkin, or any OpenTelemetry collector, so one request can be followed across services.
Timing: .with_span_events(FmtSpan::CLOSE) logs how long each span was open.
Rolling files: tracing-appender writes to daily or hourly files, on a background thread so logging never blocks a request.
Web frameworks: tower-http's TraceLayer creates a span for every HTTP request, as the next lesson shows.

Summary

Code logs with tracing's macros; the application installs one subscriber, usually tracing_subscriber::fmt(), configured in main.
Prefer structured fields (user_id = 42, %display, ?debug) to formatting values into messages.
Filter by level and module with EnvFilter, from RUST_LOG in real programs.
Spans add context to every event inside them; use #[instrument] on functions and .instrument(span) on futures.
.json() for log collectors, with_writer for stderr or files, with_default for scoped subscribers in tests.
Disabled events don't evaluate their arguments, and events from the log crate are captured too.

Next: Web Services with axum.

Part 1: Events

1. Levels, macros, and a subscriber

2. Structured fields

3. Choosing what to log with EnvFilter

Part 2: Spans

4. Spans: context for a unit of work

5. #[instrument]: a span per function call

6. Spans across async code

Part 3: Output

7. Logging errors

8. JSON logs for production

9. Writing logs to a file

10. A subscriber for one scope

11. Disabled levels cost almost nothing

12. Libraries that use the log crate

Part 4: Putting it together

13. Realistic example: an instrumented order service

Where to go from here

Summary

3. Choosing what to log with `EnvFilter`

5. `#[instrument]`: a span per function call

12. Libraries that use the `log` crate