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

Walkthrough

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:

Spans — represent a period of time (a unit of work)
Events — represent a point-in-time occurrence
Levels — TRACE, DEBUG, INFO, WARN, ERROR
Fields — structured key-value data attached to spans and events
Subscribers — receive and process span/event data
Instrumentation — attaching spans to async tasks and functions

Tracing is essential for production applications needing observability.

Code Example

# 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");
}

Setting Up Tracing

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");
}

Logging Levels and Events

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");
}

Structured Fields

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,
}

Spans and Context

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");
}

Span Lifecycle Management

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");
}

Async Instrumentation

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,
}

The #[instrument] Attribute

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![]);
}

JSON Output

# 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");
}

Error Handling and Spans

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() })
}

Multiple Subscribers and Layers

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
            }))
    }
}

Real-World Application Example

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"),
    }
}

Integration with Tower and Hyper

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");
}

Summary

Use tracing for structured, contextual logging and instrumentation
Initialize with tracing_subscriber::fmt::init() or customize with builder pattern
Log levels: trace!, debug!, info!, warn!, error!
Add structured fields: info!(user_id = 42, "Message")
Use %field for Display format, ?field for Debug format
Create spans with span!(Level::INFO, "name") and enter with .enter()
Use #[instrument] attribute for automatic function instrumentation
Skip large or sensitive fields with `#[instrument(skip(large_data))]
Use .instrument(span) for async functions
JSON output with .json() on the subscriber builder
Filter logs with EnvFilter and RUST_LOG environment variable
Use layers for multiple outputs (stdout, file, network)
Record errors with #[instrument(err)] for automatic error logging
Add custom fields with #[instrument(fields(custom = "value"))]
Tracing integrates well with async runtimes like Tokio
Use tracing-appender for file logging with rotation
Use tower-http for HTTP request tracing in web services