tracing en Rust: logging estructurado, spans, eventos y subscribers con tracing-subscriber

tracing es la biblioteca de observabilidad estándar en el ecosistema Rust async. A diferencia del logging tradicional basado en líneas de texto, tracing registra eventos estructurados con campos tipados y agrupa el trabajo relacionado en spans con inicio y fin medibles. Esto permite correlacionar eventos en sistemas con múltiples hilos o tareas async concurrentes.

Eventos y campos tipados

Los eventos en tracing se registran con las macros trace!, debug!, info!, warn! y error!. Los campos pueden ser cualquier tipo que implemente fmt::Debug o los traits de tracing, y se pasan como pares clave-valor.

// [dependencies]
// tracing = "0.1"
// tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }

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

fn procesar_pedido(id: u64, importe: f64) -> Result<String, String> {
    debug!(pedido_id = id, importe = importe, "iniciando procesamiento");

    if importe <= 0.0 {
        warn!(pedido_id = id, importe = importe, "importe inválido");
        return Err(format!("importe {importe} inválido"));
    }

    if importe > 10_000.0 {
        info!(pedido_id = id, importe = importe, "pedido de alto valor, requiere revisión");
    }

    Ok(format!("Pedido {id} procesado: {importe:.2}€"))
}

fn main() {
    tracing_subscriber::fmt::init(); // formato texto simple a stderr

    match procesar_pedido(1001, 250.0) {
        Ok(msg) => info!(mensaje = msg, "pedido completado"),
        Err(e) => error!(error = e, "fallo en pedido"),
    }
    let _ = procesar_pedido(1002, -5.0);
}

Spans: contexto persistente durante una operación

Un span representa una unidad de trabajo con duración medible. Todos los eventos que ocurren mientras el span está activo lo tienen como contexto padre. Esto permite saber qué operación de nivel superior originó cada log, incluso en código async donde varios tasks intercalan su ejecución.

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

async fn manejar_peticion(user_id: u64, endpoint: &str) {
    let span = span!(Level::INFO, "peticion_http",
        user_id = user_id,
        endpoint = endpoint,
    );

    // Todos los eventos dentro de este bloque tienen el span como contexto
    async {
        info!("iniciando handler");
        tokio::time::sleep(std::time::Duration::from_millis(10)).await;
        info!("handler completado");
    }
    .instrument(span)
    .await;
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_target(true)
        .init();

    // Las dos peticiones concurrentes mantienen sus spans independientes
    tokio::join!(
        manejar_peticion(42, "/api/usuarios"),
        manejar_peticion(99, "/api/pedidos"),
    );
}

El atributo #[instrument]

#[instrument] es la forma más cómoda de añadir spans a funciones: genera automáticamente un span con el nombre de la función y los argumentos como campos. Admite opciones para cambiar el nivel, el nombre, excluir campos o añadir campos adicionales.

use tracing::{instrument, info, error};
use std::collections::HashMap;

#[instrument(level = "debug", skip(cache), fields(cache_size = cache.len()))]
async fn buscar_usuario(id: u64, cache: &HashMap<u64, String>) -> Option<String> {
    if let Some(nombre) = cache.get(&id) {
        info!(nombre = nombre.as_str(), "encontrado en caché");
        return Some(nombre.clone());
    }
    // Simular consulta a BBDD
    tokio::time::sleep(std::time::Duration::from_millis(5)).await;
    info!("consultando base de datos");
    None
}

#[instrument(err, level = "warn")]
fn validar_email(email: &str) -> Result<(), String> {
    if email.contains('@') {
        Ok(())
    } else {
        Err(format!("email inválido: {email}"))
    }
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt::init();
    let cache = HashMap::from([(1u64, "Alice".into())]);
    let _ = buscar_usuario(1, &cache).await;
    let _ = buscar_usuario(2, &cache).await;
    let _ = validar_email("sin-arroba");
}

tracing-subscriber: EnvFilter y salida JSON

tracing-subscriber ofrece capas componibles para filtrar, formatear y exportar eventos. EnvFilter permite controlar el nivel de log por módulo con la variable de entorno RUST_LOG, sin recompilar. El formato JSON es ideal para producción e ingestión por Elasticsearch, Datadog o Grafana Loki.

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

fn init_tracing() {
    let filtro = EnvFilter::try_from_default_env()
        .unwrap_or_else(|_| EnvFilter::new("info,mi_app=debug"));

    tracing_subscriber::registry()
        .with(filtro)
        .with(
            fmt::layer()
                .json()                    // salida JSON una línea por evento
                .with_current_span(true)   // incluir span activo en cada evento
                .with_span_list(true)      // incluir lista de spans anidados
        )
        .init();
}

fn main() {
    init_tracing();
    // Controlar nivel por módulo:
    // RUST_LOG=warn,mi_app::api=debug,mi_app::db=trace cargo run
    tracing::info!(version = env!("CARGO_PKG_VERSION"), "servidor iniciado");
}

La diferencia práctica respecto a log + env_logger: tracing mantiene el contexto de spans incluso en código async donde los hilos del runtime intercalan tareas de distintos users o peticiones. En un servidor con cien peticiones concurrentes, cada evento lleva su span padre identificando a qué petición pertenece, lo que hace el diagnóstico de errores en producción radicalmente más sencillo.