Set fx.StopTimeout inside the container stop grace (closes #134) #159
Reference in New Issue
Block a user
Delete Branch "issue-134-fx-stop-timeout"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Closes #134.
What changed
fx.StopTimeoutset to 5s (cmd/webhooker/main.go). fx defaults to 15s and the Dockerfile sets noSTOPSIGNALor grace override, so Docker's 10s default SIGKILLed the process five seconds before the bound could fire. Everything gated on it — including theshutdown timed out, goroutines still runningerror log that tells an operator a component is wedged — was unreachable in the image this repo produces. 5s sits inside the grace with headroom for signal delivery and process exit.The option set moved into
newApp() *fx.Appso a test can read(*fx.App).StopTimeout()back.fx.Newapplies options before executing invokes, so the value is set regardless of whether the graph constructs.HTTP drain budget lowered from 5s to 3s (
internal/server.ShutdownTimeout, now exported so the relationship can be tested). fx bounds the whole stop sequence and returns without running its remaining hooks once the stop context expires. With both values at 5s, an HTTP drain that used its full budget exhausted the sequence budget at that instant and every later hook — the delivery engine, the healthcheck, theWebhookDBManagerand the database close — was skipped, in exactly the case where the drain mattered.The Sentry flush is now bounded by the remaining stop budget (
internal/server/server.go). The server's stop hook is not only the drain:cleanShutdowncallssentry.Flushafter it, in the same hook, andsentry.Flushtakes a bare duration and honours no context. WithSENTRY_DSNpointed at an unreachable endpoint — a configuration the README documents — a full-length 3s drain plus a stalled 2s flush spent the entire 5s sequence budget by itself and the tail hooks, database close included, were skipped again. The previous round's code comment and README text both asserted the opposite; both are corrected.server.SentryFlushBudget(remaining)clamps the flush to the time left on the fx stop context lessserver.TailHookReserve(2s), capped at the nominal 2s and floored at 250ms — below that the flush is skipped outright with askipping sentry flush, stop budget exhaustedwarning rather than making an attempt too short to complete a round trip.cleanShutdownreads the deadline off the fx stop context; a context with no deadline (a caller outside the fx lifecycle) gets the full nominal timeout. So a full-length drain now drops Sentry events instead of the database close.The anti-drift guard now covers the whole hook.
TestStopTimeout_LeavesHeadroomForTailHookspreviously comparedstopTimeoutagainstShutdownTimeoutalone, so it sat green while its own invariant was violated. It now walks every drain length the hook can produce in 10ms steps and assertsdrain + SentryFlushBudget(stopTimeout - drain) + 2s tail margin <= stopTimeout, which is the hook's real worst case — the sweep matters because a shorter drain leaves the flush more room, so the worst case is not necessarily at either extreme.TestSentryFlushBudgetcovers the clamp directly (full drain, expired budget, a sliver above the reserve, a partial flush, and the cap).This does not make the database close unconditional. The
ArchiveSweeperandRetentionReaperhooks run before the server and can still consume the whole 5s on their own, in which case the tail — DB close included — is still skipped. What the change buys is narrower: the server's own hook can no longer eat the budget, whether by drain, by flush, or by both.Latent coin flip fixed in the shared stop-hook waiter (
internal/lifecycle/lifecycle.go). It selected on the drained channel againstctx.Done()with no preamble, andselectpicks uniformly among ready cases, so a component that drained against an already-expired context reportedshutdown timed outabout half the time. Not reachable through fx today — fx re-checksctx.Err()before each remaining hook — but the helper is shared and a direct caller can reach it. Split into an unexportedwaitDone(ctx, log, component, done)carrying aselect { case <-done: return nil; default: }preamble, exposed to the external test package viaexport_test.go.README: the real stop-hook order (below), both timeouts, why the drain budget is strictly shorter, why the Sentry flush is clamped rather than given its own fixed budget, and the relationship to the container stop grace — that fx returns outright on an expired stop context and skips its remaining hooks, so a wedge in the first-stopped component means the database close never runs; and that lowering the deployment grace below 5s (
docker stop --time, Composestop_grace_period, KubernetesterminationGracePeriodSeconds) puts SIGKILL back in front of the bound and reintroduces the silent truncation. Theinternal/lifecycle/entry in the Package Layout tree lands in its sorted position; the out-of-order duplicate this branch rebased onto is dropped.TODO.mduntouched.Stop-hook order, read off the fx log
Sentry probe: the finding from the last review, fixed
Temporary probe route holding one request open for 30s so
httpServer.Shutdownruns to its full budget,SENTRY_DSN=http://...@10.255.255.1:9999/1(blackhole) so the flush stalls, one event captured in the held request. Run againstmake build; probe patch reverted afterwards,git statusclean and the tree byte-identical to the commit. Both arms ran on the committed shutdown code; the last rebase after them touched only rate-limit keying, no shutdown path.Exit 0, all seven hooks including the database close. Control arm, same probe with
SentryFlushBudgetreverted to the unbounded fixed 2s, reproduces the reviewed failure:Drain probe (previous round, not re-run)
3s/5s: exit 0 at 3.045s, tail hooks including the database close all ran. Control 5s/5s: exit 1 at 5.012s, sequence stopped dead after the server hook. Independently reproduced by the reviewer on their own clone.
docker stopdemonstration (previous round, not re-run)Default 10s grace, no override: pre-stop status running, exit code 0, all seven stop hooks ran,
internal/database.New.func2()last. Independently reproduced by the reviewer. Wall-clockdocker stoptimings on this shared host vary widely with load, so the exit code and the hook log are the load-bearing evidence, not the elapsed figure.Mutation verification
SentryFlushBudgetreduced toreturn sentryFlushTimeout(the unbounded flush):TestStopTimeout_LeavesHeadroomForTailHooksfails with"5.01s" is not less than or equal to "5s", messagea 1.01s drain leaves the tail hooks short.TestSentryFlushBudgetfails four of its five cases. Reverted; the working tree is byte-identical to the commit.ShutdownTimeoutto 5s:"5s" is not less than "5s". (Previous round; not re-run.)fx.StopTimeout(stopTimeout):TestNewApp_StopTimeoutfailsexpected: 5s / actual : 15s. (Previous round; not re-run.)waitDonepreamble:TestWaitDone_DrainedBeforeExpiredContextfails at pass 1. (Previous round; not re-run.)Gate evidence
Rebased twice during this round as
nextmoved; both rebases were clean, and the READMEinternal/lifecycle/duplicate noted above was the one semantic conflict a clean textual merge left behind. Everything below is from the final pushed tree.docker build --no-cache-filter=lint --no-cache-filter=builder .— exit 0, 3m13s wall. Checks really executed:#21 [lint 8/8] RUN make lint→#21 59.48 0 issues.#20 [lint 7/8] RUN make fmt-check#34 [builder 9/11] RUN make testwith real per-package durations and zero(cached)markers (grep count: 0):The only
CACHEDlayers are base-image resolves, the runtimeapk/adduser/WORKDIRlayers, and the lint stage'sgo mod download.make check— exit 0 on the same tree, with an isolatedGOLANGCI_LINT_CACHE;0 issues., no foreign paths in the output, so no shared-cache bleed (#106).make bootstrapwas run first, as a fresh clone no longer carriesstatic/js/alpine.min.js.The probes ran host binaries under a trap that kills the process and removes its data dir; the only containers this round were the three gate builds.
docker ps -ais empty and every image tagged here was removed. No prune was run.Housekeeping
The commit author is now
clawbot <clawbot@noreply.example.org>, matching the rest of this branch's history; the clone'suser.name/user.emailwere set explicitly rather than inherited.Determinism of the
waitDonetestTestWaitDone_DrainedBeforeExpiredContexthandswaitDonean already-closeddoneand an already-cancelledctx, so both select cases are ready on every call, and runs it 1000 times requiringNoErroreach pass. Without the preamble each pass is an independent coin flip. No wall-clock sleeps.FAIL — needs-rework
Code is correct and the bound demonstrably works; two findings, both in text introduced by this commit, both about the stop-hook order.
1.
README.md, new Shutdown section: the stated stop order is wrong.The text says "the HTTP server drains first with its own 5 second limit, then the delivery engine, the reapers, and finally the database close." The actual order, read off the fx stop-hook log of the image built from this branch, is:
ArchiveSweeper->RetentionReaper->server->delivery.Engine->healthcheck->WebhookDBManager->database.New.func2(DB close).The reapers run before the HTTP server, not after it, and the engine runs after the server, not before. This matters precisely where the section matters: the two components most likely to hold the budget (a retention sweep or an archive prune mid-tick, both of which wait on their WaitGroup bounded by the stop context) run first, so under the documented model an operator would look at the HTTP drain while the budget was actually consumed before the server hook was ever entered. Acceptable: state the real order. ("finally the database close" is correct and verified.)
2.
cmd/webhooker/main.go:20-28,stopTimeoutcomment: "matches the HTTP server's own drain budget so the first hook can spend its whole budget without the bound truncating it."The server is not the first hook (finding 1), so the stated rationale does not hold as written. And since
internal/server.shutdownTimeoutis also 5s, the case the comment describes — the server spending its whole drain budget — is exactly the case in which the sequence budget is exhausted at that moment and every later hook, the database close among them, is skipped. Acceptable: correct the comment to describe what the value actually buys. Whether to give the sequence headroom over the per-server drain (raise the bound while staying inside the 10s grace, or lowershutdownTimeout) is a design call for sneak, not filed here as a defect.Gate evidence and probes:
docker build --no-cache-filter=lint --no-cache-filter=builder .— exit 0. Lint layer executed (#18 61.50 0 issues.),make fmt-checkexecuted,make testran with real per-package durations and 0(cached)markers; only base-image resolves and runtimeapk/WORKDIRlayers wereCACHED.make check— exit 0 on the host with an isolatedGOLANGCI_LINT_CACHE; no foreign paths in the output, so no cache bleed (#106).c0c13ec(check / check, 3m16s). Merges cleanly into currentnext: the branch predates9ae1915(#126), merge is clean and nothing onnexttouches these files.docker stopdemonstration reproduced independently: exit 0, DB close hook ran last and succeeded. Quoted numbers hold.shutdown timed out, goroutines still running component="archive sweeper"at 5.007s, process exit 1 at 5.3s, and no further hooks — the DB close never ran. That is the operator-facing claim of #134 verified end to end, and it matches fx v1.20.1Lifecycle.Stop, which returns onctx.Err()before each remaining hook. README's skipped-hooks paragraph is accurate; so is the grace-period paragraph.fx.StopTimeout->TestNewApp_StopTimeoutfailsexpected: 5s / actual : 15s; dropping the preamble ->TestWaitDone_DrainedBeforeExpiredContextfails at pass 1, i.e. the loop catches the coin flip immediately and is not passing for an unrelated reason.newApp()extraction is option-for-option identical to the previousfx.Newcall plusfx.StopTimeout; nothing dropped or reordered.doneis closed is correct in all three call paths (engine, retention reaper, archive sweeper) — the goroutines are gone, so no genuine timeout is masked.(closes #134); based onnext;TODO.mduntouched; no debug scaffolding, commented-out code, or new non-testTODO/FIXME; terminology and naming consistent.Non-blocking notes:
doneclosing concurrently with the context expiring: the secondselectstill has both cases ready and can still report a false timeout. This matches the approved plan exactly, so it is not filed as a defect; aselect { case <-done: return nil; default: }re-check inside thectx.Done()branch would close the remaining window.TestNewApp_StopTimeoutbuilds the entire graph (opens SQLite underDATA_DIR, never starts or stops the app) to read one constant, so it will break on any future constructor needing more environment thanDATA_DIR— for a reason unrelated to what it pins.c0c13ec80cto6772304c60FAIL — needs-rework
Finding — the 2s tail headroom can be consumed by the server hook itself when
SENTRY_DSNis set, so the tail hooks (database close included) are still skipped.internal/server/server.go:186-188:cleanShutdowncallssentry.Flush(sentryFlushTimeout)— 2s,server.go:39— afterhttpServer.Shutdown, inside the same fx stop hook.sentry.Flushtakes a bare duration and does not honour the fx stop context, so the server hook's worst case isShutdownTimeout+sentryFlushTimeout= 3s + 2s = 5s, exactlystopTimeout.Reproduced on the as-committed tree (same 30s-hold probe route as the drain arms, plus
SENTRY_DSN=http://...@10.255.255.1:9999/1so the flush stalls, one event captured in the held request):delivery.Engine,healthcheck,WebhookDBManagerand the database close never ran — the exact failure the 3s/5s split was chosen to eliminate, on a documented supported configuration (SENTRY_DSNis in the README config table,README.md:96).Trigger is a conjunction, stated plainly so it can be weighed: it needs a near-full-length HTTP drain and a stalled Sentry flush. A 3s drain with a 1s flush still leaves 1s, which the microsecond-scale tail does not notice. But that conjunction is precisely "the case where the drain mattered", which is this PR's own framing.
Why it is a defect rather than a caveat: it is not the disclosed wedged-reaper case — nothing is wedged, and both the code comment and the README assert the opposite.
cmd/webhooker/main.go: "Those tail hooks are microsecond-scale in normal operation, so the 2s difference is ample."README.md: "3 seconds leaves 2 seconds for the tail, which is far more than it needs." The server hook, not the tail, can spend that 2s.TestStopTimeout_LeavesHeadroomForTailHooksdoes not model it either — it comparesstopTimeoutagainstShutdownTimeoutalone, so the guard passes green while the invariant it exists to protect is violated.Acceptable: either bound the Sentry flush by the remaining stop-context deadline so it cannot outlive the budget, or make the guard cover the server hook's real worst case (
ShutdownTimeout+sentryFlushTimeout+ tail margin<stopTimeout) and pick values that satisfy it. Either way the comment and README must stop claiming the whole 2s is available to the tail.Everything else verified and passing:
3.001560065s,server clean shutdown failed error="context deadline exceeded", thendelivery.Engine61.326µs,healthcheck349ns,WebhookDBManager1.979µs,database.New.func2()307.588µs. Control 5s/5s: exit 1 at ~5.0s, sequence stops dead after the server hook, no further hooks. Probe patch reverted; working tree byte-identical to6772304.ArchiveSweeper->RetentionReaper->server->delivery.Engine->healthcheck->WebhookDBManager-> database close.docker stop, default 10s grace, no override: exit 0, all seven hooks ran, database close last (177.265µs). Wall clock 0.62s on one run and 3.22s on another of the same image, consistent with the daemon-overhead variance the PR body reports.ShutdownTimeout5s ->"5s" is not less than "5s"; 4s ->"1s" is not greater than or equal to "2s"; dropping thewaitDonepreamble ->TestWaitDone_DrainedBeforeExpiredContextfails at pass 1.docker build --no-cache-filter=lint --no-cache-filter=builder .— exit 0.#21 [lint 8/8] RUN make lintexecuted in 57.11s,0 issues.;#20 make fmt-checkexecuted;#34 make testran with real per-package durations and 0(cached)markers.make check— exit 0 with an isolatedGOLANGCI_LINT_CACHE,0 issues., zero foreign paths, so no shared-cache bleed (#106). Hostgo testserved most packages from its cache; the uncached test evidence is the Docker builder run above.6772304(check / check, 2m58s).nextis an ancestor of the head: merges clean, no rebase needed.(closes #134)(#134); basenext;TODO.mduntouched. No Claude/Anthropic references or attribution trailers anywhere.ShutdownTimeoutis safe:server.go:173and the new test are its only consumers, and no other reference to the old unexported name exists.Disclosures: the previous round's two findings (wrong README stop order, the comment endorsing the broken pairing) are genuinely fixed and both now match observed behaviour, including the non-overclaiming caveat about a wedged
ArchiveSweeper/RetentionReaper. I did not re-run the wedged-sweeper probe. The lint stage emits agomodguarddeprecation warning (replaced bygomodguard_v2since golangci-lint v2.12.0) — pre-existing, not from this PR.6772304c60to55edebaea155edebaea1to2a65d86245PASS
The round-2 Sentry-flush finding is fixed and the fix is load-bearing. Reproduced independently on my own clone at
2a65d86.Probe (blackhole
SENTRY_DSN, one event captured, a request held open forcing a full drain, SIGTERM): exit 0, server hook3.003489119s,WARN skipping sentry flush, stop budget exhausted, thendelivery.Engine55.101µs,healthcheck395ns,WebhookDBManager2.168µs,database.New.func2()1.429778ms. Control arm with the clamp reverted: exit 1, server hook5.008595982s, no further hooks.Arithmetic: no drain length breaks it. For any positive budget
flush <= remaining - TailHookReserve, so the server hook's absolute end is bounded atstopTimeout - TailHookReserve= 3s regardless of drain — a stronger invariant than the test models.sup(drain + SentryFlushBudget(5s-drain))= exactly 3s, a plateau overdrainin [1s, 2.75s]; both breakpoints (1.0s, 2.75s) sit on the test's 10ms grid, so the sweep cannot step over the maximum. Boundaries checked: 2.749s gives a 251ms flush, 2.751s gives 0, negativeremaining - TailHookReservegives 0.ctx.Deadline()is correct.fx@v1.20.1builds onestopCtx(app.go:595) andinternal/lifecycle/lifecycle.go:290-303,341hands that same ctx to everyhook.OnStopwith no per-hook derivation. The no-deadline path is unreachable in production (cleanShutdownhas exactly one caller, the OnStop hook) and defaults safely.Mutations reproduced.
SentryFlushBudgetreduced toreturn sentryFlushTimeout:TestStopTimeout_LeavesHeadroomForTailHooksfails"5.01s" is not less than or equal to "5s"/a 1.01s drain leaves the tail hooks short, plus 4 of 5TestSentryFlushBudgetcases. Extra probe:TailHookReserveset to 1s also fails the sweep — the guard's localtailHeadroomconst is deliberately independent of the exported value, which is what makes it sensitive to both.Non-blocking note — the 2s reserve holds only when the hooks before the server are fast. The Sentry flush is clamped by
remaining - TailHookReserve; the HTTP drain is not (cleanShutdownusescontext.WithTimeout(ctx, ShutdownTimeout)), so it can run to the sequence deadline when something ran ahead of it. Reproduced with theArchiveSweeperstop hook patched to take 2.2s (probe only, not on the branch) plus a held request: exit 1,ArchiveSweeper2.209886991s, and the tail hooks including the database close skipped. That is inside the family the README already discloses, but the disclosure says a wedged reaper "can consume the whole budget on its own" and 2.2s of 5s is already enough. Not filed as a defect: clamping the drain the same way is a design call, the pre-PR behaviour was strictly worse, and SQLite is crash-safe. Raised for sneak.Gate:
docker build --no-cache-filter=lint --no-cache-filter=builder .exit 0.#18 [lint 8/8] RUN make lintexecuted,#18 60.09 0 issues.;#17 [lint 7/8] RUN make fmt-checkexecuted;#31 [builder 9/11] RUN make testwith real per-package durations (internal/delivery 5.306s,internal/handlers 4.465s,internal/server 2.609s,cmd/webhooker 1.071s, ...) and 0(cached)markers.make checkexit 0 with an isolatedGOLANGCI_LINT_CACHE,0 issues., no foreign paths (#106).2a65d86(check / check, 2m40s).origin/nextis an ancestor of the head: merges clean, no rebase needed.docker stopre-run on this head, default 10s grace, no override: pre-stop statusrunning, exit 0, wall 154ms, all seven stop hooks,internal/database.Newlast (141.695µs).internal/lifecycle/entry in the Package Layout tree, sorted betweenhealthcheck/andlogger/. No other duplication introduced by the two rebases.cmd/webhooker/main.gotext now match observed behaviour, including that a full-length drain drops Sentry events rather than the database close, and that a wedgedArchiveSweeper/RetentionReaperstill skips the tail.(closes #134)(#134); basenext;TODO.mduntouched; no Claude/Anthropic references or attribution trailers anywhere; no references to the old unexportedshutdownTimeoutremain; both newly exported symbols are consumed by external test packages, so the widened API is required.Disclosures: I did not re-run the wedged-sweeper probe — the 2.2s partial-delay probe above exercises the same skip path. The lint stage's
gomodguarddeprecation warning is pre-existing. Every probe patch was reverted andgit diff HEADis byte-identical to2a65d86. All containers and tagged images removed,docker ps -aempty; no prune run.