Logging estructurado avanzado con slog en Go

El logging estructurado con slog [disponible desde Go 1.21] permite transformar mensajes planos en datos jerárquicos legibles por máquinas, como JSON, facilitando enormemente la observabilidad en sistemas distribuidos. A diferencia del log estándar, slog separa el mensaje de los datos, permitiendo que herramientas como Loki o Datadog indexen campos específicos de forma eficiente. Internamente, esto se logra mediante un Handler que decide cómo se formatea y a dónde se envía la información. Para aprovecharlo, debes distinguir entre pasar pares de clave-valor genéricos y usar atributos tipados (slog.Attr), los cuales evitan la conversión de tipos a any (interface{}), reduciendo la presión sobre el Garbage Collector al evitar asignaciones innecesarias en el heap. Debes usar With para inyectar contexto persistente (como un request_id) y WithGroup para crear prefijos jerárquicos. Si usas mal el logging —especialmente abusando de any en bucles críticos o creando loggers con With dentro de funciones de alta frecuencia— terminarás con una explosión de asignaciones de memoria y un ruido insoportable en tus logs.

package main

import (
	"log/slog"
	"os"
	"time"
)

func main() {
	// Configuramos un handler JSON para producción. 
	// El nivel Debug es necesario para ver mensajes de depuración.
	handler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelDebug})
	logger := slog.New(handler)

	// Simulamos la entrada de una petición HTTP.
	requestID := "req-abc-123"
	userID := 42

	// logger.With crea un nuevo logger que hereda los atributos del original.
	// Ideal para inyectar contexto que persista durante toda la vida de la petición.
	reqLogger := logger.With(slog.String("request_id", requestID))

	// logger.WithGroup añade un prefijo a todos los atributos de este logger.
	// Útil para separar logs de capas específicas (ej. 'db' o 'auth').
	dbLogger := reqLogger.WithGroup("db")

	// 1. Log de información con atributos agrupados de forma ad-hoc.
	// slog.Group se usa dentro de la llamada para agrupar datos temporales.
	reqLogger.Info("petición recibida",
		slog.String("user_id", "42"), // Usamos strings para simplificar, pero en prod usa tipos exactos
		slog.Group("http",
			slog.String("method", "POST"),
			slog.String("path", "/api/v1/login"),
		),
	)

	// 2. Simulación de lógica de negocio (Nivel Info)
	performLogin(reqLogger, userID)

	// 3. Simulación de un error en la base de datos (Nivel Error y Warn)
	simulateDBError(dbLogger)
}

func performLogin(logger *slog.Logger, userID int) {
	// Usar atributos tipados (slog.Int) es más eficiente que "id", userID
	// porque evita el boxing de la variable a una interfaz.
	logger.Info("usuario autenticado", slog.Int("user_id", userID))
}

func simulateDBError(dbLogger *slog.Logger) {
	// El logger 'dbLogger' ya tiene el prefijo "db" y el "request_id" del padre.
	dbLogger.Warn("latencia de consulta elevada", slog.Duration("duration", 450*time.Millisecond))
	
	// Errores críticos con contexto específico
	dbLogger.Error("fallo de conexión al cluster", 
		slog.String("cluster", "us-east-1"),
		slog.Int("attempt", 3),
	)
}

Análisis del flujo

En el ejemplo, la jerarquía de datos es fundamental para el parseo. Al usar reqLogger.With(slog.String("request_id", requestID)), hemos creado una copia del logger original que ya contiene ese atributo. Esto es crucial en entornos concurrentes: el logger original permanece inmutable, permitiendo que otras goroutines no vean el request_id de esta petición específica.

Fíjate en la diferencia técnica entre WithGroup y slog.Group:
1. dbLogger := reqLogger.WithGroup("db"): Esto altera la estructura de todos los logs futuros que emita dbLogger. En el JSON resultante, cada campo estará envuelto en un objeto "db": { ... }. Esto es vital para segmentar logs de infraestructura.
2. slog.Group(...) dentro de reqLogger.Info: Esto crea un grupo temporal solo para esa línea de log. Es ideal para estructurar datos que solo existen en ese punto del flujo, como los detalles de una petición HTTP.

En cuanto al rendimiento, performLogin utiliza slog.Int("user_id", userID). Al ser un atributo tipado, el compilador puede optimizar la inserción de datos. En contraste, si usáramos logger.Info("msg", "user_id", userID), el valor userID tendría que ser convertido a una interfaz any para poder ser pasado como argumento, lo que provoca una asignación en el heap que, en un microservicio con miles de petcciones por segundo, impacta directamente en la frecuencia de las paradas del Garbage Collector.

El error frecuente

Un error común es abusar de los pares de clave-valor genéricos en procesos críticos bajo carga.

// MAL: Provoca asignaciones en el heap por el boxing de interface{}
for i := 0; i < 1000000; i++ {
    logger.Info("iteración", "index", i) 
}

// BIEN: Atributo tipado, mucho más eficiente
for i := 0; i < 1000000; i++ {
    logger.Info("iteración", slog.Int("index", i))
}

Cuando pasas i directamente, el runtime de Go debe empaquetar ese entero en una estructura eface (interface empty) para poder manejarlo como un any. Con slog.Int, pasas un tipo que el Handler puede procesar directamente sin esa transformación costosa.

N° 202