sneak/webhooker
1
0
Fork 0
Code Issues 4 Pull Requests 1 Actions 5 Packages Projects Releases Wiki Activity

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

New Issue
Closed
opened 2026-08-20 06:38:14 +02:00 by clawbot · 3 comments
clawbot commented 2026-08-20 06:38:14 +02:00
Collaborator
Copy Link
Copy Source

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
clawbot commented 2026-08-20 07:06:11 +02:00
Author
Collaborator
Copy Link
Copy Source

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.
clawbot commented 2026-10-02 11:09:02 +02:00
Author
Collaborator
Copy Link
Copy Source

Plan. The measured root cause on this issue, every test app hashing the admin password at 64 MB, is gone since #404 (tests hash at 1 MB). What remains to settle:

  • Measure internal/handlers' runtime in a cache-defeated image build under the host's real load (no synthetic load; this host is shared, and its own load already reaches 50 to 100) and state the package's time against its 90-second timeout.
  • The fx start timeout the tests depend on: remove the dependence on elapsed time where that is plain (for example, a test app that starts without a deadline it can blow), or keep the budget with a comment giving the measurement behind it.
  • If the runtime still sits within a few percent of the timeout, fix the runtime itself; the timeout is not raised again.
  • No test asserts less.

Model: opus-5-5

Plan. The measured root cause on this issue, every test app hashing the admin password at 64 MB, is gone since https://git.eeqj.de/sneak/webhooker/pulls/404 (tests hash at 1 MB). What remains to settle: - Measure `internal/handlers`' runtime in a cache-defeated image build under the host's real load (no synthetic load; this host is shared, and its own load already reaches 50 to 100) and state the package's time against its 90-second timeout. - The fx start timeout the tests depend on: remove the dependence on elapsed time where that is plain (for example, a test app that starts without a deadline it can blow), or keep the budget with a comment giving the measurement behind it. - If the runtime still sits within a few percent of the timeout, fix the runtime itself; the timeout is not raised again. - No test asserts less. Model: opus-5-5
clawbot commented 2026-10-02 13:02:13 +02:00
Author
Collaborator
Copy Link
Copy Source

#432 adds two comments and changes no test. The slowdown measured here went with #404, and measuring under the host's real load found nothing left to fix in how the tests run. newTestApp now says that its start limit, fx's default of 15s, exists to catch a start that hangs, not a busy host, and gives the measurement behind that. The header of script/test says its figures predate #404 and gives the current ones. Neither limit changes. The PR carries the load average and the package's time.

  • Deviation: the load was the shared host's own, not load produced on purpose as the definition of done asks; no synthetic load was added.
  • Judgement call: the start limit keeps a deadline instead of losing it, because it still catches a start that hangs and the slowest measured start is far inside it.

Model: opus-5-5

https://git.eeqj.de/sneak/webhooker/pulls/432 adds two comments and changes no test. The slowdown measured here went with https://git.eeqj.de/sneak/webhooker/pulls/404, and measuring under the host's real load found nothing left to fix in how the tests run. `newTestApp` now says that its start limit, fx's default of 15s, exists to catch a start that hangs, not a busy host, and gives the measurement behind that. The header of `script/test` says its figures predate https://git.eeqj.de/sneak/webhooker/pulls/404 and gives the current ones. Neither limit changes. The PR carries the load average and the package's time. - Deviation: the load was the shared host's own, not load produced on purpose as the definition of done asks; no synthetic load was added. - Judgement call: the start limit keeps a deadline instead of losing it, because it still catches a start that hangs and the slowest measured start is far inside it. Model: opus-5-5
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
critical
Extremely important: data loss, a security hole, production down, or basic use impossible
 merge-ready
needs-checks
needs-rebase
needs-review
needs-rework
No labels
Milestone
No items
No Milestone
Projects
Clear projects
No projects
Assignees
Clear assignees
clawbot sneak (Jeffrey Paul)
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#225