internal/handlers tests are load-fragile: both the fx start budget and the 90s package timeout blow under host load, so the gate reports failures unrelated to the change #225

Open
opened 2026-08-20 06:38:14 +02:00 by clawbot · 1 comment
Collaborator

Found while reviewing #219, then hit independently by the reviewers of #218, #222 and #224. Reproduced on next itself, so it is not attributable to any PR.

TWO SEPARATE BUDGETS are being blown, both in internal/handlers, both only under load:

1. fx start timeout. Subtests fail with

app.go:62: application didn't start cleanly: context deadline exceeded

Seen on TestFailedLogin_*, TestLogin_*, TestStoredUsername_* and every BodiesRoundTripByteIdentical subtest.

2. The 90s per-package go test timeout raised by #194:

panic: test timed out after 1m30s

The second is the more alarming number: on a clean re-run at lower load, internal/handlers completed in 90.203s against a 90s budget — passing by about 0.2%. That is not a margin, it is a coin flip. script/test's own header documents this package at 16.9s unloaded and 67.3s at GOMAXPROCS=4 under load; observed load averages during these runs were 122 to 170 on 48 cores.

Why this matters rather than being written off as "the host was busy": the authoritative gate is a cache-defeated container build (#119), and that gate now produces FALSE FAILURES under load. A gate that fails at random is the same category of problem #119 fixed — it stops being evidence, and every reviewer has to spend a run on next to attribute their own failure. It also means next cannot be confidently declared green under load, and next must stay green and mergeable without notice.

Related but distinct: #198 (make test wall time, driven by this same package) and #190 (the last wall-clock-dependent test).

Definition of done:

  • internal/handlers no longer sits within a few percent of the per-package timeout on a loaded host — fix the runtime, do not simply raise the number again
  • test app startup does not depend on a wall-clock budget a loaded machine can blow, or that budget is justified in a comment with the measurement behind it
  • prefer removing dependence on real elapsed time over raising a constant, consistent with #190
  • a cache-defeated build passes with the host under deliberate heavy load; state how the load was produced and the load average it was verified at
  • no reduction in what the affected tests actually assert
Found while reviewing https://git.eeqj.de/sneak/webhooker/pulls/219, then hit independently by the reviewers of https://git.eeqj.de/sneak/webhooker/pulls/218, https://git.eeqj.de/sneak/webhooker/pulls/222 and https://git.eeqj.de/sneak/webhooker/pulls/224. Reproduced on `next` itself, so it is not attributable to any PR. TWO SEPARATE BUDGETS are being blown, both in `internal/handlers`, both only under load: **1. fx start timeout.** Subtests fail with ``` app.go:62: application didn't start cleanly: context deadline exceeded ``` Seen on `TestFailedLogin_*`, `TestLogin_*`, `TestStoredUsername_*` and every `BodiesRoundTripByteIdentical` subtest. **2. The 90s per-package `go test` timeout** raised by https://git.eeqj.de/sneak/webhooker/issues/194: ``` panic: test timed out after 1m30s ``` The second is the more alarming number: on a clean re-run at lower load, `internal/handlers` completed in **90.203s against a 90s budget** — passing by about 0.2%. That is not a margin, it is a coin flip. `script/test`'s own header documents this package at 16.9s unloaded and 67.3s at `GOMAXPROCS=4` under load; observed load averages during these runs were 122 to 170 on 48 cores. Why this matters rather than being written off as "the host was busy": the authoritative gate is a cache-defeated container build (https://git.eeqj.de/sneak/webhooker/issues/119), and that gate now produces FALSE FAILURES under load. A gate that fails at random is the same category of problem https://git.eeqj.de/sneak/webhooker/issues/119 fixed — it stops being evidence, and every reviewer has to spend a run on `next` to attribute their own failure. It also means `next` cannot be confidently declared green under load, and `next` must stay green and mergeable without notice. Related but distinct: https://git.eeqj.de/sneak/webhooker/issues/198 (`make test` wall time, driven by this same package) and https://git.eeqj.de/sneak/webhooker/issues/190 (the last wall-clock-dependent test). Definition of done: - `internal/handlers` no longer sits within a few percent of the per-package timeout on a loaded host — fix the runtime, do not simply raise the number again - test app startup does not depend on a wall-clock budget a loaded machine can blow, or that budget is justified in a comment with the measurement behind it - prefer removing dependence on real elapsed time over raising a constant, consistent with https://git.eeqj.de/sneak/webhooker/issues/190 - a cache-defeated build passes with the host under deliberate heavy load; state how the load was produced and the load average it was verified at - no reduction in what the affected tests actually assert
clawbot changed title from internal/handlers tests fail under host load: fx start timeout exceeded, so the gate reports failure for reasons unrelated to the change to internal/handlers tests are load-fragile: both the fx start budget and the 90s package timeout blow under host load, so the gate reports failures unrelated to the change 2026-08-20 06:49:32 +02:00
Author
Collaborator

Root cause measured while implementing #67.

Every newTestApp in internal/handlers seeds an admin user, and that pays an Argon2id hash at 64 MB. The package's runtime is therefore roughly linear in the number of fx applications the tests stand up, not in what they assert.

Measurements, all in a cache-defeated container build:

  • unmodified next, baseline: 67.7s, and 82.8s in a separate container run — against a 90s per-package budget
  • one fx application per table row (a natural way to write a new table-driven test): panic: test timed out after 1m30s
  • the same tests consolidated to six applications: 37.8s

So the package sits at roughly 92% of budget before anyone adds anything, and the marginal cost of a new test is an Argon2id hash rather than the test's own work. That is why it tips under load and why raising the timeout again would only defer it.

Suggested direction for whoever takes this: a test-only seam that skips the Argon2id admin seed for tests that do not exercise login, leaving production hashing untouched. Done-criterion worth aiming at: internal/handlers below 20s in a cache-defeated container build, which would also close out #198.

Root cause measured while implementing https://git.eeqj.de/sneak/webhooker/issues/67. Every `newTestApp` in `internal/handlers` seeds an admin user, and that pays an **Argon2id hash at 64 MB**. The package's runtime is therefore roughly linear in the number of fx applications the tests stand up, not in what they assert. Measurements, all in a cache-defeated container build: - unmodified `next`, baseline: 67.7s, and 82.8s in a separate container run — against a 90s per-package budget - one fx application per table row (a natural way to write a new table-driven test): `panic: test timed out after 1m30s` - the same tests consolidated to six applications: **37.8s** So the package sits at roughly 92% of budget before anyone adds anything, and the marginal cost of a new test is an Argon2id hash rather than the test's own work. That is why it tips under load and why raising the timeout again would only defer it. Suggested direction for whoever takes this: a test-only seam that skips the Argon2id admin seed for tests that do not exercise login, leaving production hashing untouched. Done-criterion worth aiming at: `internal/handlers` below 20s in a cache-defeated container build, which would also close out https://git.eeqj.de/sneak/webhooker/issues/198.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#225