Pépite #17 – Rust, CircleCI et logging : Une histoire de debugging de CLI

Nous rêvons tous de devenir, du jour au lendemain, immensément riches de connaissances.
Pouvoir se prélasser sur les plages du savoir, un cocktail de science infuse à la main.

Mais nous savons aussi qu’un lingot est parfois compliqué à emporter avec soi dans le monde moderne.
C’est pourquoi nous vous proposons la nouvelle rubrique de Xebia : « Les pépites ».

Chaque pépite se propose de vous offrir, chaque semaine, un petit morceau de connaissance à très forte valeur ajoutée.
Astuce d’utilisation d’un framework, Tips & Tricks de votre IDE favori, classe méconnue… les exemples sont nombreux de ces petites astuces qui améliorent petit à petit nos vies de développeurs !

Bienvenue dans la pépite de la semaine ! Aujourd’hui nous allons parler de Rust, de CircleCI, et de logging dans un terminal… via l’histoire d’une courte session de debugging.

Depuis quelques semaines, je joue avec Rust pour créer un outil en ligne de commande. Appelons-le my-cli. Brève parenthèse : j’utilise notamment la fameuse bibliothèque clap pour toute la gestion des arguments (mais ça n’a que peu d’importance pour le reste de cet article).

Je build, teste et package my-cli via CircleCI.

Évidemment, j’ai rapidement eu besoin de logger des informations. J’ai fini par choisir simplelog comme implémentation de logging compatible avec la façade log de Rust. Je l’ai principalement choisie pour son TermLogger, décrit comme un « advanced terminal logger, that splits to stderr/out and has color support ». Parfaitement adapté à une application en ligne de commande !

Gardez à l’esprit que j’apprends toujours énormément à propos de Rust ; certaines choses pourraient vous sembler évidentes mais elles ne l’étaient pas pour moi à ce moment-là.

Quand les ennuis commencent…

En pleine étape d’industrialisation, je remarque que le pipeline CircleCI a commencé à remonter des échecs. Pas de chance pour moi, nous ne gardons pas suffisamment d’historique de builds pour être capables d’identifier précisément le commit qui a introduit cet échec.

En tout cas, le pipeline ressemblait tout à coup à ceci :

Le pipeline compile la CLI, puis la lance localement avec l’argument --help en guise de très minimal smoke test. Il y a également une vraie (mais minimale) suite de tests avec des tests unitaires que je ne lance que localement pour l’instant. Oui, ce n’est définitivement pas suffisant. Gardez à l’esprit que je n’ai passé que quelques heures sur cette CLI.

L’étape de « Smoke test » est essentiellement la suivante :

"Smoke test":
  docker:
    - image: circleci/rust:1.33.0
  steps:
    - attach_workspace:
        at: .
    - run:
        name: "Execute binary with --help"
        command: ./my-cli --help
    - run:
        name: "Execute binary with --help and check that output looks ok-ish"
        command: ./my-cli --help | head -n1 | grep my-cli

Revenons à notre sujet : pourquoi est-ce que cette étape échoue ? Tout semble compiler et se lance correctement dans mon IDE. J’ai même été jusqu’à télécharger le binaire stocké en tant qu’artefact par CircleCI pour le lancer localement sur mon laptop sans aucun problème. Voici l’échec en lui-même plus précisément :

#!/bin/bash -eo pipefail
./my-cli --help
thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', src/libcore/option.rs:345:21
note: Run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
Exited with code 101

Afin d’avoir plus d’informations sur ce qu’il se passe, j’ai donc fini par ajouter la variable d’environnement mentionnée RUST_BACKTRACE. Voici ces détails :

#!/bin/bash -eo pipefail
./my-cli --help
thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', src/libcore/option.rs:345:21
stack backtrace:
   0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace
             at src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:39
   1: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:70
   2: std::panicking::default_hook::{{closure}}
             at src/libstd/sys_common/backtrace.rs:58
             at src/libstd/panicking.rs:200
   3: std::panicking::default_hook
             at src/libstd/panicking.rs:215
   4: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:478
   5: std::panicking::continue_panic_fmt
             at src/libstd/panicking.rs:385
   6: rust_begin_unwind
             at src/libstd/panicking.rs:312
   7: core::panicking::panic_fmt
             at src/libcore/panicking.rs:85
   8: core::panicking::panic
             at src/libcore/panicking.rs:49
   9: my_cli::main
  10: std::rt::lang_start::{{closure}}
  11: std::panicking::try::do_call
             at src/libstd/rt.rs:49
             at src/libstd/panicking.rs:297
  12: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:92
  13: std::rt::lang_start_internal
             at src/libstd/panicking.rs:276
             at src/libstd/panic.rs:388
             at src/libstd/rt.rs:48
  14: main
  15: __libc_start_main
  16: _start
Exited with code 101

Pas vraiment plus utile. Aucune mention de mon propre code à l’exception de 9: my_cli::main.

En revanche, il semble que ce soit lié à un appel à Option::unwrap() ; alors trouvons le coupable !

Rappel : Option::unwrap()

Option::unwrap() est utilisé pour extraire une valeur v d’un type Option. La documentation l’explique mieux que je ne le ferais moi-même :

Notez qu’elle décourage explicitement ce que j’étais en train de faire :

In general, because this function may panic, its use is discouraged. Instead, prefer to use pattern matching and handle the None case explicitly.

C’est exactement ce qu’il semble se passer.

Note : la première version du Rust Book explique l’unwrapping plus en détails si vous souhaitez en savoir plus.

À la chasse aux .unwrap()

J’ai donc commencé à chasser chaque .unwrap() qui était dans mon code (relativisons, il n’y en avait que 3). Ce fut une bonne opportunité de me forcer à gérer les erreurs plus proprement, que j’avais (à tort) remis à plus tard; c’est le moment d’améliorer ça !

Un de ces appels était celui-ci :

    CombinedLogger::init(vec![
        TermLogger::new(LevelFilter::Debug, Config::default()).unwrap()
    ]).unwrap();

Il s’agit de l’initialisation du logger de simplelog. Je n’avais initialement pas géré ce cas d’erreur proprement et appelait juste .unwrap() en me disant : « qu’est ce qui pourrait bien poser problème dans l’initialisation d’une structure de logging avec des settings par défaut? ».

Et en effet, comme quelqu’un l’a justement remarqué sur StackOverflow, la documentation de TermLogger ne mentionne même pas pourquoi None pourrait être retourné :

The documentation of TermLogger::new is not good, because it does not explain why it returns an Option.

Traiter les cas d’erreurs proprement pour avoir plus d’informations

Pour confirmer qu’il s’agissait bien de cet appel qui causait le problème, j’ai géré le cas du None comme j’aurais dû le faire depuis le départ :

let term_logger = match TermLogger::new(LevelFilter::Debug, Config::default()) {
    Some(tl) => tl,
    None => {
        println!("Failed to create TermLogger; exiting.");
        std::process::exit(1);
    }
};
CombinedLogger::init(vec![termlogger]).expect("Failed to initialize logger");

Et bingo, après avoir traité l’erreur correctement, j’ai enfin eu une erreur utile de la part de mon pipeline de CI :

./my-cli --help
Failed to create TermLogger; exiting.
Exited with code 1

Là où tout s’explique

La grande question qui est tout l’objet de cet article est donc : pourquoi est-ce que TermLogger::new() échoue sur CircleCI alors qu’il marche parfaitement sur ma machine ?

Déroulons ce qui se passe lors de cet appel afin de voir pourquoi et comment TermLogger::new() pourrait retourner None :

• TermLogger::new() appelle principalement la bibliothèque Rust term. Ceci se fait via term::stdout() et term::stderr().
• term::stdout() et term::stderr() sont simplement des wrappers autour de la fonction Terminfo::new()
• … qui appelle TermInfo::from_env()

Et c’est là que les choses deviennent intéressantes. Voici la première ligne de TermInfo::from_env :

let term_var = env::var("TERM").ok();

On dirait bien que c’est là que tout pourrait voler en éclats.

Le vérifier en reproduisant localement est simple : il s’agit juste de supprimer TERM des variables d’environnement du shell courant (via unset TERM), de lancer le binaire, et nous y voici : le même crash que dans le pipeline de CI.

Ce comportement est complètement compréhensible de la part de la crate term, dans la mesure où elle a besoin des terminfo afin de savoir quelles possibilités offre le terminal utilisé (voir man 5 terminfo pour en savoir plus).

CircleCI et allocation de terminal

Tout ceci m’a surpris, n’ayant jamais eu aucun problème ou comportement différent dans mes pipelines CircleCI comparé à d’autres environnements, y compris dans la mesure où j’utilise le Docker executor.

CircleCI alloue bien un TTY et tout semble correct.

En revanche, et comme on peut s’en douter grâce à l’investigation effectuée précédemment, CircleCI n’exporte pas de variable d’environnement TERM (confirmé par un message sur les forums de CircleCI), ce qui cause l’échec de l’intialisation de TermInfo.

Correctif

Le correctif était vraiment facile : un simple ajout de la variable d’environnement TERM dans l’environnement de mon smoke test :

"Smoke test":
  docker:
    - image: circleci/rust:1.33.0
  environment:
    TERM: xterm
  steps:
    - attach_workspace:
        at: .
    - run:
        name: "Execute binary with --help"
        command: ./my-cli --help
    - run:
        name: "Execute binary with --help and check that output looks ok-ish"
        command: ./my-cli --help | head -n1 | grep my-cli

En revanche, corriger la situation pour moi-même n’est pas la seule chose à faire ici. D’autres personnes pourraient rencontrer (c’est déjà le cas si on en croit certains threads StackOverflow) le même problème et se demander pourquoi TermLogger::new() échoue; améliorons les choses pour tout le monde !

À cette fin, j’ai ouvert une issue sur simplelog pour réfléchir au remplacement du Option par un Result qui pourrait alors renvoyer une Err qui transmettrait plus d’informations sur la raison de l’échec. Dans tous les cas, une Pull Request a également été ouverte pour améliorer la documentation avec la mention de ce cas particulier.

Take away

Ce que vous devriez retenir de cet article :

• Ne jamais utiliser .unwrap() ! Au strict minimum, utilisez .expect() pour avoir un message approprié et vous faciliter le debugging. Idéalement, gérer les cas d’erreurs proprement : utilisez match pour traiter vos None et Err de manière appropriée.
• La documentation pour le cas None du TermLogger de simplelog pourrait être améliorée.
• Méfiez-vous de vos environnements d’intégration continue; même avec des environnements contrôlés grâce à Docker, il peut toujours y avoir de légères variations par rapport à ce que vous imaginez
• Sachez que CircleCI n’exporte pas la variable d’environnement TERM

J’espère que ce bout de debugging pourra vous aider à un moment où à un autre !