The async log salad
You are debugging a Rust server. Requests pour in. You add println! statements to track a slow endpoint. The terminal fills with output, but the order is wrong. Request A start, Request B start, Request A step 1, Request B step 1, Request A end, Request B end. The logs are interleaved. You cannot tell which message belongs to which request. The flow is lost in the noise.
This happens because async code runs many tasks on the same thread. The runtime switches between tasks at .await points. println! writes to stdout immediately, mixing output from all active tasks. You get a salad of messages with no structure.
tracing solves this by grouping logs into spans. Each request gets a unique span. Every log message attaches to the current span. The output shows the hierarchy. You can follow a single request from start to finish, even when hundreds of requests run concurrently.
Spans, events, and the case file
tracing uses two core concepts: spans and events.
A span represents a unit of work. Think of a span as a folder in a detective's case file. When a request arrives, you open a folder. When the request enters a function, you open a subfolder inside that folder. That subfolder is a nested span. When the function returns, you close the subfolder. The folder structure captures the execution path.
An event is a log message. An event is a sticky note you write and drop into the current folder. The note records what happened and when. Events can carry data, like a user ID or an error code.
The subscriber is the detective who reads the case files. The subscriber collects spans and events, formats them, and writes them to the console, a file, or a remote service. tracing itself does not print anything. It only generates the data. You must install a subscriber to see output. This separation lets you swap outputs without changing your code.
Minimal setup
Add tracing and tracing-subscriber to your dependencies. tracing provides the API. tracing-subscriber provides the default subscriber that prints to the console.
[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter"] }
tokio = { version = "1", features = ["full"] }
The env-filter feature enables filtering logs via the RUST_LOG environment variable. This is the standard way to control log levels in Rust.
Here is a minimal async example. The #[instrument] attribute automatically creates a span for the function. It logs entry, exit, and arguments.
use tracing::{info, instrument};
/// Fetches data with automatic span creation.
#[instrument]
async fn fetch_data() {
// This event attaches to the span created by #[instrument].
info!("Fetching data from upstream");
// Simulate async work. The span survives this await point.
tokio::time::sleep(std::time::Duration::from_millis(50)).await;
info!("Data received");
}
#[tokio::main]
async fn main() {
// Initialize the subscriber. Without this, tracing produces no output.
tracing_subscriber::fmt::init();
fetch_data().await;
}
Run this with RUST_LOG=debug cargo run. The output shows the span name and the events inside it.
2024-01-15T10:00:00.000000Z DEBUG fetch_data: Fetching data from upstream
2024-01-15T10:00:00.050000Z DEBUG fetch_data: Data received
The fetch_data: prefix indicates the event occurred inside the fetch_data span. If you nest functions, the prefix grows to show the full path.
Convention: Always call tracing_subscriber::fmt::init() early in main. If you forget this, tracing silently discards all logs. This is the most common mistake. The code compiles and runs, but nothing appears. Check the subscriber first when logs vanish.
How #[instrument] saves async
Async functions pose a unique challenge. When you .await, the function pauses. The stack frame disappears. The local variables are stored in a generated Future struct. If you create a span manually and store it in a local variable, that variable gets dropped when the function yields. The span is lost.
#[instrument] handles this automatically. The macro captures the span and stores it inside the Future struct. When the future resumes, the span is restored. Events emitted after the await point still attach to the correct span.
Manual span management requires you to enter the span before every await and exit after. This is error-prone. Forgetting to re-enter the span breaks the hierarchy. #[instrument] eliminates this risk. Use #[instrument] on every async function that does meaningful work.
Convention: Use #[instrument(level = "debug")] for most functions. This keeps the span active only when debug logging is enabled. Spans have a small overhead. Filtering at the span level prevents creating spans when they are not needed. The default level is TRACE, which is too verbose for production.
Realistic handler with fields
Real code needs more than function names. You need context. tracing supports fields. Fields are key-value pairs attached to spans or events. You can record fields when the span starts or update them later.
The #[instrument] attribute supports fields via the fields() argument. You can also skip arguments that do not implement Debug or are too large to log.
use tracing::{info, warn, instrument, Span};
/// Database client that does not implement Debug.
struct DatabaseClient;
impl DatabaseClient {
async fn fetch(&self, id: u64) -> Option<String> {
if id == 42 {
Some("Secret Data".to_string())
} else {
None
}
}
}
/// Handles a request with user context.
///
/// Skips the db_client because it does not implement Debug.
/// Records the user_id as a field for filtering.
#[instrument(skip(db_client), fields(user_id))]
async fn handle_request(user_id: u64, db_client: &DatabaseClient) {
// Record the user_id in the span fields.
Span::current().record("user_id", &user_id);
info!("Processing request");
let data = db_client.fetch(user_id).await;
match data {
Some(content) => {
info!(content_len = content.len(), "Data found");
}
None => {
warn!("User not found");
}
}
}
#[tokio::main]
async fn main() {
tracing_subscriber::fmt::init();
let db = DatabaseClient;
handle_request(42, &db).await;
}
The skip(db_client) argument tells #[instrument] not to try to log the db_client argument. If you omit skip, the compiler rejects the code because DatabaseClient does not implement Debug. The error is E0277 (trait bound not satisfied). The macro requires all logged arguments to implement Debug.
The fields(user_id) argument declares a field. You must record the value using Span::current().record(). This pattern is useful when the value is not available at function entry. You can update fields at any point while the span is active.
Convention: Use skip() for any argument that does not implement Debug, or for large objects like connections, buffers, or clients. Log IDs and metadata, not the objects themselves. Logging a large struct can degrade performance and leak sensitive data.
Pitfalls and compiler errors
tracing has a few traps. Knowing them saves debugging time.
Silent logs. If you do not initialize a subscriber, tracing drops all data. The code runs normally. No warnings. No errors. Just empty output. Always verify the subscriber is installed. Check main() for tracing_subscriber::fmt::init() or a custom subscriber setup.
Missing Debug bounds. If you add #[instrument] to a function with an argument that lacks Debug, compilation fails with E0277. The error message points to the macro expansion. Fix this by adding skip(arg_name) to the attribute.
struct NoDebug;
#[instrument]
fn bad_func(x: NoDebug) {
// Error: E0277 the trait bound `NoDebug: std::fmt::Debug` is not satisfied
}
Blocking the subscriber. tracing itself is non-blocking. It writes to a channel. The subscriber reads from the channel and formats output. If the subscriber blocks, it can back up the channel. The default fmt subscriber writes to stdout, which is usually fast. If you write to a slow destination like a network socket, use a subscriber that handles backpressure. tracing-subscriber supports async layers for this purpose.
Over-logging. Spans and events have overhead. Creating millions of spans per second can impact performance. Use level = "debug" or level = "trace" for high-frequency functions. Filter aggressively in production. Use RUST_LOG=info to disable debug spans. The compiler optimizes away disabled spans and events. The overhead is zero when filtered out.
Decision matrix
Use tracing when you need structured logs with spans, especially in async code where interleaving matters. Use tracing when you want to filter logs at runtime via RUST_LOG without recompiling. Use tracing when you need to attach context fields to spans for correlation.
Use log only when maintaining legacy code that depends on the log crate and you cannot migrate. The log crate lacks spans and async support. It is a flat stream of messages.
Reach for println! only for quick, throwaway scripts where structured output is overkill. println! has no filtering, no structure, and interleaves in async code.
Pick eprintln! when you need to write to stderr for a CLI tool that does not use a logging framework. eprintln! writes to standard error, which is appropriate for error messages in simple tools.
Async code demands structure. tracing gives you that structure for free. Trust the spans. They keep your logs readable when concurrency spikes.