Hasta esta semana, cuando algo salía mal en este blog la evidencia vivía en los logs de docker en el servidor, lo que significa que en la práctica no vivía en ningún sitio. Un usuario podía toparse con un error, contármelo, y mi herramienta de depuración era desplazarme por la salida de la terminal buscando una marca de tiempo que coincidiera más o menos con su mensaje. Hora de arreglar eso.
La idea es simple: cada vez que un servicio escribe una respuesta de error, también escribe una fila en una tabla error_log. Ruta, estado, código de error, mensaje, id de la solicitud, el usuario si lo había. El panel de administración obtiene una pestaña de logs que lee de ambos servicios y los fusiona en una sola lista que puedo filtrar. El usuario dice "se rompió sobre las ocho", filtro a esa ventana y veo exactamente qué encontró su solicitud.
La primera decisión de diseño que resultó equivocada: solo registraba errores 5xx, bajo la teoría de que 4xx significa que el usuario hizo algo mal y 5xx significa que lo hice yo. Pero las respuestas 4xx suelen ser la pista. Un montón de 413 significa que alguien sigue chocando con un límite de subida que puse demasiado bajo. Una racha de 403 significa un ataque o un bug de permisos. Así que la red se amplió a 5xx más unos pocos elegidos: 403, 413 y 429. No cada 404 de un bot escaneando en busca de wordpress.php, eso solo sería ruido con una factura de base de datos.
El bug sutil en medio de todo esto tenía que ver con el contexto. El código obvio pasa el contexto de la solicitud a la inserción en la base de datos. Pero para cuando se escribe la respuesta de error, esa solicitud básicamente ya terminó, y su contexto ya puede estar cancelado, lo que mata la inserción. La fila del log sobre el fallo se pierde justo porque ocurrió el fallo. La solución es darle a la inserción su propio contexto independiente con un timeout corto:
ctx, cancel := context.WithTimeout(context.Background(), errorLogInsertTimeout)
defer cancel()
if err := q.InsertErrorLog(ctx, db.InsertErrorLogParams{ ... }); err != nil {
log.Printf("error_log insert failed: %v", err)
}Y fíjate qué pasa cuando la propia inserción falla: una simple línea de log, nada más. Lo único que un registrador de errores nunca debe hacer es producir su propia respuesta de error, porque ese error se registraría, lo cual podría fallar, lo cual se registraría. He leído suficientes postmortems para tenerle verdadero miedo a ese bucle.
La pestaña también obtuvo un botón de eliminar por fila y un borrar todo, porque un log que no puedes limpiar simplemente se convierte en una pared de ruido viejo que dejas de leer. Las filas de más de 90 días se eliminan solas junto con los eventos de analítica, mismo conserje, mismo horario.
¿Es un registro de errores de dos tablas con una fusión en el navegador una gran plataforma de observabilidad? No. Hay un servicio de logging central de verdad esbozado para la v2, con batching y reintentos cuando la red falla. Pero ese es un diseño para más adelante. Lo que necesitaba esta semana era dejar de depurar a través de los logs de docker, y ese problema ahora está resuelto con dos tablas y una pestaña de administración.