The async logging trap
You are debugging an async service. A request times out. You grep the logs for the request ID. You find three lines. They are scattered across timestamps that span ten seconds. In between, logs from fifty other requests have interleaved. You have to mentally reconstruct the timeline. This is the async logging trap. Standard loggers write to a flat stream. They do not know about concurrency. They do not know which message belongs to which task.
tracing fixes this by introducing spans. A span is a named, scoped interval with a start and an end. It can contain events. Events are instantaneous points in time with data. Spans can be nested. When you enter a span, it becomes the active context. Any event fired while the span is active gets tagged with that span's ID. This creates a hierarchy. You can reconstruct the execution tree from the logs. The library handles the async complexity for you. Spans stay attached to tasks even when they yield and resume.
Spans and events
Think of a span like a folder in a filing cabinet. When a request starts, you open a folder labeled "Request /api/users". Every log message inside that request goes into that folder. When the request finishes, you close the folder. Even if the request pauses and resumes while other requests run, the folder stays open. When you look at the output, you can see exactly which messages belong together.
Events are the messages you write. An event has a level, a message, and optional fields. Fields are structured data. Instead of a string like "Error: 404", you get status=404 and url="/api/users". This lets you filter and search logs programmatically. You can query for all events where status > 400 without parsing text.
Spans also carry fields. You can set a request_id on the span once, and every event inside that span inherits it. This eliminates repetitive logging. You do not need to pass the ID to every log call. The context is implicit.
Minimal setup
Add tracing and tracing-subscriber to your dependencies. tracing provides the macros and types. tracing-subscriber collects the data and outputs it. Without a subscriber, traces are generated but nowhere to go.
[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"
tokio = { version = "1", features = ["full"] }
The #[instrument] attribute is the workhorse. It wraps a function in a span automatically. It captures the function name, arguments, and return value. It handles entering and exiting the span. For async functions, it attaches the span to the future so the context survives .await points.
use tracing::{info, instrument};
// #[instrument] creates a span named "fetch_url" with fields for arguments
#[instrument]
async fn fetch_url(url: &str) -> Result<String, Box<dyn std::error::Error>> {
// info! emits an event. The current span is attached automatically.
info!("Starting fetch");
// Simulate async work
tokio::time::sleep(std::time::Duration::from_millis(10)).await;
info!(status = 200, "Fetch complete");
Ok("Hello".to_string())
}
#[tokio::main]
async fn main() {
// fmt::init() installs a subscriber that prints to stdout.
// Do this early, before any tracing code runs.
tracing_subscriber::fmt::init();
let result = fetch_url("https://example.com").await;
info!(?result, "Main finished");
}
Run this with cargo run. You will see the span hierarchy in the output. The subscriber prints the span name, the events, and the duration. The ?result syntax in the last info! uses debug formatting for the field. This is a convention. Prefix fields with ? for Debug formatting, % for Display, or nothing for Value formatting.
How context survives awaits
Async functions return futures. When you call .await, the future yields control. The task might be suspended for milliseconds or seconds. Other tasks run in the meantime. If you used a thread-local logger, the context would be lost when the task resumes. The thread-local might point to a different span.
tracing solves this by storing the span context inside the future. The #[instrument] macro adds .instrument(span) to the returned future. This implements the tracing::Instrument trait. The trait attaches the span to the future. When the future is polled, the span is entered. When the poll yields, the span is exited but kept alive. When the future is polled again, the span is re-entered. The context travels with the future.
You can do this manually for futures you construct. This is useful when you wrap a future in a combinator or create a custom future type.
use tracing::{info, info_span, Instrument};
async fn manual_instrumentation() {
// Create a span explicitly
let span = info_span!("manual_span", id = 42);
// Attach the span to a future
let future = async {
info!("Inside the future");
"result"
}.instrument(span);
// Poll the future. The span is active during polling.
let result = future.await;
info!(?result, "Done");
}
Convention aside: use #[instrument] for functions. Use .instrument() for futures you build manually. The macro is cleaner and handles argument capture. Manual instrumentation is for edge cases where the macro does not fit.
Realistic usage
Real applications have nested operations. You might validate a request, query a database, and send a response. Each step gets its own span. Errors need to be logged with context. The skip parameter in #[instrument] handles arguments that do not implement Debug.
use tracing::{debug, error, info, instrument, warn};
// skip(client) prevents the macro from trying to debug-print the client.
// The client likely does not implement Debug.
#[instrument(skip(client))]
async fn process_request(
client: &HttpClient,
request: Request,
) -> Result<Response, AppError> {
// info! with structured fields. %request.id uses Display formatting.
info!(request_id = %request.id, "Processing request");
// Nested span for validation
let data = {
// debug_span creates a span at debug level.
// It only records if debug is enabled.
let _span = tracing::debug_span!("validate").entered();
if request.data.is_empty() {
warn!("Empty data received");
return Err(AppError::InvalidData);
}
request.data
};
debug!(data_len = data.len(), "Validated data");
// Nested span for the network call
let response = {
let _span = tracing::info_span!("send_request", url = %request.url).entered();
match client.send(data).await {
Ok(resp) => resp,
Err(e) => {
// error! logs the error with structured data.
// The error is attached to the current span.
error!(error = %e, "Network request failed");
return Err(AppError::Network(e));
}
}
};
info!(status = response.status, "Request succeeded");
Ok(response.into())
}
The entered() guard keeps the span active for the block. When the block ends, the guard drops and the span exits. This is the manual way to create nested spans. #[instrument] does this automatically for the whole function.
Convention aside: keep spans focused. A span should represent a discrete unit of work. Do not span the entire application. Do not span a single line of code. Aim for logical boundaries. Validation, database query, network call, serialization. These are good span boundaries.
Pitfalls and compiler errors
Forgetting to initialize the subscriber is the most common mistake. tracing emits events, but nothing prints until a subscriber is installed. If you forget tracing_subscriber::fmt::init(), your logs vanish. The code compiles fine. You just see nothing. Install the subscriber early in main.
Using #[instrument] on a function with arguments that do not implement Debug causes a compile error. The macro tries to capture arguments as fields. If an argument lacks Debug, the compiler rejects it with E0277 (the trait Debug is not implemented for YourType). Fix this by adding skip(arg_name) to the attribute.
#[instrument(skip(client))] // Correct: client is skipped
async fn bad_example(client: Client) { ... }
Mixing tracing and log crates can cause confusion. tracing is not a drop-in replacement for log. If you use log::info! inside a tracing span, the log message does not get the span context. The message appears in the flat stream without hierarchy. Use tracing macros consistently. If you depend on a crate that uses log, you can bridge it with tracing-log, but prefer tracing in your own code.
Performance concerns are rare but worth noting. tracing macros check if the level is enabled before formatting arguments. If info is disabled, info!("format {}", expensive_call()) does not call expensive_call(). The cost is a single check. This makes tracing safe to use in hot paths. Do not remove tracing calls for performance. Configure the level instead.
Configure levels with the RUST_LOG environment variable. This is the standard convention. RUST_LOG=info cargo run sets the global level. RUST_LOG=my_crate=debug,other=warn sets per-module levels. Hardcoding levels in code is a maintenance debt. Use environment configuration.
Install the subscriber early. If you don't, your traces are ghosts.
Decision matrix
Use tracing when you are building a new async application and need structured, hierarchical diagnostics.
Use tracing when you want to correlate logs with request IDs, user IDs, or other contextual metadata.
Use log when you are maintaining a legacy codebase that depends on the log crate and the migration cost outweighs the benefits.
Use println! only for quick debugging scripts that will be deleted before production.
Use tracing-opentelemetry when you need to send traces to a distributed tracing backend like Jaeger, Zipkin, or AWS X-Ray.
Start with tracing. It scales from local debugging to production observability without changing your code.