📋 Como Manter os Logs de Testes Unitários em Go Limpos: Registre Apenas as Entradas que Falharem 🔗

Ao escrever testes unitários em Go — especialmente testes orientados a tabelas (table-driven tests) —, funções que escrevem no pacote global padrão log podem rapidamente poluir o seu terminal.

Se você tiver uma dúzia de casos de teste e apenas um falhar, ainda precisará rolar a tela pelos logs de todos os casos bem-sucedidos só para encontrar o erro. Esse ruído atrasa a depuração e torna a saída dos seus testes difícil de ler.

Vamos analisar um cenário comum e ver como corrigi-lo capturando os logs e imprimindo-os apenas quando um teste falhar.

📑 Índice 🔗

🔊 O Problema: Saída de Teste Poluída 🔗

Digamos que temos uma função simples que registra suas entradas e seu resultado final no log:

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
}

Agora, escrevemos um teste unitário padrão orientado a tabela com três casos (onde o último foi intencionalmente projetado para falhar):

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

Quando executamos go test, a saída contém os logs de todas as entradas que passaram antes de finalmente nos mostrar a falha:

$ 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

🛠️ A Solução: Injeção de Dependência e Buffers 🔗

Seria muito melhor ver apenas os logs gerados pelas entradas que falharam. Podemos alcançar isso passando um logger para a nossa função (Injeção de Dependência) e gravando os logs em um buffer temporário durante os testes.

Primeiro, vamos atualizar nossa função para aceitar um *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
}

Em seguida, atualizamos nosso teste. Para cada iteração de caso de teste, criaremos um novo bytes.Buffer e conectaremos um novo logger a ele. Se o teste passar, o buffer é simplesmente descartado. Se o teste falhar, imprimimos o conteúdo do buffer junto com a mensagem de erro!

(Nota: Também estamos atualizando o teste para usar t.Run, que é a maneira idiomática de executar subtestes orientados a tabelas em 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())
			}
		})
	}
}

✨ A Saída Limpa 🔗

Agora, quando executamos nossos testes, a saída fica perfeitamente limpa e altamente acionável. Vemos apenas os logs relevantes para a falha:

$ 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

Ao desacoplar nossas funções do logger global, tornamos nosso código mais flexível, nossas suítes de teste mais silenciosas e nosso processo de depuração significativamente mais rápido.