Loading page…
Rust walkthroughs
Loading page…
The tracing crate provides structured, async-aware diagnostics for Rust applications. Unlike the basic log crate, tracing captures contextual information through spans and events. Spans represent units of work with beginning and end, while events are point-in-time occurrences. Tracing integrates with various subscribers (like tracing-subscriber) to output logs in different formats, send to distributed tracing systems, or filter based on verbosity levels.
Key concepts:
Tracing is essential for production applications needing observability.
# Cargo.toml
[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"use tracing::{info, warn, error, debug, trace, span, Level};
fn main() {
// Initialize the subscriber
tracing_subscriber::fmt::init();
// Basic logging
trace!("Very detailed information");
debug!("Debug information");
info!("Normal information");
warn!("Warning message");
error!("Error occurred");
// Structured logging with fields
info!(user_id = 42, action = "login", "User logged in");
}use tracing::{info, debug};
use tracing_subscriber::{fmt, EnvFilter};
fn main() {
// Basic initialization with defaults
tracing_subscriber::fmt::init();
info!("Application started");
// Custom initialization with options
tracing_subscriber::fmt()
.with_max_level(tracing::Level::DEBUG) // Set max level
.with_target(false) // Hide target module
.with_thread_ids(true) // Show thread IDs
.with_thread_names(true) // Show thread names
.with_line_number(true) // Show line numbers
.with_file(true) // Show file names
.with_timer(fmt::time::time()) // Use local time
.init();
debug!("Debug with custom subscriber");
// Use environment variable RUST_LOG for filtering
tracing_subscriber::fmt()
.with_env_filter(EnvFilter::from_default_env()
.add_directive("my_app=debug".parse().unwrap()))
.init();
debug!("This respects RUST_LOG env var");
}use tracing::{trace, debug, info, warn, error, event, Level};
fn main() {
tracing_subscriber::fmt::init();
// Level hierarchy: TRACE < DEBUG < INFO < WARN < ERROR
trace!("Very detailed trace information");
debug!("Debug-level information");
info!("Info-level information");
warn!("Warning: something might be wrong");
error!("Error: something went wrong");
// Using the event! macro directly
event!(Level::INFO, "Explicit event at INFO level");
event!(Level::DEBUG, user_id = 42, "User performed action");
// Conditional logging
let verbose = true;
if verbose {
debug!("Verbose mode enabled");
}
// Log with values (expressions are evaluated)
let count = 42;
info!(count, "Processed items");
info!(count = count * 2, "Double count");
// String formatting
let name = "Alice";
info!(%name, "User name"); // Use % for Display
info!(?name, "User name"); // Use ? for Debug
info!(%name, ?count, "Mixed formatting");
}use tracing::{info, debug, warn, error, span, Level};
fn main() {
tracing_subscriber::fmt::init();
// Simple fields
info!(user_id = 42, "User logged in");
info!(user_id = 42, action = "purchase", "User action");
// Fields with different types
let id: u32 = 42;
let name = "Alice";
let balance = 1234.56;
let is_active = true;
info!(
id,
%name, // Display format
balance, // Uses Debug
is_active, // bool
"User info"
);
// Debug format with ?
let data = vec![1, 2, 3];
debug!(?data, "Processing data");
// Display format with %
let url = "https://example.com";
info!(%url, "Making request");
// Computed fields
let items = vec![("a", 1), ("b", 2)];
info!(
count = items.len(),
sum = items.iter().map(|(_, v)| v).sum::<i32>(),
"Item statistics"
);
// Nested values
let user = User { id: 42, name: "Alice".to_string() };
info!(user.id, user.name = %user.name, "User details");
}
#[derive(Debug)]
struct User {
id: u32,
name: String,
}use tracing::{info, debug, span, Level};
fn main() {
tracing_subscriber::fmt::init();
// Create a span
let span = span!(Level::INFO, "process_request", request_id = %"abc-123");
let _enter = span.enter();
info!("Processing request");
// Nested spans
let inner_span = span!(Level::DEBUG, "database_query", query = "SELECT * FROM users");
let _inner_enter = inner_span.enter();
debug!("Executing query");
// Span exits when _inner_enter is dropped
info!("Request completed");
// Main span exits when _enter is dropped
}
// Better approach: using span with block
fn process_request(request_id: &str) {
let span = span!(Level::INFO, "process_request", %request_id);
let _enter = span.enter();
debug!("Starting processing");
validate_request();
query_database();
debug!("Processing complete");
}
fn validate_request() {
let span = span!(Level::DEBUG, "validate_request");
let _enter = span.enter();
debug!("Validating");
}
fn query_database() {
let span = span!(Level::DEBUG, "query_database");
let _enter = span.enter();
debug!("Querying");
}use tracing::{info, debug, warn, span, Level};
fn main() {
tracing_subscriber::fmt::init();
// Method 1: Manual enter/exit
let span = span!(Level::INFO, "operation");
let _guard = span.enter();
info!("Inside span");
// _guard dropped here, exits span
// Method 2: Using in_scope
let span = span!(Level::INFO, "scoped_operation");
span.in_scope(|| {
info!("Inside in_scope");
another_function();
});
info!("Outside span");
// Method 3: Cloned spans for async
let span = span!(Level::INFO, "async_operation", id = 1);
let span_clone = span.clone();
span.in_scope(|| {
debug!("In original span");
});
span_clone.in_scope(|| {
debug!("In cloned span");
});
}
fn another_function() {
info!("In another function");
}
// Span with fields that are added later
fn deferred_fields_example() {
let span = span!(Level::INFO, "request", request_id = %"req-123");
let _enter = span.enter();
// Add field after creation
span.record("status", "processing");
info!("Processing");
span.record("status", "complete");
info!("Done");
}use tracing::{info, debug, span, Level, Instrument};
#[tokio::main]
async fn main() {
tracing_subscriber::fmt::init();
// Instrument async tasks
let span = span!(Level::INFO, "async_task", task_id = 1);
// Method 1: Using instrument()
let result = my_async_function()
.instrument(span)
.await;
info!(result, "Task completed");
// Method 2: Using #[instrument] attribute
process_data(42).await;
}
async fn my_async_function() -> i32 {
debug!("Starting async work");
tokio::time::sleep(std::time::Duration::from_millis(100)).await;
debug!("Async work complete");
42
}
// Use #[instrument] attribute for automatic span creation
#[tracing::instrument]
async fn process_data(id: u32) -> String {
debug!("Processing");
fetch_from_db(id).await;
format!("result-{}", id)
}
#[tracing::instrument]
async fn fetch_from_db(id: u32) {
debug!("Fetching from database");
tokio::time::sleep(std::time::Duration::from_millis(50)).await;
}
// Instrument with fields
#[tracing::instrument(
name = "user_request", // Custom span name
skip(large_data), // Skip large fields
fields(user_id = %user.id) // Add custom fields
)]
async fn handle_request(user: User, large_data: Vec<u8>) {
debug!("Handling request");
}
#[derive(Debug)]
struct User {
id: u32,
name: String,
}use tracing::{info, debug, warn, Level};
// Basic instrumentation
#[tracing::instrument]
fn basic_function(param: i32) -> i32 {
debug!("Inside function");
param * 2
}
// Skip certain parameters
#[tracing::instrument(skip(large_buffer, password))]
fn secure_function(user_id: u32, large_buffer: Vec<u8>, password: &str) {
debug!("Processing securely");
}
// Add custom fields
#[tracing::instrument(fields(extra = "custom_value", timestamp = %chrono::Utc::now().format("%H:%M:%S")))]
fn function_with_extra_fields(data: &str) {
info!("Processing data");
}
// Rename span
#[tracing::instrument(name = "process_user_request")]
fn renamed_function() {
debug!("This span has a custom name");
}
// Change log level
#[tracing::instrument(level = Level::DEBUG)]
fn debug_level_function() {
debug!("This is a DEBUG level span");
}
// Skip all fields
#[tracing::instrument(skip_all)]
fn skip_all_params(a: i32, b: String, c: Vec<u8>) {
info!("No params logged");
}
// Retain fields but format differently
#[tracing::instrument(fields(id = %user.id, name = %user.name))]
fn formatted_params(user: User) {
info!("User processed");
}
// Instrument methods
struct Service {
name: String,
}
impl Service {
#[tracing::instrument(skip(self))]
fn process(&self, data: &str) {
debug!("Service {} processing", self.name);
}
#[tracing::instrument(skip(self), fields(service = %self.name))]
fn process_with_field(&self, data: &str) {
debug!("Processing with field");
}
}
#[derive(Debug)]
struct User {
id: u32,
name: String,
}
fn main() {
tracing_subscriber::fmt::init();
basic_function(21);
secure_function(1, vec![0; 1000], "secret");
function_with_extra_fields("test");
renamed_function();
debug_level_function();
skip_all_params(1, "test".to_string(), vec![]);
}# Cargo.toml
[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["json"] }use tracing::{info, debug, warn, error, span, Level};
fn main() {
// JSON formatter
tracing_subscriber::fmt()
.json()
.with_target(true)
.with_thread_ids(true)
.with_current_span(true)
.with_span_list(true)
.init();
info!("Simple message");
let span = span!(Level::INFO, "request", request_id = %"req-123");
let _enter = span.enter();
info!(user_id = 42, action = "login", "User logged in");
debug!("Additional debug info");
warn!("Something to watch");
error!("An error occurred");
}
// Custom JSON fields
fn custom_json_output() {
tracing_subscriber::fmt()
.json()
.with_max_level(tracing::Level::INFO)
.with_target(false)
.with_current_span(true)
.with_span_list(true)
.flatten_event(true) // Flatten event fields to top level
.init();
info!(user_id = 42, "User action");
}use tracing::{info, debug, warn, error, span, Level};
use std::error::Error;
#[derive(Debug)]
struct MyError {
message: String,
}
impl std::fmt::Display for MyError {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(f, "MyError: {}", self.message)
}
}
impl std::error::Error for MyError {}
fn main() {
tracing_subscriber::fmt::init();
// Log errors with context
if let Err(e) = fallible_operation() {
error!(error = %e, "Operation failed");
error!(error = ?e, "Operation failed (debug)");
}
// Error in span
let span = span!(Level::INFO, "operation");
let _enter = span.enter();
match another_fallible() {
Ok(result) => info!(result, "Success"),
Err(e) => {
// Record error on span
span.record("error", &e.to_string());
error!(error = %e, "Failed");
}
}
}
fn fallible_operation() -> Result<(), MyError> {
Err(MyError { message: "Something went wrong".to_string() })
}
fn another_fallible() -> Result<String, MyError> {
Err(MyError { message: "Another error".to_string() })
}
// Instrument with error logging
#[tracing::instrument(err)]
fn instrumented_fallible(should_fail: bool) -> Result<String, MyError> {
debug!("Working...");
if should_fail {
Err(MyError { message: "Failed!".to_string() })
} else {
Ok("Success!".to_string())
}
}
// Instrument with error level customization
#[tracing::instrument(err(level = Level::WARN))]
fn warn_on_error() -> Result<(), MyError> {
Err(MyError { message: "Warning level error".to_string() })
}use tracing::{info, debug, warn, Level};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, fmt, EnvFilter};
fn main() {
// Combine multiple layers
let stdout_layer = fmt::layer()
.with_target(false)
.with_filter(EnvFilter::from_default_env().add_directive(Level::INFO.into()));
// Note: For file output, you'd use tracing-appender crate
// Here we just show the pattern
tracing_subscriber::registry()
.with(stdout_layer)
.init();
info!("This goes to stdout");
debug!("This might be filtered");
// Filtered logging
demo_filtered_logging();
}
fn demo_filtered_logging() {
use tracing_subscriber::EnvFilter;
// Per-layer filtering
let filter = EnvFilter::new("my_app=debug,other_crate=warn");
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
info!("Application log");
}
// Dynamic filtering
mod dynamic_filter {
use tracing_subscriber::Layer;
use tracing_core::{Metadata, Level};
pub fn create_filter() -> impl Layer<tracing_subscriber::Registry> {
tracing_subscriber::fmt::layer()
.with_filter(tracing_subscriber::filter::filter_fn(|metadata| {
// Only allow INFO and above
metadata.level() <= &Level::INFO
}))
}
}use tracing::{info, debug, warn, error, span, Level, Instrument};
use std::time::Instant;
#[derive(Debug)]
struct User {
id: u32,
name: String,
}
#[derive(Debug)]
struct Order {
id: u32,
user_id: u32,
total: f64,
}
struct AppService {
name: String,
}
impl AppService {
#[tracing::instrument(skip(self), fields(service = %self.name))]
async fn process_order(&self, user: User, order: Order) -> Result<String, String> {
let start = Instant::now();
debug!(order_id = order.id, "Starting order processing");
// Validate
self.validate_order(&order).await?;
// Process payment
let payment_id = self.process_payment(&order).await?;
// Update inventory
self.update_inventory(&order).await?;
let elapsed = start.elapsed();
info!(
order_id = order.id,
payment_id = %payment_id,
elapsed_ms = elapsed.as_millis(),
"Order completed successfully"
);
Ok(format!("order-{}-complete", order.id))
}
#[tracing::instrument(skip(self))]
async fn validate_order(&self, order: &Order) -> Result<(), String> {
debug!(order_id = order.id, "Validating order");
if order.total <= 0.0 {
warn!(order_id = order.id, total = order.total, "Invalid order total");
return Err("Invalid order total".to_string());
}
// Simulate async work
tokio::time::sleep(std::time::Duration::from_millis(10)).await;
debug!(order_id = order.id, "Order validated");
Ok(())
}
#[tracing::instrument(skip(self))]
async fn process_payment(&self, order: &Order) -> Result<String, String> {
debug!(order_id = order.id, total = order.total, "Processing payment");
// Simulate payment processing
tokio::time::sleep(std::time::Duration::from_millis(50)).await;
let payment_id = format!("pay-{}", order.id);
debug!(payment_id = %payment_id, "Payment processed");
Ok(payment_id)
}
#[tracing::instrument(skip(self))]
async fn update_inventory(&self, order: &Order) -> Result<(), String> {
debug!(order_id = order.id, "Updating inventory");
// Simulate inventory update
tokio::time::sleep(std::time::Duration::from_millis(20)).await;
debug!(order_id = order.id, "Inventory updated");
Ok(())
}
}
#[tokio::main]
async fn main() {
// Initialize with JSON output for production-like logs
tracing_subscriber::fmt()
.with_max_level(Level::DEBUG)
.with_target(false)
.with_thread_ids(true)
.init();
let service = AppService {
name: "OrderService".to_string(),
};
let user = User {
id: 1,
name: "Alice".to_string(),
};
let order = Order {
id: 100,
user_id: 1,
total: 99.99,
};
info!(user_id = user.id, "Starting order processing");
match service.process_order(user, order).await {
Ok(result) => info!(result, "Order processed"),
Err(e) => error!(error = %e, "Order failed"),
}
}use tracing::{info, debug, Level};
use tower::ServiceBuilder;
use tower_http::trace::{TraceLayer, DefaultMakeSpan, DefaultOnResponse};
// Example showing Tower HTTP tracing setup
// Requires: tower-http = { version = "0.4", features = ["trace"] }
/*
async fn serve() {
tracing_subscriber::fmt()
.with_max_level(Level::DEBUG)
.init();
let trace_layer = TraceLayer::new_for_http()
.make_span_with(DefaultMakeSpan::new().level(Level::INFO))
.on_response(DefaultOnResponse::new().level(Level::INFO));
let app = ServiceBuilder::new()
.layer(trace_layer)
.service(/* your service */);
// Run with hyper or axum
}
*/
// Manual request tracing example
fn trace_request_example() {
let span = tracing::span!(Level::INFO, "http_request",
method = "GET",
path = "/api/users",
status = tracing::field::Empty,
duration_ms = tracing::field::Empty
);
let start = std::time::Instant::now();
let _enter = span.enter();
// Simulate request handling
debug!("Processing request");
// ... handle request ...
// Record response info
span.record("status", 200);
span.record("duration_ms", start.elapsed().as_millis() as i64);
info!("Request completed");
}tracing for structured, contextual logging and instrumentationtracing_subscriber::fmt::init() or customize with builder patterntrace!, debug!, info!, warn!, error!info!(user_id = 42, "Message")%field for Display format, ?field for Debug formatspan!(Level::INFO, "name") and enter with .enter()#[instrument] attribute for automatic function instrumentation.instrument(span) for async functions.json() on the subscriber builderEnvFilter and RUST_LOG environment variable#[instrument(err)] for automatic error logging#[instrument(fields(custom = "value"))]tracing-appender for file logging with rotationtower-http for HTTP request tracing in web services