Cartouche

Introduction

console.log("aaaaa"), println!("b"), eprintln!("wtf?"), dbg!(users) vos projets en sont probablement jonchés, et ce probablement pour de bonnes raisons. Vous voulez comprendre ce qu’il se passe dans votre code.

Le problème c’est qu’après, vos sorties standard et d’erreur ne ressemblent à rien. Donc avant de ship on passe un coup de Kärcher.

Et si je vous disais qu’il existe un monde meilleur auquel on peut s’élever ? Un monde où vous pourriez avoir la plus propre des sorties mais aussi toutes les informations qu’il vous faut pour comprendre ce qu’il se passe dans votre projet. Un monde où vous n’auriez même pas besoin de choisir quoi écrire dans vos logs. Me croiriez-vous ?

Découvrez donc : tracing, un framework pour l’émission et le ramassage d’événements qui se produisent à l’intérieur d’une application.

Tracing ce n’est pas juste des fonctions de produire des logs textuels, nan nan nan nan, c’est tout un framework qui permet d’associer un contexte riche à des événements qui se produisent dans vos programmes.

~ Augustin Heliot (dans ma tête)

crates

Ce sujet a été écrit avec les crates aux versions et features qui suivent :

tracing = "0.1.44"
tracing-subscriber = { version = "0.3.23", features = ["env-filter", "json"] }

Produire un événement tracing

Au lieu d’utiliser println! ou eprintln! on va utiliser des macros de tracing comme :

• error! pour rapporter une erreur ;
• warn! pour émettre un avertissement ;
• info! pour simplement dire ce qu’il se passe actuellement ;
• debug pour des logs rarement nécessaires sauf pour déterminer sur le programme à un bug ;
• trace pour les situation les plus extrêmes, les plus petits détails qui la plupart du temps ne sont même pas utiles au débugage.

Voici un exemple de ce que l’on peut écrire avec tracing :

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

struct Point2d {
    x: usize,
    y: usize,
}

impl std::fmt::Display for Point2d {
    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
        write!(f, "({}, {})", self.x, self.y)
    }
}

#[tokio::main]
async fn main() {
    info!("hello");
    let words = vec!["hello", "world", "this", "is", "me"];
    info!(?words, "words are ready");
    
    let player_pos = Point2d { x: 12, y: 46 };
    error!(%player_pos, "out of bound!");
}

S’il s’agissait d’une librairie, c’est tout ce que l’on aurait à faire pour produire des logs, mais ça n’est pas suffisant si on souhaite les voir ou les exploiter.

Afficher des événements Tracing

Pour ramasser des événements produits par Tracing on utilise fmt, un ramasseur d’événement dont le but est de les formatter pour les afficher.

tracing_subscriber::fmt()
	.with_max_level(tracing::Level::TRACE)
	.init();

L’utiliser avec init l’active comme ramasseur par défaut. Il faut l’utiliser seulement lorsqu’on écrit son propre main et pas une librairie.

Si des événements sont produit avant cet appel, ils ne seront pas affichés.

Ajouter des champs aux événements

Vous avez peut-être remarqué des syntaxes particulières dans l’exemple de production d’événements, on va les étudier ici.

Premièrement on peut utiliser les macros d’émission comme on utiliserait fmt :

info!("hello");
info!("hello {my_printable_variable}");
info!("hello {}", my_printable_variable);
info!("hello {:?}", my_debugable_struct);

Mais on peut aussi profiter de nos variables pour y accrocher du contexte plutôt que de juste générer une chaîne de caractère.

info!(%my_printable_variable, "hello");
info!(?my_debugable_struct, "hello");

Ces syntaxes là vont ajouter un champ à l’événement qui de base n’a qu’un message.

Voici une comparaison entre l’utilisation d’une chaîne de format ou l’ajout d’un field avec des logs produits en json, plutôt que de façon textuelle :

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

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::TRACE)
        .json()
        .init();
    let my_num = 67;
    info!("hello {my_num}");
    info!("hello {}", my_num);
    info!(my_num, "hello");
}

Sortie standard :

{"timestamp":"2026-03-26T08:40:04.604110Z","level":"INFO","fields":{"message":"hello 67"},"target":"fields"}
{"timestamp":"2026-03-26T08:40:04.604363Z","level":"INFO","fields":{"message":"hello 67"},"target":"fields"}
{"timestamp":"2026-03-26T08:40:04.604420Z","level":"INFO","fields":{"message":"hello","my_num":67},"target":"fields"}

On y constate que les deux premiers événements ne contiennent qu’un seul field : message. Le 3ème lui contient un field my_num en plus.

On peut nommer un champ en faisant :

info!(my_super_event_field = my_num, "hello");

{"timestamp":"2026-03-26T08:47:24.481146Z","level":"INFO","fields":{"message":"hello","my_super_event_fild":67},"target":"fields"}

Enfin, voyons pourquoi dans certains exemple j’emploie un ? ou un % devant les variables que j’utilise pour mes champs :

• ? indique à Tracing qu’il faut utiliser le trait Debug de la variable pour remplir le champ (pratique sur des structures) ; et
• % lui indique qu’il faut utiliser le trait std::fmt::Display pour remplie le champ.

Ce qui nous donne les clés pour comprendre toutes les syntaxes de cet exemple :

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

#[derive(Debug)]
struct User {
    login: &'static str,
    display_name: &'static str,
}

impl std::fmt::Display for User {
    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
        write!(f, "{}: \"{}\"", self.login, self.display_name)
    }
}

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::TRACE)
        .json()
        .init();
    let user_elise = User {
        login: "eriizu",
        display_name: "Élise C. Philippe",
    };
    info!("hello {}", user_elise);
    info!("hello {:?}", user_elise);
    info!(my_super_struct = %user_elise, "hello");
    info!(my_super_struct = ?user_elise, "hello");
}

Faites l’exercice : déterminez par vous-même, sans exécuter le code, les champs et leur contenu pour les 4 événements de cet exemple.

Cible des événements

Explications

Vous avez peut-être remarqué la valeur target sur les événements que nous avons produit jusqu’à maintenant. Il s’agit d’un identifiant qui permet de savoir qui a produit ce log. La target commence en général par le nom du crate. C’est pratique pour différencier les logs produit par votre programme ou ses dépendances

Par défaut lorsqu’on active un tracing_subscriber, il va capturer et afficher tous les événements produits, par vous, comme par vos dépendances.

En ajoutant un EnvFilter au subscriber on va pouvoir exprimer dans une variable d’environnement quels événements nous intéressent. La variable d’environnement s’écrit :

RUST_LOG=target_name=log_level,other_target=other_log_level

Si on est dans un projet “patate” et qu’on ne veut que log ses événements, on peut écrire :

• au niveau par défaut : RUST_LOG=patate cargo run ;
• au niveau debug : RUST_LOG=patate=debug cargo run.

Si ce projet patate se sert d’un librairie comme lab_tracing_20230318 dont on veut les logs info:

• RUST_LOG=patate=debug,lab_tracing_20230318=info.

Manipulation

Dans un dossier faites :

git clone https://git.ecole-89.com/eriizu/20260318_lab_tracing.git lab_tracing
cargo create patate
cd patate

Modifiez le Cargo.toml de sorte qu’il contienne :

[package]
name = "patate"
version = "0.1.0"
edition = "2024"

[dependencies]
anyhow = "1.0.102"
lab_tracing_20260318 = { version = "0.1.0", path = "../lab_tracing" }
tokio = { version = "1.50.0", features = ["full"] }
tracing = "0.1.44"
tracing-subscriber = { version = "0.3.23", features = ["env-filter", "json"] }

Modifiez maintenant le main.rs :

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

#[tokio::main]
async fn main() {
    use tracing_subscriber::filter::{EnvFilter, LevelFilter};

    let env_filter = EnvFilter::builder()
        .with_default_directive(LevelFilter::INFO.into())
        .from_env()
        .expect("RUST_LOG directive must be correct");
    tracing_subscriber::fmt()
        .with_env_filter(env_filter)
        .pretty()
        // .json()
        .init();
    trace!("this is an example trace");
    debug!("this is an example debug");
    info!("about to start lab tracing server");
    warn!("this is an example warning");
    error!("this is an example error");
    lab_tracing_20260318::run().await.unwrap();
}

Vous pouvez essayer de modifier les messages qui s’affichent en modifiant ce que vous mettez dans RUST_LOG au moment de cargo run.

Alternative de main avec anyhow

use anyhow::Context as _;
use tracing::{error, warn, info, debug, trace};

#[tokio::main]
async fn main() -> anyhow::Result<()> {
    use tracing_subscriber::filter::{EnvFilter, LevelFilter};

    let env_filter = EnvFilter::builder()
        .with_default_directive(LevelFilter::INFO.into())
        .from_env()
        .context("building tracing env filter")?;
    tracing_subscriber::fmt()
        .with_env_filter(env_filter)
        .pretty()
        // .json()
        .init();
    trace!("this is an example trace");
    debug!("this is an example debug");
    info!("about to start lab tracing server");
    warn!("this is an example warning");
    error!("this is an example error");
    lab_tracing_20260318::run().await.context("runing server")?;
    Ok(())
}

Portées et instruments

Avec Tracing, les événements peuvent avoir lieu dans des portées. Une portée c’est un nom et un ensemble de champs qui s’appliquent à tous les logs produits en son sein.

Cela nous permet d’associer à des logs le contexte dans lequel ils ont eu lieu.

Pourquoi c’est utile ? Imaginez un burger. Imaginez une API. Un log d’erreur apparaît : “failed to encode value: Guðrún”. Votre serveur renvoie 500 à l’utilisateur. Une investigation commence :

• c’était une requête de création, de modification ?
• c’était le nom de quelqu’un sur son profil ?
• c’était le nom de sa ville dans son adresse ?
• on est sur un encodage manuel ou un bind ?
• l’utilisateur était connecté ? Si oui qui est-ce que c’était ?
• est-ce qu’il y a d’autres données qui sont utiles à comprendre ce qu’il s’est passé ?

C’est ce genre de situation qui peut provoquer la prolifération de dbg! et de println! avec de plus en plus de données, sans que ça soit pour autant facile à lire.

L’avantage de générer événements structurés avec des informations de contexte c’est que l’on peut regrouper touts les événements qui ont un rapport les uns avec les autres, et trouver un problème sans avoir de difficultés à le reproduire, ou sans même avoir besoin de le reproduire.

Les portées les plus faciles à créer sont celles qui touchent aux fonctions, grâce à une superbe macro : instrument.

Les fonctions peuvent être décorées par instrument, ainsi :

#[instrument(skip(game))]
fn slay_and_move_forward(game: &mut GameWorld, turn_id: usize) {
    game.player_slay_enemy();
    if let Err(err) = game.player_move_forward(1) {
        error!(%err, "stoping");
        panic!();
    }
}

Cette fonction contient un log error!, qui fait partie portée slay_and_move_forward avec pour seul champ le paramètre turn_id. L’autre paramètre game est skip, de façon arbitraire, parce qu’il ne m’intéressait pas dans ce contexte. Ce log peut produire :

  2026-03-26T14:47:54.709314Z ERROR world: stoping, err: position is out of bounds
    at examples/world.rs:89
    in world::slay_and_move_forward with turn_id: 4

Ou en JSON :

{
    "timestamp":"2026-03-26T14:56:25.850393Z",
    "level":"ERROR",
    "fields":{"message":"stoping","err":"position is out of bounds"},
    "target":"world",
    "span":{"turn_id":4,"name":"slay_and_move_forward"},
    "spans":[{"turn_id":4,"name":"slay_and_move_forward"}]
}

Mais là où les choses deviennent intéressantes, c’est dans les fonctions appelées par slay_and_move_forward :

    #[instrument(err)]
    fn player_move_forward(&mut self, distance: usize) -> Result<Point2d, GameError> {
        let mut new_pos = self.player_pos.clone();
        new_pos.x = new_pos.x + distance;
        trace!(%new_pos, "trying to move");
        
        if new_pos.x < self.map_size.x {
            self.player_pos = new_pos;
            info!(player_pos = %self.player_pos, "updated");
            
            if self.enemies.contains(&self.player_pos) {
                Err(GameError::PlayerDead)
            } else {
                Ok(self.player_pos.clone())
            }
        } else {
            Err(GameError::MoveOOB)
        }
    }

player_move_forward est aussi un instrument ; elle va donc produire des logs qui ressemblent à :

[
    {
        "timestamp": "2026-03-26T15:00:34.571525Z",
        "level": "TRACE",
        "fields": { "message": "trying to move", "new_pos": "(6, 5)" },
        "target": "world",
        "span": {
            "distance": 1,
            "self": "GameWorld { player_pos: Point2d { x: 5, y: 5 }, map_size: Point2d { x: 10, y: 10 }, enemies: [Point2d { x: 5, y: 7 }, Point2d { x: 7, y: 5 }] }",
            "name": "player_move_forward"
        },
        "spans": [
            { "turn_id": 0, "name": "slay_and_move_forward" },
            {
                "distance": 1,
                "self": "GameWorld { player_pos: Point2d { x: 5, y: 5 }, map_size: Point2d { x: 10, y: 10 }, enemies: [Point2d { x: 5, y: 7 }, Point2d { x: 7, y: 5 }] }",
                "name": "player_move_forward"
            }
        ]
    },
    {
        "timestamp": "2026-03-26T15:00:34.571651Z",
        "level": "INFO",
        "fields": { "message": "updated", "player_pos": "(6, 5)" },
        "target": "world",
        "span": {
            "distance": 1,
            "self": "GameWorld { player_pos: Point2d { x: 5, y: 5 }, map_size: Point2d { x: 10, y: 10 }, enemies: [Point2d { x: 5, y: 7 }, Point2d { x: 7, y: 5 }] }",
            "name": "player_move_forward"
        },
        "spans": [
            { "turn_id": 0, "name": "slay_and_move_forward" },
            {
                "distance": 1,
                "self": "GameWorld { player_pos: Point2d { x: 5, y: 5 }, map_size: Point2d { x: 10, y: 10 }, enemies: [Point2d { x: 5, y: 7 }, Point2d { x: 7, y: 5 }] }",
                "name": "player_move_forward"
            }
        ]
    }
]

Dans ces logs on voit bien la pile de portées :

• les arguments de slay_and_move_forward ; et
• les arguments (dont le self) de player_move_forward.

Dans cet exemple le self de player_move_forward nous pollue pas mal la sortie, ce serait cohérent de choisir les champs que l’on souhaite, ce que l’on peut faire ainsi :

#[instrument(err, skip(self), fields(player_pos = %self.player_pos, map_size = %self.map_size))]

• err crée un événement si la fonction renvoie une variante d’erreur.
• skip(self) n’ajoute pas self sur la portée créée lorsqu’on entre dans la fonction.
• fields permet d’ajouter des champs arbitraires à la portée.

Pareil pour la fonction player_slay_enemy :

#[instrument(skip(self), fields(player_pos = %self.player_pos, enemies = ?self.enemies))]

Liens pratiques

Doc de tracing Doc de tracing subscriber Doc de tracing subscriber (env filter) Dépôt des exemples du TP