📋 Comment garder les logs des tests unitaires Go propres : n’afficher que les entrées en échec 🔗

Lors de l’écriture de tests unitaires en Go — en particulier les tests pilotés par table (table-driven tests) — les fonctions qui écrivent dans le paquet log global standard peuvent rapidement encombrer votre terminal.

Si vous avez une douzaine de cas de test et qu’un seul échoue, vous devez tout de même faire défiler la sortie des logs de tous les cas réussis juste pour trouver l’erreur. Ce bruit ralentit le débogage et rend la sortie de vos tests difficile à lire.

Examinons un scénario courant et voyons comment le résoudre en capturant les logs et en les affichant uniquement lorsqu’un test échoue.

📑 Table des Matières 🔗

🔊 Le problème : une sortie de test bruyante 🔗

Supposons que nous ayons une fonction simple qui journalise ses entrées et son résultat final :

package add

import (
	"log"
)

func add(x, y int) int {
	log.Printf("add %d %d", x, y)
	res := x + y
	log.Printf("add %d %d = %d", x, y, res)
	return res
}

Maintenant, nous écrivons un test unitaire standard piloté par table avec trois cas (où le dernier est intentionnellement conçu pour échouer) :

package add

import (
	"testing"
)

func TestAdd(t *testing.T) {
	inputs := []struct {
		x    int
		y    int
		want int
	}{
		{x: 1, y: 2, want: 3},
		{x: 3, y: 2, want: 5},
		{x: 4, y: 5, want: 0}, // Intentionally failing case
	}

	for _, in := range inputs {
		got := add(in.x, in.y)
		if in.want != got {
			t.Errorf("add %d %d got %d want %d", in.x, in.y, got, in.want)
		}
	}
}

Lorsque nous exécutons go test, la sortie contient les logs de toutes les entrées réussies avant de nous montrer enfin l’échec :

$ go test
2020/09/05 09:01:25 add 1 2
2020/09/05 09:01:25 add 1 2 = 3
2020/09/05 09:01:25 add 3 2
2020/09/05 09:01:25 add 3 2 = 5
2020/09/05 09:01:25 add 4 5
2020/09/05 09:01:25 add 4 5 = 9
--- FAIL: TestAdd (0.00s)
    add_test.go:28: add 4 5 got 9 want 0
FAIL
exit status 1

🛠️ La solution : injection de dépendances et tampons 🔗

Il serait bien préférable de ne voir que les logs générés par les entrées en échec. Nous pouvons y parvenir en passant un logger à notre fonction (injection de dépendances) et en écrivant les logs dans un tampon temporaire pendant nos tests.

Tout d’abord, mettons à jour notre fonction pour qu’elle accepte un *log.Logger :

package add

import "log"

func add(logger *log.Logger, x, y int) int {
	logger.Printf("add %d %d", x, y)
	res := x + y
	logger.Printf("add %d %d = %d", x, y, res)
	return res
}

Ensuite, nous mettons à jour notre test. Pour chaque itération de cas de test, nous allons créer un nouveau bytes.Buffer et y attacher un nouveau logger. Si le test réussit, le tampon est simplement ignoré. Si le test échoue, nous affichons le contenu du tampon à côté du message d’erreur !

(Remarque : nous mettons également à niveau le test pour utiliser t.Run, qui est la façon idiomatique d’exécuter des sous-tests pilotés par table en Go).

package add

import (
	"bytes"
	"log"
	"testing"
)

func TestAdd(t *testing.T) {
	inputs := []struct {
		name string
		x    int
		y    int
		want int
	}{
		{name: "1+2", x: 1, y: 2, want: 3},
		{name: "3+2", x: 3, y: 2, want: 5},
		{name: "4+5", x: 4, y: 5, want: 0}, // Intentionally failing case
	}

	for _, in := range inputs {
		t.Run(in.name, func(t *testing.T) {
			// 1. Create a buffer to capture the logs
			var buf bytes.Buffer
			
			// 2. Create a new logger that writes to the buffer
			logger := log.New(&buf, "", log.LstdFlags)
			
			// 3. Pass the custom logger into our function
			got := add(logger, in.x, in.y)
			
			if in.want != got {
				// 4. Print the buffer contents ONLY if the test fails
				t.Errorf("got %d want %d\n\nExecution Logs:\n%s", got, in.want, buf.String())
			}
		})
	}
}

✨ Une sortie propre 🔗

Désormais, lorsque nous exécutons nos tests, la sortie est parfaitement propre et directement exploitable. Nous ne voyons que les logs pertinents pour l’échec :

$ go test
--- FAIL: TestAdd (0.00s)
    --- FAIL: TestAdd/4+5 (0.00s)
        add_test.go:35: got 9 want 0
            
            Execution Logs:
            2020/09/05 09:22:48 add 4 5
            2020/09/05 09:22:48 add 4 5 = 9
            
FAIL
exit status 1

En découplant nos fonctions du logger global, nous rendons notre code plus flexible, nos suites de tests plus silencieuses et notre processus de débogage nettement plus rapide.