Llegó una alerta diciendo que la base de datos estaba caída. La base de datos nunca se cayó

Abrí Slack por la mañana y había cuatro alertas CRITICAL acumuladas.

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

La última línea es la que más miedo da, porque significa que la base de datos está muerta. Al ver las cuatro en la misma pantalla se dibuja una historia: la base de datos lo pasó mal, por eso se acumularon las consultas, por eso las peticiones dieron timeout y al final falló hasta el health check. Es una historia verosímil.

Así que empecé abriendo las métricas de la base de datos. Esa historia se derrumbó en la primera pantalla.

La base de datos estuvo ociosa durante 21 horas seguidas

Saqué las métricas de RDS del intervalo de 21 horas que incluía el incidente, en tramos de 5 minutos. 252 puntos de datos.

Métrica	Mínimo	Máximo
CPU	4.6%	19.7%
Conexiones	53	73
Saldo de créditos de CPU	576	576
Latencia de lectura	0s	0.01s
Latencia de escritura	0.01s	0.08s

La CPU nunca pasó del 20% y el saldo de créditos tiene el mismo valor mínimo y máximo, o sea que no se gastó ni uno. La latencia de escritura llegó como mucho a 80 milisegundos. También revisé RDS Proxy: latencia máxima de préstamo de conexión, 26 milisegundos; conexiones de backend, 36 como máximo. En ninguna parte hay un número que explique consultas de 8 o 10 segundos.

La base de datos no se había caído. Ni siquiera estaba ocupada.

Una sola petición cruza el Atlántico veinticinco veces

Entonces, ¿de dónde salían las consultas de 8 segundos? Mirando la estructura aparece la respuesta.

Nuestro servicio corre en dos regiones: us-east y eu-west. Solo hay un primary, en us-east, y aunque las lecturas de la app de eu-west las atiende una réplica local, todas las escrituras cruzan el Atlántico y llegan al primary de us-east pasando por RDS Proxy.

El problema era el número de escrituras. Seguí en el código una única petición de guardado de práctica (POST /customer/practice/attempts) y las conté. Un upsert de asset, 3 lecturas de agregados precalculados, una transacción de intento de aprendizaje con 4, una reconsulta del runner, de 2 a 3 actualizaciones de progreso, unas 6 en la transacción de racha, 2 en la de estadísticas y de 2 a 3 actualizaciones del estado de repaso. Unas veinticinco en total, repartidas en tres bloques de transacciones interactivas independientes.

En los logs estaba ese número, tal cual.

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

25 consultas, 11.7 segundos. Y esta petición ni siquiera falló: después de aguantar 11.7 segundos, terminó con un 201.

Aquí conviene ser honesto con una cosa. Yo no medí cuántos milisegundos cuesta cada uno de esos viajes. Un comentario del código apuntaba un RTT entre regiones de 220 milisegundos, y otro comentario decía de 80 a 100 milisegundos por sentencia. Sin comprobar cuál de los dos era el bueno, escribí en el cuerpo de la issue el cálculo "25 x 220ms = 5.5 segundos". Visto ahora, eso no es una medición, es una cita. La afirmación exacta es esta: conté los viajes de ida y vuelta (25) y no medí el coste de cada viaje. Aun así, la conclusión no se tambalea. Cruzar el Atlántico veinticinco veces acumula un coste que se cuenta en segundos.

En el pico de la mañana europea (06:00-06:10 UTC) se juntaron 57 escrituras al primary que superaron los 3 segundos. LearningAttempt.create 8,989ms, UserActiveDate.upsert 9,070ms, LearningAttempt.findUnique 10,561ms. Las peticiones se empujaban unas a otras y la latencia de los viajes se iba acumulando.

Dos de las alertas salieron de ahí.

Alertas 1 y 2: una transacción de 5 segundos no aguantó 9.3

El código que actualiza la racha tenía esta pinta.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... seis consultas que cruzan de region ...
});

No hay objeto de opciones. Así que se aplica el timeout por defecto de las transacciones interactivas de Prisma: 5000 milisegundos. Normalmente no da ningún problema. Siempre que no cruces de región.

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9326 milisegundos. Y eso se convierte en un P2028, y la petición acaba siendo un 504 en el gateway.

Este código era el único desprotegido de todo nuestro código base. Las demás rutas con transacciones pasan por la utilidad withTxRetry, que sube el timeout a 8 segundos y trata el P2028 como reintentable. Solo la actualización de la racha se había quedado fuera de ese paraguas, usando el valor por defecto de 5 segundos.

Alerta 4: el health check pasó por el mismo cuello de botella que vigilaba

La más aterradora, "servicio DATABASE caído", resultó ser en realidad la más absurda.

El código del health check estaba bien escrito. Lanza un SELECT 1 con 2 segundos de timeout, y si falla espera 500 milisegundos y lo intenta una vez más; si eso también falla, dispara la alerta CRITICAL. Incluso tiene su propio pool de conexiones (máximo 2) para no mezclarse con el pool de Prisma de la app. La idea es que el health check siga vivo aunque el pool de la app se agote.

Pero la ruta por la que esta sonda llega a la base de datos no estaba aislada.

// health.service.ts:139
// Si existe DIRECT_DATABASE_URL se usa; si no, se recurre a DATABASE_URL

DIRECT_DATABASE_URL no estaba configurada. Se aplicó el fallback, y DATABASE_URL apunta justo al RDS Proxy donde se agolpan las escrituras de la app. Es decir, el SELECT 1 que lanzaba la sonda de salud de eu-west tenía que cruzar el Atlántico, atravesar ese proxy que en ese momento estaba atascado, llegar hasta el primary de us-east y volver. En menos de 2 segundos.

El código sabía todo esto. Está preparado para dejar esta advertencia cuando se aplica el fallback.

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

Esa línea estaba en los logs, tal cual. Solo que nadie la había leído.

La prueba decisiva es que las dos regiones fallaron juntas a la misma hora. 12:02:17, timeout en el health check de la tarea de us-east. 12:02:18, timeout también en la de eu-west. Si hubiera sido un problema regional, solo debería haber muerto una. Que murieran las dos a la vez significa que la causa está en lo que comparten: la ruta del proxy.

Lo que viene después es un guion escrito de antemano. Como el health check falló las dos veces, /public/health devuelve un 503, el orquestador da la tarea por defectuosa y la reemplaza. Cuatro minutos más tarde arrancó una tarea nueva. Y nada más arrancar, esa tarea nueva se comió exactamente el mismo timeout en el health check. Cambiar la tarea no estrecha el Atlántico.

"Servicio DATABASE caído" no era un síntoma del incidente. Era el vigilante que había recorrido el camino congestionado de aquello que vigilaba y luego había informado de que se sentía mal.

El 500 del admin iba por su cuenta

Aquí llega la tentación de meter las cuatro alertas en el mismo saco. Yo mismo intenté ordenarlo así al principio. Pero el 500 del admin tenía otra raíz.

Cuando GET /admin/dashboard/stats saca las palabras más populares, aplica un filtro de los últimos 7 días. Solo que la tabla sobre la que cae ese filtro (category_attempt) no tiene columna de fecha propia. La fecha está únicamente en el lado de learning_attempt, que entra por join. Así que Postgres no tiene forma de recortar category_attempt por fecha de antemano y le toca recorrer todo el histórico. Por bien que pongas los índices, ese filtro no se puede volver selectivo.

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

El statement_timeout está en 8000 milisegundos. 8009 milisegundos. Murió por 9 milisegundos de diferencia. Era un full scan que no tiene nada que ver con las regiones y que, a medida que la tabla creciera, tarde o temprano iba a estallar.

De las cuatro alertas, tres compartían raíz y una no. Que aparezcan cuatro en la misma pantalla no significa que la causa sea una sola.

Una hipótesis que descarté

Había un sospechoso bastante verosímil: la hipótesis de que el cron de device-cleanup, que se ejecuta justo antes de la ráfaga de las 06:00, estuviera provocando contención de locks. Las horas encajaban, así que resultaba bastante convincente.

Repasé los logs de las dos regiones en el intervalo 05:30-06:15. No había ni un solo log del cron. Al comprobar la ruta del Device.updateMany que iba lento, no era la actualización masiva del cron, sino /v2/public/auth/refresh, es decir, una petición corriente de refresco de token de un usuario. La hipótesis quedó descartada por medición. Que las horas coincidan es correlación; que no esté en los logs es un hecho.

Plegamos los viajes

La receta se bifurca en dos. Está el camino de aguantar el síntoma: subir el timeout a 8 segundos, agrandar el pool, añadir reintentos. Y está el camino de eliminar el coste mismo: reducir el número de viajes.

Hicimos las dos cosas. Ponerle withTxRetry a la transacción de la racha es una tirita, pero era una tirita necesaria. La receta de verdad, sin embargo, era plegar los viajes.

La herramienta ya estaba construida. En una migración con fecha del 27 de junio existía una función del lado del servidor llamada create_practice_attempt_v1. Pliega el bloqueo de sesión, la consulta, la inserción, la actualización de los metadatos de sesión y la lectura de agregados precalculados en una sola función SQL, y lo resuelve todo en un único viaje. Incluso es idempotente (si la llamas dos veces con el mismo client attempt id, la segunda devuelve la fila existente y inserted=false).

El detalle es que el feature flag que enciende esta función, PRACTICE_ATTEMPT_SINGLE_RT_ENABLED, tenía false como valor por defecto y estaba apagado en producción.

En vez de eliminar una región o irnos a active-active, lo que hicimos fue encender un interruptor que ya estaba puesto.

Canary: qué mirar para decidir

Encendimos el flag solo en eu-west. us-east se quedó apagado como grupo de control. Subimos la task definition de la 786 a la 787 y desplegamos en rolling.

Y aquí está el corazón de esta historia: qué métrica tomas como veredicto. La latencia es una trampa. Si despliegas en una franja de poco tráfico, el p95 mejora aunque no hayas arreglado nada. De hecho, la latencia mejoró: el p50 bajó de 2,784ms a menos de 2000ms. Pero esa evidencia es débil.

Yo miré, en su lugar, el número de consultas por petición.

antes   n=85   avg query_count = 22.0
despues n=49   avg query_count = 15.3

El número de consultas es una métrica por petición independiente de la carga. Haya mucho tráfico o poco, cuántas consultas lanza una petición lo decide la ruta del código. De 22 a 15.3, unas 7 menos. Y esas 7 coinciden exactamente con el número de consultas de la lista que plegamos en una sola función (bloqueo de sesión + consulta + inserción + metadatos de sesión + lectura de agregados precalculados). La prueba de que la ruta del código cambió de verdad es ese número. No la latencia.

La muestra posterior al despliegue son 49 peticiones en 15 minutos. En esa ventana no hubo ni un 5xx ni un P2028, pero no llegué a medir en paralelo el número de errores de una ventana "antes del despliegue" del mismo día y la misma duración. Este flag solo pliega el guardado del attempt: la transacción de la racha sigue cruzando de región. Que en esa ventana hubiera 0 P2028 significa que tuvimos suerte, no es una demostración.

El despliegue salió bien, pero el flag estuvo a punto de desaparecer

La forma de encender la canary tenía su precio. La 787 es una task definition registrada a mano desde la consola. Cuando corriera el siguiente despliegue oficial, el pipeline de CD la sobrescribiría con una task definition sin el flag. No es fatal (al sobrescribirla se vuelve al OFF seguro), pero la mejora desaparecería en silencio.

Así que había que promoverla a terraform, y ahí apareció la segunda trampa. El workflow de terraform hace apply solo de staging en los push a develop, y de production solo en los push a main. Pero es que en staging no existe la región eu-west. Es decir, si mergeas a develop un PR con un cambio de eu-west en producción, no pasa absolutamente nada. Había que cambiar la base a main.

Y había una tercera trampa. Si mergeas directamente a main, develop se queda atrás, y si no haces el merge de vuelta, la siguiente release revierte este cambio. Hubo que crear aparte un PR de back-merge.

"El terraform apply ha ido bien" y "está aplicado en producción" son dos frases distintas.

Lo que queda

Cuando llega una alerta de "DB caída", lo primero que hay que abrir son las métricas de la base de datos. El nombre de una alerta se lo pone el código que la dispara, no la causa. Nuestro health check llegó a tener hasta un pool propio, aislado del de la app, y aun así se atascó junto con la app porque el camino hacia la base de datos era el mismo. Aislar no consiste solo en separar recursos: también hay que separar las rutas.

Si subes el timeout de 5 a 8 segundos, las alertas de ese día se paran. Pero la petición sigue cruzando el Atlántico veinticinco veces. Con que el tráfico crezca un poco más, 8 segundos tampoco bastarán. Es mejor decidir de antemano si vas a aguantar el síntoma o a eliminar el coste. Si el coste se compone de "número x distancia", lo que hay que reducir es el número.

La latencia se tambalea con la carga; las métricas por petición no. Antes de quedarte tranquilo porque el p95 mejoró tras desplegar un arreglo de rendimiento, mira si de verdad ha bajado la cantidad de trabajo que hace una petición. Ese número es el mismo si despliegas de madrugada o a la hora de comer.

Yo conté los viajes de ida y vuelta y la latencia por viaje la tomé prestada de los comentarios del código. Esos dos comentarios decían valores distintos. Menos mal que la conclusión no cambió, pero la próxima vez podría cambiar. Lo que no hemos medido, escribámoslo como no medido.