Los tests estaban en verde, pero la notificación nunca llegó a enviarse

Saltó una alerta de 500 en Slack. El mensaje de error me resultaba desconocido: Error: Custom Id cannot contain :. La API con la que un administrador registra la respuesta a la pregunta de un usuario estaba fallando, y el stack trace apuntaba a Job.validateOptions de BullMQ.

Hasta aquí, un informe de bug corriente. La historia deja de ser corriente justo después de encontrar la causa. El código que lanzaba este error no había cambiado en el despliegue de ese día. Fallaba siempre, el 100% de las veces, desde el día en que la funcionalidad entró. Lo que significa que las notificaciones push que esta cola debía enviar no se habían enviado ni una sola vez. Y durante todo ese tiempo, los tests estuvieron en verde.

La causa era un solo carácter

El código problemático era este. Es el punto donde se encola el job que envía un push al usuario cuando su pregunta recibe respuesta.

await this.queue.add(ANSWER_NOTIFY_JOB_NAME, data, {
  jobId: `answer-notify:${data.questionId}`, // ← estos dos puntos
});

Se le dio un jobId personalizado para que el job no entrara dos veces para la misma pregunta, pero como separador se usaron dos puntos. BullMQ monta las claves de Redis con dos puntos y por eso los prohíbe en los jobId personalizados. En v5 la condición exacta es esta: si el jobId contiene dos puntos y al dividirlo por ellos no salen tres partes, lanza el error. La excepción de las tres partes es un carve-out para el formato legacy de los jobs repetibles, así que un jobId de dos partes como answer-notify:123 recibe siempre Custom Id cannot contain :. Por cierto, un jobId puramente numérico también se rechaza con Custom Id cannot be integers, así que quitar el prefijo tampoco es la solución.

Las decenas de otras colas del código usaban todas guiones. Solo este archivo llevaba dos puntos.

El bug estaba desde el primer día. Entonces, ¿por qué explotó hoy?

Arreglarlo es una línea: cambiar los dos puntos por un guion. La pregunta interesante es otra. ¿Por qué un código que fallaba siempre estuvo callado todo este tiempo y se convirtió en un 500 justo hoy?

Cuando la funcionalidad se desplegó por primera vez, el enqueue estaba envuelto así.

try {
  await this.queue.add(/* ... */);
  return true;
} catch (err) {
  this.logger.error("enqueue failed", err);
  return false; // ← el fallo desaparece aquí
}

Registra el fallo en el log y devuelve false. El código que lo llama no comprueba el valor de retorno. Así que la excepción que se lanzaba cada vez se tragaba cada vez, la API devolvía 200 y la notificación se evaporaba en silencio.

Entonces, un commit fusionado ese mismo día cambió este contrato. La intención era que si el enqueue fallaba, en vez de tragarse el error lo lanzara, para poder revertir la marca de "respondida" escrita en la transacción y permitir el reintento. Un cambio en la dirección correcta. En ese momento, el enqueue que siempre había fallado hizo ruido por primera vez. El 500 no era un bug creado por ese commit; era el primer grito de un bug que siempre estuvo ahí.

Este es el coste del código que se traga los errores. La señal desaparece y el bug se queda, llevándose por delante una funcionalidad entera.

¿Por qué los tests estaban en verde?

Esta cola tenía tests. Un spec del tipo habitual: llamar al enqueue y comprobar que queue.add se invoca con los argumentos correctos. Y el queue.add de ese test era un mock que siempre tenía éxito.

El add real de BullMQ valida el jobId y rechaza los dos puntos. El add del mock acepta cualquier cosa. En la misma medida en que el mock es más permisivo que el contrato real, el test dejó pasar en verde una entrada que en la realidad jamás podría pasar. Cuando el mock difiere del contrato real, un test verde no certifica código vivo sino código muerto.

Al corregir, lo primero fue tapar este agujero. Cambié el add del mock de la cola para que ejecute el Job.validateOptions real de BullMQ. Es una validación pura que funciona sin Redis, así que se puede montar tal cual en los tests. Y comprobé con un test de mutación que la guardia era una guardia de verdad: reintroduje los dos puntos, vi que el test se ponía en rojo exactamente en ese punto, y solo entonces hice el commit. Si reviertes el bug y el test sigue en verde, ese test es como si no existiera.

No era un caso aislado

Haberme parado aquí habría sido arreglar solo la mitad. Si el mismo error está en un sitio, es muy probable que esté en otros. Definí la "clase" del defecto - jobId personalizado con dos puntos - rastreé toda la base de código y puse varios agentes de revisión a hacer verificación cruzada. Salieron dos casos más.

Uno era la cola que transcribe a texto los audios subidos por los usuarios. jobId: "stt:${id}". Aquí el error seguía tragándose, así que ni siquiera había un 500. Al comprobarlo, resultó que desde hacía 12 días ni un solo job de transcripción había entrado en la cola. Los archivos de audio se guardaban con normalidad, los fallos quedaban solo en los logs y en la pantalla del usuario el texto seguía vacío para siempre. Completamente asintomático.

El otro era la cola de correos informativos de eventos programados. Su jobId tenía cuatro partes separadas por dos puntos, así que ni los recordatorios ni los avisos de cancelación llegaban a entrar en la cola.

Unifiqué los producers de las tres colas en un único builder de jobId compartido: una función que une con guiones, sustituye los dos puntos que se cuelen y rechaza los valores puramente numéricos. Como prevención añadí una regla de lint que atrapa exactamente el patrón de un literal con dos puntos entrando en un jobId. No migré a la fuerza al nuevo builder los cincuenta y tantos jobId con guiones ya existentes: si cambia el jobId de un job repetible, el cron corre el riesgo de registrarse duplicado, así que preferí apuntar solo a la clase del defecto.

La segunda trampa: un jobId fijo mata los reintentos en silencio

Habría estado bien que la historia terminara aquí, pero durante la verificación de la revisión salió un problema más de fondo. Una vez corregidos los dos puntos, revive el jobId fijo tipo answer-notify-123, y ese jobId fijo contradecía por sí mismo el contrato de reintentos establecido el mismo día.

Si el hash de un job con el mismo jobId sigue en Redis, BullMQ ignora el nuevo add sin error alguno y devuelve el jobId existente. Es un comportamiento que el verificador confirmó leyendo hasta los scripts Lua de BullMQ. Pero esta cola usa removeOnComplete: { count: 100 }, así que el hash de un job recién completado se queda tal cual. Combinándolo todo, el escenario es este. El job de notificación falla una vez. Según el contrato, la marca de "respondida" se revierte y el administrador reintenta. El nuevo enqueue tropieza con el hash que quedó atrás, no hace nada y retorna como si hubiera tenido éxito. La notificación no sale jamás, pero esta vez no hay ni error ni DLQ.

Quitamos el catch que se tragaba los fallos, y el dedupe de la librería ocupó el mismo asiento. Al final, en esta cola eliminamos el jobId personalizado por completo. La prevención de duplicados se movió al lado del consumidor: el procesador se apropia de forma atómica de la marca de "notificación enviada" con una actualización condicional. Aunque el job entre dos veces, solo envía el push el lado que capturó la marca primero.

Si bloqueas duplicados con un jobId personalizado y a la vez tienes un diseño que reencola al fallar, merece la pena comprobar que los dos mecanismos no se matan entre sí. Puede ser, como en nuestro caso, una combinación en la que el reintento se convierte en un no-op silencioso.

¿Cuánto fue el daño?

Una funcionalidad muerta durante 12 días suena a daño grande, pero la medición real dijo otra cosa. Las notificaciones de respuesta pertenecían a una funcionalidad aún sin uso real en producción, así que las pérdidas fueron cero. La cola de correos solo tenía eventos ya pasados, sin nada que reenviar. Lo único que hubo que recuperar fueron dos audios sin transcribir. Se retranscribieron a partir de los archivos de audio conservados.

Tuvimos suerte. Y esa suerte no se repite. Si hubiera sido una funcionalidad en uso real, 12 días de notificaciones y transcripciones se habrían perdido sin más, y el despliegue no habría recuperado nada, porque los jobs nunca llegaron a crearse en la cola. Escribir el script de backfill era lo secundario. Juzgué que lo esencial era arreglar el hecho de que una funcionalidad muerta llevara 12 días muerta sin que nadie lo supiera. Así que los fallos de transcripción ya no se quedan solo en los logs sino que suben a un canal de alertas, y la ruta de las notificaciones de respuesta se movió a un outbox que se confirma junto con la transacción, eliminando de raíz el estado de "en la base de datos consta el éxito, pero el job no existe".

Lo que queda

Tres cosas de este incidente que durarán más que el código.

Primera: un catch que solo registra en el log y retorna con normalidad hace que nadie se entere aunque esa ruta falle el 100% de las veces. Si vas a tragarte el error, al menos debe ir acompañado de una métrica o una alerta que cuente los fallos; si no las hay, es mejor lanzar. Un error lanzado hace ruido pero se arregla; uno tragado vive 12 días.

Segunda: el mock debe ser tan estricto como el contrato real. Sobre un mock que siempre tiene éxito no se valida ninguna entrada. Si la librería tiene una función de validación pura, móntala en el mock y comprueba, revirtiendo el bug, que el test se pone en rojo. Solo entonces es una guardia.

Tercera: los defectos se cazan por clases. En una misma base de código, el mismo error no ocurre una sola vez. Cuando encuentres uno, define la clase, rastréalo todo y llega hasta impedir que esa clase vuelva a entrar, sea con una regla de lint o con un builder compartido. Solo así un hallazgo vale lo que cuesta.