How do I add structured logging and diagnostics to my application?

Walkthrough

The tracing crate provides structured, event-based logging with spans that track context through async code. Unlike traditional logging, tracing captures the causal relationship between events, making it invaluable for debugging complex systems. It integrates seamlessly with async runtimes like Tokio and supports multiple subscribers (formatters).

Core concepts:

Spans — represent a unit of work or period of time (like a function call)
Events — represent a point in time (like a log message)
Fields — structured key-value data attached to spans and events
Subscribers — collect and process span/event data
Instrumentation — attach span context to futures

Tracing is essential for production systems where understanding the flow of requests through services is critical.

Code Example

# Cargo.toml
[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter"] }

use tracing::{debug, error, info, span, trace, warn, Level};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};
 
fn main() {
    // Initialize the tracing subscriber
    tracing_subscriber::registry()
        .with(EnvFilter::new(
            std::env::var("RUST_LOG").unwrap_or_else(|_| "debug".into()),
        ))
        .with(tracing_subscriber::fmt::layer())
        .init();
    
    // Basic logging events
    trace!("Very detailed trace message");
    debug!("Debug information");
    info!("General information");
    warn!("Warning: something might be wrong");
    error!("Error: something went wrong");
    
    // Events with structured fields
    info!(
        user_id = 12345,
        action = "login",
        ip_address = "192.168.1.1",
        "User logged in successfully"
    );
    
    // Create a span to track a unit of work
    let span = span!(Level::INFO, "process_request", request_id = %"abc-123");
    let _enter = span.enter();
    
    info!("Processing started");
    do_work();
    info!("Processing completed");
}
 
fn do_work() {
    // Events inside this function will be associated with the parent span
    debug!("Doing some work...");
}

Spans and Nested Context

use tracing::{info, span, Instrument, Level};
use tracing_subscriber::util::SubscriberInitExt;
 
#[tracing::instrument]
fn process_order(order_id: u64, customer: &str) -> u32 {
    info!("Validating order");
    validate_order(order_id);
    
    info!("Calculating total");
    let total = calculate_total(order_id);
    
    info!(total, "Order processed successfully");
    total
}
 
#[tracing::instrument(skip_all)]
fn validate_order(order_id: u64) {
    info!("Checking inventory");
    info!("Checking payment info");
}
 
#[tracing::instrument]
fn calculate_total(order_id: u64) -> u32 {
    // Simulated calculation
    (order_id % 100) as u32 * 10
}
 
fn main() {
    tracing_subscriber::fmt().with_max_level(Level::DEBUG).finish().init();
    
    let result = process_order(12345, "Alice");
    info!("Final result: {}", result);
}

Async Instrumentation

use tracing::{info, instrument, Instrument, Span};
use tokio::time::{sleep, Duration};
 
#[instrument(skip(user_ids))]
async fn batch_process(user_ids: Vec<u64>) -> Vec<String> {
    info!("Starting batch processing");
    
    let results: Vec<String> = user_ids
        .iter()
        .map(|&id| process_user(id))
        .collect();
    
    info!(count = results.len(), "Batch complete");
    results
}
 
#[instrument]
async fn process_user(user_id: u64) -> String {
    info!("Processing user");
    sleep(Duration::from_millis(10)).await;
    format!("processed_{}", user_id)
}
 
#[tokio::main]
async fn main() {
    tracing_subscriber::fmt().with_max_level(Level::DEBUG).finish().init();
    
    let span = tracing::info_span!("main_operation", trace_id = %"xyz-789");
    
    // Instrument async block with span
    let result = batch_process(vec![1, 2, 3, 4, 5])
        .instrument(span)
        .await;
    
    info!(?result, "All done");
}

Custom Fields and Error Handling

use tracing::{error, info, instrument, warn, Level};
use std::error::Error;
 
#[derive(Debug)]
struct User {
    id: u64,
    name: String,
}
 
impl std::fmt::Display for User {
    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
        write!(f, "User({}: {})", self.id, self.name)
    }
}
 
#[instrument(
    name = "fetch_user",  // Custom span name
    skip(db),            // Skip field from being displayed
    fields(%user_id),    // Always include this field
    err                   // Record errors
)]
async fn fetch_user(db: &Db, user_id: u64) -> Result<User, String> {
    info!("Looking up user in database");
    
    // Simulate DB lookup
    if user_id == 0 {
        return Err("Invalid user ID".to_string());
    }
    
    let user = db.get(user_id).ok_or_else(|| "User not found".to_string())?;
    
    info!(user.name = %user.name, "User found");
    Ok(user)
}
 
struct Db {
    users: std::collections::HashMap<u64, User>,
}
 
impl Db {
    fn get(&self, id: u64) -> Option<&User> {
        self.users.get(&id)
    }
}
 
#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_target(false)
        .with_thread_ids(true)
        .with_max_level(Level::DEBUG)
        .finish()
        .init();
    
    let mut users = std::collections::HashMap::new();
    users.insert(1, User { id: 1, name: "Alice".to_string() });
    users.insert(2, User { id: 2, name: "Bob".to_string() });
    let db = Db { users };
    
    match fetch_user(&db, 1).await {
        Ok(user) => info!(?user, "Success"),
        Err(e) => error!(%e, "Failed to fetch user"),
    }
    
    // Test error case
    match fetch_user(&db, 999).await {
        Ok(user) => info!(?user, "Success"),
        Err(e) => error!(%e, "Failed to fetch user"),
    }
}

JSON Output for Production

use tracing::{info, instrument, Level};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 
fn main() {
    // JSON format for structured logging in production
    tracing_subscriber::registry()
        .with(tracing_subscriber::fmt::layer().json())
        .init();
    
    #[instrument(skip(data))]
    fn process_data(id: u64, data: &[i32]) {
        info!(len = data.len(), "Processing data batch");
        let sum: i32 = data.iter().sum();
        info!(sum, "Calculation complete");
    }
    
    process_data(42, &[1, 2, 3, 4, 5]);
}

Multiple Layers and Filtering

use tracing::{info, warn, Level};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};
 
fn main() {
    tracing_subscriber::registry()
        // Filter by level and target
        .with(EnvFilter::try_from_default_env()
            .unwrap_or_else(|_| "my_app=debug,my_module=trace,warn".into()))
        // Pretty console output for development
        .with(tracing_subscriber::fmt::layer()
            .with_target(true)
            .with_line_number(true))
        .init();
    
    info!("Application starting");
    warn!("This is a warning");
}

Summary

Use info!, debug!, trace!, warn!, error! macros for log events with structured fields
Create spans with span!(Level::INFO, "name", field = value) and enter with .enter()
The #[instrument] attribute macro automatically creates spans for functions
Skip fields from instrumentation with #[instrument(skip(arg1, arg2))]
Record errors with #[instrument(err)] to automatically log function errors
Use .instrument(span) on futures to attach span context to async operations
Field syntax: name = value (display), ?name (debug), %name (display, alternate)
Configure output format with tracing_subscriber::fmt::layer().json() for production
Filter logs with EnvFilter and the RUST_LOG environment variable
Tracing integrates with Tokio, Axum, and other async frameworks for automatic span propagation