Skip to content

El ack espera a que el job termine, y el hilo de E/S sigue latiendo - #997

Merged
github-actions[bot] merged 3 commits into
developfrom
fix/el-ack-espera-al-job
Oct 8, 2026
Merged

github-actions[bot] merged 3 commits into
developfrom
fix/el-ack-espera-al-job

Conversation

@frapercan

Copy link
Copy Markdown
Owner

Por qué

El consumer confirmaba el mensaje antes de ejecutar el job, para esquivar el
consumer_timeout del broker. Eso tenía dos efectos medidos durante la fase 2
de la campaña GOA:

  1. El segundo nodo se quedaba sin trabajo. Con el ack inmediato el canal
    queda con 0 sin confirmar, así que RabbitMQ asigna el siguiente mensaje al
    mismo consumidor, que lo deja en su buffer local durante la hora que dura la
    carga en curso. El sobremesa no veía nada que tomar.
  2. La conexión se moría en cada carga. El consumer_timeout no era el
    temporizador que mandaba: lo era el heartbeat AMQP. handle_job bloquea el
    bucle de E/S de pika, pika deja de enviar heartbeats, y el broker cierra a
    los 2x600 s. Medido en el log del worker: 58 StreamLostError y 75 avisos de
    missed heartbeats en el log del broker, uno por carga, a los ~20-26 min.

Qué cambia

El job pasa a un hilo propio y el hilo de E/S se queda bombeando la conexión
cada 5 s mientras dura (_run_job_while_pumping). El ack se mueve al finally,
detrás del job, de modo que el mensaje sigue sin confirmar mientras se ejecuta y
el prefetch de 1 reserva el nodo. Las dos mitades son inseparables: mover el ack
sin bombear deja que el broker cierre la conexión igual, y bombear sin mover el
ack no reparte trabajo.

Un fallo del worker sigue confirmando el mensaje, sin reencolar: eso no cambia,
y los tests que lo fijaban siguen ahí con el nombre corregido
(test_worker_failure_still_acks). Se añaden dos guardas de orden:
test_the_ack_waits_for_the_job y test_a_failing_job_is_still_acked_last.

Medido en producción

Desplegado en el portátil el 2026-10-08 a las 15:49. En las 35 min siguientes y
en la carga completa de la release 168 (63,6 min):

  • StreamLostError nuevos: 0 (antes: uno por carga)
  • missed heartbeats nuevos: 0 (antes: uno por carga)
  • messages_ready=0, messages_unacknowledged=1 — el nodo retiene su mensaje
    durante toda la carga, que es el efecto buscado
  • el log muestra Job finished y Job acked en el mismo segundo, y ya no
    Job acked junto al Dispatching

La 168 tardó 63,6 min contra los 62,7 de la 166 en solitario: correr dos nodos
no le cuesta nada al que ya iba.

Lo otro que lleva

El commit de la deuda de formato (toLocaleString en 83 sitios, la guarda
noAmbientLocale y scripts/deploy-frontend.sh) se quedó fuera de #996 porque
entró después del merge. Va aquí sin cambios.

… no tumba el sitio

Francisco: "no me gusta la deuda tecnica". Barrida entera.

QUE ERA. `x.toLocaleString()` y `new Date(x).toLocaleString([])` leen el
locale y la zona horaria del ENTORNO. Node en esta maquina resuelve a
es-ES / Europe/Madrid y el navegador del visitante resuelve al suyo, asi
que el servidor pintaba "754.862" y un navegador en ingles "754,862".
React se niega a reconciliar eso: era el React #418 de
/instrument/datasets y la razon de que el separador de miles no
coincidiera entre paginas.

Ahora todo pasa por lib/format.ts, con formateadores fijos: en-GB para
los numeros y UTC etiquetado para las fechas. UTC a proposito, porque en
una pagina de operaciones una hora vale mas si todos los lectores miran
el mismo instante. La prosa de la portada NO pasa por aqui: esa va por
el `{n, number}` de next-intl, que si es sensible al idioma y ya coincide
en ambos lados porque los dos conocen la ruta.

LA GUARDA ES LO QUE IMPIDE QUE VUELVA. Un test recorre app, components,
lib Y tests buscando cualquier `toLocale*` sin locale. Comprobado que
falla si se reintroduce una. Encontro ademas 8 que mis expresiones no
cogian, las variantes toLocaleDateString y toLocaleTimeString.

Incluye los tests a proposito: lib/cellPopulation.test.ts construia su
cadena esperada llamando a `(6234).toLocaleString()`, lo mismo que
llamaba el codigo. Era una tautologia, afirmaba que la funcion coincide
consigo misma, y por eso llevaba pasando todo este tiempo con un test
cuyo NOMBRE dice "formats large counts with separators" mientras esperaba
"6234" sin separador.

Y LO QUE PASO MIENTRAS, que es lo que mas importa de este commit.

Un corte de red de dos minutos dejo a next/font/google sin alcanzar, el
build murio, y como `next build` BORRA .next antes de reconstruirlo, el
servicio se quedo sin nada que servir: protea.ngrok.app devolvio 502
durante unos diez minutos. Es exactamente la trampa que documente esta
manana y sobre la que avise al auditor, y cai en ella por dejar de hacer
la copia de seguridad que si hice en el primer despliegue.

scripts/deploy-frontend.sh existe para que no vuelva a depender de que yo
me acuerde: guarda el build que esta sirviendo, construye, reinicia,
COMPRUEBA que responde 200, y si cualquiera de esos pasos falla deja otra
vez el anterior. Probado de punta a punta.

Tres componentes mas que el barrido rompio y tsc no veia: el import
quedo ANTES de la directiva "use client", que tiene que ir la primera.
TypeScript no vigila eso; Turbopack si.
Dos cambios que tienen que ir juntos, y la razon de que sean inseparables
es la parte interesante.

EL SINTOMA. Con dos nodos en protea.jobs, el segundo se moria de hambre.
El worker ocupado ackeaba al EMPEZAR, su ventana de prefetch quedaba
libre, el broker le entregaba el siguiente mensaje y ese mensaje se
quedaba una hora sin llegar al callback. Medido: ready=0, unacked=1,
consumers=2, con un nodo ocioso.

LA CAUSA MAS PROFUNDA, que encontro una revision adversaria y que no
habiamos visto en dias de campana: el pre-ack existia para esquivar el
consumer_timeout de RabbitMQ, pero ese nunca fue el reloj que mandaba.
Pika manda los latidos desde su bucle de E/S, handle_job lo bloquea una
hora entera y nada en ese camino cede el control, asi que el broker
cerraba la conexion a los dos intervalos de heartbeat. Medido en el
sistema vivo:

  timeout de las tres conexiones            600 s
  "missed heartbeats" en el log del broker   75
  StreamLostError en el log del worker       58  seguidos de reconexion

O sea que la conexion se caia en CADA carga larga, y llevaba asi desde
el principio. Subir consumer_timeout, que fue mi primer intento, no
habria servido de nada: el canal ya estaba muerto.

POR QUE LOS DOS ARREGLOS SON INSEPARABLES. Si solo bombeo eventos para
mantener viva la conexion y sigo ackeando al principio, la ventana libre
deja que pika entregue un SEGUNDO job de forma reentrante dentro del
mismo callback, donde _guard.track pisaria el job en curso y el
heartbeat del lease no arrancaria por estar ya vivo. Y si solo muevo el
ack al final sin bombear, el canal esta muerto cuando toca ackear y falla
en el 100% de las cargas largas. Juntos se sostienen: el bombeo mantiene
el enlace para que el ack llegue, y el ack retenido mantiene la ventana
ocupada para que el bombeo no entregue nada.

Seguro de hilar: el worker construye cada Session desde un sessionmaker
plano dentro de la llamada, y el unico AMQP que hace es publish_job /
publish_operation, que abren su propia conexion desde una URL en vez de
tocar este canal. Los dos hilos no comparten ningun objeto de pika.

LOS TESTS NO PODIAN VER ESTO. Las siete aserciones de ack en
test_queue.py comprueban los ARGUMENTOS y el NUMERO de llamadas, que el
cambio no toca, asi que la suite entera pasaba con el ack en cualquier
sitio. Tres de ellas se llamaban "acks_before_execution" y afirmaban lo
contrario de lo que comprobaban. Renombradas, y dos guardas nuevas fijan
el ORDEN: con el ack devuelto a su sitio viejo fallan ocho tests.
@github-actions
github-actions Bot enabled auto-merge (squash) October 8, 2026 16:35
@codecov

codecov Bot commented Oct 8, 2026 •

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 78.37838% with 8 lines in your changes missing coverage. Please review.
✅ Project coverage is 87.78%. Comparing base (d8bc801) to head (7354f37).
⚠️ Report is 96 commits behind head on develop.

Files with missing lines Patch % Lines
protea/infrastructure/queue/_job_pump.py 76.47% 8 Missing ⚠️
Additional details and impacted files

Impacted file tree graph

@@             Coverage Diff             @@
##           develop     #997      +/-   ##
===========================================
- Coverage    87.85%   87.78%   -0.08%     
===========================================
  Files          306      329      +23     
  Lines        23414    25321    +1907     
===========================================
+ Hits         20570    22227    +1657     
- Misses        2844     3094     +250     
Files with missing lines Coverage Δ
protea/infrastructure/queue/consumer.py 93.96% <100.00%> (+1.99%) ⬆️
protea/infrastructure/queue/_job_pump.py 76.47% <76.47%> (ø)

... and 35 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

`_dispatch_job` se habia quedado en 90 LOC y consumer.py en 913, y el
presupuesto de smells los marco como nuevo y empeorado. El arreglo no es
reescribir el baseline: lo que sobraba en `_dispatch_job` era la explicacion
de por que el ack espera, que describe la pareja bombeo+ack y no el
despacho.

`_job_pump.py` se queda con las dos funciones, que son inseparables: el
bombeo mantiene viva la conexion para que el ack tardio pueda llegar, y
retener el ack ocupa la ventana de prefetch para que el bombeo no despache
un segundo job de forma reentrante en el mismo callback. Las mediciones del
2026-10-08 que justificaban el cambio se van con ellas al docstring del
modulo.

Sin cambio de comportamiento: consumer.py queda en 834 LOC contra un
baseline de 835, el presupuesto pasa, y los 68 tests de cola siguen en
verde, incluidas las dos guardas de orden del ack.
@github-actions
github-actions Bot merged commit a38486d into develop Oct 8, 2026
21 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant