📋 Cómo mantener limpios los registros de pruebas unitarias en Go: registra solo las entradas fallidas 🔗

Al escribir pruebas unitarias en Go —especialmente pruebas basadas en tablas (table-driven tests)—, las funciones que escriben en el paquete global estándar log pueden saturar rápidamente tu terminal.

Si tienes una docena de casos de prueba y solo uno falla, aun así tienes que desplazarte por la salida de registro de todos los casos exitosos solo para encontrar el error. Este ruido ralentiza la depuración y dificulta la lectura de los resultados de tus pruebas.

Veamos un escenario común y cómo solucionarlo capturando los registros (logs) e imprimiéndolos únicamente cuando una prueba falla.

📑 Tabla de Contenidos 🔗

🔊 El problema: salida de pruebas ruidosa 🔗

Supongamos que tenemos una función sencilla que registra sus entradas y su resultado 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
}

Ahora, escribimos una prueba unitaria estándar basada en tablas con tres casos (donde el último está diseñado intencionadamente para fallar):

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 diseñado intencionadamente para fallar
	}

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

Cuando ejecutamos go test, la salida contiene los registros de todas las entradas que pasaron antes de mostrarnos finalmente el fallo:

$ 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 solución: inyección de dependencias y búferes 🔗

Sería mucho mejor ver únicamente los registros generados por las entradas que fallan. Podemos lograrlo pasando un registrador (logger) a nuestra función (inyección de dependencias) y escribiendo los registros en un búfer temporal durante nuestras pruebas.

Primero, actualicemos nuestra función para que acepte 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
}

A continuación, actualizamos nuestra prueba. En cada iteración de los casos de prueba, crearemos un bytes.Buffer nuevo y le asociaremos un nuevo logger. Si la prueba pasa, el búfer simplemente se descarta. ¡Si la prueba falla, imprimimos el contenido del búfer junto con el mensaje de error!

(Nota: También estamos actualizando la prueba para usar t.Run, que es la forma idiomática de ejecutar subpruebas basadas en tablas 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}, // Caso diseñado intencionadamente para fallar
	}

	for _, in := range inputs {
		t.Run(in.name, func(t *testing.T) {
			// 1. Crear un búfer para capturar los registros
			var buf bytes.Buffer
			
			// 2. Crear un nuevo logger que escriba en el búfer
			logger := log.New(&buf, "", log.LstdFlags)
			
			// 3. Pasar el logger personalizado a nuestra función
			got := add(logger, in.x, in.y)
			
			if in.want != got {
				// 4. Imprimir el contenido del búfer SOLO si la prueba falla
				t.Errorf("got %d want %d\n\nExecution Logs:\n%s", got, in.want, buf.String())
			}
		})
	}
}

✨ La salida limpia 🔗

Ahora, cuando ejecutamos nuestras pruebas, la salida es perfectamente limpia y muy fácil de procesar. Solo vemos los registros que son relevantes para el fallo:

$ 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

Al desacoplar nuestras funciones del logger global, hacemos que nuestro código sea más flexible, nuestras baterías de pruebas más silenciosas y nuestro proceso de depuración significativamente más rápido.