Report worker boot failures on /health instead of exiting silently - #262
Open
NathanTarbert wants to merge 1 commit into
Open
Report worker boot failures on /health instead of exiting silently#262NathanTarbert wants to merge 1 commit into
NathanTarbert wants to merge 1 commit into
Conversation
… worker stalled Restores the worker /health endpoint deferred by d0c6f99, with the three incident-class defects that deferral named actually fixed rather than re-landed. main's drift guard, start.sh and repair migration are untouched -- the regex classifier from defect 2 is NOT reintroduced. THE LIVENESS MODEL Defect 1 was a healthy worker answering 503 "stalled". poll() stamps lastPollTime and then awaits the jobs it claimed, so the stamp freezes for as long as the work takes. b8a68e3 compared it against STALE_POLL_MS=60s; a 300s job therefore read as wedged and the container probe killed it mid-job. Bounding the poll instead does not work either, and this is worth recording because it is the trap: claimJobsByType awaits each TYPE's batch sequentially, so one poll can legitimately run the SUM of every registered type's timeout -- 930s against this worker's ten types, against a max-plus-grace bound of 360s. Same incident, different arithmetic. So poll duration is not the signal. Worker now publishes overdueJobCount: in-flight jobs past their OWN timeout plus a grace, which needs no scheduling arithmetic and cannot drift out of step with how poll() batches. A poll with nothing claimed is separately bounded by CLAIM_STALL_MS, since that is the one case no job can be blamed for. lastPollCompletedAt measures the gap BETWEEN polls, which is what STALE_POLL_MS was always trying to measure. Also fixed, per review: an explicitly-set but unusable PORT is now fatal rather than defaulted. Number.parseInt reads a numeric prefix, so "3003abc" bound 3003 and "0" bound an OS-assigned ephemeral port -- and the Dockerfile probes ${PORT:-...}, where shell :- substitutes only for unset or EMPTY, so serving on a fallback guarantees a probe that can never connect. A wrong port is unreportable over that port, exactly like EADDRINUSE. DEFECT 3 Number(process.env.X ?? default) collapsed to 0 on a cleared variable: `??` guards undefined and null, and Number('') is 0, not NaN. resolveDurationMs replaces it for SHUTDOWN_WATCHDOG_MS and BOOT_FAILURE_LINGER_MS, and also bounds the top -- setTimeout clamps past 2**31-1 to 1ms, so "effectively never" became "immediately", which is the same bug from the other end. HONESTY failFatally now stops the scheduler and worker before exiting. It was leaving every job claimed in its 5s window at status='PROCESSING', and nothing requeues a stale lockedAt, so those jobs were lost rather than retried -- the hazard the boot-after-shutdown guard exists to prevent, reached by another path. It also reports a post-boot crash as 'crashed', not 'failed': the failed-boot advice points at schema.prisma and the drift guard, so filing a handler's stray rejection under it sends whoever is paged to audit migrations. Config warnings now ride on /health instead of dying in a boot log. The watchdog one prints at boot and bites at the next deploy, potentially weeks later. VERIFICATION turbo build/typecheck/lint/test 10/10, lint 0 errors. apps/worker 22 -> 70 tests, packages/outpost 1196 -> 1208. Root vitest.config.ts (which no turbo task runs) 4 files / 64 passing. Prettier clean on every changed file. Mutation-tested, since vacuous tests are what sank the first attempt: the old max-bound model fails 7; reordering the overdue check fails 1; resolvePort accepting 0 fails 1; lenient parseInt fails 3; dropping the duration upper bound fails 3; crash-as-failed fails 2; a second exit timer fails 1; removing the overdue grace fails 1. Two guards were REMOVED after mutation showed no input could reach them: a poll re-entrancy check (poll() only runs from a timer armed at the end of a poll) and a poll-generation token (its only scenario needs a stop()/start() overlap nothing performs, and it mutually masked with the !running check). reschedule() keeps its !running guard, and the test comment says plainly that removing it leaves the suite green rather than implying coverage.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The worker reports why a boot failed instead of dying silently, and a worker doing long work is no longer reported as stalled. This restores the
/healthrework thatd0c6f99deferred, with the three incident-class defects that deferral named fixed rather than re-landed.Closes the worker half of #187's split (CPK-7926).
What is deliberately NOT restored
apps/worker/start.sh, the schema-drift guard and the repair migration stay exactly as they are onmain. Those are the verified parts of the original PR, andd0c6f99replaced the drift guard's regex classifier with the plainmigrate diff --exit-codeform for good reason — the classifier passed real drift, sinceALTER TYPE ... ADD VALUEandALTER COLUMNmatch neither pattern. Restoringb8a68e3wholesale would have brought it back.apps/worker/Dockerfileis untouched too; its HEALTHCHECK port fix was kept onmain.The liveness model, which is the substance of this PR
Defect 1 was a healthy worker answering 503
"stalled".poll()stampslastPollTimeand then awaits the jobs it claimed, so the stamp freezes for as long as the work takes.b8a68e3compared it againstSTALE_POLL_MS = 60s, so a 300sHUBSPOT_SYNCread as wedged and the container probe killed the worker mid-job.Bounding the poll instead does not work, and this is the part worth reading. My first attempt at this fix bounded an in-flight poll at
max(jobTimeouts) + grace= 360s. That is also wrong, becauseclaimJobsByTypeawaits each type's batch sequentially:One poll is therefore the sum across types, not the max — 930s against this worker's ten registered types, every job inside its own timeout. Same incident as the one being fixed, reached by different arithmetic.
So poll duration is not the signal at all:
overdueJobCount— in-flight jobs past their own timeout plus a grace. Needs no scheduling arithmetic, so it cannot drift out of step with howpoll()batches.CLAIM_STALL_MS— bounds a poll with nothing claimed, which is the one case no job can be blamed for.lastPollCompletedAt— measures the gap between polls, which is whatSTALE_POLL_MSwas always trying to measure.maxJobTimeoutMswas in an earlier revision of this branch and is gone; it existed only to support the bound that was wrong.Defect 3, and a variant of it from the other end
Number(process.env.X ?? default)collapsed to 0 on a cleared variable:??guardsundefinedandnull, andNumber('')is0, notNaN. A clearedSHUTDOWN_WATCHDOG_MSbecame a 0ms watchdog forcingexit(1)on every SIGTERM mid-drain.resolveDurationMsreplaces it.It also bounds the top, which the original did not:
setTimeoutclamps anything above 2³¹−1 to 1ms, so an operator reaching for "effectively never" got "immediately" — the same defect from the other side. (Same shape as theSHADOW_MODEfail-open in #233, and worth noticing that this class keeps recurring.)resolvePortis now strict and fatal on an explicitly-set but unusable value.Number.parseIntreads a numeric prefix, so"3003abc"silently bound 3003 and"0"bound an OS-assigned ephemeral port. The Dockerfile probes${PORT:-${HEALTH_PORT:-3003}}, and shell:-substitutes only for unset or empty — so serving on a fallback guarantees a probe that can never connect, a container dead in ~90s, and/healthanswering 200 the whole way. A wrong port cannot be reported over that port, exactly likeEADDRINUSE, so it fails closed.Honesty fixes
failFatallynow stops the scheduler and worker before exiting. It was leaving every job claimed in its 5s window atstatus='PROCESSING', and nothing requeues a stalelockedAt, so those jobs were lost rather than retried — the hazardstartWorker's boot-after-shutdown guard exists to prevent, reached by another path. A stale-lockedAtrequeue sweep is worth its own change; abrupt exits are not avoidable in general.A post-boot crash now reports as
crashed, notfailed. The failed-boot log advice points atschema.prismaand the drift guard, so filing a handler's stray rejection under it sends whoever is paged to audit migrations for a bug in an AI handler.Config warnings ride on
/healthinstead of dying in a boot log. The watchdog one is the sharpest: it prints at boot and only bites at the next deploy, potentially weeks later, when nobody is looking at that line.Verification
turbo build/typecheck/lint/test10/10, lint 0 errors. apps/worker 22 → 70 tests. packages/outpost 1196 → 1208. Prettier clean on every changed file. Also ran the rootvitest.config.ts— 4 files / 64 passing — because no turbo task runs it, soscripts/__tests__/**is otherwise green-by-absence in CI.Mutation-tested, since vacuous tests are what sank the first attempt:
max(jobTimeouts)bound model restoredresolvePortaccepts0againresolvePortback to lenientparseIntfailedTwo guards I removed, and one I kept without coverage
Mutation testing showed no input could reach either of these, so they are gone rather than sitting there looking like protection: a poll re-entrancy check (
poll()only ever runs from a timer armed at the end of a poll, so it cannot overlap itself) and a poll-generation token (its only scenario needs astop()/start()overlap nothing performs, and it mutually masked with the!runningcheck, so no single mutation could fail).reschedule()keeps its!runningguard. Being straight about it: removing that guard leaves the suite green.poll()already returns on!running, so the guard prevents a queued timer handle rather than lost work, and after processingnextPollDelayis 0 — so the re-armed timer fires on the next flush either way. The test comment says so rather than implying coverage. It is kept because a handle queued behind a resolvedstop()is worth preventing at the source.What is not covered
index.tshas no direct tests. It is a top-level-await module with import-time side effects, so its boot behaviour cannot be exercised in-process.classifyFatalErrorand the boot-state logic are extracted intohealth.tsfor that reason and are tested there, but the wiring itself is not. ExtractingstartWorkerto accept injectedWorker/Schedulerfactories would fix that and is worth doing separately./healthis still the only place to read it.railway.tomlis untouched. An earlier revision of this branch loweredhealthcheckTimeoutto 180; I reverted it. The Dockerfile budgets--start-period=120sfor two Prisma CLI invocations before anything binds, which leaves only 60s of headroom, and the deploy this unblocks is staging — the environment with the largest pending-migration backlog. Timing a realmigrate deployagainst that backlog should come before narrowing the window.runWithTimeoutis aPromise.racethat does not cancel the handler, so an orphaned handler keeps running and holding its connection after its job is marked failed.activeJobCounttherefore understates real work. Pre-existing, andoverdueJobCountis measured against the tracked entry rather than the orphan, so this PR does not depend on it./healthis unauthenticated and spreads the whole worker snapshot, includingregisteredHandlers.main's handler did the same, so this is pre-existing — flagging it because this is the change that establishes what the endpoint is allowed to say.Review note
The earlier revision of this branch went through a review round, which is what caught the 360s bound described above. The rewrite that replaced it has not been reviewed, so a pass over
overdueJobCountandCLAIM_STALL_MSspecifically would be worth having before merge.