Logging com tracing e tracing-subscriber

1. Introdução ao ecossistema tracing

O ecossistema tracing representa uma evolução significativa no logging para Rust, especialmente projetado para aplicações assíncronas e concorrentes. Diferente do crate log tradicional, que apenas registra eventos pontuais, tracing introduz dois conceitos fundamentais: spans e events.

Spans representam períodos de tempo em uma execução — como o processamento de uma requisição HTTP ou uma consulta ao banco de dados. Eles podem ser aninhados, criando uma árvore de contexto que permite rastrear o fluxo completo de uma operação.

Events são pontos únicos no tempo (como um log tradicional), mas enriquecidos com o contexto dos spans ativos.

Subscribers são os consumidores desses spans e events — eles decidem o que fazer com as informações: imprimir no terminal, escrever em arquivo, ou enviar para sistemas de observabilidade.

Enquanto log é suficiente para aplicações simples, tracing brilha em cenários com concorrência, async/await e sistemas distribuídos, onde o contexto de execução precisa ser preservado através de tasks e threads.

2. Configuração básica com tracing-subscriber

Para começar, adicione as dependências no Cargo.toml:

[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"

O tracing-subscriber fornece implementações prontas de subscribers. O mais comum é o FmtSubscriber, que formata a saída para stdout:

use tracing_subscriber::FmtSubscriber;

fn main() {
    // Inicializa um subscriber com configuração padrão
    let subscriber = FmtSubscriber::builder()
        .with_max_level(tracing::Level::INFO)
        .with_target(true)
        .with_thread_ids(true)
        .with_line_number(true)
        .with_file(true)
        .finish();

    tracing::subscriber::set_global_default(subscriber)
        .expect("Falha ao definir subscriber global");

    tracing::info!("Aplicação iniciada");
}

Para habilitar cores e timestamps formatados:

let subscriber = FmtSubscriber::builder()
    .with_ansi(true)           // cores no terminal
    .with_timer(tracing_subscriber::fmt::time::ChronoLocal::rfc_3339())
    .with_env_filter("info")   // filtro por nível
    .init();                   // atalho para set_global_default

3. Trabalhando com spans e contexto

Spans são criados com a macro info_span! e ativados com span.enter():

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

fn processar_pedido(pedido_id: u64) {
    let span = info_span!("processar_pedido", id = pedido_id);
    let _guard = span.enter();

    info!("Iniciando processamento");

    // Operações do pedido...
    validar_estoque(pedido_id);

    info!("Processamento concluído");
}

fn validar_estoque(pedido_id: u64) {
    let span = info_span!("validar_estoque", pedido_id);
    let _guard = span.enter();

    warn!("Estoque baixo para pedido {}", pedido_id);
}

O atributo #[instrument] automatiza a criação de spans para funções:

use tracing::instrument;

#[instrument(skip(senha), fields(usuario = %nome))]
fn autenticar_usuario(nome: &str, senha: &str) -> bool {
    info!("Tentativa de autenticação");
    nome == "admin" && senha == "1234"
}

Spans herdam automaticamente o contexto do span pai, criando uma hierarquia rastreável.

4. Eventos e níveis de log

As macros de evento seguem a mesma hierarquia do log tradicional:

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

fn processar_dados(dados: &[u8]) {
    trace!("Iniciando processamento em baixo nível"); // só aparece com trace
    debug!("Dados recebidos: {} bytes", dados.len()); // útil para debug
    info!("Processando lote de dados");               // informação normal
    warn!("Buffer quase cheio");                      // aviso
    error!("Falha na validação: {}", err);            // erro crítico
}

Eventos podem incluir campos estruturados:

info!(
    usuario = "joao",
    acao = "login",
    ip = "192.168.1.1",
    duracao_ms = 45,
    "Usuário autenticado com sucesso"
);

Para filtragem dinâmica, use EnvFilter:

use tracing_subscriber::EnvFilter;

let filter = EnvFilter::new("info,meu_crate=debug,reqwest=warn");
let subscriber = FmtSubscriber::builder()
    .with_env_filter(filter)
    .init();

5. Integração com aplicações assíncronas

O tracing se integra perfeitamente com tokio e async/await:

use tokio::time::{sleep, Duration};
use tracing::instrument;

#[instrument]
async fn buscar_usuario(id: u64) -> String {
    sleep(Duration::from_millis(100)).await;
    format!("Usuário {}", id)
}

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

    let usuario = buscar_usuario(42).await;
    info!("Resultado: {}", usuario);
}

Exemplo prático com Axum (servidor HTTP):

use axum::{Router, routing::get, extract::Path};
use tracing::instrument;

#[instrument(skip(state))]
async fn handler_health() -> &'static str {
    "OK"
}

#[instrument(fields(usuario_id = %id))]
async fn handler_usuario(Path(id): Path<u64>) -> String {
    info!("Buscando usuário");
    format!("Usuário {}", id)
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_env_filter("info,axum=debug")
        .init();

    let app = Router::new()
        .route("/health", get(handler_health))
        .route("/usuario/:id", get(handler_usuario));

    axum::Server::bind(&"0.0.0.0:3000".parse().unwrap())
        .serve(app.into_make_service())
        .await
        .unwrap();
}

O tracing propaga automaticamente os spans através de tasks tokio, mantendo o contexto mesmo com tokio::spawn.

6. Saídas avançadas e formatação

Para escrever logs em arquivo, use tracing-appender:

[dependencies]
tracing-appender = "0.2"

use tracing_appender::rolling;

fn main() {
    let file_appender = rolling::daily("/var/log/app", "app.log");
    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

    tracing_subscriber::fmt()
        .with_writer(non_blocking)
        .with_ansi(false)
        .json()  // saída JSON
        .init();

    info!(evento = "inicializacao", "Aplicação iniciou");
}

Para saída JSON personalizada:

tracing_subscriber::fmt()
    .json()
    .with_current_span(true)
    .with_span_list(true)
    .with_timer(tracing_subscriber::fmt::time::UtcTime::rfc_3339())
    .init();

7. Boas práticas e desempenho

Em builds de release, o tracing pode ser completamente removido em tempo de compilação usando feature flags:

[features]
default = ["console-log"]
console-log = ["tracing-subscriber/env-filter"]
release-log = ["tracing-subscriber/json"]

Para evitar overhead, use #[instrument] apenas em funções críticas:

#[instrument(skip_all, fields(resultado))]
fn operacao_custosa() -> u64 {
    // apenas instrumentar funções importantes
}

Gerenciamento de subscribers em testes:

#[cfg(test)]
mod tests {
    use tracing_subscriber::fmt::TestWriter;

    #[test]
    fn test_com_logging() {
        let subscriber = tracing_subscriber::fmt()
            .with_writer(TestWriter::new())
            .with_test_writer()
            .init();

        // testes que produzem logs
    }
}

O tracing foi projetado para ter desempenho excepcional — quando desligado via filtros, os spans e eventos têm custo praticamente zero. Use #[instrument] liberalmente em desenvolvimento e refine os filtros em produção.

Com tracing, você obtém observabilidade profunda sem sacrificar desempenho, tornando suas aplicações Rust mais fáceis de depurar e monitorar.

Referências