When flat logs fail
You are running a web server. Suddenly, the logs flood with "Processing request" and "Database query started". A user complains their order failed. You grep for the error, find it, but now you have no idea which request caused it, what happened right before, or how long the database took. The logs are a flat list of events with no context. You are staring at a wall of text trying to reconstruct a timeline that happened milliseconds ago.
Rust's tracing crate solves this with spans. Spans give your logs structure, hierarchy, and context. They turn a flat list of messages into a navigable timeline of what your program actually did. Instead of guessing which log line belongs to which request, you get a tree of execution that shows exactly how time was spent and where things went wrong.
Spans are context containers
A span represents a period of time in your program. It has a start, an end, and a name. It can also hold data, called fields. When you enter a span, it becomes the active context. Any event you log inside that span gets associated with it. Spans can be nested. A "handle_request" span might contain a "query_database" span. This creates a tree.
Think of a span like a video recording session. You press record to start a span. You talk and move around, which are events. You stop recording to end the span. If you start a second recording session while the first is running, you get nested recordings. Later, you can watch the outer recording and jump into the inner one to see the details. The span captures the "when" and the "where".
Events are point-in-time occurrences. An event happens at a single moment. It carries data and a level, like info, warn, or error. Events live inside spans. If you log an event without an active span, it floats in the global context, which is rarely useful for request tracing.
The tracing crate provides the API to create spans and events. It does not print anything to the console by itself. You need a subscriber to collect the data and format it. This separation lets you swap out logging backends without changing your application code.
The minimal example
The fastest way to add tracing is the #[instrument] macro. It wraps a function in a span automatically. It captures the function's arguments as fields, so you don't have to type them in every log line.
use tracing::{info, instrument};
/// Handles an incoming request and logs progress.
#[instrument]
fn handle_request(request_id: &str) {
// The macro creates a span named "handle_request".
// It captures `request_id` as a field automatically.
info!("Processing request");
}
Run this with a subscriber installed, and you get structured output. The span starts when the function is called. The event fires inside the span. The span ends when the function returns. The output shows the hierarchy. You see the span name, the fields, and the event message, all linked together.
Convention aside: #[instrument] captures arguments by default. This is a community standard because it saves boilerplate. If you have a function with ten arguments, typing them all into every info! call is tedious and error-prone. The macro does it for you.
How the macro works
The #[instrument] macro expands your function at compile time. It generates code to create a span, enter it, run the function body, and exit the span. It also generates code to capture the arguments.
When handle_request is called, the generated code creates a span. It calls span.enter(). This pushes the span onto a thread-local stack. The stack tracks the current context. The function body runs. When info! is called, it checks the stack, finds the active span, and attaches the event to it. The function returns. The generated code calls span.exit(). The span is popped from the stack.
This mechanism ensures that spans are always balanced. You cannot accidentally leave a span open. The compiler guarantees that exit is called when the function returns, even if a panic occurs. This prevents context leaks.
Convention aside: Keep spans short and focused. A span should represent a single unit of work. If a function does three distinct things, consider splitting it or using manual spans inside the function. Long spans make it hard to pinpoint bottlenecks.
Realistic request tracing
Real code has nested calls, results, and types that don't implement Debug. The #[instrument] macro has attributes to handle these cases. You can skip arguments, capture return values, and set span levels.
use tracing::{info, instrument, warn};
/// Queries the database and logs the duration.
#[instrument(skip(db_conn))]
fn query_database(db_conn: &mut DbConnection, query: &str) -> Vec<String> {
// `skip` prevents capturing `db_conn` because it doesn't implement Debug.
// Capturing large objects can hurt performance.
info!("Executing query");
// Simulate query work
vec!["result1".to_string()]
}
/// Handles the request flow with nested spans.
#[instrument(ret)]
fn handle_request(request_id: &str, db_conn: &mut DbConnection) -> Result<Vec<String>, String> {
info!("Request received");
let results = query_database(db_conn, "SELECT * FROM items");
info!(count = results.len(), "Query returned results");
Ok(results)
}
The skip attribute tells the macro not to capture an argument. Use this for types that don't implement Debug, or for large objects where capturing would be expensive. The ret attribute captures the return value as a field. This is incredibly useful for debugging. You can see the result of a function without adding extra log lines.
Convention aside: Use skip liberally. You don't need to log the entire database connection object or a large buffer. Skip anything that is heavy or lacks Debug. Use ret on functions that return Result or important data. It turns your logs into a trace of inputs and outputs.
Fields can be static or dynamic. Static fields are known at compile time. Dynamic fields are set at runtime. The #[instrument] macro creates static fields for arguments. You can add dynamic fields in your log calls. The info!(count = results.len(), ...) line adds a dynamic field. This lets you filter logs by field values later.
Pitfalls and gotchas
Tracing is powerful, but there are traps. The most common one is forgetting to install a subscriber. If you don't call tracing_subscriber::fmt::init() or equivalent, your spans and events vanish into the void. The code compiles fine, but you see nothing. Initialize the subscriber early in main.
Async functions break the span context by default. The span context is thread-local. When you hit an .await, the task might pause and resume on a different thread. If you create a span manually and try to use it across an await, the context might be lost. The #[instrument] macro handles this correctly for async functions by attaching the span to the future. If you write manual tracing in async code, use tracing::Instrument to attach the span to the future explicitly.
Another pitfall is logging sensitive data. The #[instrument] macro captures arguments automatically. If you pass a password or a token, it gets logged. Use skip to exclude sensitive fields. Audit your instrumented functions regularly.
Performance is rarely an issue. Spans and events are cheap. The overhead is minimal. The cost comes from the subscriber formatting and writing output. Use filtering to reduce the volume of logs in production. Set RUST_LOG=info or RUST_LOG=warn to drop debug events. The tracing crate checks filters at compile time for static events, so filtered events cost almost nothing.
Convention aside: Use RUST_LOG to control verbosity. This is the standard environment variable. It supports hierarchical filtering. You can set RUST_LOG=my_crate=debug,other_crate=info to tune logging per module. Don't hardcode log levels in your code.
Choosing the right tool
Tracing offers several ways to create spans and events. Pick the right one for the job.
Use #[instrument] when you want automatic span creation and argument capture for a whole function. Use info_span! and manual enter() when you need fine-grained control over span lifetimes inside a function, like wrapping a loop or a conditional block. Use event! macros like info! or warn! when you need to record a point-in-time occurrence without a duration. Use tracing::Instrument when you need to attach a span to a future explicitly, especially in async code where #[instrument] might not cover the whole execution path.
Don't fight the compiler here. Reach for #[instrument] first. It covers 90% of use cases. Drop to manual spans only when you need to split a function's work into multiple spans.