fix(runner): laat waitForEnqueue echt tot de deadline wachten #63

Merged
janpeter merged 1 commit from fix/wait-for-enqueue-single-shot into master 2026-07-16 12:11:31 +02:00
Owner

De bug

waitForEnqueue keerde onvoorwaardelijk terug na de eerste tick:

while (Date.now() < deadline) {
  await new Promise<void>((resolve) => {
    const pollTimer = setTimeout(resolve, POLL_INTERVAL_MS)   // ← resolvet ook zónder NOTIFY
    ...
  })
  // Out of the inner promise — caller will retry tryClaimJob.
  return                                                       // ← altijd, na ~5s
}

De inner promise resolvet op een matchende NOTIFY of op de poll-timer. Door de return gaf de functie dus na POLL_INTERVAL_MS (5s) op, en was while (Date.now() < deadline) dode code — de 270s werd nooit gehaald.

De caller deed daarna nog één claim-poging en logde claim timeout after 270s — exiting 0. Dat was onwaar: het waren ~5 seconden. Het proces exitte, de supervisor startte het opnieuw, en zo cyclede elke worker een compleet nieuw proces per ~8s — met per keer een eigen registerWorker, auth-check, Prisma-pool en LISTEN-verbinding.

Gemeten op max2 (agent-codex, idle queue): 421 runs in uur 08, 323 in uur 09. NOTIFY leverde effectief niets op; de latency was puur poll-gedreven via procesherstarts.

De fix

Na elke tick opnieuw claimen, binnen één LISTEN-verbinding, tot er werk is of de deadline verstrijkt.

Bewust niet alleen de return weggehaald: dan zou bij een gemiste NOTIFY 270s lang geen enkele claim-poging gedaan worden — dat maakt de latency juist slechter. De poll blijft het vangnet voor een NOTIFY die we niet kúnnen zien (job stond al in de queue vóór de LISTEN), dus de worst-case latency blijft ~5s, nu zonder procesherstart. De claim timeout after 270s-regel klopt voortaan.

Tweede bug, meegefixt: de listener werd alleen op het NOTIFY-pad verwijderd. Zolang de functie single-shot was viel dat niet op; met een echte loop stapelt elke poll-tick een listener op de langlevende client. finish() ruimt nu in beide paden op.

Structuur

De tick/claim-loop staat nu in lib/wait-for-enqueue.ts — conform de bestaande lib/-conventie (pure, testbare logica; run-one-job.ts roept main() aan bij import en is niet importeerbaar). connect/LISTEN/end blijft in de runner.

Verificatie

npx vitest run16/16 groen (5 nieuwe tests).

De tests vangen beide bugs aantoonbaar — ik heb ze los teruggezet:

mutatie resultaat
single-shot return terug 3 tests falen (blijft-claimen, deadline→null, listener-cleanup)
listener-cleanup alleen op NOTIFY-pad 1 test faalt (listener-cleanup)
beide hersteld 16/16 groen

Gedekt: doorclaimen bij elke poll-tick, directe claim bij NOTIFY zonder de poll af te wachten, null op de deadline, geen listener-lek, en negeren van NOTIFY voor een andere user / ander type / onparseerbare payload.

Effect op DB-connecties

Het aantal gelijktijdige verbindingen per worker verandert niet (~2: Prisma-pool + LISTEN-client), maar ze worden nu vastgehouden i.p.v. elke ~8s opnieuw opgebouwd. De connect-storm verdwijnt; gemiddeld per worker gaat het van ~60% duty-cycle naar ~100% (dus ~+0,8 verbinding per worker, verwaarloosbaar tegen max_connections), tegenover ~450 connect/disconnect-cycli per uur minder.

Uitrol

Vergt image-rebuild + recreate (redeploy_all_workers); bin/ en lib/ zijn image-baked.

## De bug `waitForEnqueue` keerde onvoorwaardelijk terug na de **eerste** tick: ```ts while (Date.now() < deadline) { await new Promise<void>((resolve) => { const pollTimer = setTimeout(resolve, POLL_INTERVAL_MS) // ← resolvet ook zónder NOTIFY ... }) // Out of the inner promise — caller will retry tryClaimJob. return // ← altijd, na ~5s } ``` De inner promise resolvet op een matchende NOTIFY **of** op de poll-timer. Door de `return` gaf de functie dus na `POLL_INTERVAL_MS` (5s) op, en was `while (Date.now() < deadline)` dode code — de 270s werd nooit gehaald. De caller deed daarna nog één claim-poging en logde `claim timeout after 270s — exiting 0`. Dat was **onwaar**: het waren ~5 seconden. Het proces exitte, de supervisor startte het opnieuw, en zo cyclede elke worker een compleet nieuw proces per ~8s — met per keer een eigen `registerWorker`, auth-check, Prisma-pool en LISTEN-verbinding. Gemeten op max2 (agent-codex, idle queue): **421 runs in uur 08, 323 in uur 09**. NOTIFY leverde effectief niets op; de latency was puur poll-gedreven via procesherstarts. ## De fix Na elke tick opnieuw claimen, binnen **één** LISTEN-verbinding, tot er werk is of de deadline verstrijkt. Bewust **niet** alleen de `return` weggehaald: dan zou bij een gemiste NOTIFY 270s lang geen enkele claim-poging gedaan worden — dat maakt de latency juist slechter. De poll blijft het vangnet voor een NOTIFY die we niet kúnnen zien (job stond al in de queue vóór de `LISTEN`), dus de worst-case latency blijft ~5s, nu zonder procesherstart. De `claim timeout after 270s`-regel klopt voortaan. **Tweede bug, meegefixt:** de listener werd alleen op het NOTIFY-pad verwijderd. Zolang de functie single-shot was viel dat niet op; met een echte loop stapelt elke poll-tick een listener op de langlevende client. `finish()` ruimt nu in beide paden op. ## Structuur De tick/claim-loop staat nu in `lib/wait-for-enqueue.ts` — conform de bestaande `lib/`-conventie (pure, testbare logica; `run-one-job.ts` roept `main()` aan bij import en is niet importeerbaar). `connect`/`LISTEN`/`end` blijft in de runner. ## Verificatie `npx vitest run` → **16/16 groen** (5 nieuwe tests). De tests vangen beide bugs aantoonbaar — ik heb ze los teruggezet: | mutatie | resultaat | |---|---| | single-shot `return` terug | **3 tests falen** (blijft-claimen, deadline→null, listener-cleanup) | | listener-cleanup alleen op NOTIFY-pad | **1 test faalt** (listener-cleanup) | | beide hersteld | 16/16 groen | Gedekt: doorclaimen bij elke poll-tick, directe claim bij NOTIFY zonder de poll af te wachten, `null` op de deadline, geen listener-lek, en negeren van NOTIFY voor een andere user / ander type / onparseerbare payload. ## Effect op DB-connecties Het aantal gelijktijdige verbindingen per worker verandert niet (~2: Prisma-pool + LISTEN-client), maar ze worden nu vastgehouden i.p.v. elke ~8s opnieuw opgebouwd. De connect-storm verdwijnt; gemiddeld per worker gaat het van ~60% duty-cycle naar ~100% (dus ~+0,8 verbinding per worker, verwaarloosbaar tegen `max_connections`), tegenover ~450 connect/disconnect-cycli per uur minder. ## Uitrol Vergt image-rebuild + recreate (`redeploy_all_workers`); `bin/` en `lib/` zijn image-baked.
fix(runner): laat waitForEnqueue echt tot de deadline wachten
All checks were successful
CI / Compose config (pull_request) Successful in 4s
CI / Docker build (pull_request) Successful in 1m12s
55bf565964
waitForEnqueue keerde onvoorwaardelijk terug na de EERSTE tick. Die tick
resolvet ook op de poll-timer, dus de functie gaf na POLL_INTERVAL_MS (5s)
op en `while (Date.now() < deadline)` was dode code — de 270s deadline werd
nooit gehaald.

Gevolg: run-one-job probeerde nog één claim, logde "claim timeout after
270s — exiting 0" (onwaar: het waren ~5s) en exitte. De supervisor startte
opnieuw, dus elke worker cyclede een compleet nieuw proces per ~8s:
op max2 421 runs in één uur, elk met een eigen registerWorker, auth-check,
Prisma-pool en LISTEN-verbinding. De queue-latency was daarmee feitelijk
poll-gedreven; NOTIFY leverde niets op.

Nu wordt na elke tick opnieuw geclaimd, binnen één LISTEN-verbinding, tot
er werk is of de deadline verstrijkt. De poll blijft het vangnet voor een
NOTIFY die we niet kunnen zien (job stond al in de queue vóór de LISTEN),
dus de worst-case latency blijft ~5s — alleen zonder procesherstart. Het
"claim timeout after 270s"-logregel klopt nu ook.

Tweede bug, meegefixt: de listener werd alleen op het NOTIFY-pad verwijderd.
Zolang de functie single-shot was viel dat niet op; met een echte loop zou
elke poll-tick een listener opstapelen op de langlevende client. finish()
ruimt nu in beide paden op.

De tick/claim-loop staat in lib/wait-for-enqueue.ts (conform lib/-conventie:
pure logica, testbaar zonder DB); connect/LISTEN/end blijft in de runner.

Tests dekken beide bugs — geverifieerd door ze los terug te zetten:
single-shot return laat 3 tests falen, het listener-lek 1.

Effect op DB-connecties: het aantal gelijktijdige verbindingen per worker
verandert niet (~2), maar ze worden nu vastgehouden i.p.v. elke ~8s op-
nieuw opgebouwd — de connect-storm verdwijnt.
s4m-codex-reviewer left a comment

Verdict: APPROVED

Geen gekoppeld plan gevonden — beoordeeld op codekwaliteit + product-standaarden.

Findings

  • Geen blokkerende findings.

De wijziging houdt de LISTEN/DB-koppeling in bin/run-one-job.ts en verplaatst de herbruikbare wacht-/claim-loop naar een pure helper met gerichte regressietests. De testset dekt de kernbug (single-shot wait), NOTIFY-pad, deadline-pad, listener-cleanup en genegeerde payloads.

# Verdict: APPROVED Geen gekoppeld plan gevonden — beoordeeld op codekwaliteit + product-standaarden. ## Findings - Geen blokkerende findings. De wijziging houdt de LISTEN/DB-koppeling in `bin/run-one-job.ts` en verplaatst de herbruikbare wacht-/claim-loop naar een pure helper met gerichte regressietests. De testset dekt de kernbug (single-shot wait), NOTIFY-pad, deadline-pad, listener-cleanup en genegeerde payloads.
janpeter merged commit 8e0afca3af into master 2026-07-16 12:11:31 +02:00
Sign in to join this conversation.
No reviewers
No labels
No milestone
No project
No assignees
2 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
janpeter/scrum4me-docker!63
No description provided.