tracing: instrumentación estructurada que sí sigue a la tarea

La lección anterior dejó un vacío: si la pila ya no cuenta la historia y el println! se entrelaza en un caos ilegible, ¿cómo sabe cada tarea quién es y qué está haciendo? La respuesta de Rust async es tracing, y su idea central es sutil. En lugar de imprimir líneas planas de texto, emites datos estructurados organizados por dos primitivas: el span, que representa un periodo —el tiempo que una tarea pasa atendiendo una petición— y el event, que representa un instante dentro de ese periodo. Los spans se anidan y forman un árbol, y aquí está la magia: ese árbol de spans es exactamente el árbol de llamadas que la pila del hilo dejó de guardar. Cuando cada evento arrastra la cadena de spans que lo contiene —esta petición, dentro de este usuario, dentro de este servicio—, recuperas la ancestralidad que el backtrace perdió, y la recuperas de una forma que sobrevive a la migración de hilos y a las diez mil tareas concurrentes. tracing no es “un logger mejor”: es la reconstrucción de la pila lógica como dato observable.

Span y event: el periodo y el instante

tracing parte de dos conceptos que el println! funde en uno. Un event es un suceso puntual —“la consulta devolvió 512 bytes”—, el análogo estructurado de una línea de log. Un span es distinto: modela un tramo de tiempo con un principio y un fin, durante el cual el programa ejecuta una unidad de trabajo. Mientras un span está activo, todo event que se emita queda anotado como hijo suyo, y los spans se anidan: un span “peticion” contiene un span “consulta_db” que contiene los events de esa consulta.

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

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

async fn atender(id: u64) {
    let s = span!(Level::INFO, "atender", peticion = id);
    let _guard = s.enter();          // el span queda activo mientras viva _guard
    debug!("validando la peticion"); // este event es hijo del span atender
    let datos = consultar(id).await;
    info!(bytes = datos.len(), "consulta lista");
}

Nada de esto hace nada por sí solo: los spans y events se emiten a un subscriber, un componente que decide qué registrar y cómo. Sin subscriber instalado, la instrumentación es casi gratis; con uno, cobra vida. El más común imprime a la consola con formato legible y filtra por la variable RUST_LOG:

tracing_subscriber::fmt()
    .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
    .init();

instrument: el span que respeta las suspensiones

La forma idiomática de instrumentar una función async es el atributo #[instrument], que envuelve todo el cuerpo en un span, captura los argumentos como campos y —esto es lo esencial— gestiona correctamente las suspensiones:

use tracing::{info, instrument};

#[instrument]
async fn atender(id: u64, region: &str) -> usize {
    info!("empezando");
    let datos = consultar(id).await;
    info!(bytes = datos.len(), "consulta lista");
    datos.len()
}

#[instrument] genera un span llamado atender con id y region como campos, y en vez de entrar el span de golpe, aplica internamente el adaptador Instrument al Future. El efecto es quirúrgico: el span se re-entra en cada poll de la tarea y se sale en cada Poll::Pending. Así, aunque la tarea se duerma en el .await y se reanude en otro hilo trabajador —recuerda el robo de trabajo del nivel anterior—, cada tramo de ejecución vuelve a activar el span correcto en el hilo correcto. La ancestralidad que la pila perdía en cada suspensión, tracing la reconstruye en cada reanudación.

Cuando llamas a una async fn instrumentada desde otra también instrumentada, sus spans se anidan: el subscriber ve atender conteniendo a consultar, y cada event lleva la lista completa de spans padres. Ese es el árbol de llamadas lógico —el que el backtrace no podía darte— materializado como dato.

#[instrument(skip(cliente), fields(usuario = %ctx.usuario_id))]
async fn consultar(cliente: &Cliente, ctx: &Contexto, id: u64) -> Vec<u8> {
    // skip(cliente): no intentes formatear un Cliente enorme como campo.
    // fields(...): añade campos calculados que los argumentos no dan.
    cliente.get(id).await
}

El skip es indispensable: sin él, #[instrument] intentaría registrar todos los argumentos con su Debug, incluido un cliente de red de miles de bytes. fields(...) deja añadir contexto derivado —el % pide Display, el ? pediría Debug—.

flowchart TD
R[span peticion] --> A[span atender id 42]
A --> C[span consultar usuario 7]
C --> E1[event validando]
C --> E2[event consulta lista bytes 512]
A --> E3[event respondido]
style R fill:#cba6f7,color:#11111b
style A fill:#89b4fa,color:#11111b
style C fill:#89b4fa,color:#11111b
style E2 fill:#a6e3a1,color:#11111b

Por qué reemplaza al println en async

La superioridad de tracing sobre println! no es cosmética; resuelve cada uno de los fallos que la lección anterior expuso. Comparemos los dos mundos sobre el mismo problema:

La diferencia de fondo: println! describe lo que pasó en un hilo en un instante, y en async ni el hilo ni el instante identifican nada. tracing describe lo que le pasó a una tarea a lo largo de un periodo, que es justo la unidad de la que async está hecho. Por eso no es un lujo de observabilidad para producción: es la sustitución natural del depurador de pila para el desarrollo diario. Y como el mismo flujo de spans y events alimenta tanto la consola en tu máquina como un colector distribuido en producción, tracing es también el sustrato sobre el que se apoya tokio-console, la herramienta de la próxima lección.