Git Bisect : débusquer rapidement l'origine d'un bug
Par Christophe Porteneuve • Publié le 9 décembre 2014 • 9 min

Ouh, le vilain bug que vous venez de remarquer ! Hélas, impossible de repérer tout de suite son origine dans le code, et apparemment il ne date pas d’hier… Comment faire pour éviter de devoir repasser tout l’historique au peigne fin ?

Dans cet article, nous allons voir comment Git nous assiste pour isoler au plus vite l’origine d’un bug, même très loin en arrière dans l’historique.

(English version of this article here)

La bonne façon de parcourir un historique

Un historique, c’est une liste triée. Le critère de tri ? Le temps ! Les commits partent du plus ancien vers le plus récent, même s’ils peuvent bifurquer puis se rejoindre au fil du graphe des branches et des fusions.

Lorsqu’on cherche quelque chose au sein d’une liste triée, il serait dommage de simplement commencer au début pour avancer vers la fin… Vous avez probablement déjà joué au jeu du « plus petit, plus grand » : vous devez trouver un nombre entre 1 et 100, par exemple. Dans un tel cas, je m’inquièterais pour une personne qui commencerait à 1, ou vers 100, pour ensuite piocher au hasard. Instinctivement, la plupart des gens commencent au milieu, à 50, et si on leur répond « plus petit », piochent ensuite au milieu du sous-ensemble ainsi défini, donc à 25, etc.

Ce type d’algorithme porte un nom : c’est une dichotomie (parfois appelée recherche dichotomique). Il permet de trouver ce qu’on cherche au maximum en [log₂(n)] coups, soit pour un ensemble [1, 100], au maximum en 7 coups. C’est encore bien plus impressionnant lorsqu’on étend l’intervalle de façon significative : pour [1, 1 000 000 000], il ne faudrait au pire que 27 coups ! Un sérieux gain de temps…

Il est possible d’appliquer ce principe à la recherche du premier commit qui, dans un historique de commits (c’est-à-dire une liste temporellement ordonnée de commits), a introduit un bug.

En anglais, cet algorithme se nomme binary search, mais c’est son exploitation mathématique, nommée bisection, qui a donné son nom à la commande git bisect.

Méthodologie

La commande git bisect exploite toute une série de sous-commandes.

On démarre avec un git bisect start. Il est possible de préciser d’entrée de jeu un commit foireux (généralement le HEAD et un autre qui est bon), sinon on les indiquera ensuite :
Un git bisect bad identifie le premier commit problématique connu (si on n’ajoute rien, c’est le HEAD, ce qui est normalement le cas)
Un git bisect good identifie un commit qui n’avait pas le problème (le plus proche possible de nous, mais au pire on ira le chercher loin pour ne pas galérer)
À partir de là, la dichotomie commence : Git fait un checkout au milieu (ou à peu près) de l’intervalle, nous dit où on en est, et demande le verdict : suivant le cas, on répondra par un git bisect bad ou git bisect good (plus rarement, git bisect skip).
Au bout d’un moment, si on n’a pas répondu n’importe quoi ni laissé trop de cas indéterminés, Git nous indiquera le premier commit fautif.
On pourra alors abandonner le bisecting avec un git bisect reset.

Pratiquons ensemble

Afin de pratiquer, nous allons utiliser un dépôt que je vous ai préparé aux p’tits oignons, avec des tas de messages de commit bien lourdaux et quatre contributeurs que vous allez sans doute reconnaître…

Télécharger le dépôt d’exemple

Décompressez-le où bon vous semble ; il crée un dossier bisect-demo dans lequel vous n’avez plus qu’à ouvrir une ligne de commande (sous Windows, préférez le Git Bash). Ce dépôt contient plus de 1 000 commits répartis sur environ un an et, quelque part là-dedans, un bug s’est glissé.

En effet, si vous exécutez ./demo.sh, il affiche un KO tout penaud. Alors qu’il devrait afficher glorieusement OK. Ce souci remonte à assez loin, et nous allons utiliser git bisect pour le débusquer.

Ici on n’a aucune idée du dernier commit valable, alors on va prendre le commit initial, d7ffe6a. Vérifions que demo.sh y a une bonne tête :

$ git show d7ffe6a:demo.sh
#! /bin/bash

echo OK

En effet, ça devrait aller…

Armés de cette information, nous pouvons donc démarrer le bisecting :

(master) $ git bisect start
(master|BISECTING) $ git bisect bad
(master|BISECTING) $ git bisect good d7ffe6a
Bisecting: 511 revisions left to test after this (roughly 9 steps)
[262113f0e09a308225fb61267ada2f1e6018c0d2] This is why git rebase is a horrible horrible thing.
((bisect/bad~512)|BISECTING) $

Notez qu’on pouvait aussi lancer la procédure en une seule commande :

(master) $ git bisect start HEAD d7ffe6a
Bisecting: 511 revisions left to test after this (roughly 9 steps)
[262113f0e09a308225fb61267ada2f1e6018c0d2] This is why git rebase is a horrible horrible thing.
((bisect/bad~512)|BISECTING) $

À partir de là, nous n’avons plus qu’à tester à chaque fois, et répondre par good ou bad :

((bisect/bad~512)|BISECTING) $ ./demo.sh
KO
((bisect/bad~512)|BISECTING) $ git bisect bad
Bisecting: 255 revisions left to test after this (roughly 8 steps)
[429ca3d34a579b9f2f75fe46b186fd49829bfcbe] well crap.
((bisect/bad~256)|BISECTING) $ ./demo.sh
KO
((bisect/bad~256)|BISECTING) $ git bisect bad
Bisecting: 127 revisions left to test after this (roughly 7 steps)
[81a283e5769134b5a8a8e6e53238cd8946e41088] oops, forgot to add the file
((bisect/bad~128)|BISECTING) $ ./demo.sh
OK
((bisect/bad~128)|BISECTING) $ git bisect good
Bisecting: 63 revisions left to test after this (roughly 6 steps)
[1645cbacd09690cf802370f6e5c26e047498c214] need another beer
((bisect/bad~64)|BISECTING) $ ./demo.sh
KO
((bisect/bad~64)|BISECTING) $ git bisect bad
Bisecting: 31 revisions left to test after this (roughly 5 steps)
[5a90898873b87b83d1999fbe2e9b06bbce83688d] Obligatory placeholder commit message
((bisect/bad~32)|BISECTING) $ ./demo.sh
KO
((bisect/bad~32)|BISECTING) $ git bisect bad
Bisecting: 15 revisions left to test after this (roughly 4 steps)
[7a67cd4fcb1a1fffa9675e471a149db8c7a1b56b] Continued development...
((bisect/bad~16)|BISECTING) $ ./demo.sh
KO
((bisect/bad~16)|BISECTING) $ git bisect bad
Bisecting: 7 revisions left to test after this (roughly 3 steps)
[3ce01cbb2542325d308a64689af386943a7795a7] fixed errors in the previous commit
((bisect/bad~8)|BISECTING) $ ./demo.sh
OK
((bisect/bad~8)|BISECTING) $ git bisect good
Bisecting: 3 revisions left to test after this (roughly 2 steps)
[a4ed1ba1be89da6b88db9171cdea686256b978f0] Added missing file in previous commit
((bisect/bad~4)|BISECTING) $ ./demo.sh
OK
((bisect/bad~4)|BISECTING) $ git bisect good
Bisecting: 1 revision left to test after this (roughly 1 step)
[9bd29eb9821c29556249fd9c4c6b8d18e3fac37c] typo
((bisect/bad~2)|BISECTING) $ ./demo.sh
OK
((bisect/bad~2)|BISECTING) $ git bisect good
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[465194af92951519c7da6542eaca0c56ee09fcd9] bara bra grejjor
((bisect/bad~1)|BISECTING) $ ./demo.sh
KO
((bisect/bad~1)|BISECTING) $ git bisect bad
465194af92951519c7da6542eaca0c56ee09fcd9 is the first bad commit
commit 465194af92951519c7da6542eaca0c56ee09fcd9
Author: Sheldon Cooper <sheldon.cooper@caltech.edu>
Date:   Sat Feb 8 16:39:47 2014 +0100

    bara bra grejjor

:100755 100755 87528969d6b53ec587d72faddd526bc2ac86e4fd a5d0b1c200926f20c89c2a8aaa7daf5f3559f7b6 M  demo.sh
((bisect/bad)|BISECTING) $ git bisect bad

Remarquez l’affichage final :

465194af92951519c7da6542eaca0c56ee09fcd9 is the first bad commit

Et de fait, le listing qui suit fait bien état d’une modification à demo.sh.

Ici, si nous en croyons notre prompt, nous sommes en effet sur bisect/bad, donc sur le commit fautif. Ça n’avait rien d’obligatoire, ça dépend entièrement du cheminement de la dichotomie, car une fois le fautif identifié, bisect ne fait pas automatiquement de checkout dessus.

De toutes façons, un git show 465194a nous montre que c’est bien là que le problème est survenu :

$ git show 465194a
commit 465194a
Author: Sheldon Cooper <sheldon.cooper@caltech.edu>
Date:   Sat Feb 8 16:39:47 2014 +0100

    bara bra grejjor

diff --git a/demo.sh b/demo.sh
index 8752896..a5d0b1c 100755
--- a/demo.sh
+++ b/demo.sh
@@ -1,3 +1,3 @@
 #! /bin/bash

-echo OK
+echo KO

N’oublions pas d’arrêter le bisecting pour revenir à notre HEAD original, avec un git bisect reset :

((bisect/bad)|BISECTING) $ git bisect reset
Previous HEAD position was 465194a... bara bra grejjor
Switched to branch 'master'
(master) $

Et voilà, alors que le commit fautif était 881 positions en amont, il ne nous aura fallu que 10 tests successifs pour l’isoler ! Même quand le protocole de test est rapide, comme ici, on gagne beaucoup de temps. Imaginez quand le test est plus lent (compilation, exécution pilotée, etc.) : le gain de temps devient alors énorme.

Commits intestables ou à éviter

Il peut arriver que, sur un commit précis, voire un ensemble de commits, vous ne soyez pas en mesure de tester si le bug se manifeste. Peut-être, par exemple, que le code concerné a des dépendances qui ne peuvent plus être satisfaites (libs obsolètes, changement d’architecture processeur depuis, etc.). Dans un tel cas, vous pouvez simplement répondre git bisect skip.

Il vous est d’ailleurs possible, d’entrée de jeu après le git bisect start, de préciser des commits ou intervalles de commits à ignorer, en qualifiant git bisect skip. Par exemple :

((bisect/good~502)|BISECTING) $ git bisect skip 3f24b5a v0.4..v1.1

Ici, on indique d’entrée de jeu à Git qu’il est inutile de tenter un test sur 3f24b5a et sur tout l’intervalle depuis v0.4 (exclus, comme toujours) jusqu’à v1.1 (inclus).

Lorsque vous savez dès le début quelles parties de votre codebase sont suspectes, il est possible de considérablement réduire le bisecting en précisant les chemins concernés à git bisect start, après les arguments classiques. On n’opèrera dès lors que sur le log des chemins fournis.

Dans notre dépôt d’exemple, ça n’aurait pas rendu grand chose car je n’ai modifié demo.sh qu’une fois après le commit initial : pour introduire le bug. On serait donc tombé immédiatement sur le commit foireux, ça aurait perdu de son impact :-)

Interruption et reprise

Il peut arriver que vous soyez dérangés en plein milieu de votre bisecting, en particulier si la mise en place du test, à chaque commit testable, prend du temps. Si vous avez alors besoin de vous mettre au travail sur le dépôt pour une autre raison, il serait dommage de perdre l’état de votre bisecting.

Plutôt que de noter dans un coin vos réponses, afin de les répéter plus tard, laissez Git le faire pour vous. La commande git bisect log détaille où vous en étiez jusqu’ici, il suffit de la sauver dans un fichier à l’aide d’une redirection. Plus tard, vous pourrez rejouer tout ça avec git bisect replay.

Imaginons par exemple que vous êtes interrompus au bout de 5 tests :

(master) $ git bisect start HEAD d7ffe6a
Bisecting: 511 revisions left to test after this (roughly 9 steps)
[262113f0e09a308225fb61267ada2f1e6018c0d2] This is why git rebase is a horrible horrible thing.
((bisect/bad~512)|BISECTING) $ ./demo.sh
KO
((bisect/bad~512)|BISECTING) $ git bisect bad
Bisecting: 255 revisions left to test after this (roughly 8 steps)
[429ca3d34a579b9f2f75fe46b186fd49829bfcbe] well crap.
((bisect/bad~256)|BISECTING) $ ./demo.sh
KO
((bisect/bad~256)|BISECTING) $ git bisect bad
Bisecting: 127 revisions left to test after this (roughly 7 steps)
[81a283e5769134b5a8a8e6e53238cd8946e41088] oops, forgot to add the file
((bisect/bad~128)|BISECTING) $ ./demo.sh
OK
((bisect/bad~128)|BISECTING) $ git bisect good
Bisecting: 63 revisions left to test after this (roughly 6 steps)
[1645cbacd09690cf802370f6e5c26e047498c214] need another beer
((bisect/bad~64)|BISECTING) $ ./demo.sh
KO
((bisect/bad~64)|BISECTING) $ git bisect bad
Bisecting: 31 revisions left to test after this (roughly 5 steps)
[5a90898873b87b83d1999fbe2e9b06bbce83688d] Obligatory placeholder commit message
((bisect/bad~32)|BISECTING) $ ./demo.sh
KO
((bisect/bad~32)|BISECTING) $ git bisect bad
Bisecting: 15 revisions left to test after this (roughly 4 steps)
[7a67cd4fcb1a1fffa9675e471a149db8c7a1b56b] Continued development...
((bisect/bad~16)|BISECTING) $ git bisect log > ../bisecting.log
((bisect/bad~16)|BISECTING) $ git bisect reset
Previous HEAD position was 7a67cd4... Continued development...
Switched to branch 'master'
(master) $

Vous pouvez jeter un œil au log ; vous allez voir qu’il contient notamment le démarrage :

(master) $ cat ../bisecting.log
# bad: [817b6fabcd468a19755518704b12e38ef82e1fbe] I'm totally adding this to epic win. +300
# good: [d7ffe6aa41e3c440398151c7c57e9255e38da4c5] Initial demo
git bisect start 'HEAD' 'd7ffe6a'
# bad: [262113f0e09a308225fb61267ada2f1e6018c0d2] This is why git rebase is a horrible horrible thing.
git bisect bad 262113f0e09a308225fb61267ada2f1e6018c0d2
# bad: [429ca3d34a579b9f2f75fe46b186fd49829bfcbe] well crap.
git bisect bad 429ca3d34a579b9f2f75fe46b186fd49829bfcbe
# good: [81a283e5769134b5a8a8e6e53238cd8946e41088] oops, forgot to add the file
git bisect good 81a283e5769134b5a8a8e6e53238cd8946e41088
# bad: [1645cbacd09690cf802370f6e5c26e047498c214] need another beer
git bisect bad 1645cbacd09690cf802370f6e5c26e047498c214
# bad: [5a90898873b87b83d1999fbe2e9b06bbce83688d] Obligatory placeholder commit message
git bisect bad 5a90898873b87b83d1999fbe2e9b06bbce83688d
(master) $

Une fois vos travaux effectués, vous reprenez votre bisecting directement grâce au log :

(master) $ git bisect replay ../bisecting.log
We are not bisecting.
Bisecting: 511 revisions left to test after this (roughly 9 steps)
[262113f0e09a308225fb61267ada2f1e6018c0d2] This is why git rebase is a horrible horrible thing.
Bisecting: 15 revisions left to test after this (roughly 4 steps)
[7a67cd4fcb1a1fffa9675e471a149db8c7a1b56b] Continued development...
((bisect/bad~16)|BISECTING) $

Sympa, non ?

Accélérer avec un script de test

Le top du top, pour du bisecting, c’est de ne même pas avoir à être là pour qu’il se fasse. En automatisant le parcours, vous restez libre de travailler sur le projet pendant ce temps-là (mais dans un autre working tree, forcément).

Le principe : créer un script de test (n’importe quoi d’exécutable, en fait) qui sera invoqué sans paramètres sur chaque commit à tester, et devra renvoyer un code de sortie appoprié :

0 (zéro) si le commit est bon (équivalent de good)
125 si le commit n’est pas testable (équivalent de skip)
N’importe quoi d’autre (le plus courant étant 127) si le commit est mauvais (équivalent de bad)

Ça peut être aussi simple qu’un npm test ou make test, si vous avez déjà ça sous le coude (et suffisamment complet à chaque commit). Sinon, vous vous faites un script dédié, placé de préférence hors du working tree pour ne pas risquer d’être endommagé par les checkouts successifs.

Dans notre cas, le test est super trivial : il suffit de vérifier que ./demo.sh affiche bien OK. Un simple grep fera donc l’affaire, et ça tombe bien, si celui-ci trouve son texte, il renvoie zéro, sinon il renvoie 127 : on n’a même pas à transformer son code de retour pour nos besoins.

Créons un script ../test.sh et donnons-lui les droits d’exécution :

(master) $ cat > ../test.sh <<EOS
> #! /bin/bash
> ./demo.sh | grep -q OK
> EOS
(master) $ chmod +x ../test.sh

Il suffit maintenant de lancer le bisecting (en indiquant l’intervalle), puis de lancer le script. Après quoi, si les tests sont rapides (comme dans notre cas), on aura quasi instantanément la réponse ; dans le cas contraire, eh bien… On est libres de faire autre chose pendant ce temps là.

(master) $ git bisect start HEAD d7ffe6a
Bisecting: 511 revisions left to test after this (roughly 9 steps)
[262113f0e09a308225fb61267ada2f1e6018c0d2] This is why git rebase is a horrible horrible thing.
((bisect/bad~512)|BISECTING) $ git bisect run ../test.sh
running ../test.sh
Bisecting: 255 revisions left to test after this (roughly 8 steps)
[429ca3d34a579b9f2f75fe46b186fd49829bfcbe] well crap.
running ../test.sh
Bisecting: 127 revisions left to test after this (roughly 7 steps)
[81a283e5769134b5a8a8e6e53238cd8946e41088] oops, forgot to add the file
running ../test.sh
Bisecting: 63 revisions left to test after this (roughly 6 steps)
[1645cbacd09690cf802370f6e5c26e047498c214] need another beer
running ../test.sh
Bisecting: 31 revisions left to test after this (roughly 5 steps)
[5a90898873b87b83d1999fbe2e9b06bbce83688d] Obligatory placeholder commit message
running ../test.sh
Bisecting: 15 revisions left to test after this (roughly 4 steps)
[7a67cd4fcb1a1fffa9675e471a149db8c7a1b56b] Continued development...
running ../test.sh
Bisecting: 7 revisions left to test after this (roughly 3 steps)
[3ce01cbb2542325d308a64689af386943a7795a7] fixed errors in the previous commit
running ../test.sh
Bisecting: 3 revisions left to test after this (roughly 2 steps)
[a4ed1ba1be89da6b88db9171cdea686256b978f0] Added missing file in previous commit
running ../test.sh
Bisecting: 1 revision left to test after this (roughly 1 step)
[9bd29eb9821c29556249fd9c4c6b8d18e3fac37c] typo
running ../test.sh
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[465194af92951519c7da6542eaca0c56ee09fcd9] bara bra grejjor
running ../test.sh
465194af92951519c7da6542eaca0c56ee09fcd9 is the first bad commit
commit 465194af92951519c7da6542eaca0c56ee09fcd9
Author: Sheldon Cooper <sheldon.cooper@caltech.edu>
Date:   Sat Feb 8 16:39:47 2014 +0100

    bara bra grejjor

:100755 100755 87528969d6b53ec587d72faddd526bc2ac86e4fd a5d0b1c200926f20c89c2a8aaa7daf5f3559f7b6 M  demo.sh
bisect run success
((bisect/bad)|BISECTING) $

Et hop ! En 2–3 secondes, c’est réglé ! Elle est pas belle la vie ?

Tu veux aller plus loin et maîtriser pleinement les fondamentaux de Git ou être accompagné pour garantir la qualité de tes projets grâce à une bonne mise en place de Git ? On peut t’aider ou te former, il suffit de nous décrire ton besoin !

Git Bisect : débusquer rapidement l'origine d'un bug Par Christophe Porteneuve • Publié le 9 décembre 2014 • 9 min