Logging em Rust com log e tracing

Quando algo dá errado num programa, você quer saber o que ele estava fazendo logo antes. É para isso que serve o logging (registro de logs). Um log é como o diário de bordo de um navio: anotações curtas, cada uma com um horário e um nível de importância, que você pode ler depois para entender o que aconteceu.

Você até poderia espalhar println! por todo lado, mas logo esbarraria nos limites dele. Não dá para desligá-lo sem mexer no código. Não dá para dizer “mostre só os avisos”. E ele mistura as suas anotações de depuração com a saída de verdade do programa. Os crates (pacotes) de logging do Rust resolvem esses três problemas. Nesta página você vai aprender os dois mais populares: log (com o env_logger) e tracing.

Por que não usar só println!?

A diferença, num quadro só:

	println!	um crate de logging
Ligar/desligar sem recompilar	Não	Sim, com a variável RUST_LOG
Níveis (error, warn, info, …)	Não	Sim
Mostra de onde veio a mensagem	Não	Sim (o nome do módulo)
Para onde vai	stdout	stderr por padrão (env_logger)

Essa última linha importa mais do que parece. O stdout é o resultado de verdade do seu programa: aquilo que alguém pode redirecionar para um arquivo ou para outro programa. O stderr é o canal paralelo para mensagens sobre a execução. Logs pertencem ao stderr, assim my_app > result.txt salva só o resultado, enquanto os logs continuam aparecendo no terminal.

A fachada log e o env_logger

O crate log dá a você cinco macros, uma por nível, do mais grave ao menos grave: error!, warn!, info!, debug! e trace!. Elas funcionam igualzinho ao println!, com a mesma formatação com {}.

Mas o log, sozinho, não imprime nada. Ele é uma fachada (facade): um conjunto padrão de macros que qualquer biblioteca pode usar, sem escolher como as mensagens serão exibidas. A sua aplicação escolhe um logger, que é quem de fato escreve as mensagens. O mais simples é o env_logger. Adicione os dois ao seu projeto:

cargo add log env_logger

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

Agora chame env_logger::init() uma vez, no começo do main, e pode logar à vontade:

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

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide chamada com a={a}, b={b}");
    if b == 0.0 {
        warn!("recusando dividir {a} por zero");
        return None;
    }
    Some(a / b)
}

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

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

    error!("é assim que uma linha de erro aparece");
}

Saída:

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

▶ Experimente você mesmo

A saída acima é só o stdout, o resultado de verdade do programa. As linhas de log vão para o stderr. No Playground, elas aparecem na área separada “Standard Error”.

Repare numa coisa: por padrão, o env_logger mostra só os erros. Para ver mais, defina a variável de ambiente RUST_LOG ao rodar o programa. Foi assim que o stderr e o stdout apareceram juntos quando rodamos num terminal com RUST_LOG=debug cargo run (trocamos cada data e hora por …; no seu, vão aparecer a data e a hora atuais):

[… INFO  my_app] calculadora iniciando
[… DEBUG my_app] divide chamada com a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide chamada com a=1, b=0
[… WARN  my_app] recusando dividir 1 por zero
1 / 0 = None
[… ERROR my_app] é assim que uma linha de erro aparece

Cada linha de log mostra o nível e o módulo de onde ela veio (my_app, o nome do crate). As linhas simples, sem colchetes, são a saída do println!.

Escolhendo o que você vê com RUST_LOG

Um nível mostra aquele nível e tudo o que for mais grave. Então RUST_LOG=warn mostra avisos e erros; RUST_LOG=trace mostra tudo.

RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # só warn e error
RUST_LOG=off cargo run       # nenhum log

No PowerShell do Windows, defina a variável antes: $env:RUST_LOG="debug"; cargo run.

Você também pode filtrar por módulo. Isso é ótimo quando uma biblioteca fala demais, ou quando você só se importa com uma parte do seu código. Veja um programa com um módulo db:

use log::{debug, info};

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

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("procurando o usuário {id}");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("resultado da busca: {name:?}");
        name
    }
}

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

    for id in [1, 3] {
        match db::find_user(id) {
            Some(name) => println!("usuário {id}: {name}"),
            None => println!("usuário {id}: não encontrado"),
        }
    }

    debug!("todas as buscas concluídas");
}

Saída:

usuário 1: Ada
usuário 3: não encontrado

▶ Experimente você mesmo

Alguns filtros que testamos, e o que eles imprimiram no stderr (datas e horas trocadas por …):

$ RUST_LOG=my_app=trace cargo run       # tudo do nosso crate
[… INFO  my_app] servidor iniciando
[… TRACE my_app::db] procurando o usuário 1
[… DEBUG my_app::db] resultado da busca: Some("Ada")
usuário 1: Ada
[… TRACE my_app::db] procurando o usuário 3
[… DEBUG my_app::db] resultado da busca: None
usuário 3: não encontrado
[… DEBUG my_app] todas as buscas concluídas

$ RUST_LOG=my_app::db=debug cargo run   # só o módulo db, de debug para cima
[… DEBUG my_app::db] resultado da busca: Some("Ada")
usuário 1: Ada
[… DEBUG my_app::db] resultado da busca: None
usuário 3: não encontrado

Você pode combinar regras com vírgulas: RUST_LOG=info,my_app::db=trace quer dizer “info para tudo, mas trace para o módulo db”. Uma pequena armadilha: o filtro usa o nome do crate com sublinhados. Um pacote chamado my-app aparece nos logs como my_app.

Definindo um nível padrão no código

Muitas vezes você quer que o info apareça mesmo quando RUST_LOG não está definida. Use env_logger::Builder em vez de init(). Você também pode desligar a data e hora, o que é prático para ferramentas pequenas:

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

fn main() {
    // Mostra `info` e acima, a não ser que RUST_LOG diga outra coisa.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("app iniciado");
    debug!("você só vê isto com RUST_LOG=debug");

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

Saída:

total = 55

▶ Experimente você mesmo

Sem a data e hora, o stderr de verdade do cargo run fica curto e limpo:

[INFO  my_app] app iniciado

Logging estruturado com tracing

O log dá a você linhas de texto. O tracing dá eventos com dados, agrupados em spans (trechos). Ele foi criado pelo time do Tokio, e é o que frameworks web assíncronos como o axum usam. Adicione assim:

cargo add tracing tracing-subscriber

Três ideias para aprender:

• Eventos são como linhas de log: info!, warn! e companhia, com os mesmos nomes do log.
• Campos anexam dados no formato chave = valor: info!(user_id = 42, "login feito"). Ferramentas podem buscar e filtrar por esses campos, em vez de analisar texto.
• Spans descrevem um período de trabalho, como “processando o pedido 7”. Todo evento dentro de um span é marcado com ele.

Assim como o log, o tracing precisa de um subscriber (assinante) para exibir qualquer coisa. O tracing_subscriber::fmt() é o padrão. Uma surpresa: ele escreve no stdout por padrão, então mandamos para o stderr com .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, "login feito");

    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, "carrinho somado");

    if total > 2000 {
        warn!(total, limit = 2000, "pedido precisa de revisão manual");
    }

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

Saída:

total do pedido: 2549

▶ Experimente você mesmo

Este é o stderr da nossa execução (datas e horas trocadas por …, cores removidas):

…  INFO my_app: login feito user_id=42
…  INFO checkout{order_id=7}: my_app: carrinho somado items=3 total=2549
…  WARN checkout{order_id=7}: my_app: pedido precisa de revisão manual total=2549 limit=2000

Viu como as duas últimas linhas começam com checkout{order_id=7}? Esse é o span. Enquanto o _guard estiver vivo, todo evento está “dentro” do checkout. Escrever só total é um atalho para total = total.

#[instrument]: um span para cada chamada

Criar spans na mão cansa. Coloque #[instrument] numa função, e o tracing cria um span para cada chamada, com os argumentos registrados como campos (eles precisam implementar Debug):

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

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "desconto 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, "pronto");
    println!("preço final: {final_price}");
}

Saída:

preço final: 2250

▶ Experimente você mesmo

O stderr da nossa execução:

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

O subscriber fmt() mostra info e acima, a não ser que você diga outra coisa. É por isso que definimos .with_max_level(tracing::Level::DEBUG). Se você quer que o RUST_LOG funcione como no env_logger, ative a feature env-filter e use 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();

Qual escolher?

• Ferramenta de linha de comando pequena ou script? log + env_logger. Configuração mínima, texto simples, pronto.
• Servidor web, código assíncrono ou muitas tarefas ao mesmo tempo? tracing. Os spans registram a qual requisição cada mensagem pertence, mesmo quando centenas rodam ao mesmo tempo.
• Escrevendo uma biblioteca? Use só as macros (log ou tracing) e nunca chame init(). Quem decide como os logs são exibidos é a aplicação.

Você não precisa escolher para sempre. A configuração padrão do tracing-subscriber também captura as mensagens do crate log, então bibliotecas que usam qualquer um dos dois aparecem juntas.

Erros comuns

Esquecer de configurar um logger. Se você nunca chamar env_logger::init() (ou o init() de um subscriber do tracing), as macros compilam sem problema e imprimem… nada. Nenhum erro, nenhum aviso. Se os seus logs sumirem, confira isso primeiro, e depois confira a RUST_LOG.

Chamar init() duas vezes. Só pode existir um logger global. A segunda chamada dá panic. Esta é a mensagem real, que vem em inglês. Ela diz que o env_logger::init não deve ser chamado depois que o logger já foi 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(())

Chame uma vez só, bem no começo do main. Nos testes, use let _ = env_logger::builder().is_test(true).try_init();, que retorna um erro em vez de dar panic.

Descartar o guard do span na mesma hora. let _ = span.enter(); parece inofensivo, mas _ não é um nome de variável: o guard é descartado na mesma linha, e o span termina imediatamente. A nossa execução imprimiu INFO my_app: tratando a requisição sem span nenhum. Dê um nome ao guard, como let _guard = span.enter();, para que ele viva até o fim do escopo.

Resumo

• Use um crate de logging em vez de println! para poder filtrar por nível e manter os logs no stderr, longe da sua saída de verdade.
• O log dá a você error!, warn!, info!, debug!, trace!; o env_logger::init() imprime essas mensagens.
• A RUST_LOG controla o que você vê: RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
• O tracing acrescenta campos estruturados (info!(user_id = 42, "login feito")) e spans; #[instrument] cria um span por chamada de função.
• Bibliotecas usam só as macros; a aplicação configura o logger uma única vez.

Teste o que aprendeu

Teste o que aprendeu

1. Você roda um programa que usa env_logger sem definir RUST_LOG. Quais linhas de log você vê?

Todas Só info! e acima Só error! Nenhuma

2. Onde o env_logger escreve as mensagens de log por padrão?

stdout stderr Num arquivo chamado log.txt

3. O que RUST_LOG=warn mostra?

Só os avisos Os avisos e tudo o que for menos grave Os avisos e os erros

4. O que acontece quando você coloca #[instrument] numa função?

Ela é cronometrada e a duração é impressa Um span é criado para cada chamada, com os argumentos como campos A função roda mais rápido O logging é ativado no programa inteiro

5. Você está escrevendo um crate de biblioteca. O que ele deve fazer em relação a logs?

Usar as macros de logging, mas deixar a aplicação configurar o logger Chamar env_logger::init() quando a biblioteca carregar Usar println! para sempre aparecer

Pontuação: 0 / 5

Para saber mais

• Documentação do crate log (em inglês): as cinco macros e como a fachada funciona, incluindo dicas para quem escreve bibliotecas.
• Documentação do env_logger (em inglês): a sintaxe completa da RUST_LOG e todas as opções do Builder.
• Documentação do tracing (em inglês): spans, eventos, campos e #[instrument] em detalhes.
• Documentação do tracing-subscriber (em inglês): opções de formatação, EnvFilter e saída em JSON.
• Getting started with Tracing — Tokio (em inglês): um passo a passo amigável, feito pelo time que mantém o tracing.