📋 Come mantenere puliti i log degli unit test in Go: registrare solo gli input falliti 🔗

Quando si scrivono unit test in Go — specialmente i test guidati da tabelle (table-driven test) — le funzioni che scrivono nel pacchetto globale standard log possono intasare rapidamente il terminale.

Se hai una dozzina di casi di test e solo uno fallisce, devi comunque scorrere l’output di log di tutti i casi riusciti solo per trovare l’errore. Questo rumore rallenta il debug e rende l’output dei test difficile da leggere.

Vediamo uno scenario comune e come risolverlo catturando i log e stampandoli solo quando un test fallisce.

📑 Indice 🔗

🔊 Il problema: output dei test rumoroso 🔗

Supponiamo di avere una semplice funzione che registra i suoi input e il risultato finale:

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
}

Ora scriviamo uno unit test standard guidato da tabella con tre casi (in cui l’ultimo è progettato intenzionalmente per fallire):

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}, // Caso progettato intenzionalmente per fallire
	}

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

Quando eseguiamo go test, l’output contiene i log di tutti gli input passati prima di mostrarci finalmente l’errore:

$ 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 soluzione: Dependency Injection e buffer 🔗

Sarebbe molto meglio vedere solo i log generati dagli input che falliscono. Possiamo ottenere questo risultato passando un logger alla nostra funzione (Dependency Injection) e scrivendo i log in un buffer temporaneo durante i test.

Per prima cosa, aggiorniamo la nostra funzione in modo che accetti 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
}

Successivamente, aggiorniamo il nostro test. Per ogni iterazione dei casi di test, creeremo un nuovo bytes.Buffer e vi collegheremo un nuovo logger. Se il test passa, il buffer viene semplicemente scartato. Se il test fallisce, stampiamo il contenuto del buffer insieme al messaggio di errore!

(Nota: stiamo anche aggiornando il test per utilizzare t.Run, che è il modo idiomatico per eseguire sottotest guidati da tabelle in 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}, // Caso progettato intenzionalmente per fallire
	}

	for _, in := range inputs {
		t.Run(in.name, func(t *testing.T) {
			// 1. Crea un buffer per catturare i log
			var buf bytes.Buffer
			
			// 2. Crea un nuovo logger che scrive nel buffer
			logger := log.New(&buf, "", log.LstdFlags)
			
			// 3. Passa il logger personalizzato alla nostra funzione
			got := add(logger, in.x, in.y)
			
			if in.want != got {
				// 4. Stampa il contenuto del buffer SOLO se il test fallisce
				t.Errorf("got %d want %d\n\nExecution Logs:\n%s", got, in.want, buf.String())
			}
		})
	}
}

✨ L’output pulito 🔗

Ora, quando eseguiamo i nostri test, l’output è perfettamente pulito e immediatamente utilizzabile. Vediamo solo i log pertinenti al fallimento:

$ 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

Disaccoppiando le nostre funzioni dal logger globale, rendiamo il nostro codice più flessibile, le nostre suite di test più silenziose e il nostro processo di debug significativamente più veloce.