Salta ai contenuti
Ferris the Rust crabTutorial Rust

Logging in Rust con log e tracing

Quando qualcosa va storto in un programma, vuoi sapere cosa stava facendo subito prima. A questo serve il logging. Un log è come il giornale di bordo di una nave: brevi annotazioni, ognuna con un’ora e un livello di importanza, che puoi rileggere dopo per capire cos’è successo.

Potresti spargere println! ovunque, ma ne incontreresti presto i limiti. Non puoi spegnerli senza modificare il codice. Non puoi dire «mostrami solo gli avvisi». E mescolano le tue note di debug con l’output vero del programma. I crate di logging di Rust risolvono tutti e tre i problemi. In questa pagina imparerai i due più diffusi: log (con env_logger) e tracing.

Perché non usare semplicemente println!?

Sezione intitolata “Perché non usare semplicemente println!?”

Ecco la differenza in un colpo d’occhio:

println! un crate di logging
Accenderlo/spegnerlo senza ricompilare No Sì, con la variabile RUST_LOG
Livelli (error, warn, info, …) No Sì
Mostra da dove arriva il messaggio No Sì (il nome del modulo)
Dove finisce stdout stderr di default (env_logger)

L’ultima riga conta più di quanto sembri. stdout è il risultato vero del programma, quello che qualcuno potrebbe reindirizzare in un file o in un altro programma. stderr è il canale secondario per i messaggi sull’esecuzione. I log vanno su stderr, così my_app > result.txt salva solo il risultato, mentre i log continuano a comparire nel terminale.

La facciata log ed env_logger

Sezione intitolata “La facciata log ed env_logger”

Il crate log ti dà cinque macro, una per livello, dalla più grave alla meno grave: error!, warn!, info!, debug! e trace!. Funzionano proprio come println!, con la stessa formattazione {}.

Ma log da solo non stampa niente. È una facciata (facade): un insieme standard di macro che ogni libreria può usare, senza scegliere come vengono mostrati i messaggi. È la tua applicazione a scegliere un logger che li scrive davvero. Il più semplice è env_logger. Aggiungili entrambi al progetto:

Terminal window
cargo add log env_logger
[dependencies]
log = "0.4"
env_logger = "0.11"

Ora chiama env_logger::init() una volta, all’inizio di main, e scrivi pure i tuoi log. (I messaggi di log restano in inglese in tutta la pagina, perché più sotto vedrai l’output reale su stderr che li contiene.)

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


fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide called with a={a}, b={b}");
    if b == 0.0 {
        warn!("refusing to divide {a} by zero");
        return None;
    }
    Some(a / b)
}


fn main() {
    env_logger::init();
    info!("calculator starting");


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


    error!("this is what an error line looks like");
}

Output:

10 / 4 = Some(2.5)
1 / 0 = None
▶ Provalo tu

L’output qui sopra è solo lo stdout, cioè il risultato vero del programma. Le righe di log vanno su stderr. Nel Playground compaiono nell’area separata «Standard Error».

Nota una cosa: di default env_logger mostra solo gli errori. Per vedere di più, imposta la variabile d’ambiente RUST_LOG quando esegui il programma. Ecco come apparivano insieme stderr e stdout quando l’abbiamo eseguito in un terminale con RUST_LOG=debug cargo run (abbiamo sostituito ogni timestamp con …; il tuo mostrerà la data e l’ora attuali):

[… INFO  my_app] calculator starting
[… DEBUG my_app] divide called with a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide called with a=1, b=0
[… WARN  my_app] refusing to divide 1 by zero
1 / 0 = None
[… ERROR my_app] this is what an error line looks like

Ogni riga di log mostra il livello e il modulo da cui arriva (my_app, il nome del crate). Le righe semplici, senza parentesi quadre, sono l’output di println!.

Scegliere cosa vedere con RUST_LOG

Sezione intitolata “Scegliere cosa vedere con RUST_LOG”

Un livello mostra quel livello e tutti quelli più gravi. Quindi RUST_LOG=warn mostra avvisi ed errori; RUST_LOG=trace mostra tutto.

Terminal window
RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # solo warn ed error
RUST_LOG=off cargo run       # nessun log

Su Windows PowerShell, imposta prima la variabile: $env:RUST_LOG="debug"; cargo run.

Puoi anche filtrare per modulo. È ottimo quando una libreria è troppo chiacchierona, o quando ti interessa solo una parte del codice. Ecco un programma con un modulo db:

use log::{debug, info};


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


    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("looking up user {id}");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("lookup result: {name:?}");
        name
    }
}


fn main() {
    env_logger::init();
    info!("server starting");


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


    debug!("all lookups done");
}

Output:

user 1: Ada
user 3: not found
▶ Provalo tu

Alcuni filtri che abbiamo provato, e cosa hanno stampato su stderr (timestamp sostituiti con …):

$ RUST_LOG=my_app=trace cargo run       # everything from our crate
[… INFO  my_app] server starting
[… TRACE my_app::db] looking up user 1
[… DEBUG my_app::db] lookup result: Some("Ada")
user 1: Ada
[… TRACE my_app::db] looking up user 3
[… DEBUG my_app::db] lookup result: None
user 3: not found
[… DEBUG my_app] all lookups done


$ RUST_LOG=my_app::db=debug cargo run   # only the db module, debug and up
[… DEBUG my_app::db] lookup result: Some("Ada")
user 1: Ada
[… DEBUG my_app::db] lookup result: None
user 3: not found

Il primo filtro mostra tutto ciò che arriva dal nostro crate; il secondo solo il modulo db, da debug in su. Puoi combinare più regole con le virgole: RUST_LOG=info,my_app::db=trace significa «info per tutto, ma trace per il modulo db». Una piccola trappola: il filtro usa il nome del crate con i trattini bassi. Un pacchetto chiamato my-app scrive i log come my_app.

Impostare un livello predefinito nel codice

Sezione intitolata “Impostare un livello predefinito nel codice”

Spesso vuoi che info venga mostrato anche quando RUST_LOG non è impostata. Usa env_logger::Builder invece di init(). Puoi anche togliere il timestamp, comodo per gli strumenti brevi:

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


fn main() {
    // Mostra `info` e superiori, a meno che RUST_LOG non dica altro.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();


    info!("app started");
    debug!("you only see this with RUST_LOG=debug");


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

Output:

totale = 55
▶ Provalo tu

Senza timestamp, lo stderr reale di cargo run è corto e pulito:

[INFO  my_app] app started

Logging strutturato con tracing

Sezione intitolata “Logging strutturato con tracing”

log ti dà righe di testo. tracing ti dà eventi con dati, raggruppati in span. È stato creato dal team di Tokio, ed è quello che usano i framework web asincroni come axum. Aggiungilo così:

Terminal window
cargo add tracing tracing-subscriber

Tre idee da imparare:

  • Gli eventi sono come le righe di log: info!, warn! e compagnia, con gli stessi nomi di log.
  • I campi (field) aggiungono dati nella forma chiave = valore: info!(user_id = 42, "logged in"). Gli strumenti possono cercare e filtrare su questi campi, invece di analizzare il testo.
  • Gli span descrivono un periodo di lavoro, come «gestione dell’ordine 7». Ogni evento dentro uno span viene etichettato con esso.

Come log, anche tracing ha bisogno di un subscriber per mostrare qualcosa. tracing_subscriber::fmt() è quello standard. Una sorpresa: di default scrive su stdout, quindi lo mandiamo su 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, "logged in");


    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, "cart totalled");


    if total > 2000 {
        warn!(total, limit = 2000, "order needs manual review");
    }


    println!("totale dell'ordine: {total}");
}

Output:

totale dell'ordine: 2549
▶ Provalo tu

Ecco lo stderr della nostra esecuzione (timestamp sostituiti con …, colori rimossi):

…  INFO my_app: logged in user_id=42
…  INFO checkout{order_id=7}: my_app: cart totalled items=3 total=2549
…  WARN checkout{order_id=7}: my_app: order needs manual review total=2549 limit=2000

Vedi come le ultime due righe iniziano con checkout{order_id=7}? Quello è lo span. Finché _guard è vivo, ogni evento sta «dentro» il checkout. Scrivere solo total è un’abbreviazione di total = total.

#[instrument]: uno span per ogni chiamata

Sezione intitolata “#[instrument]: uno span per ogni chiamata”

Creare gli span a mano diventa presto faticoso. Metti #[instrument] su una funzione, e tracing crea uno span per ogni chiamata, registrando gli argomenti come campi (devono implementare Debug):

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


#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "discount computed");
    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, "done");
    println!("prezzo finale: {final_price}");
}

Output:

prezzo finale: 2250
▶ Provalo tu

Lo stderr della nostra esecuzione:

… DEBUG apply_discount{price=2500 percent=10}: my_app: discount computed off=250
…  INFO my_app: done final_price=2250

Il subscriber fmt() mostra info e superiori, a meno che tu non gli dica altro: ecco perché abbiamo impostato .with_max_level(tracing::Level::DEBUG). Se vuoi che RUST_LOG funzioni come con env_logger, attiva la feature env-filter e 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();

Quale scegliere?

Sezione intitolata “Quale scegliere?”
  • Piccolo strumento da riga di comando o script? log + env_logger. Configurazione minima, testo semplice, fatto.
  • Server web, codice asincrono o tanti task contemporaneamente? tracing. Gli span tengono traccia di a quale richiesta appartiene un messaggio, anche quando ne girano centinaia nello stesso momento.
  • Stai scrivendo una libreria? Usa solo le macro (log o tracing) e non chiamare mai init(). È l’applicazione a decidere come mostrare i log.

Non devi scegliere per sempre. La configurazione predefinita di tracing-subscriber raccoglie anche i messaggi del crate log, quindi le librerie che usano l’uno o l’altro compaiono insieme.

Errori comuni

Sezione intitolata “Errori comuni”

Dimenticare di configurare un logger. Se non chiami mai env_logger::init() (o l’init() di un subscriber di tracing), le macro compilano senza problemi e stampano… niente. Nessun errore, nessun avviso. Se i tuoi log spariscono, controlla prima questo, e poi RUST_LOG.

Chiamare init() due volte. Può esserci un solo logger globale. La seconda chiamata va in panic. Questo è il messaggio reale:

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(())

Il panic dice che env_logger::init non va chiamato dopo che il logger è già stato inizializzato. Chiamalo una volta sola, in cima a main. Nei test usa let _ = env_logger::builder().is_test(true).try_init();, che restituisce un errore invece di andare in panic.

Distruggere subito la guardia dello span. let _ = span.enter(); sembra innocuo, ma _ non è un nome di variabile: la guardia viene distrutta sulla stessa riga, quindi lo span finisce subito. La nostra esecuzione ha stampato INFO my_app: handling request senza nessuno span. Dai un nome alla guardia, come let _guard = span.enter();, così vive fino alla fine dello scope.

Sezione intitolata “Riepilogo”
  • Usa un crate di logging invece di println!, così puoi filtrare per livello e tenere i log su stderr, lontani dal tuo output vero.
  • log ti dà error!, warn!, info!, debug!, trace!; env_logger::init() li stampa.
  • RUST_LOG decide cosa vedi: RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
  • tracing aggiunge campi strutturati (info!(user_id = 42, "logged in")) e span; #[instrument] crea uno span per ogni chiamata di funzione.
  • Le librerie usano solo le macro; l’applicazione configura il logger una volta sola.

Verifica veloce

Sezione intitolata “Verifica veloce”

Verifica veloce

1. Esegui un programma che usa env_logger senza impostare RUST_LOG. Quali righe di log vedi?

2. Dove scrive i messaggi di log env_logger di default?

3. Cosa mostra RUST_LOG=warn?

4. Cosa fa mettere #[instrument] su una funzione?

5. Stai scrivendo un crate di libreria. Cosa dovrebbe fare per il logging?

Punteggio: 0 / 5

Per approfondire

Sezione intitolata “Per approfondire”