Logging en Rust con log y tracing

Cuando algo sale mal en un programa, quieres saber qué estaba haciendo justo antes. Para eso sirve el logging (registro de eventos). Un log es como el cuaderno de bitácora de un barco: notas cortas, cada una con una hora y un nivel de importancia, que puedes leer más tarde para entender qué pasó.

Podrías llenar el código de println!, pero pronto chocarías con sus límites. No puedes apagarlo sin editar el código. No puedes decir “enséñame solo los avisos”. Y mezcla tus notas de depuración con la salida real del programa. Los crates de logging de Rust resuelven los tres problemas. En esta página aprenderás los dos más populares: log (con env_logger) y tracing.

¿Por qué no usar println! y ya?

Aquí tienes la diferencia de un vistazo:

	println!	un crate de logging
Encenderlo o apagarlo sin recompilar	No	Sí, con la variable RUST_LOG
Niveles (error, warn, info, …)	No	Sí
Muestra de dónde viene el mensaje	No	Sí (el nombre del módulo)
Adónde va	stdout	stderr por defecto (env_logger)

La última fila importa más de lo que parece. stdout es el resultado real de tu programa: lo que alguien podría redirigir a un archivo o a otro programa. stderr es el canal secundario para mensajes sobre la ejecución. Los logs van en stderr, así que my_app > result.txt guarda solo el resultado, y los logs siguen apareciendo en la terminal.

La fachada log y env_logger

El crate log te da cinco macros, una por nivel, de más grave a menos grave: error!, warn!, info!, debug! y trace!. Funcionan igual que println!, con el mismo formato {}.

Pero log por sí solo no imprime nada. Es una fachada (facade): un conjunto estándar de macros que cualquier biblioteca puede usar sin decidir cómo se muestran los mensajes. Tu aplicación elige un logger que los escribe de verdad. El más sencillo es env_logger. Añade los dos a tu proyecto:

cargo add log env_logger

[dependencies]
log = "0.4"
env_logger = "0.11"

Ahora llama a env_logger::init() una vez, al principio de main, y ya puedes escribir logs:

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

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide llamada con a={a}, b={b}");
    if b == 0.0 {
        warn!("me niego a dividir {a} entre cero");
        return None;
    }
    Some(a / b)
}

fn main() {
    env_logger::init();
    info!("arrancando la calculadora");

    println!("10 / 4 = {:?}", divide(10.0, 4.0));
    println!("1 / 0 = {:?}", divide(1.0, 0.0));

    error!("así se ve una línea de error");
}

Salida:

10 / 4 = Some(2.5)
1 / 0 = None

▶ Pruébalo tú mismo

La salida de arriba es solo stdout, el resultado real del programa. Las líneas de log van a stderr. En el Playground aparecen en la zona aparte “Standard Error”.

Fíjate en una cosa: por defecto, env_logger muestra solo los errores. Para ver más, define la variable de entorno RUST_LOG al ejecutar el programa. Así se veían stderr y stdout juntos cuando lo ejecutamos en una terminal con RUST_LOG=debug cargo run (cambiamos cada marca de tiempo por …; en la tuya verás la fecha y hora actuales):

[… INFO  my_app] arrancando la calculadora
[… DEBUG my_app] divide llamada con a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide llamada con a=1, b=0
[… WARN  my_app] me niego a dividir 1 entre cero
1 / 0 = None
[… ERROR my_app] así se ve una línea de error

Cada línea de log muestra el nivel y el módulo del que viene (my_app, el nombre del crate). Las líneas sin corchetes son la salida de println!.

Elegir qué ves con RUST_LOG

Un nivel muestra ese nivel y todos los más graves. Así que RUST_LOG=warn muestra avisos y errores, y RUST_LOG=trace lo muestra todo.

RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # solo warn y error
RUST_LOG=off cargo run       # ningún log

En PowerShell de Windows, define primero la variable: $env:RUST_LOG="debug"; cargo run.

También puedes filtrar por módulo. Es genial cuando una biblioteca habla demasiado, o cuando solo te interesa una parte de tu código. Aquí tienes un programa con un módulo db:

use log::{debug, info};

mod db {
    use log::{debug, trace};

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("buscando el usuario {id}");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("resultado de la búsqueda: {name:?}");
        name
    }
}

fn main() {
    env_logger::init();
    info!("arrancando el servidor");

    for id in [1, 3] {
        match db::find_user(id) {
            Some(name) => println!("usuario {id}: {name}"),
            None => println!("usuario {id}: no encontrado"),
        }
    }

    debug!("búsquedas terminadas");
}

Salida:

usuario 1: Ada
usuario 3: no encontrado

▶ Pruébalo tú mismo

Algunos filtros que probamos, y lo que imprimieron en stderr (marcas de tiempo cambiadas por …):

$ RUST_LOG=my_app=trace cargo run       # todo lo de nuestro crate
[… INFO  my_app] arrancando el servidor
[… TRACE my_app::db] buscando el usuario 1
[… DEBUG my_app::db] resultado de la búsqueda: Some("Ada")
usuario 1: Ada
[… TRACE my_app::db] buscando el usuario 3
[… DEBUG my_app::db] resultado de la búsqueda: None
usuario 3: no encontrado
[… DEBUG my_app] búsquedas terminadas

$ RUST_LOG=my_app::db=debug cargo run   # solo el módulo db, de debug para arriba
[… DEBUG my_app::db] resultado de la búsqueda: Some("Ada")
usuario 1: Ada
[… DEBUG my_app::db] resultado de la búsqueda: None
usuario 3: no encontrado

Puedes combinar reglas con comas: RUST_LOG=info,my_app::db=trace significa “info para todo, pero trace para el módulo db”. Una pequeña trampa: el filtro usa el nombre del crate con guiones bajos. Un paquete llamado my-app aparece en los logs como my_app.

Un nivel por defecto desde el código

A menudo quieres que info se vea aunque RUST_LOG no esté definida. Usa env_logger::Builder en lugar de init(). También puedes quitar la marca de tiempo, algo práctico para herramientas pequeñas:

use env_logger::Env;
use log::{debug, info};

fn main() {
    // Muestra `info` y superiores, salvo que RUST_LOG diga otra cosa.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("aplicación iniciada");
    debug!("esto solo lo ves con RUST_LOG=debug");

    let total: u32 = (1..=10).sum();
    println!("total = {total}");
}

Salida:

total = 55

▶ Pruébalo tú mismo

Sin marca de tiempo, el stderr real de cargo run queda corto y limpio:

[INFO  my_app] aplicación iniciada

Logging estructurado con tracing

log te da líneas de texto. tracing te da eventos con datos, agrupados en spans (tramos). Lo creó el equipo de Tokio, y es lo que usan los frameworks web asíncronos como axum. Añádelo así:

cargo add tracing tracing-subscriber

Tres ideas que aprender:

• Los eventos son como líneas de log: info!, warn! y compañía, con los mismos nombres que en log.
• Los campos adjuntan datos como clave = valor: info!(user_id = 42, "sesión iniciada"). Las herramientas pueden buscar y filtrar por estos campos en lugar de analizar texto.
• Los spans describen un periodo de trabajo, como “procesando el pedido 7”. Cada evento dentro de un span queda etiquetado con él.

Igual que log, tracing necesita un subscriber (suscriptor) para mostrar algo. tracing_subscriber::fmt() es el estándar. Una sorpresa: escribe en stdout por defecto, así que lo mandamos a stderr con .with_writer(std::io::stderr):

use tracing::{info, info_span, warn};

fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stderr)
        .init();

    info!(user_id = 42, "sesión iniciada");

    let span = info_span!("checkout", order_id = 7);
    let _guard = span.enter();

    let items = [1200, 350, 999];
    let total: u32 = items.iter().sum();
    info!(items = items.len(), total, "carrito sumado");

    if total > 2000 {
        warn!(total, limit = 2000, "el pedido necesita revisión manual");
    }

    println!("total del pedido: {total}");
}

Salida:

total del pedido: 2549

▶ Pruébalo tú mismo

Este es el stderr de nuestra ejecución (marcas de tiempo cambiadas por …, sin colores):

…  INFO my_app: sesión iniciada user_id=42
…  INFO checkout{order_id=7}: my_app: carrito sumado items=3 total=2549
…  WARN checkout{order_id=7}: my_app: el pedido necesita revisión manual total=2549 limit=2000

¿Ves que las dos últimas líneas empiezan con checkout{order_id=7}? Ese es el span. Mientras _guard sigue vivo, cada evento está “dentro” del checkout (el proceso de pago). Escribir solo total es una forma abreviada de total = total.

#[instrument]: un span por cada llamada

Crear spans a mano cansa. Pon #[instrument] encima de una función y tracing crea un span en cada llamada, con los argumentos guardados como campos (tienen que implementar Debug):

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

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "descuento calculado");
    price - off
}

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::DEBUG)
        .with_writer(std::io::stderr)
        .init();

    let final_price = apply_discount(2500, 10);
    info!(final_price, "listo");
    println!("precio final: {final_price}");
}

Salida:

precio final: 2250

▶ Pruébalo tú mismo

El stderr de nuestra ejecución:

… DEBUG apply_discount{price=2500 percent=10}: my_app: descuento calculado off=250
…  INFO my_app: listo final_price=2250

El subscriber fmt() muestra info y superiores salvo que le digas otra cosa; por eso pusimos .with_max_level(tracing::Level::DEBUG). Si quieres que RUST_LOG funcione como con env_logger, activa la feature env-filter y usa EnvFilter:

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

use tracing_subscriber::EnvFilter;

tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::from_default_env())
    .with_writer(std::io::stderr)
    .init();

¿Cuál deberías elegir?

• ¿Una herramienta de línea de comandos pequeña o un script? log + env_logger. Configuración mínima, texto plano y listo.
• ¿Un servidor web, código asíncrono o muchas tareas a la vez? tracing. Los spans recuerdan a qué petición pertenece cada mensaje, aunque se estén atendiendo cientos a la vez.
• ¿Estás escribiendo una biblioteca? Usa solo las macros (log o tracing) y nunca llames a init(). La aplicación decide cómo se muestran los logs.

No tienes que elegir para siempre. La configuración por defecto de tracing-subscriber también recoge los mensajes del crate log, así que las bibliotecas que usan uno u otro aparecen juntas.

Errores comunes

Olvidar configurar un logger. Si nunca llamas a env_logger::init() (o al init() de un subscriber de tracing), las macros compilan sin problema e imprimen… nada. Ni un error, ni un aviso. Si tus logs desaparecen, revisa esto primero, y luego revisa RUST_LOG.

Llamar a init() dos veces. Solo puede haber un logger global. La segunda llamada hace panic. Este es el mensaje real (en inglés, como lo imprime Rust): dice que env_logger::init no debe llamarse después de que el logger ya esté inicializado.

thread 'main' (12345) panicked at …/env_logger-0.11.11/src/logger.rs:901:16:
env_logger::init should not be called after logger initialized: SetLoggerError(())

Llámalo una vez, al principio de main. En los tests, usa let _ = env_logger::builder().is_test(true).try_init();, que devuelve un error en lugar de hacer panic.

Soltar el guard del span enseguida. let _ = span.enter(); parece inofensivo, pero _ no es un nombre de variable: el guard se destruye en esa misma línea, así que el span termina al instante. En nuestra prueba se imprimió INFO my_app: handling request sin ningún span. Ponle nombre al guard, como let _guard = span.enter();, para que viva hasta el final del ámbito.

Resumen

• Usa un crate de logging en lugar de println! para poder filtrar por nivel y mantener los logs en stderr, lejos de tu salida real.
• log te da error!, warn!, info!, debug! y trace!; env_logger::init() los imprime.
• RUST_LOG controla lo que ves: RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
• tracing añade campos estructurados (info!(user_id = 42, "sesión iniciada")) y spans; #[instrument] crea un span por cada llamada a una función.
• Las bibliotecas solo usan las macros; la aplicación configura el logger una vez.

Comprueba lo que aprendiste

Comprueba lo aprendido

1. Ejecutas un programa que usa env_logger sin definir RUST_LOG. ¿Qué líneas de log ves?

Todas Solo info! y superiores Solo error! Ninguna

2. ¿Dónde escribe env_logger los mensajes de log por defecto?

stdout stderr Un archivo llamado log.txt

3. ¿Qué muestra RUST_LOG=warn?

Solo los avisos Los avisos y todo lo menos grave Los avisos y los errores

4. ¿Qué hace poner #[instrument] en una función?

Mide el tiempo de la función e imprime la duración Crea un span en cada llamada, con los argumentos como campos Hace que la función vaya más rápido Activa el logging en todo el programa

5. Estás escribiendo un crate de biblioteca. ¿Qué debería hacer con el logging?

Usar las macros de logging, pero dejar que la aplicación configure el logger Llamar a env_logger::init() cuando se carga la biblioteca Usar println! para que siempre se vea

Puntuación: 0 / 5

Para leer más

• Documentación del crate log (en inglés): las cinco macros y cómo funciona la fachada, con consejos para autores de bibliotecas.
• Documentación de env_logger (en inglés): la sintaxis completa de RUST_LOG y todas las opciones de Builder.
• Documentación de tracing (en inglés): spans, eventos, campos y #[instrument] a fondo.
• Documentación de tracing-subscriber (en inglés): opciones de formato, EnvFilter y salida en JSON.
• Getting started with Tracing — Tokio (en inglés): un recorrido amable del equipo que mantiene tracing.