Set fx.StopTimeout inside the container stop grace (closes #134) #159

Merged
clawbot merged 1 commits from issue-134-fx-stop-timeout into next 2026-08-18 00:12:52 +02:00
Collaborator

Closes #134.

What changed

fx.StopTimeout set to 5s (cmd/webhooker/main.go). fx defaults to 15s and the Dockerfile sets no STOPSIGNAL or grace override, so Docker's 10s default SIGKILLed the process five seconds before the bound could fire. Everything gated on it — including the shutdown timed out, goroutines still running error 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.App so a test can read (*fx.App).StopTimeout() back. fx.New applies 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, the WebhookDBManager and 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: cleanShutdown calls sentry.Flush after it, in the same hook, and sentry.Flush takes a bare duration and honours no context. With SENTRY_DSN pointed 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 less server.TailHookReserve (2s), capped at the nominal 2s and floored at 250ms — below that the flush is skipped outright with a skipping sentry flush, stop budget exhausted warning rather than making an attempt too short to complete a round trip. cleanShutdown reads 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_LeavesHeadroomForTailHooks previously compared stopTimeout against ShutdownTimeout alone, so it sat green while its own invariant was violated. It now walks every drain length the hook can produce in 10ms steps and asserts drain + 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. TestSentryFlushBudget covers 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 ArchiveSweeper and RetentionReaper hooks 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 against ctx.Done() with no preamble, and select picks uniformly among ready cases, so a component that drained against an already-expired context reported shutdown timed out about half the time. Not reachable through fx today — fx re-checks ctx.Err() before each remaining hook — but the helper is shared and a direct caller can reach it. Split into an unexported waitDone(ctx, log, component, done) carrying a select { case <-done: return nil; default: } preamble, exposed to the external test package via export_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, Compose stop_grace_period, Kubernetes terminationGracePeriodSeconds) puts SIGKILL back in front of the bound and reintroduces the silent truncation. The internal/lifecycle/ entry in the Package Layout tree lands in its sorted position; the out-of-order duplicate this branch rebased onto is dropped.

TODO.md untouched.

Stop-hook order, read off the fx log

ArchiveSweeper -> RetentionReaper -> server -> delivery.Engine
  -> healthcheck -> WebhookDBManager -> database close

Sentry probe: the finding from the last review, fixed

Temporary probe route holding one request open for 30s so httpServer.Shutdown runs 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 against make build; probe patch reverted afterwards, git status clean 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.

sentry: enabled
process exit:    0
elapsed to exit: 3.012s
ArchiveSweeper ...   ran successfully in 132.727µs
RetentionReaper ...  ran successfully in 70.093µs
server.New.func2() executing
  ERROR "server clean shutdown failed" error="context deadline exceeded"
  WARN  "skipping sentry flush, stop budget exhausted"
server.New.func2()   ran successfully in 3.000580266s
delivery.Engine ...  ran successfully in 156.133µs
healthcheck ...      ran successfully in 489ns
WebhookDBManager ... ran successfully in 2.907µs
database.New.func2() ran successfully in 500.794µs

Exit 0, all seven hooks including the database close. Control arm, same probe with SentryFlushBudget reverted to the unbounded fixed 2s, reproduces the reviewed failure:

process exit:    1
elapsed to exit: 5.023s
server.New.func2()   ran successfully in 5.008697109s
<no further hooks>

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 stop demonstration (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-clock docker stop timings 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

  • New this round. SentryFlushBudget reduced to return sentryFlushTimeout (the unbounded flush): TestStopTimeout_LeavesHeadroomForTailHooks fails with "5.01s" is not less than or equal to "5s", message a 1.01s drain leaves the tail hooks short. TestSentryFlushBudget fails four of its five cases. Reverted; the working tree is byte-identical to the commit.
  • Restoring ShutdownTimeout to 5s: "5s" is not less than "5s". (Previous round; not re-run.)
  • Dropping fx.StopTimeout(stopTimeout): TestNewApp_StopTimeout fails expected: 5s / actual : 15s. (Previous round; not re-run.)
  • Dropping the waitDone preamble: TestWaitDone_DrainedBeforeExpiredContext fails at pass 1. (Previous round; not re-run.)

Gate evidence

Rebased twice during this round as next moved; both rebases were clean, and the README internal/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 test with real per-package durations and zero (cached) markers (grep count: 0):
#34 54.55 ok  sneak.berlin/go/webhooker/cmd/webhooker        1.096s
#34 56.16 ok  sneak.berlin/go/webhooker/internal/database    2.703s
#34 57.90 ok  sneak.berlin/go/webhooker/internal/delivery    4.378s
#34 57.90 ok  sneak.berlin/go/webhooker/internal/lifecycle   1.149s
#34 57.90 ok  sneak.berlin/go/webhooker/internal/server      2.232s

The only CACHED layers are base-image resolves, the runtime apk/adduser/WORKDIR layers, and the lint stage's go mod download.

make checkexit 0 on the same tree, with an isolated GOLANGCI_LINT_CACHE; 0 issues., no foreign paths in the output, so no shared-cache bleed (#106). make bootstrap was run first, as a fresh clone no longer carries static/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 -a is 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's user.name/user.email were set explicitly rather than inherited.

Determinism of the waitDone test

TestWaitDone_DrainedBeforeExpiredContext hands waitDone an already-closed done and an already-cancelled ctx, so both select cases are ready on every call, and runs it 1000 times requiring NoError each pass. Without the preamble each pass is an independent coin flip. No wall-clock sleeps.

Closes https://git.eeqj.de/sneak/webhooker/issues/134. ## What changed **`fx.StopTimeout` set to 5s** (`cmd/webhooker/main.go`). fx defaults to 15s and the Dockerfile sets no `STOPSIGNAL` or grace override, so Docker's 10s default SIGKILLed the process five seconds before the bound could fire. Everything gated on it — including the `shutdown timed out, goroutines still running` error 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.App` so a test can read `(*fx.App).StopTimeout()` back. `fx.New` applies 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, the `WebhookDBManager` and 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: `cleanShutdown` calls `sentry.Flush` after it, in the same hook, and `sentry.Flush` takes a bare duration and honours no context. With `SENTRY_DSN` pointed 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 less `server.TailHookReserve` (2s), capped at the nominal 2s and floored at 250ms — below that the flush is skipped outright with a `skipping sentry flush, stop budget exhausted` warning rather than making an attempt too short to complete a round trip. `cleanShutdown` reads 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_LeavesHeadroomForTailHooks` previously compared `stopTimeout` against `ShutdownTimeout` alone, so it sat green while its own invariant was violated. It now walks every drain length the hook can produce in 10ms steps and asserts `drain + 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. `TestSentryFlushBudget` covers 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 `ArchiveSweeper` and `RetentionReaper` hooks 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 against `ctx.Done()` with no preamble, and `select` picks uniformly among ready cases, so a component that drained against an already-expired context reported `shutdown timed out` about half the time. Not reachable through fx today — fx re-checks `ctx.Err()` before each remaining hook — but the helper is shared and a direct caller can reach it. Split into an unexported `waitDone(ctx, log, component, done)` carrying a `select { case <-done: return nil; default: }` preamble, exposed to the external test package via `export_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`, Compose `stop_grace_period`, Kubernetes `terminationGracePeriodSeconds`) puts SIGKILL back in front of the bound and reintroduces the silent truncation. The `internal/lifecycle/` entry in the Package Layout tree lands in its sorted position; the out-of-order duplicate this branch rebased onto is dropped. `TODO.md` untouched. ## Stop-hook order, read off the fx log ``` ArchiveSweeper -> RetentionReaper -> server -> delivery.Engine -> healthcheck -> WebhookDBManager -> database close ``` ## Sentry probe: the finding from the last review, fixed Temporary probe route holding one request open for 30s so `httpServer.Shutdown` runs 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 against `make build`; probe patch reverted afterwards, `git status` clean 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. ``` sentry: enabled process exit: 0 elapsed to exit: 3.012s ArchiveSweeper ... ran successfully in 132.727µs RetentionReaper ... ran successfully in 70.093µs server.New.func2() executing ERROR "server clean shutdown failed" error="context deadline exceeded" WARN "skipping sentry flush, stop budget exhausted" server.New.func2() ran successfully in 3.000580266s delivery.Engine ... ran successfully in 156.133µs healthcheck ... ran successfully in 489ns WebhookDBManager ... ran successfully in 2.907µs database.New.func2() ran successfully in 500.794µs ``` Exit 0, all seven hooks including the database close. Control arm, same probe with `SentryFlushBudget` reverted to the unbounded fixed 2s, reproduces the reviewed failure: ``` process exit: 1 elapsed to exit: 5.023s server.New.func2() ran successfully in 5.008697109s <no further hooks> ``` ## 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 stop` demonstration (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-clock `docker stop` timings 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 - **New this round.** `SentryFlushBudget` reduced to `return sentryFlushTimeout` (the unbounded flush): `TestStopTimeout_LeavesHeadroomForTailHooks` fails with `"5.01s" is not less than or equal to "5s"`, message `a 1.01s drain leaves the tail hooks short`. `TestSentryFlushBudget` fails four of its five cases. Reverted; the working tree is byte-identical to the commit. - Restoring `ShutdownTimeout` to 5s: `"5s" is not less than "5s"`. (Previous round; not re-run.) - Dropping `fx.StopTimeout(stopTimeout)`: `TestNewApp_StopTimeout` fails `expected: 5s / actual : 15s`. (Previous round; not re-run.) - Dropping the `waitDone` preamble: `TestWaitDone_DrainedBeforeExpiredContext` fails at pass 1. (Previous round; not re-run.) ## Gate evidence Rebased twice during this round as `next` moved; both rebases were clean, and the README `internal/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 test` with real per-package durations and **zero `(cached)` markers** (grep count: 0): ``` #34 54.55 ok sneak.berlin/go/webhooker/cmd/webhooker 1.096s #34 56.16 ok sneak.berlin/go/webhooker/internal/database 2.703s #34 57.90 ok sneak.berlin/go/webhooker/internal/delivery 4.378s #34 57.90 ok sneak.berlin/go/webhooker/internal/lifecycle 1.149s #34 57.90 ok sneak.berlin/go/webhooker/internal/server 2.232s ``` The only `CACHED` layers are base-image resolves, the runtime `apk`/`adduser`/`WORKDIR` layers, and the lint stage's `go mod download`. `make check` — **exit 0** on the same tree, with an isolated `GOLANGCI_LINT_CACHE`; `0 issues.`, no foreign paths in the output, so no shared-cache bleed (https://git.eeqj.de/sneak/webhooker/issues/106). `make bootstrap` was run first, as a fresh clone no longer carries `static/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 -a` is 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's `user.name`/`user.email` were set explicitly rather than inherited. ## Determinism of the `waitDone` test `TestWaitDone_DrainedBeforeExpiredContext` hands `waitDone` an already-closed `done` and an already-cancelled `ctx`, so both select cases are ready on every call, and runs it 1000 times requiring `NoError` each pass. Without the preamble each pass is an independent coin flip. No wall-clock sleeps.
clawbot added 1 commit 2026-08-17 22:49:39 +02:00
Set fx.StopTimeout inside the container stop grace (closes #134)
All checks were successful
check / check (push) Successful in 3m16s
c0c13ec80c
fx defaults the stop timeout to 15s and the Dockerfile sets no
STOPSIGNAL or grace override, so Docker's 10s default SIGKILLs the
process five seconds before the bound can fire. Everything gated on
it — including the "shutdown timed out, goroutines still running"
error log that tells an operator a component is wedged — was
unreachable in the image this repo produces.

Set fx.StopTimeout to 5s: inside the grace with headroom for signal
delivery and process exit, and equal to the HTTP server's own drain
budget so the first hook can spend its whole budget without the
sequence bound truncating it. The option set moves into newApp() so
a test can read (*fx.App).StopTimeout() back and pin it against
drift; dropping the option makes that test report fx's 15s default.

Also fix a latent coin flip in the shared stop-hook waiter. It
selected on the drained channel against ctx.Done() with no
preamble, and select picks uniformly among ready cases, so a
component that drained against an already-expired context reported
a timeout about half the time. Not reachable through fx, which
re-checks ctx.Err() before each hook, but the helper is shared and
a direct caller can reach it. waitDone now settles the drained case
in a non-blocking preamble first; the test drives it over 1000
passes, so a restored coin flip cannot pass by luck.

README records the timeout and its relationship to the container
stop grace: that lowering the grace below it puts SIGKILL back in
front of the bound, and that an expired stop context makes fx skip
its remaining hooks, so a wedge in the first-stopped component
means the database close never runs. Adds the missing
internal/lifecycle/ entry to the Package Layout tree.
clawbot added the needs-review label 2026-08-17 22:49:50 +02:00
clawbot self-assigned this 2026-08-17 22:49:54 +02:00
Author
Collaborator

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, stopTimeout comment: "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.shutdownTimeout is 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 lower shutdownTimeout) 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-check executed, make test ran with real per-package durations and 0 (cached) markers; only base-image resolves and runtime apk/WORKDIR layers were CACHED.
  • make check — exit 0 on the host with an isolated GOLANGCI_LINT_CACHE; no foreign paths in the output, so no cache bleed (#106).
  • CI green on c0c13ec (check / check, 3m16s). Merges cleanly into current next: the branch predates 9ae1915 (#126), merge is clean and nothing on next touches these files.
  • docker stop demonstration reproduced independently: exit 0, DB close hook ran last and succeeded. Quoted numbers hold.
  • Wedge probe (temporary local patch making the sweeper goroutine ignore cancellation — not part of this branch): SIGTERM under the default 10s grace produced 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.1 Lifecycle.Stop, which returns on ctx.Err() before each remaining hook. README's skipped-hooks paragraph is accurate; so is the grace-period paragraph.
  • Mutations reproduced: dropping fx.StopTimeout -> TestNewApp_StopTimeout fails expected: 5s / actual : 15s; dropping the preamble -> TestWaitDone_DrainedBeforeExpiredContext fails 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 previous fx.New call plus fx.StopTimeout; nothing dropped or reordered.
  • Preamble semantics: returning nil when done is closed is correct in all three call paths (engine, retention reaper, archive sweeper) — the goroutines are gone, so no genuine timeout is masked.
  • No Claude/Anthropic references or attribution trailers anywhere; one commit; title ends (closes #134); based on next; TODO.md untouched; no debug scaffolding, commented-out code, or new non-test TODO/FIXME; terminology and naming consistent.

Non-blocking notes:

  • The preamble does not cover done closing concurrently with the context expiring: the second select still 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; a select { case <-done: return nil; default: } re-check inside the ctx.Done() branch would close the remaining window.
  • TestNewApp_StopTimeout builds the entire graph (opens SQLite under DATA_DIR, never starts or stops the app) to read one constant, so it will break on any future constructor needing more environment than DATA_DIR — for a reason unrelated to what it pins.
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`, `stopTimeout` comment: "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.shutdownTimeout` is 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 lower `shutdownTimeout`) 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-check` executed, `make test` ran with real per-package durations and **0** `(cached)` markers; only base-image resolves and runtime `apk`/`WORKDIR` layers were `CACHED`. - `make check` — exit 0 on the host with an isolated `GOLANGCI_LINT_CACHE`; no foreign paths in the output, so no cache bleed (https://git.eeqj.de/sneak/webhooker/issues/106). - CI green on `c0c13ec` (`check / check`, 3m16s). Merges cleanly into current `next`: the branch predates `9ae1915` (https://git.eeqj.de/sneak/webhooker/pulls/126), merge is clean and nothing on `next` touches these files. - `docker stop` demonstration reproduced independently: exit **0**, DB close hook ran last and succeeded. Quoted numbers hold. - Wedge probe (temporary local patch making the sweeper goroutine ignore cancellation — **not** part of this branch): SIGTERM under the default 10s grace produced `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 https://git.eeqj.de/sneak/webhooker/issues/134 verified end to end, and it matches fx v1.20.1 `Lifecycle.Stop`, which returns on `ctx.Err()` before each remaining hook. README's skipped-hooks paragraph is accurate; so is the grace-period paragraph. - Mutations reproduced: dropping `fx.StopTimeout` -> `TestNewApp_StopTimeout` fails `expected: 5s / actual : 15s`; dropping the preamble -> `TestWaitDone_DrainedBeforeExpiredContext` fails 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 previous `fx.New` call plus `fx.StopTimeout`; nothing dropped or reordered. - Preamble semantics: returning nil when `done` is closed is correct in all three call paths (engine, retention reaper, archive sweeper) — the goroutines are gone, so no genuine timeout is masked. - No Claude/Anthropic references or attribution trailers anywhere; one commit; title ends ` (closes #134)`; based on `next`; `TODO.md` untouched; no debug scaffolding, commented-out code, or new non-test `TODO`/`FIXME`; terminology and naming consistent. Non-blocking notes: - The preamble does not cover `done` closing *concurrently* with the context expiring: the second `select` still 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; a `select { case <-done: return nil; default: }` re-check inside the `ctx.Done()` branch would close the remaining window. - `TestNewApp_StopTimeout` builds the entire graph (opens SQLite under `DATA_DIR`, never starts or stops the app) to read one constant, so it will break on any future constructor needing more environment than `DATA_DIR` — for a reason unrelated to what it pins.
clawbot added needs-rework and removed needs-review labels 2026-08-17 23:04:54 +02:00
clawbot force-pushed issue-134-fx-stop-timeout from c0c13ec80c to 6772304c60 2026-08-17 23:23:05 +02:00 Compare
clawbot added needs-review and removed needs-rework labels 2026-08-17 23:25:07 +02:00
Author
Collaborator

FAIL — needs-rework

Finding — the 2s tail headroom can be consumed by the server hook itself when SENTRY_DSN is set, so the tail hooks (database close included) are still skipped.

internal/server/server.go:186-188: cleanShutdown calls sentry.Flush(sentryFlushTimeout) — 2s, server.go:39after httpServer.Shutdown, inside the same fx stop hook. sentry.Flush takes a bare duration and does not honour the fx stop context, so the server hook's worst case is ShutdownTimeout + sentryFlushTimeout = 3s + 2s = 5s, exactly stopTimeout.

Reproduced on the as-committed tree (same 30s-hold probe route as the drain arms, plus SENTRY_DSN=http://...@10.255.255.1:9999/1 so the flush stalls, one event captured in the held request):

process exit:     1
elapsed to exit:  5.021s
ArchiveSweeper ...   ran successfully in 118.493µs
RetentionReaper ...  ran successfully in 60.036µs
server.New.func2()   ran successfully in 5.008830967s
  ERROR "server clean shutdown failed" error="context deadline exceeded"
<no further hooks>

delivery.Engine, healthcheck, WebhookDBManager and the database close never ran — the exact failure the 3s/5s split was chosen to eliminate, on a documented supported configuration (SENTRY_DSN is 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_LeavesHeadroomForTailHooks does not model it either — it compares stopTimeout against ShutdownTimeout alone, 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:

  • Both drain-probe arms reproduced independently on my own clone. 3s/5s: exit 0 at ~3.05s, server hook 3.001560065s, server clean shutdown failed error="context deadline exceeded", then delivery.Engine 61.326µs, healthcheck 349ns, WebhookDBManager 1.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 to 6772304.
  • Stop order read off my own container's log matches the README numbered list exactly: 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.
  • Mutations all reproduced this round: ShutdownTimeout 5s -> "5s" is not less than "5s"; 4s -> "1s" is not greater than or equal to "2s"; dropping the waitDone preamble -> TestWaitDone_DrainedBeforeExpiredContext fails at pass 1.
  • docker build --no-cache-filter=lint --no-cache-filter=builder . — exit 0. #21 [lint 8/8] RUN make lint executed in 57.11s, 0 issues.; #20 make fmt-check executed; #34 make test ran with real per-package durations and 0 (cached) markers.
  • make check — exit 0 with an isolated GOLANGCI_LINT_CACHE, 0 issues., zero foreign paths, so no shared-cache bleed (#106). Host go test served most packages from its cache; the uncached test evidence is the Docker builder run above.
  • CI green on 6772304 (check / check, 2m58s). next is an ancestor of the head: merges clean, no rebase needed.
  • One commit; title ends (closes #134) (#134); base next; TODO.md untouched. No Claude/Anthropic references or attribution trailers anywhere.
  • Exporting ShutdownTimeout is safe: server.go:173 and 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 a gomodguard deprecation warning (replaced by gomodguard_v2 since golangci-lint v2.12.0) — pre-existing, not from this PR.

FAIL — needs-rework **Finding — the 2s tail headroom can be consumed by the server hook itself when `SENTRY_DSN` is set, so the tail hooks (database close included) are still skipped.** `internal/server/server.go:186-188`: `cleanShutdown` calls `sentry.Flush(sentryFlushTimeout)` — 2s, `server.go:39` — *after* `httpServer.Shutdown`, inside the same fx stop hook. `sentry.Flush` takes a bare duration and does not honour the fx stop context, so the server hook's worst case is `ShutdownTimeout` + `sentryFlushTimeout` = 3s + 2s = **5s**, exactly `stopTimeout`. Reproduced on the as-committed tree (same 30s-hold probe route as the drain arms, plus `SENTRY_DSN=http://...@10.255.255.1:9999/1` so the flush stalls, one event captured in the held request): ``` process exit: 1 elapsed to exit: 5.021s ArchiveSweeper ... ran successfully in 118.493µs RetentionReaper ... ran successfully in 60.036µs server.New.func2() ran successfully in 5.008830967s ERROR "server clean shutdown failed" error="context deadline exceeded" <no further hooks> ``` `delivery.Engine`, `healthcheck`, `WebhookDBManager` and the database close never ran — the exact failure the 3s/5s split was chosen to eliminate, on a documented supported configuration (`SENTRY_DSN` is 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_LeavesHeadroomForTailHooks` does not model it either — it compares `stopTimeout` against `ShutdownTimeout` alone, 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: - **Both drain-probe arms reproduced independently** on my own clone. 3s/5s: exit 0 at ~3.05s, server hook `3.001560065s`, `server clean shutdown failed error="context deadline exceeded"`, then `delivery.Engine` 61.326µs, `healthcheck` 349ns, `WebhookDBManager` 1.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 to `6772304`. - **Stop order** read off my own container's log matches the README numbered list exactly: `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. - **Mutations all reproduced this round**: `ShutdownTimeout` 5s -> `"5s" is not less than "5s"`; 4s -> `"1s" is not greater than or equal to "2s"`; dropping the `waitDone` preamble -> `TestWaitDone_DrainedBeforeExpiredContext` fails at **pass 1**. - `docker build --no-cache-filter=lint --no-cache-filter=builder .` — exit 0. `#21 [lint 8/8] RUN make lint` executed in 57.11s, `0 issues.`; `#20 make fmt-check` executed; `#34 make test` ran with real per-package durations and **0** `(cached)` markers. - `make check` — exit 0 with an isolated `GOLANGCI_LINT_CACHE`, `0 issues.`, zero foreign paths, so no shared-cache bleed (https://git.eeqj.de/sneak/webhooker/issues/106). Host `go test` served most packages from its cache; the uncached test evidence is the Docker builder run above. - CI green on `6772304` (`check / check`, 2m58s). `next` is an ancestor of the head: merges clean, no rebase needed. - One commit; title ends ` (closes #134)` (https://git.eeqj.de/sneak/webhooker/issues/134); base `next`; `TODO.md` untouched. No Claude/Anthropic references or attribution trailers anywhere. - Exporting `ShutdownTimeout` is safe: `server.go:173` and 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 a `gomodguard` deprecation warning (replaced by `gomodguard_v2` since golangci-lint v2.12.0) — pre-existing, not from this PR.
clawbot added needs-rework and removed needs-review labels 2026-08-17 23:34:33 +02:00
clawbot force-pushed issue-134-fx-stop-timeout from 6772304c60 to 55edebaea1 2026-08-17 23:53:10 +02:00 Compare
clawbot force-pushed issue-134-fx-stop-timeout from 55edebaea1 to 2a65d86245 2026-08-17 23:53:44 +02:00 Compare
clawbot added needs-review and removed needs-rework labels 2026-08-18 00:01:27 +02:00
Author
Collaborator

PASS

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 hook 3.003489119s, WARN skipping sentry flush, stop budget exhausted, then delivery.Engine 55.101µs, healthcheck 395ns, WebhookDBManager 2.168µs, database.New.func2() 1.429778ms. Control arm with the clamp reverted: exit 1, server hook 5.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 at stopTimeout - TailHookReserve = 3s regardless of drain — a stronger invariant than the test models. sup(drain + SentryFlushBudget(5s-drain)) = exactly 3s, a plateau over drain in [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, negative remaining - TailHookReserve gives 0.

ctx.Deadline() is correct. fx@v1.20.1 builds one stopCtx (app.go:595) and internal/lifecycle/lifecycle.go:290-303,341 hands that same ctx to every hook.OnStop with no per-hook derivation. The no-deadline path is unreachable in production (cleanShutdown has exactly one caller, the OnStop hook) and defaults safely.

Mutations reproduced. SentryFlushBudget reduced to return sentryFlushTimeout: TestStopTimeout_LeavesHeadroomForTailHooks fails "5.01s" is not less than or equal to "5s" / a 1.01s drain leaves the tail hooks short, plus 4 of 5 TestSentryFlushBudget cases. Extra probe: TailHookReserve set to 1s also fails the sweep — the guard's local tailHeadroom const 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 (cleanShutdown uses context.WithTimeout(ctx, ShutdownTimeout)), so it can run to the sequence deadline when something ran ahead of it. Reproduced with the ArchiveSweeper stop hook patched to take 2.2s (probe only, not on the branch) plus a held request: exit 1, ArchiveSweeper 2.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 lint executed, #18 60.09 0 issues.; #17 [lint 7/8] RUN make fmt-check executed; #31 [builder 9/11] RUN make test with 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 check exit 0 with an isolated GOLANGCI_LINT_CACHE, 0 issues., no foreign paths (#106).
  • CI green on 2a65d86 (check / check, 2m40s). origin/next is an ancestor of the head: merges clean, no rebase needed.
  • docker stop re-run on this head, default 10s grace, no override: pre-stop status running, exit 0, wall 154ms, all seven stop hooks, internal/database.New last (141.695µs).
  • Exactly one internal/lifecycle/ entry in the Package Layout tree, sorted between healthcheck/ and logger/. No other duplication introduced by the two rebases.
  • README and cmd/webhooker/main.go text now match observed behaviour, including that a full-length drain drops Sentry events rather than the database close, and that a wedged ArchiveSweeper/RetentionReaper still skips the tail.
  • One commit; title ends (closes #134) (#134); base next; TODO.md untouched; no Claude/Anthropic references or attribution trailers anywhere; no references to the old unexported shutdownTimeout remain; 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 gomodguard deprecation warning is pre-existing. Every probe patch was reverted and git diff HEAD is byte-identical to 2a65d86. All containers and tagged images removed, docker ps -a empty; no prune run.

PASS 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 hook `3.003489119s`, `WARN skipping sentry flush, stop budget exhausted`, then `delivery.Engine` 55.101µs, `healthcheck` 395ns, `WebhookDBManager` 2.168µs, `database.New.func2()` 1.429778ms. Control arm with the clamp reverted: exit **1**, server hook `5.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 at `stopTimeout - TailHookReserve` = 3s regardless of drain — a stronger invariant than the test models. `sup(drain + SentryFlushBudget(5s-drain))` = exactly 3s, a plateau over `drain` in [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, negative `remaining - TailHookReserve` gives 0. **`ctx.Deadline()` is correct.** `fx@v1.20.1` builds one `stopCtx` (`app.go:595`) and `internal/lifecycle/lifecycle.go:290-303,341` hands that same ctx to every `hook.OnStop` with no per-hook derivation. The no-deadline path is unreachable in production (`cleanShutdown` has exactly one caller, the OnStop hook) and defaults safely. **Mutations reproduced.** `SentryFlushBudget` reduced to `return sentryFlushTimeout`: `TestStopTimeout_LeavesHeadroomForTailHooks` fails `"5.01s" is not less than or equal to "5s"` / `a 1.01s drain leaves the tail hooks short`, plus 4 of 5 `TestSentryFlushBudget` cases. Extra probe: `TailHookReserve` set to 1s also fails the sweep — the guard's local `tailHeadroom` const 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 (`cleanShutdown` uses `context.WithTimeout(ctx, ShutdownTimeout)`), so it can run to the sequence deadline when something ran ahead of it. Reproduced with the `ArchiveSweeper` stop hook patched to take 2.2s (probe only, not on the branch) plus a held request: exit **1**, `ArchiveSweeper` 2.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 lint` executed, `#18 60.09 0 issues.`; `#17 [lint 7/8] RUN make fmt-check` executed; `#31 [builder 9/11] RUN make test` with 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 check` exit 0 with an isolated `GOLANGCI_LINT_CACHE`, `0 issues.`, no foreign paths (https://git.eeqj.de/sneak/webhooker/issues/106). - CI green on `2a65d86` (`check / check`, 2m40s). `origin/next` is an ancestor of the head: merges clean, no rebase needed. - `docker stop` re-run on this head, default 10s grace, no override: pre-stop status `running`, exit **0**, wall 154ms, all seven stop hooks, `internal/database.New` last (141.695µs). - Exactly one `internal/lifecycle/` entry in the Package Layout tree, sorted between `healthcheck/` and `logger/`. No other duplication introduced by the two rebases. - README and `cmd/webhooker/main.go` text now match observed behaviour, including that a full-length drain drops Sentry events rather than the database close, and that a wedged `ArchiveSweeper`/`RetentionReaper` still skips the tail. - One commit; title ends ` (closes #134)` (https://git.eeqj.de/sneak/webhooker/issues/134); base `next`; `TODO.md` untouched; no Claude/Anthropic references or attribution trailers anywhere; no references to the old unexported `shutdownTimeout` remain; 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 `gomodguard` deprecation warning is pre-existing. Every probe patch was reverted and `git diff HEAD` is byte-identical to `2a65d86`. All containers and tagged images removed, `docker ps -a` empty; no prune run.
clawbot merged commit bef9986542 into next 2026-08-18 00:12:52 +02:00
clawbot deleted branch issue-134-fx-stop-timeout 2026-08-18 00:12:52 +02:00
Sign in to join this conversation.
No Reviewers
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#159