How do I work with Tracing for Structured Logging and Diagnostics in Rust?

Walkthrough

Tracing is a framework for instrumenting Rust programs to collect structured, event-based diagnostic information. It provides a more powerful alternative to the log crate by supporting spans (periods of time), structured fields, and async-aware instrumentation. Tracing is essential for understanding the behavior of complex systems, especially distributed and async applications.

Key concepts:

Spans — Represent a period of time with context
Events — Point-in-time occurrences (similar to log messages)
Subscribers — Collect and process span/event data
Fields — Structured key-value pairs attached to spans/events
Levels — TRACE, DEBUG, INFO, WARN, ERROR

When to use Tracing:

Production applications requiring observability
Async and concurrent code
Distributed systems with request tracing
Performance analysis and debugging
Structured logging with context

When NOT to use Tracing:

Simple scripts (use log crate)
When you need minimal dependencies
Very constrained environments

Code Examples

Basic Setup

use tracing::{info, warn, error, debug};
use tracing_subscriber;
 
fn main() {
    // Initialize the default subscriber
    tracing_subscriber::fmt::init();
    
    info!("Application started");
    debug!("Debug information");
    warn!("Warning message");
    error!("Error occurred");
}

Structured Fields

use tracing::{info, error};
use tracing_subscriber;
 
fn main() {
    tracing_subscriber::fmt::init();
    
    let user_id = 42;
    let request_id = "abc123";
    
    // Structured logging with fields
    info!(
        user_id = user_id,
        request_id = %request_id,
        "User logged in"
    );
    
    // Fields can use display formatting with %
    error!(
        error_code = 500,
        path = "/api/users",
        "Request failed"
    );
}

Spans for Context

use tracing::{info, span, Level};
use tracing_subscriber;
 
fn process_request(user_id: u64) {
    // Create a span that represents this operation
    let span = span!(Level::INFO, "process_request", user_id = user_id);
    let _enter = span.enter();
    
    // All events inside this scope will have the span context
    info!("Starting request processing");
    
    // Simulate work
    std::thread::sleep(std::time::Duration::from_millis(100));
    
    info!("Request completed");
}
 
fn main() {
    tracing_subscriber::fmt::init();
    
    process_request(42);
}

Instrument Functions

use tracing::{info, instrument};
use tracing_subscriber;
 
#[instrument]
fn calculate_sum(a: i32, b: i32) -> i32 {
    info!("Calculating sum");
    a + b
}
 
#[instrument(skip(large_data))]
fn process_data(data_id: u64, large_data: &[u8]) -> usize {
    info!("Processing data");
    large_data.len()
}
 
#[instrument(level = "debug", fields(extra = "context"))]
fn debug_function(value: i32) {
    debug!("Debug output");
}
 
fn main() {
    tracing_subscriber::fmt::init();
    
    let result = calculate_sum(5, 10);
    println!("Result: {}", result);
    
    let data = vec![0u8; 1000];
    let size = process_data(1, &data);
    println!("Size: {}", size);
}

Async Function Instrumentation

use tracing::{info, instrument};
use tracing_subscriber;
 
#[instrument]
async fn fetch_user(user_id: u64) -> String {
    info!("Fetching user from database");
    // Simulate async operation
    tokio::time::sleep(std::time::Duration::from_millis(100)).await;
    format!("User {}", user_id)
}
 
#[instrument(skip(db))]
async fn save_to_db(db: &str, data: &str) -> bool {
    info!("Saving to database");
    tokio::time::sleep(std::time::Duration::from_millis(50)).await;
    true
}
 
#[tokio::main]
async fn main() {
    tracing_subscriber::fmt::init();
    
    let user = fetch_user(42).await;
    println!("Got: {}", user);
    
    let saved = save_to_db("mydb", "some data").await;
    println!("Saved: {}", saved);
}

Error Handling with Spans

use tracing::{info, error, span, Level};
use anyhow::{Result, Context};
use tracing_subscriber;
 
fn process_file(path: &str) -> Result<()> {
    let span = span!(Level::INFO, "file_processing", path = %path);
    let _enter = span.enter();
    
    info!("Reading file");
    
    let content = std::fs::read_to_string(path)
        .context("Failed to read file")?;
    
    info!(bytes = content.len(), "File read successfully");
    
    if content.is_empty() {
        error!("File is empty");
        anyhow::bail!("Empty file");
    }
    
    info!("Processing complete");
    Ok(())
}
 
fn main() {
    tracing_subscriber::fmt::init();
    
    if let Err(e) = process_file("test.txt") {
        error!(error = %e, "Processing failed");
    }
}

Nested Spans

use tracing::{info, span, Level};
use tracing_subscriber;
 
fn handle_request(request_id: &str) {
    let request_span = span!(Level::INFO, "request", id = %request_id);
    let _enter1 = request_span.enter();
    
    info!("Received request");
    
    // Nested span for database query
    {
        let db_span = span!(Level::DEBUG, "database_query", table = "users");
        let _enter2 = db_span.enter();
        
        info!("Executing query");
        // Query execution...
        info!(rows = 5, "Query complete");
    }
    
    // Back to request span
    info!("Sending response");
}
 
fn main() {
    tracing_subscriber::fmt::init();
    handle_request("req-123");
}

JSON Output Format

use tracing::{info, error};
use tracing_subscriber::{fmt, EnvFilter};
 
fn main() {
    // Configure JSON output
    tracing_subscriber::fmt()
        .json()
        .with_env_filter(EnvFilter::from_default_env()
            .add_directive("info".parse().unwrap()))
        .init();
    
    info!(user_id = 42, action = "login", "User logged in");
    error!(code = 500, "Internal server error");
}

Custom Formatting

use tracing::{info, warn};
use tracing_subscriber::{fmt, EnvFilter};
 
fn main() {
    tracing_subscriber::fmt()
        .with_target(false)  // Don't show module path
        .with_thread_ids(true)  // Show thread IDs
        .with_line_number(true)  // Show line numbers
        .with_env_filter(
            EnvFilter::try_from_default_env()
                .unwrap_or_else(|_| EnvFilter::new("info"))
        )
        .init();
    
    info!("Application started");
    warn!("This is a warning");
}

Log Levels and Filtering

use tracing::{info, debug, trace, warn, error, Level};
use tracing_subscriber::{fmt, EnvFilter};
 
fn main() {
    // Configure log level filtering
    tracing_subscriber::fmt()
        .with_env_filter(
            EnvFilter::builder()
                .with_default_directive(Level::INFO.into())
                .from_env_lossy()
        )
        .init();
    
    trace!("This won't show at INFO level");
    debug!("This won't show at INFO level");
    info!("This will show");
    warn!("This will show");
    error!("This will show");
}

Span Fields with Dynamic Values

use tracing::{info, span, Level, Instrument};
use tracing_subscriber;
 
fn process_order(order_id: u64, item_count: usize) {
    let span = span!(
        Level::INFO,
        "order_processing",
        order_id = order_id,
        item_count = item_count
    );
    let _enter = span.enter();
    
    info!("Processing order");
    
    // Update span field dynamically
    span.record("item_count", &format!("{} items", item_count));
    
    info!("Order processed");
}
 
fn main() {
    tracing_subscriber::fmt::init();
    process_order(12345, 5);
}

HTTP Request Tracing

use tracing::{info, instrument, span, Level};
use tracing_subscriber;
 
struct Request {
    id: String,
    path: String,
    method: String,
}
 
struct Response {
    status: u16,
    body: String,
}
 
#[instrument(skip(request), fields(id = %request.id, path = %request.path))]
fn handle_request(request: Request) -> Response {
    info!(method = %request.method, "Handling request");
    
    let response = process_business_logic(&request.path);
    
    info!(status = response.status, "Request completed");
    response
}
 
fn process_business_logic(path: &str) -> Response {
    info!("Processing business logic");
    Response {
        status: 200,
        body: format!("Response for {}", path),
    }
}
 
fn main() {
    tracing_subscriber::fmt::init();
    
    let request = Request {
        id: "req-001".to_string(),
        path: "/api/users".to_string(),
        method: "GET".to_string(),
    };
    
    let response = handle_request(request);
    println!("Status: {}", response.status);
}

Timing with Spans

use tracing::{info, span, Level};
use tracing_subscriber;
use std::time::Instant;
 
fn timed_operation() {
    let span = span!(Level::INFO, "timed_operation");
    let _enter = span.enter();
    
    let start = Instant::now();
    
    // Simulate work
    std::thread::sleep(std::time::Duration::from_millis(150));
    
    let elapsed = start.elapsed();
    info!(duration_ms = elapsed.as_millis() as u64, "Operation completed");
}
 
fn main() {
    tracing_subscriber::fmt()
        .with_target(false)
        .init();
    
    timed_operation();
}

Multiple Subscribers

use tracing::{info, error};
use tracing_subscriber::{fmt, Layer, Registry};
use std::io::Write;
 
fn main() {
    // Create a subscriber with multiple layers
    let stdout_layer = fmt::layer()
        .with_target(false);
    
    let file_layer = fmt::layer()
        .with_writer(std::fs::File::create("app.log").unwrap());
    
    tracing_subscriber::registry()
        .with(stdout_layer)
        .with(file_layer)
        .init();
    
    info!("This goes to both stdout and file");
    error!("Error also goes to both");
}

Conditional Logging

use tracing::{info, debug, trace, Level};
use tracing_subscriber::{fmt, EnvFilter};
 
#[derive(Debug)]
struct Config {
    verbose: bool,
}
 
fn process_with_logging(config: &Config) {
    // These only compile when the level is enabled
    if config.verbose {
        debug!("Verbose mode enabled");
        trace!("Detailed trace information");
    }
    
    info!("Processing complete");
}
 
fn main() {
    tracing_subscriber::fmt()
        .with_env_filter(
            EnvFilter::builder()
                .with_default_directive(Level::INFO.into())
                .from_env_lossy()
        )
        .init();
    
    let config = Config { verbose: true };
    process_with_logging(&config);
}

Error Recording in Spans

use tracing::{info, error, span, Level};
use tracing_subscriber;
use std::error::Error;
 
fn risky_operation() -> Result<String, Box<dyn Error>> {
    Err("Something went wrong".into())
}
 
fn main() {
    tracing_subscriber::fmt::init();
    
    let span = span!(Level::INFO, "operation", status = "running");
    let _enter = span.enter();
    
    info!("Starting operation");
    
    match risky_operation() {
        Ok(result) => {
            span.record("status", &"success");
            info!(result = %result, "Operation succeeded");
        }
        Err(e) => {
            span.record("status", &"failed");
            error!(error = %e, "Operation failed");
        }
    }
}

Integration with Log Crate

// Use tracing-log to convert log records to tracing events
use tracing::{info, warn};
use tracing_subscriber;
use log as old_log;
 
fn main() {
    // Initialize tracing with log integration
    tracing_subscriber::fmt::init();
    
    // Tracing events
    info!("Using tracing");
    
    // Log crate calls (need tracing-log crate)
    // old_log::info!("Using old log crate");
    
    warn!("All logging goes through tracing");
}

Structured Error Context

use tracing::{info, error, instrument, span, Level};
use tracing_subscriber;
use anyhow::{Result, Context};
 
#[instrument(err)]
fn load_config(path: &str) -> Result<String> {
    info!("Loading configuration");
    
    let content = std::fs::read_to_string(path)
        .context("Failed to read config file")?;
    
    if content.is_empty() {
        anyhow::bail!("Configuration is empty");
    }
    
    Ok(content)
}
 
fn main() {
    tracing_subscriber::fmt::init();
    
    match load_config("config.toml") {
        Ok(config) => info!("Configuration loaded"),
        Err(e) => error!(error = %e, "Failed to load configuration"),
    }
}

Performance Considerations

use tracing::{info, debug, trace, span, Level};
use tracing_subscriber;
 
// Expensive computation only runs if debug level is enabled
fn expensive_debug_info() -> String {
    // Simulate expensive operation
    "Detailed debug information".to_string()
}
 
fn process() {
    let span = span!(Level::DEBUG, "process");
    let _enter = span.enter();
    
    info!("Processing");
    
    // Use closure for lazy evaluation
    debug!(info = %expensive_debug_info(), "Debug details");
    
    // Span fields also support lazy evaluation
    span.record("result", &"success");
}
 
fn main() {
    tracing_subscriber::fmt()
        .with_max_level(Level::INFO)  // Debug won't be evaluated
        .init();
    
    process();
}

Summary

Tracing Key Imports:

use tracing::{info, debug, trace, warn, error, span, Level, instrument};
use tracing_subscriber;

Core Macros:

Macro	Description
`info!`	Info level event
`debug!`	Debug level event
`trace!`	Trace level event
`warn!`	Warning level event
`error!`	Error level event
`span!`	Create a span
`instrument`	Decorate functions with spans

Log Levels:

Level	Description
TRACE	Very detailed information
DEBUG	Debugging information
INFO	General information
WARN	Warning conditions
ERROR	Error conditions

Instrument Attributes:

Attribute	Description
`skip`	Don't record specific arguments
`skip_all`	Don't record any arguments
`fields`	Add extra fields
`level`	Set span level
`err`	Record error return values

Subscriber Configuration:

// Basic
tracing_subscriber::fmt::init();
 
// With JSON
tracing_subscriber::fmt().json().init();
 
// With filtering
tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::new("info"))
    .init();
 
// With multiple layers
tracing_subscriber::registry()
    .with(stdout_layer)
    .with(file_layer)
    .init();

Key Points:

Use spans for contextual scope tracking
Use #[instrument] for automatic function tracing
Use fields for structured data
Configure output format with tracing_subscriber
Set appropriate log levels for environment
JSON format for production/log aggregation
Essential for async and distributed systems