📋 Go-Unit-Test-Logs sauber halten: Nur fehlgeschlagene Eingaben protokollieren 🔗

Beim Schreiben von Unit-Tests in Go – insbesondere bei tabellengesteuerten Tests (Table-Driven Tests) – können Funktionen, die in das globale Standardpaket log schreiben, Ihr Terminal schnell überfluten.

Wenn Sie ein Dutzend Testfälle haben und nur einer davon fehlschlägt, müssen Sie sich dennoch durch die Log-Ausgaben aller erfolgreichen Testfälle scrollen, nur um den Fehler zu finden. Dieses Rauschen verlangsamt das Debugging und macht die Testausgabe schwer lesbar.

Schauen wir uns ein typisches Szenario an und wie wir es beheben können, indem wir Logs abfangen und nur dann ausgeben, wenn ein Test fehlschlägt.

📑 Inhaltsverzeichnis 🔗

🔊 Das Problem: Überladene Testausgaben 🔗

Nehmen wir an, wir haben eine einfache Funktion, die ihre Eingaben und ihr Endergebnis protokolliert:

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
}

Nun schreiben wir einen klassischen tabellengesteuerten Unit-Test mit drei Fällen (wobei der letzte absichtlich fehlschlagen soll):

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}, // Absichtlich fehlschlagender Testfall
	}

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

Wenn wir go test ausführen, enthält die Ausgabe die Logs aller bestandenen Eingaben, bevor uns endlich der eigentliche Fehler angezeigt wird:

$ 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

🛠️ Die Lösung: Dependency Injection und Puffer 🔗

Es wäre deutlich besser, nur die Logs der fehlgeschlagenen Eingaben zu sehen. Wir können dies erreichen, indem wir unserer Funktion einen Logger übergeben (Dependency Injection) und die Logs während unserer Tests in einen temporären Puffer schreiben.

Aktualisieren wir zunächst unsere Funktion so, dass sie einen *log.Logger akzeptiert:

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
}

Als Nächstes passen wir unseren Test an. Für jeden Durchlauf eines Testfalls erstellen wir einen neuen bytes.Buffer und verknüpfen ihn mit einem neuen Logger. Besteht der Test, wird der Puffer einfach verworfen. Schlägt der Test jedoch fehl, geben wir den Inhalt des Puffers zusammen mit der Fehlermeldung aus!

(Hinweis: Wir stellen den Test außerdem auf t.Run um, was in Go der idiomatische Weg ist, um tabellengesteuerte Subtests auszuführen).

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}, // Absichtlich fehlschlagender Testfall
	}

	for _, in := range inputs {
		t.Run(in.name, func(t *testing.T) {
			// 1. Einen Puffer erstellen, um die Logs aufzuzeichnen
			var buf bytes.Buffer
			
			// 2. Einen neuen Logger erstellen, der in den Puffer schreibt
			logger := log.New(&buf, "", log.LstdFlags)
			
			// 3. Den benutzerdefinierten Logger an unsere Funktion übergeben
			got := add(logger, in.x, in.y)
			
			if in.want != got {
				// 4. Den Pufferinhalt NUR ausgeben, wenn der Test fehlschlägt
				t.Errorf("got %d want %d\n\nExecution Logs:\n%s", got, in.want, buf.String())
			}
		})
	}
}

✨ Die saubere Ausgabe 🔗

Wenn wir unsere Tests jetzt ausführen, ist die Ausgabe vollkommen aufgeräumt und direkt nutzbar. Wir sehen ausschließlich die Logs, die für den Fehler relevant sind:

$ 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

Indem wir unsere Funktionen vom globalen Logger entkoppeln, machen wir unseren Code flexibler, unsere Test-Suites ruhiger und unseren Debugging-Prozess erheblich schneller.