When print statements stop working
You are debugging a production service. The logs are a wall of text. Timestamps, thread IDs, and raw strings bleed into each other. You need to find every request from user 42, but the logs are just lines. You grep for "42" and get hits from order IDs, timestamps, and random noise. You switch to a structured format. Every log line becomes a machine-readable record with named fields. You filter by user_id = 42 and instantly see the full lifecycle of that request. That is the shift from traditional logging to structured logging.
Stop treating logs like diary entries. Treat them like database rows.
Structured logging in plain words
Traditional logging treats output as text. You format a string, print it, and hope the next developer can parse it in their head. Structured logging treats output as data. You emit events with a level, a message, and a set of key-value pairs. The logging framework handles the formatting. You get consistent fields, type safety, and the ability to filter or transform logs without changing your application code.
Think of it like a shipping manifest. Instead of writing "Package from warehouse 3, fragile, weight 5kg" on a sticky note, you fill out a standardized form. The warehouse system reads the form, routes it, and stores it. You can query by weight, origin, or fragility without ever reading the sticky notes. tracing is that form system for Rust.
The tracing crate splits into two pieces. The core crate defines the API you call from your code. The subscriber crate handles where the data goes. You need both. The core crate is lightweight and compiles fast. The subscriber crate contains the heavy lifting for formatting, filtering, and output.
The minimal setup
Here is the smallest working configuration. You initialize a subscriber, then emit an event.
use tracing::{info, Level};
/// Entry point that initializes logging and emits a test event
fn main() {
// Initialize the default subscriber to capture events up to INFO level
tracing_subscriber::fmt()
.with_max_level(Level::INFO)
.init();
// Emit a structured event with a named field
info!(user_id = 42, "User logged in");
}
Add these to your Cargo.toml:
[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"
Run it. You get a clean line with a timestamp, level, target, message, and the user_id field. The framework formatted it for you. You did not write a single format! macro.
Initialize the subscriber first. Emit events second. The order matters.
How the pipeline actually works
Here is what happens under the hood. When you call info!, the macro expands into a function call that checks if the INFO level is currently enabled. If it is disabled, the macro returns immediately. No string formatting happens. No field evaluation happens. This is the zero-cost abstraction promise. If the level is enabled, the macro builds a small record containing the message, the fields, and metadata like the file and line number. It hands that record to the active subscriber.
The subscriber you initialized with fmt() is a pipeline. It takes the record, formats it into a human-readable string, and writes it to stdout. You can swap that subscriber for one that writes to a file, sends to JSON, or forwards to a remote logging service. Your application code stays identical.
The macro checks the level before it touches a single byte. That is how you get zero-cost logging.
A realistic service example
Real applications need more than a single log line. You need to track context across function calls. You need to control verbosity without recompiling. You need to follow community conventions so other Rust developers recognize your patterns.
use tracing::{info, warn, Level};
/// Process an incoming request and log relevant lifecycle events
fn handle_request(request_id: u64, payload: &str) {
// Check payload length before processing
if payload.is_empty() {
warn!(request_id, "Received empty payload");
return;
}
// Log successful processing with structured fields
info!(
request_id,
payload_size = payload.len(),
"Request processed successfully"
);
}
/// Entry point that sets up dynamic filtering and runs test requests
fn main() {
// Initialize subscriber with environment variable support
tracing_subscriber::fmt()
.with_env_filter(
tracing_subscriber::EnvFilter::from_default_env()
)
.init();
handle_request(101, "valid data");
handle_request(102, "");
}
Notice the with_env_filter call. This replaces the hard-coded Level::INFO with a dynamic filter. You control the logging level at runtime using the RUST_LOG environment variable. Run it with RUST_LOG=debug cargo run and you get debug output. Run it with RUST_LOG=error and you only see errors. This is the standard convention in the Rust ecosystem. Hard-coding levels in production code is an anti-pattern.
Also notice the field shorthand. request_id without a value tells tracing to capture the local variable request_id and attach it to the event. This keeps the macro call clean and reduces boilerplate. The community prefers this shorthand over explicit request_id = request_id when the names match.
Let the environment control verbosity. Hard-coding levels is a maintenance trap.
Common pitfalls and compiler friction
New developers run into a few predictable friction points. The first is forgetting to initialize a subscriber. If you call info! without calling init() on a subscriber, nothing happens. The events are silently dropped. The compiler will not warn you. You will stare at a blank terminal and wonder where your logs went. Always initialize the subscriber before emitting any events.
The second friction point is mixing println! with tracing. You might keep using println! for quick debugging while adding tracing for production logs. This splits your output stream. println! bypasses the subscriber entirely. It goes straight to standard output with no timestamps, no levels, and no structured fields. Stick to tracing macros consistently. Use debug! for temporary debugging. Remove it or lower the log level when you are done.
The third issue is over-eager field evaluation. If you pass a function call as a field value, that function runs every time the event is emitted. If you pass an expensive computation to a trace! event, it still runs if the trace level is enabled. Be mindful of what you put inside the macro. The macro does not lazy-evaluate arbitrary expressions. It captures the values at the call site.
Silent drops are the enemy. If you do not see output, check your subscriber initialization.
Choosing your logging strategy
Use tracing when you need structured, filterable logs with zero overhead for disabled levels. Use tracing when you want to swap log destinations without touching application code. Use log when you are maintaining a legacy codebase that already depends on it, though tracing can bridge to it. Use println! only for interactive CLI prompts or when you explicitly want unbuffered terminal output. Reach for tracing spans when you need to track the lifecycle of a request across multiple functions. Reach for tracing events when you need to record discrete moments in time.
Pick the tool that matches your data shape. Text for humans. Structured data for machines.