tracing en Rust: logging estructurado y async-aware con spans y eventos

El crate log fue durante años el estándar de logging en Rust. Tiene una interfaz simple con macros como info!(), warn!() y error!(). Pero tiene una limitación fundamental en código async: no hay forma de asociar un log con el contexto de la operación que lo generó.

Imagina un servidor que procesa cien peticiones concurrentes. Cuando ves un mensaje de log [INFO] Iniciando procesamiento, ¿de cuál de las cien peticiones es? Con log, no hay forma de saberlo.

tracing resuelve esto con el concepto de span: un período de tiempo delimitado con contexto asociado. Los eventos de log que ocurren dentro de un span llevan ese contexto automáticamente, incluso cruzando puntos .await.

Añadir tracing al proyecto

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

El crate tracing define la API. tracing-subscriber es el backend que recibe los eventos y los formatea para la terminal (o los envía a otro destino).

Configurar el subscriber

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

fn main() {
    tracing_subscriber::registry()
        .with(tracing_subscriber::EnvFilter::new(
            std::env::var("RUST_LOG").unwrap_or_else(|_| "info".into()),
        ))
        .with(tracing_subscriber::fmt::layer())
        .init();

    // Ahora puedes usar las macros de tracing
    tracing::info!("Aplicación iniciada");
}

Con RUST_LOG=debug, verás todos los eventos. Con RUST_LOG=info, solo los de nivel info o superior. Puedes filtrar por módulo: RUST_LOG=mi_app=debug,tower_http=info.

Eventos: la alternativa a los logs

Los eventos son la unidad básica de tracing, el equivalente a los mensajes de log:

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

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

    if total < 0.0 {
        error!(pedido_id = id, total = total, "Total negativo");
        return Err("Total inválido".to_string());
    }

    if total > 10_000.0 {
        warn!(pedido_id = id, total = total, "Pedido de importe alto");
    }

    info!(pedido_id = id, total = total, "Pedido procesado correctamente");
    Ok(())
}

Los campos estructurados (pedido_id = id) son clave-valor que se adjuntan al evento y están disponibles para procesamiento posterior (buscar, filtrar, agregar).

Spans: contexto a través de .await

Un span es un bloque de código con contexto asociado. Todo lo que ocurra dentro del span (eventos, otros spans) hereda ese contexto:

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

async fn manejar_peticion(id_peticion: &str, usuario: &str) {
    let span = span!(Level::INFO, "manejar_peticion",
        peticion_id = id_peticion,
        usuario = usuario
    );
    let _guard = span.enter();  // Activa el span hasta que _guard se dropea

    info!("Petición recibida");

    // Todos los logs dentro de este span incluyen peticion_id y usuario
    let datos = obtener_datos().await;
    info!(datos_count = datos.len(), "Datos obtenidos");

    procesar_datos(datos).await;
    info!("Procesamiento completado");
}

// Forma más ergonómica con .instrument():
async fn manejar_peticion_v2(id: &str) {
    obtener_datos()
        .instrument(span!(Level::INFO, "obtener_datos", peticion_id = id))
        .await;
}

La macro #[instrument]

La macro #[instrument] es la forma más cómoda de añadir tracing a funciones. Crea un span automáticamente con el nombre de la función y registra los argumentos como campos:

use tracing::instrument;

#[instrument]
async fn procesar_usuario(id: u64, nombre: &str) -> Result<String, String> {
    info!("Iniciando procesamiento");
    // El span incluye automáticamente: id=42, nombre="Ana"

    let datos = obtener_datos_usuario(id).await?;
    info!("Datos obtenidos");

    Ok(format!("Procesado: {}", datos))
}

// Controlar qué campos se incluyen:
#[instrument(
    name = "procesar",   // nombre personalizado del span
    skip(clave_secreta), // excluir argumentos sensibles
    fields(              // campos adicionales
        extra = "valor",
        calculado = tracing::field::Empty,  // se rellena después
    ),
    err,                 // loguear automáticamente los errores devueltos
)]
async fn operacion_segura(
    usuario: &str,
    clave_secreta: &str,
) -> Result<(), anyhow::Error> {
    // Añadir el campo calculado durante la ejecución
    tracing::Span::current().record("calculado", &usuario.len());
    // ...
    Ok(())
}

Campos estructurados y Display

use tracing::info;
use std::net::SocketAddr;

fn registrar_conexion(addr: SocketAddr, usuario: &str) {
    info!(
        %addr,          // usa Display (%)
        ?usuario,       // usa Debug (?)
        usuario_len = usuario.len(),  // valor directo
        "Nueva conexión"
    );
}

El prefijo % usa el trait Display para formatear el valor. El prefijo ? usa Debug. Sin prefijo, el valor debe implementar el trait Value de tracing (implementado para tipos primitivos).

Configuración para producción

En producción querrás logs en formato JSON para que sean procesables por herramientas como Elasticsearch o Loki:

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

tracing_subscriber::registry()
    .with(tracing_subscriber::EnvFilter::from_default_env())
    .with(tracing_subscriber::fmt::layer().json())
    .init();

Para enviar traces a OpenTelemetry (Jaeger, Tempo, etc.):

[dependencies]
tracing-opentelemetry = "0.22"
opentelemetry-otlp = { version = "0.15", features = ["tokio"] }
opentelemetry = "0.22"

use opentelemetry_otlp::WithExportConfig;
use tracing_opentelemetry::OpenTelemetryLayer;

let tracer = opentelemetry_otlp::new_pipeline()
    .tracing()
    .with_exporter(
        opentelemetry_otlp::new_exporter()
            .tonic()
            .with_endpoint("http://localhost:4317"),
    )
    .install_batch(opentelemetry_sdk::runtime::Tokio)?;

tracing_subscriber::registry()
    .with(OpenTelemetryLayer::new(tracer))
    .with(tracing_subscriber::fmt::layer())
    .init();

Compatibilidad con el crate log

Si tienes dependencias que usan el crate log clásico, puedes hacer que sus mensajes aparezcan en tracing:

[dependencies]
tracing-log = "0.2"

// En la inicialización:
tracing_log::LogTracer::init()?;

Esto hace que todos los mensajes de log se redirijan automáticamente como eventos de tracing. La transición de log a tracing en proyectos existentes suele ser gradual y esta compatibilidad hace que sea sin fricciones.