La journalisation (logging) en Rust avec log et tracing

Quand quelque chose tourne mal dans un programme, vous voulez savoir ce qu’il était en train de faire juste avant. C’est à ça que sert la journalisation (en anglais, logging). Un journal (un log), c’est comme le journal de bord d’un navire : de courtes notes, chacune avec une heure et un niveau d’importance, que vous pouvez relire plus tard pour comprendre ce qui s’est passé.

Vous pourriez semer des println! partout, mais vous en atteindriez vite les limites. Impossible de les désactiver sans modifier le code. Impossible de dire « montre-moi seulement les avertissements ». Et ils mélangent vos notes de débogage avec la vraie sortie du programme. Les crates de journalisation de Rust règlent ces trois problèmes. Sur cette page, vous allez découvrir les deux plus populaires : log (avec env_logger) et tracing.

Pourquoi pas simplement println! ?

Voici la différence en un coup d’œil :

	println!	un crate de journalisation
L’activer ou le désactiver sans recompiler	Non	Oui, avec la variable RUST_LOG
Des niveaux (error, warn, info, …)	Non	Oui
Indique d’où vient le message	Non	Oui (le nom du module)
Où ça s’affiche	stdout	stderr par défaut (env_logger)

La dernière ligne compte plus qu’il n’y paraît. stdout (la sortie standard) contient le vrai résultat de votre programme, celui qu’on peut rediriger vers un fichier ou vers un autre programme. stderr (la sortie d’erreur) est le canal à part pour les messages à propos de l’exécution. Les logs ont leur place sur stderr : ainsi, my_app > result.txt n’enregistre que le résultat, et les logs s’affichent toujours dans le terminal.

La façade log et env_logger

Le crate log vous donne cinq macros, une par niveau, du plus grave au moins grave : error!, warn!, info!, debug! et trace!. Elles s’utilisent exactement comme println!, avec le même formatage {}.

Mais log, à lui seul, n’affiche rien. C’est une façade : un ensemble standard de macros que toutes les bibliothèques peuvent utiliser, sans choisir comment les messages seront affichés. C’est votre application qui choisit un logger, chargé de les écrire pour de vrai. Le plus simple s’appelle env_logger. Ajoutez les deux à votre projet :

cargo add log env_logger

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

Appelez maintenant env_logger::init() une seule fois, au début de main, et journalisez à volonté :

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

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide appelée avec a={a}, b={b}");
    if b == 0.0 {
        warn!("refus de diviser {a} par zéro");
        return None;
    }
    Some(a / b)
}

fn main() {
    env_logger::init();
    info!("démarrage de la calculatrice");

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

    error!("voici à quoi ressemble une ligne d'erreur");
}

Sortie :

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

▶ Essayez par vous-même

La sortie ci-dessus ne montre que stdout, le vrai résultat du programme. Les lignes de log partent sur stderr. Dans le Playground, elles apparaissent dans la zone séparée « Standard Error ».

Remarquez une chose : par défaut, env_logger n’affiche que les erreurs. Pour en voir davantage, définissez la variable d’environnement RUST_LOG quand vous lancez le programme. Voici stderr et stdout mélangés, tels qu’ils sont apparus quand nous l’avons lancé dans un terminal avec RUST_LOG=debug cargo run (nous avons remplacé chaque horodatage par … ; chez vous, vous verrez la date et l’heure actuelles) :

[… INFO  my_app] démarrage de la calculatrice
[… DEBUG my_app] divide appelée avec a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide appelée avec a=1, b=0
[… WARN  my_app] refus de diviser 1 par zéro
1 / 0 = None
[… ERROR my_app] voici à quoi ressemble une ligne d'erreur

Chaque ligne de log indique le niveau et le module d’où elle vient (my_app, le nom du crate). Les lignes simples, sans crochets, viennent de println!.

Choisir ce que vous voyez avec RUST_LOG

Un niveau affiche ce niveau et tout ce qui est plus grave. Donc RUST_LOG=warn affiche les avertissements et les erreurs ; RUST_LOG=trace affiche tout.

RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # seulement warn et error
RUST_LOG=off cargo run       # aucun log

Sous Windows PowerShell, définissez d’abord la variable : $env:RUST_LOG="debug"; cargo run.

Vous pouvez aussi filtrer par module. C’est très utile quand une bibliothèque est trop bavarde, ou quand seule une partie de votre code vous intéresse. Voici un programme avec un module db :

use log::{debug, info};

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

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("recherche de l'utilisateur {id}");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("résultat de la recherche : {name:?}");
        name
    }
}

fn main() {
    env_logger::init();
    info!("démarrage du serveur");

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

    debug!("toutes les recherches sont terminées");
}

Sortie :

utilisateur 1 : Ada
utilisateur 3 : introuvable

▶ Essayez par vous-même

Quelques filtres que nous avons essayés, et ce qu’ils ont écrit sur stderr (horodatages remplacés par …) :

$ RUST_LOG=my_app=trace cargo run       # tout ce qui vient de notre crate
[… INFO  my_app] démarrage du serveur
[… TRACE my_app::db] recherche de l'utilisateur 1
[… DEBUG my_app::db] résultat de la recherche : Some("Ada")
utilisateur 1 : Ada
[… TRACE my_app::db] recherche de l'utilisateur 3
[… DEBUG my_app::db] résultat de la recherche : None
utilisateur 3 : introuvable
[… DEBUG my_app] toutes les recherches sont terminées

$ RUST_LOG=my_app::db=debug cargo run   # seulement le module db, debug et au-dessus
[… DEBUG my_app::db] résultat de la recherche : Some("Ada")
utilisateur 1 : Ada
[… DEBUG my_app::db] résultat de la recherche : None
utilisateur 3 : introuvable

Vous pouvez combiner plusieurs règles avec des virgules : RUST_LOG=info,my_app::db=trace veut dire « info pour tout le monde, mais trace pour le module db ». Un petit piège : le filtre utilise le nom du crate avec des tirets bas. Un paquet appelé my-app journalise sous le nom my_app.

Définir un niveau par défaut dans le code

Souvent, vous voulez que les messages info s’affichent même quand RUST_LOG n’est pas défini. Utilisez env_logger::Builder au lieu de init(). Vous pouvez aussi supprimer l’horodatage, ce qui est pratique pour les petits outils :

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

fn main() {
    // Affiche `info` et au-dessus, sauf si RUST_LOG dit autre chose.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("application démarrée");
    debug!("vous ne voyez ceci qu'avec RUST_LOG=debug");

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

Sortie :

total = 55

▶ Essayez par vous-même

Sans horodatage, le vrai stderr de cargo run est court et net :

[INFO  my_app] application démarrée

Une journalisation structurée avec tracing

log vous donne des lignes de texte. tracing vous donne des événements avec des données, regroupés dans des spans (des intervalles de travail). Il a été créé par l’équipe de Tokio, et c’est lui qu’utilisent les frameworks web async comme axum. Ajoutez-le comme ceci :

cargo add tracing tracing-subscriber

Trois idées à retenir :

• Les événements ressemblent aux lignes de log : info!, warn! et compagnie, avec les mêmes noms que dans log.
• Les champs attachent des données sous la forme clé = valeur : info!(user_id = 42, "connexion réussie"). Les outils peuvent chercher et filtrer sur ces champs, au lieu de décortiquer du texte.
• Les spans décrivent une période de travail, comme « traitement de la commande 7 ». Chaque événement à l’intérieur d’un span est étiqueté avec lui.

Comme log, tracing a besoin d’un subscriber (un abonné) pour afficher quoi que ce soit. tracing_subscriber::fmt() est le subscriber standard. Une surprise : il écrit sur stdout par défaut, donc nous l’envoyons vers stderr avec .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, "connexion réussie");

    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, "panier calculé");

    if total > 2000 {
        warn!(total, limit = 2000, "commande à vérifier à la main");
    }

    println!("total de la commande : {total}");
}

Sortie :

total de la commande : 2549

▶ Essayez par vous-même

Voici le stderr de notre exécution (horodatages remplacés par …, couleurs retirées) :

…  INFO my_app: connexion réussie user_id=42
…  INFO checkout{order_id=7}: my_app: panier calculé items=3 total=2549
…  WARN checkout{order_id=7}: my_app: commande à vérifier à la main total=2549 limit=2000

Vous voyez que les deux dernières lignes commencent par checkout{order_id=7} ? C’est le span (checkout veut dire « passage en caisse »). Tant que _guard est vivant, chaque événement se trouve « à l’intérieur » du checkout. Écrire simplement total est un raccourci pour total = total.

#[instrument] : un span pour chaque appel

Créer des spans à la main devient vite lassant. Mettez #[instrument] sur une fonction, et tracing crée un span à chaque appel, en enregistrant les arguments comme champs (ils doivent implémenter Debug) :

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

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "remise calculée");
    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, "terminé");
    println!("prix final : {final_price}");
}

Sortie :

prix final : 2250

▶ Essayez par vous-même

Le stderr de notre exécution :

… DEBUG apply_discount{price=2500 percent=10}: my_app: remise calculée off=250
…  INFO my_app: terminé final_price=2250

Le subscriber fmt() affiche info et au-dessus, sauf si vous lui dites autre chose : c’est pour ça que nous avons mis .with_max_level(tracing::Level::DEBUG). Si vous voulez que RUST_LOG fonctionne comme avec env_logger, activez la feature env-filter et utilisez 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();

Lequel choisir ?

• Un petit outil en ligne de commande ou un script ? log + env_logger. Une installation minuscule, du texte simple, et c’est réglé.
• Un serveur web, du code async, ou beaucoup de tâches en même temps ? tracing. Les spans permettent de savoir à quelle requête appartient un message, même quand des centaines s’exécutent en même temps.
• Vous écrivez une bibliothèque ? Utilisez seulement les macros (log ou tracing) et n’appelez jamais init(). C’est l’application qui décide comment les logs sont affichés.

Ce choix n’est pas définitif. La configuration par défaut de tracing-subscriber récupère aussi les messages du crate log : les bibliothèques qui utilisent l’un ou l’autre s’affichent donc ensemble.

Erreurs courantes

Oublier de mettre en place un logger. Si vous n’appelez jamais env_logger::init() (ou le init() d’un subscriber tracing), les macros compilent sans problème et n’affichent… rien. Ni erreur, ni avertissement. Si vos logs disparaissent, vérifiez d’abord ce point, puis vérifiez RUST_LOG.

Appeler init() deux fois. Il ne peut y avoir qu’un seul logger global. Le deuxième appel provoque une panic. Voici le vrai message :

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

Le message vient d’env_logger et dit qu’init ne doit pas être appelé une fois le logger initialisé. Appelez-le une seule fois, tout en haut de main. Dans les tests, utilisez let _ = env_logger::builder().is_test(true).try_init();, qui renvoie une erreur au lieu de provoquer une panic.

Laisser tomber le guard du span tout de suite. let _ = span.enter(); a l’air inoffensif, mais _ n’est pas un nom de variable : le guard est libéré sur la même ligne, et le span se termine immédiatement. Notre exécution a affiché INFO my_app: traitement de la requête, sans aucun span. Donnez un nom au guard, comme let _guard = span.enter();, pour qu’il vive jusqu’à la fin de la portée.

Récapitulatif

• Utilisez un crate de journalisation plutôt que println! : vous pouvez filtrer par niveau et garder les logs sur stderr, à l’écart de votre vraie sortie.
• log vous donne error!, warn!, info!, debug! et trace! ; env_logger::init() les affiche.
• RUST_LOG contrôle ce que vous voyez : RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
• tracing ajoute des champs structurés (info!(user_id = 42, "connexion réussie")) et des spans ; #[instrument] crée un span à chaque appel de fonction.
• Les bibliothèques se contentent des macros ; l’application met en place le logger, une seule fois.

Petit quiz

Petit quiz

1. Vous lancez un programme qui utilise env_logger sans définir RUST_LOG. Quelles lignes de log voyez-vous ?

Toutes Seulement info! et au-dessus Seulement error! Aucune

2. Où env_logger écrit-il les messages de log par défaut ?

stdout stderr Dans un fichier appelé log.txt

3. Qu'affiche RUST_LOG=warn ?

Seulement les avertissements Les avertissements et tout ce qui est moins grave Les avertissements et les erreurs

4. Que fait #[instrument] placé sur une fonction ?

Il chronomètre la fonction et affiche la durée Il crée un span à chaque appel, avec les arguments comme champs Il rend la fonction plus rapide Il active les logs dans tout le programme

5. Vous écrivez un crate de bibliothèque. Que doit-il faire pour les logs ?

Utiliser les macros de journalisation, mais laisser l'application mettre en place le logger Appeler env_logger::init() au chargement de la bibliothèque Utiliser println! pour que ça s'affiche toujours

Score : 0 / 5

Pour aller plus loin

• Documentation du crate log (en anglais) : les cinq macros et le fonctionnement de la façade, avec des conseils pour les auteurs de bibliothèques.
• Documentation d’env_logger (en anglais) : la syntaxe complète de RUST_LOG et toutes les options de Builder.
• Documentation de tracing (en anglais) : les spans, les événements, les champs et #[instrument] en détail.
• Documentation de tracing-subscriber (en anglais) : les options de formatage, EnvFilter et la sortie JSON.
• Getting started with Tracing — Tokio (en anglais) : une présentation accessible, par l’équipe qui maintient tracing.