How to add logging with tracing

Short answer: Add tracing and tracing-subscriber to Cargo.toml, install a subscriber with tracing_subscriber::fmt().with_max_level(Level::INFO).init() as the first line of main, and log with the info!, warn!, error!, debug! and trace! macros. With the level pinned at info, the subscriber prints info and everything above it to stdout.

println! sends everything to stdout at the same volume: a bug that happens once per hour and a heartbeat that happens once per second look identical, and there is no way to turn the heartbeat off. tracing splits the job in two. The tracing crate is where you emit events — each macro compiles down to a function call that hands a timestamped record to whoever is listening. The tracing-subscriber crate is the listener: it decides which levels to print and in what format. That split is why the same binary can be loud in development and quiet in production without recompiling it.

The two crates, and the one call

Cargo.toml

[dependencies]
tracing = "0.1.44"
tracing-subscriber = "0.3.23"

The versions are whatever cargo add resolved on the day; the crate names are the part that matters. The examples below assume a project created with cargo new tracing-demo — the outputs name it, and a project with a different name prints that name instead.

The macros do nothing until a subscriber is installed. info!("server started") compiles and runs in a program without one — it just evaporates. The subscriber is installed once, at the top of main:

src/main.rs

use tracing::info;
use tracing_subscriber::fmt;

fn main() {
    fmt().with_max_level(tracing::Level::INFO).init();
    info!("server started");
}

2026-10-29T16:37:30.501888Z  INFO tracing-demo: server started

The timestamp will differ on every run; the rest is fixed. The pieces are: the time the event happened, the level, the module path the event came from, and the message. That module path is the crate name for code in main.rs — it is not decoration: when several crates in one dependency tree all log, that field says who spoke.

Note the two spaces in front of INFO — the level column is padded to five characters so the columns line up, and ERROR takes the full width.

There is a shorter call, tracing_subscriber::fmt::init(), and it is worth knowing what it hides. A subscriber has to decide which levels to show, and that decision moves with the features tracing-subscriber was built with: in a fresh project the default is info and above, but with the env-filter feature enabled it reads the RUST_LOG variable instead — and when that variable is unset, only error gets through. Pinning the level with with_max_level makes the program mean what it says no matter which features are in the tree. How to make the level follow RUST_LOG at runtime is the next article’s subject.

The five levels

tracing has five macros, from quietest to loudest: trace!, debug!, info!, warn!, error!. Emit one of each:

src/main.rs

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

fn main() {
    fmt().with_max_level(tracing::Level::INFO).init();
    trace!("server heartbeat");
    debug!("cache hit");
    info!("server started");
    warn!("disk 80% full");
    error!("connection lost");
}

2026-10-29T16:37:30.501888Z  INFO tracing-demo: server started
2026-10-29T16:37:30.502129Z  WARN tracing-demo: disk 80% full
2026-10-29T16:37:30.502154Z ERROR tracing-demo: connection lost

Five calls, three lines out. A subscriber pinned at info drops debug! and trace! — they are still compiled in, still executed, but the subscriber throws them away. That is the convention worth copying: info for things an operator would want in a normal log, warn for something suspicious that did not stop the program, error for something that did, and debug/trace for the firehose you only want while developing. The call sites do not change when the filter does — the macros stay, the subscriber decides.

Fields

A level plus a message is still just a line of text. The second half of tracing is structured fields — values that travel with the event instead of being formatted into the string:

src/main.rs

use tracing::info;
use tracing_subscriber::fmt;

fn main() {
    fmt().with_max_level(tracing::Level::INFO).init();
    info!(user_id = 42, name = "grace", "user logged in");
}

2026-10-29T16:37:30.502166Z  INFO tracing-demo: user logged in user_id=42 name="grace"

The message comes last, and the fields trail after it as key=value. Numbers stay numbers, strings get quotes — the syntax is one step away from JSON, and a log collector can pull user_id out without a regex. A local variable whose name matches the field can be written bare: info!(amount_cents, "order processed") records the variable amount_cents under that same name.

Spans

An event is instantaneous. A span has a duration — a request being handled, a file being read — and every event logged inside it carries the span’s name and fields on its line. The easiest way to make one is #[instrument], which wraps a function in a span named after it, with its arguments recorded as fields:

src/main.rs

use tracing::{info, instrument};
use tracing_subscriber::fmt;

#[instrument]
fn process_order(order_id: u32, amount_cents: u32) {
    info!(amount_cents, "order processed");
}

fn main() {
    fmt().with_max_level(tracing::Level::INFO).init();
    process_order(1001, 2500);
}

2026-10-29T16:37:30.502254Z  INFO process_order{order_id=1001 amount_cents=2500}: tracing-demo: order processed amount_cents=2500

The process_order{order_id=1001 amount_cents=2500}: prefix is the span. Every info! inside the function would carry it — which is the mechanism behind “one request id on every line” once a real web framework is involved. For now, the whole loop fits in four lines: install the subscriber, pick a level, emit fields, and wrap functions in spans.