Rust Tracing

Rust Tracing and Structured Logging

Comprehensive guide for observability with the tracing ecosystem.

Setup

Basic Setup

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

use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};

fn init_tracing() {
    tracing_subscriber::registry()
        .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| {
            // Default log level
            "info,nebula=debug,tower_http=debug".into()
        }))
        .with(tracing_subscriber::fmt::layer())
        .init();
}

fn main() {
    init_tracing();
    // ...
}

Production Setup with JSON

use tracing_subscriber::{
    fmt::{self, format::FmtSpan},
    layer::SubscriberExt,
    util::SubscriberInitExt,
    EnvFilter,
};

fn init_production_tracing() {
    let env_filter = EnvFilter::try_from_default_env()
        .unwrap_or_else(|_| "info".into());

    let fmt_layer = fmt::layer()
        .json()                           // JSON output for log aggregation
        .with_current_span(true)          // Include current span
        .with_span_list(true)             // Include span hierarchy
        .with_file(true)                  // Include file name
        .with_line_number(true)           // Include line number
        .with_thread_ids(true)            // Include thread ID
        .with_target(true);               // Include target module

    tracing_subscriber::registry()
        .with(env_filter)
        .with(fmt_layer)
        .init();
}

Development Setup with Pretty Output

fn init_dev_tracing() {
    tracing_subscriber::registry()
        .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| "debug".into()))
        .with(
            tracing_subscriber::fmt::layer()
                .pretty()                  // Human-readable output
                .with_file(true)
                .with_line_number(true)
                .with_thread_names(true)
        )
        .init();
}

Log Levels

Choosing the Right Level

use tracing::{trace, debug, info, warn, error};

fn process_request(req: &Request) -> Result<Response, Error> {
    // TRACE: Very detailed debugging, high volume
    trace!(headers = ?req.headers(), "Raw request headers");
    
    // DEBUG: Diagnostic information for debugging
    debug!(method = %req.method(), path = %req.path(), "Processing request");
    
    // INFO: Notable events in normal operation
    info!(user_id = %user.id, "User authenticated successfully");
    
    // WARN: Unexpected but recoverable situations
    warn!(retry_count = 3, "Request failed, retrying");
    
    // ERROR: Failures that need attention
    error!(error = ?err, "Failed to process request");
    
    Ok(response)
}

Level Guidelines

Structured Fields

Field Types

use tracing::info;

fn log_examples() {
    let user_id = 42;
    let username = "alice";
    let request = Request::new();
    
    // Display formatting (uses Display trait)
    info!(%user_id, "User action");  // user_id=42
    
    // Debug formatting (uses Debug trait)
    info!(?request, "Request received");  // request=Request { ... }
    
    // Named fields
    info!(user.id = user_id, user.name = username, "User logged in");
    
    // Literal values
    info!(version = 1, "API version");
    
    // Empty message with just fields
    info!(user_id, action = "login");
}

Consistent Field Naming

// Use consistent, hierarchical field names across the codebase

// Request context
info!(
    request.id = %request_id,
    request.method = %method,
    request.path = %path,
    "Handling request"
);

// User context
info!(
    user.id = %user_id,
    user.role = %role,
    "User action"
);

// Database operations
debug!(
    db.query = query,
    db.duration_ms = duration.as_millis(),
    db.rows_affected = rows,
    "Query executed"
);

// External service calls
info!(
    service.name = "payment-api",
    service.operation = "charge",
    service.duration_ms = duration.as_millis(),
    "External call completed"
);

// Error context
error!(
    error.kind = %err.kind(),
    error.message = %err,
    error.source = ?err.source(),
    "Operation failed"
);

Spans

Function Instrumentation

use tracing::{instrument, info, debug, Span};

// Basic instrumentation
#[instrument]
fn process_item(item_id: u64) -> Result<(), Error> {
    info!("Processing started");
    // All logs here are within the span
    do_work()?;
    info!("Processing completed");
    Ok(())
}

// Skip sensitive fields
#[instrument(skip(password, api_key))]
fn authenticate(username: &str, password: &str, api_key: &str) -> Result<User, AuthError> {
    info!("Authentication attempt");
    // password and api_key won't be logged
    Ok(user)
}

// Custom span name and level
#[instrument(name = "handle_request", level = "info")]
async fn handle(req: Request) -> Response {
    // ...
}

// Add custom fields
#[instrument(fields(request_id = %generate_id()))]
async fn process_request(req: Request) -> Response {
    // ...
}

// Skip all parameters, add specific ones
#[instrument(skip_all, fields(user_id = %user.id, action = "update"))]
fn update_user(user: &User, data: UpdateData) -> Result<(), Error> {
    // ...
}

Manual Spans

use tracing::{span, Level, info, Instrument};

async fn complex_operation() {
    // Create a span
    let span = span!(Level::INFO, "complex_operation", phase = "init");
    let _guard = span.enter();
    
    info!("Starting phase 1");
    
    // Nested span
    {
        let inner_span = span!(Level::DEBUG, "phase_1");
        let _inner_guard = inner_span.enter();
        do_phase_1().await;
    }
    
    // Update span fields
    Span::current().record("phase", "complete");
    info!("All phases complete");
}

// For async code, use .instrument()
async fn async_operation() {
    let span = span!(Level::INFO, "async_op");
    
    async move {
        info!("Inside async operation");
        do_async_work().await;
    }
    .instrument(span)
    .await;
}

Span Events

use tracing::{span, Level, event};

fn with_span_events() {
    let span = span!(Level::INFO, "operation");
    let _guard = span.enter();
    
    // Event within span
    event!(Level::INFO, "Operation started");
    
    // Event with fields
    event!(Level::DEBUG, items = 42, "Processing items");
    
    // Parent span is automatically included
}

Async Tracing

Instrument Async Functions

use tracing::{instrument, info, Instrument};
use std::future::Future;

#[instrument]
async fn fetch_data(url: &str) -> Result<Data, Error> {
    info!("Fetching data");
    let response = client.get(url).await?;
    info!(status = %response.status(), "Response received");
    Ok(response.json().await?)
}

// For closures
async fn process_items(items: Vec<Item>) {
    let futures = items.into_iter().map(|item| {
        let span = tracing::info_span!("process_item", item_id = %item.id);
        async move {
            process(item).await
        }
        .instrument(span)
    });
    
    futures::future::join_all(futures).await;
}

Tokio Console Integration

# Cargo.toml
[dependencies]
console-subscriber = "0.4"
tokio = { version = "1", features = ["full", "tracing"] }

fn init_with_console() {
    console_subscriber::init();  // For tokio-console debugging
}

Request Tracing

HTTP Request Spans

use axum::{
    extract::Request,
    middleware::Next,
    response::Response,
};
use tracing::{info_span, Instrument};
use uuid::Uuid;

pub async fn trace_request(request: Request, next: Next) -> Response {
    let request_id = Uuid::new_v4();
    let method = request.method().clone();
    let uri = request.uri().clone();
    
    let span = info_span!(
        "http_request",
        request.id = %request_id,
        request.method = %method,
        request.path = %uri.path(),
        request.query = ?uri.query(),
        response.status = tracing::field::Empty,
        response.duration_ms = tracing::field::Empty,
    );
    
    async move {
        let start = std::time::Instant::now();
        let response = next.run(request).await;
        let duration = start.elapsed();
        
        // Record response fields
        tracing::Span::current()
            .record("response.status", response.status().as_u16())
            .record("response.duration_ms", duration.as_millis() as u64);
        
        tracing::info!("Request completed");
        
        response
    }
    .instrument(span)
    .await
}

Tower HTTP Tracing

use axum::Router;
use tower_http::trace::{self, TraceLayer};
use tracing::Level;

fn create_router() -> Router {
    Router::new()
        .route("/", get(handler))
        .layer(
            TraceLayer::new_for_http()
                .make_span_with(trace::DefaultMakeSpan::new().level(Level::INFO))
                .on_request(trace::DefaultOnRequest::new().level(Level::INFO))
                .on_response(trace::DefaultOnResponse::new().level(Level::INFO))
                .on_failure(trace::DefaultOnFailure::new().level(Level::ERROR))
        )
}

Error Tracing

Logging Errors

use tracing::{error, warn, instrument};

#[instrument(err)]  // Automatically logs errors at ERROR level
fn fallible_operation() -> Result<(), Error> {
    do_something()?;
    Ok(())
}

#[instrument(err(level = "warn"))]  // Log errors at WARN level
fn recoverable_operation() -> Result<(), Error> {
    // ...
}

// Manual error logging with context
fn process() -> Result<Output, Error> {
    match do_work() {
        Ok(result) => Ok(result),
        Err(e) => {
            error!(
                error = %e,
                error.kind = ?e.kind(),
                "Operation failed"
            );
            Err(e)
        }
    }
}

// Chain of errors
fn with_error_chain() {
    if let Err(e) = operation() {
        error!(error = ?e, "Top-level error");
        
        let mut source = e.source();
        while let Some(cause) = source {
            error!(cause = %cause, "Caused by");
            source = cause.source();
        }
    }
}

Filtering and Output

Environment Filter Syntax

# Set via environment variable
RUST_LOG=info                           # All modules at INFO
RUST_LOG=debug,hyper=info               # Default DEBUG, hyper at INFO
RUST_LOG=nebula=debug,tower_http=debug  # Specific modules
RUST_LOG=nebula::api=trace              # Specific path
RUST_LOG="info,nebula[user_id]=debug"   # Filter by span field

Programmatic Filtering

use tracing_subscriber::{filter, layer::SubscriberExt, util::SubscriberInitExt};

fn init_filtered() {
    let filter = filter::Targets::new()
        .with_default(tracing::Level::INFO)
        .with_target("nebula", tracing::Level::DEBUG)
        .with_target("hyper", tracing::Level::WARN)
        .with_target("tower_http", tracing::Level::DEBUG);
    
    tracing_subscriber::registry()
        .with(tracing_subscriber::fmt::layer())
        .with(filter)
        .init();
}

Multiple Outputs

use tracing_subscriber::{
    fmt::{self, writer::MakeWriterExt},
    layer::SubscriberExt,
    util::SubscriberInitExt,
};
use std::io;

fn init_multi_output() {
    // Stderr for errors, stdout for everything else
    let stderr = io::stderr.with_max_level(tracing::Level::WARN);
    let stdout = io::stdout.with_max_level(tracing::Level::INFO);
    
    tracing_subscriber::registry()
        .with(fmt::layer().with_writer(stderr))
        .with(fmt::layer().with_writer(stdout))
        .init();
}

OpenTelemetry Integration

Setup with Jaeger

[dependencies]
opentelemetry = "0.27"
opentelemetry_sdk = { version = "0.27", features = ["rt-tokio"] }
opentelemetry-otlp = "0.27"
tracing-opentelemetry = "0.28"

use opentelemetry::trace::TracerProvider;
use opentelemetry_sdk::trace::SdkTracerProvider;
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};

fn init_otel() -> Result<SdkTracerProvider, Box<dyn std::error::Error>> {
    let exporter = opentelemetry_otlp::SpanExporter::builder()
        .with_tonic()
        .build()?;
    
    let provider = SdkTracerProvider::builder()
        .with_batch_exporter(exporter)
        .build();
    
    let tracer = provider.tracer("nebula");
    let telemetry = tracing_opentelemetry::layer().with_tracer(tracer);
    
    tracing_subscriber::registry()
        .with(telemetry)
        .with(tracing_subscriber::fmt::layer())
        .init();
    
    Ok(provider)
}

// Shutdown properly
async fn shutdown(provider: SdkTracerProvider) {
    provider.shutdown().expect("Failed to shutdown tracer");
}

Testing

Capturing Logs in Tests

#[cfg(test)]
mod tests {
    use tracing_test::traced_test;
    
    #[traced_test]
    #[test]
    fn test_with_logs() {
        tracing::info!("This will be captured");
        assert!(logs_contain("captured"));
    }
    
    #[traced_test]
    #[tokio::test]
    async fn test_async_with_logs() {
        tracing::debug!("Async test log");
        assert!(logs_contain("Async test"));
    }
}

Test Subscriber

use tracing_subscriber::fmt::MakeWriter;
use std::sync::{Arc, Mutex};

struct TestWriter {
    logs: Arc<Mutex<Vec<String>>>,
}

impl std::io::Write for TestWriter {
    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
        let log = String::from_utf8_lossy(buf).to_string();
        self.logs.lock().unwrap().push(log);
        Ok(buf.len())
    }
    
    fn flush(&mut self) -> std::io::Result<()> {
        Ok(())
    }
}

#[test]
fn test_logging() {
    let logs = Arc::new(Mutex::new(Vec::new()));
    let writer = TestWriter { logs: logs.clone() };
    
    let subscriber = tracing_subscriber::fmt()
        .with_writer(move || writer.clone())
        .finish();
    
    tracing::subscriber::with_default(subscriber, || {
        tracing::info!("Test message");
    });
    
    let captured = logs.lock().unwrap();
    assert!(captured.iter().any(|l| l.contains("Test message")));
}

Nebula Conventions

Standard Span Names

// HTTP requests
#[instrument(name = "http.request")]

// Database operations
#[instrument(name = "db.query")]
#[instrument(name = "db.transaction")]

// Background jobs
#[instrument(name = "job.execute")]

// Workflow operations
#[instrument(name = "workflow.run")]
#[instrument(name = "workflow.step")]

// External services
#[instrument(name = "external.call")]

Standard Field Names

// Request context
request.id
request.method
request.path

// Response context
response.status
response.duration_ms

// User context
user.id
user.role

// Workflow context
workflow.id
workflow.name
workflow.step

// Database context
db.query
db.table
db.duration_ms
db.rows_affected

// Error context
error.kind
error.message
error.code

Log Message Style

// Use lowercase, present tense, no trailing punctuation
info!("processing request");           // Good
info!("Processing Request.");          // Bad

// Include context in fields, not message
info!(user_id = %id, "user logged in");  // Good
info!("User {} logged in", id);           // Less structured

// Be specific
info!("workflow step completed");         // Good
info!("done");                            // Too vague