The debugging nightmare
You are debugging a background service. The logs scroll by in a flat stream of text. You see Error: connection failed followed by Retrying in 5s followed by Request completed. You know something broke, but you have no idea which request triggered the failure, how long the retry took, or whether the database was slow or the network dropped. You are staring at a pile of disconnected facts and trying to reconstruct a timeline in your head.
println! gives you a diary entry. tracing gives you a security camera system with timestamps, camera IDs, and motion detection zones. The tracing crate is the standard framework for application-level diagnostics in Rust. It captures structured events and hierarchical context so you can reconstruct exactly what your program did, when it did it, and why it failed.
Events, spans, and subscribers
tracing separates three distinct concepts that logging libraries often mash together. Understanding the difference is the key to using the crate effectively.
Events are points in time. An event records that something happened. "User logged in." "Database query took 50ms." "Connection dropped." Events are instantaneous. They carry fields, which are key-value pairs attached to the event. Fields can be static strings or dynamic values computed at runtime.
Spans are intervals of time. A span represents a unit of work. "Processing request 123." "Fetching user profile." "Parsing JSON." Spans have a start and an end. They can be nested. A "handle_request" span might contain a "db_query" span, which contains a "cache_lookup" span. Spans carry context. When an event fires inside a span, the event inherits the span's fields. This creates a tree structure instead of a flat list.
Subscribers are the consumers. The tracing macros do not print to the console by themselves. They emit data into a global channel. A subscriber listens to that channel and decides what to do with the data. The default subscriber prints formatted text to stdout. Other subscribers can write JSON to a file, send metrics to Prometheus, or stream data to a logging service. You can stack multiple subscribers using layers.
Events tell you what happened. Spans tell you where it happened in the flow. Subscribers decide where the data goes.
Minimal setup
The tracing ecosystem is split into two crates. tracing provides the macros and the core types. tracing-subscriber provides the default subscriber and the layer system. You need both to see output.
Add them to your Cargo.toml.
[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"
Initialize the subscriber in main before you emit any events. If you skip this step, your tracing calls compile and run, but the data vanishes into the void.
use tracing::{info, Level};
use tracing_subscriber;
fn main() {
// Initialize the default subscriber.
// This connects the tracing macros to stdout.
// Without init(), events are generated but never consumed.
tracing_subscriber::fmt()
.with_max_level(Level::TRACE)
.init();
info!("Application started");
process_data(42);
}
#[tracing::instrument]
fn process_data(value: i32) {
// This macro automatically creates a span for the function.
// The span captures the 'value' argument as a field.
tracing::debug!("Processing value: {}", value);
}
Run the code. You see timestamped output with the level, the target, and the message. The #[instrument] attribute creates a span named process_data that opens when the function starts and closes when it returns. The debug! event fires inside that span. The subscriber prints the event along with the span's context.
Initialize the subscriber before the first event, or lose the data forever.
How the data flows
When you call info!("Hello"), the macro captures the message and any fields. It checks if a global subscriber is registered. If yes, it dispatches the event to the subscriber. The subscriber checks its filters. If the event passes the filter, the subscriber formats the data and writes it out.
Filters are critical for performance. Tracing has overhead. If you log at TRACE level in a hot loop, the formatting and dispatch cost can slow down your application. The subscriber filters events before they are fully processed. You can set the filter statically in code, as shown above with with_max_level. You can also set it dynamically using the RUST_LOG environment variable.
# Set the default level to INFO, but enable DEBUG for your crate
RUST_LOG="info,my_crate=debug" cargo run
The tracing-subscriber crate parses this string and configures the filter automatically. This lets you turn on verbose logging in production without recompiling. You just restart the service with a different environment variable.
The subscriber is the destination. The macros are just the post office.
Instrumenting real code
The #[instrument] attribute is the most common way to add spans. It saves you from writing boilerplate. You can control which arguments are captured as fields. By default, it captures all arguments that implement Debug. If an argument is large or does not implement Debug, you skip it.
use tracing::{info, instrument, Level};
// Skip the db_connection because it doesn't implement Debug.
// Capture the id and the method as fields.
#[instrument(skip(db_connection), fields(method = "GET"))]
fn handle_request(id: u64, db_connection: &mut DbConnection) {
// The span is created automatically.
// It includes id, method, and the function name.
info!("Handling request for user {}", id);
let user = db_connection.get_user(id);
// Record an event inside the span.
// The event inherits the span's fields.
info!("User found: {:?}", user);
}
The fields argument in the attribute lets you add static metadata to the span. Every call to handle_request will have a method field set to "GET". The id field is dynamic and changes per call.
You can also create spans manually when you need more control. Manual spans are useful when the work spans multiple functions or when you need to conditionally enter a span.
use tracing::{info, span, Level};
fn main() {
tracing_subscriber::fmt::init();
// Create a top-level span for the entire request.
let request_span = span!(Level::INFO, "handle_request", id = 123);
// Enter the span. This pushes it onto the current span stack.
let _guard = request_span.enter();
info!("Received request");
fetch_database_data();
// The span exits here when _guard is dropped.
// Any events after this point are not inside the span.
}
fn fetch_database_data() {
// Nested span created manually.
let db_span = span!(Level::DEBUG, "db_query", table = "users");
let _guard = db_span.enter();
info!("Executing query");
// Simulate work
std::thread::sleep(std::time::Duration::from_millis(10));
// db_span exits here.
}
The _guard variable holds the span entry. When it goes out of scope, the span closes. This pattern is explicit and safe. It works with async code too. Spans in tracing are designed to work across await points. The span context is stored in a thread-local variable and restored when the future resumes. This is a major advantage over the log crate, which has no concept of spans and breaks down in async applications.
Let the macro handle the boilerplate. Keep your code clean.
Pitfalls and performance
Tracing is powerful, but it introduces complexity. A few common traps trip up new users.
Silent failure. If you forget to initialize a subscriber, your code compiles and runs without errors. The tracing macros emit events, but nothing consumes them. The data is dropped. This is the most common mistake. Always call tracing_subscriber::fmt().init() or a similar initialization function in main. If you are writing a library, do not initialize a subscriber. Libraries should not impose a global subscriber on the user. Leave that to the binary.
Performance cost. Tracing macros have overhead. The info! macro checks the filter, formats the arguments, and dispatches the event. If you log at TRACE level in a tight loop, the cost adds up. Use RUST_LOG to filter out verbose levels in production. Avoid logging large structures. If you must log a large value, use skip in #[instrument] or log a summary instead.
Mixing log and tracing. Many crates in the ecosystem still use the log crate. If you want to see their logs in your tracing output, you need a bridge. Add tracing-log = "0.2" to your dependencies and call tracing_log::LogTracer::init() in main. This redirects log events into the tracing subscriber.
Field types. Tracing fields must implement Value or be convertible to one. Most standard types work. If you have a custom type, implement Debug or Display. If you try to log a type that does not implement the required traits, the compiler rejects you with a trait bound error. The error message points to the macro call. Fix it by implementing the trait or skipping the field.
Filter early. Performance matters.
Choosing your tool
Rust has several ways to output diagnostics. The right choice depends on your project type and distribution model.
Use tracing when you are building an application, a web server, or an async service. Use tracing when you need structured logs, hierarchical context, or integration with observability backends. Use tracing when you want to filter logs dynamically at runtime using RUST_LOG.
Use log when you are writing a library that must remain lightweight. Use log when you do not want to force a runtime dependency on a subscriber. Use log when your library is used in environments where tracing is not available or desired. The log crate is a facade. It defines the macros but does not provide the implementation. The user of your library chooses the backend.
Use println! when you are writing a throwaway script or a one-off tool. Use println! when structured output is overkill and you just need to see a value during development. Use println! for quick debugging that you will delete before shipping.
Use eprintln! when you need immediate output to stderr for a critical failure. Use eprintln! when the program is about to exit and you need to guarantee the message appears. Use eprintln! for usage errors in CLI tools.
Pick the tool that matches your distribution model.