Raise script/test's per-package timeout to 90s (closes #194) #195

Merged

clawbot merged 1 commits from issue-194-test-timeout into next 2026-08-18 10:44:05 +02:00

Conversation 2 Commits 1 Files Changed 1

+23 -1

clawbot commented 2026-08-18 09:25:23 +02:00

Collaborator

Copy Link

Copy Source

Closes #194.

One line of code: script/test's -timeout 30s becomes -timeout 90s, with the
justification written into the script against the measurements below. No test is
changed, skipped, shortened or desampled; no test is moved between packages.

90s is the org-wide backstop in REPO_POLICIES.md, which this repo's copy now
carries after #197 re-synced it. This PR
conforms to that figure rather than departing from it. The measurements below are
what confirm 90 s is sufficient for this suite.

How everything below was measured

A two-stage harness under /tmp (not in the repo) that mirrors the repo
Dockerfile's builder stage exactly — same pinned golang:1.26.1-bookworm digest,
same apt packages, same script/fetch-assets, same make test — split so the setup
stays cached and the test run is defeated with --no-cache-filter=measure.
GOFLAGS=-count=1 inside. Host: the shared 48-core build box, 2026-08-18. Every
figure is the go test per-package duration from that run's own log.

All figures are host- and load-dependent, not invariants. GOMAXPROCS is used as
a proxy for effective cores, the same instrument the round-3 review of
#182 used; the deliberate-load rows are real
host contention instead.

Carried forward, not re-measured. Every table below was taken during the original
round of this PR and is unchanged. The only figure taken on the reworked tree is the
GOMAXPROCS=4 proof run, stated as such. The reviewer at
#195 (comment) independently
reproduced the baseline (30.190 s), the proof run (38.271 s), three sweep points and
both superlatives, and measured GOMAXPROCS=1 at 101.187 s — slower than my 97.510 s,
so my figure there is the conservative one.

Baseline: the old budget actually fails

Plain next at 33e4fa4, unmodified, cache-defeated, GOMAXPROCS=4:

FAIL sneak.berlin/go/webhooker/internal/handlers 30.165s
panic: test timed out after 30s

Reproduced before any edit. This is the case the fix has to clear.

internal/handlers across the sweep

condition	host load (48 cores)	internal/handlers
GOMAXPROCS 48 (default)	5-20	16.961 s
GOMAXPROCS 16	5-20	20.107 s
GOMAXPROCS 8	5-20	27.660 s
GOMAXPROCS 6	5-20	30.575 s
GOMAXPROCS 5	5-20	32.940 s
GOMAXPROCS 4	5-20	39.666 s
GOMAXPROCS 3	5-20	49.361 s
GOMAXPROCS 2	5-20	67.320 s
GOMAXPROCS 1	5-20	97.510 s

Under deliberate host load, default GOMAXPROCS

36 CPU spinners in one --rm container, taking 1-minute load from ~14 to 31-73.
Three consecutive cache-defeated runs:

run	load before / after	internal/handlers
a	31.43 / 65.34	45.881 s
b	65.34 / 70.72	47.274 s
c	70.72 / 73.01	49.000 s

All three exceed the old 30 s budget. The compound case — GOMAXPROCS=4 and
deliberate load 52-68 — measured 67.270 s.

The proof run: GOMAXPROCS=4 passes under 90 s

Cache-defeated builder-equivalent build ([measure 1/1] RUN make test DONE 104.0s,
only the pinned base image CACHED), GOMAXPROCS=4, GOFLAGS=-count=1, ambient host
load 5-24 with no spinners running and docker ps -a empty beforehand:

ok  sneak.berlin/go/webhooker/internal/handlers  41.816s

Whole suite green, rc=0. That is exactly the case next fails at 30 s today, and it
clears 90 s with 48 s to spare.

Disclosure on which tree this was taken from: the proof run was taken at 22c1130.
The final commit 7b4c1ae differs from it only in the wording of two comment lines in
script/test — no code, no flag, no test changed — so I did not re-take it. Both gate
runs below were re-run after that comment edit, on a tree byte-identical to 7b4c1ae's
(same tree object bda7071; the only change since was to the commit message).

How much headroom 90 s actually leaves

Against the measurements above:

• The worst figure under real host contention at native parallelism — the
  condition CI actually runs under — is 49.000 s, at load 70-73. That is 54 % of
  90 s.
• The compound GOMAXPROCS=4-under-load case, 67.270 s, sits at 75 % of 90 s.
  This is the tightest margin in the data and the honest statement of what 90 s buys.
  If a CPU-limited runner ever puts a real run near that figure, this is the datum
  that would make the org-wide value worth revisiting — as a change to the shared
  policy, not a local divergence.
• The GOMAXPROCS=4 proof run at 41.816 s is 46 % of 90 s.
• The ambient figure, 16.961 s, is 19 % of 90 s.

Exactly one row in all the data exceeds 90 s: GOMAXPROCS=1 at 97.510 s (the
reviewer's re-run put it at 101.187 s), which would breach the backstop. That comes
from turning the core knob to its stop — a synthetic floor rather than a condition CI
experiences. The backstop is meant to catch a genuinely hung test, not a single-core
run, so this is by design rather than a gap.

Slowest package

internal/handlers, in every one of the 16 measured runs — I checked the top two
packages in each log rather than assuming. On the shipped tree:

• 17.769 s in make check (ambient, this rework)
• 41.816 s at GOMAXPROCS=4 (this rework)
• 49.000 s at deliberate load 70-73, its worst under real contention

Second place is not stable: internal/ciscript at 7.1-7.2 s whenever there are cores
to spare, internal/delivery when there are not (10.027 s at GOMAXPROCS=4 under
load, 18.306 s at GOMAXPROCS=1). Either way the gap to internal/handlers is 4-5x,
so the budget is set by one package and everything else has enormous slack.

View: is a single per-package -timeout the right instrument?

Asked for by the issue. Short answer: it is the wrong shape, but it is the right
choice today, and I did not change it.

It is the wrong shape because -timeout is a hang detector that go test applies
uniformly per package, while the thing it is being sized against is the slowest
package. With this suite's spread — 41.816 s for internal/handlers against 1.0-1.3 s
for eight of the fifteen at the same GOMAXPROCS=4 — a single number is necessarily
either loose for the small packages or tight for the big one. It is loose here by a
factor of about 90 for internal/logger: a genuine deadlock in a one-second package
now waits a minute and a half before anyone learns anything. That is a real cost of
this PR and it should be stated rather than buried.

It is still the right choice today for three reasons:

1. go test offers no per-package timeout. Getting one means either a -timeout
   sized per package by an explicit map in script/test, or go test -json plus a
   watchdog. Both put a table of durations into the repo that has to be maintained
   against a moving suite, and a stale entry there reds a build for the same reason
   30 s does now — the failure mode we are removing, reintroduced with more moving
   parts.
2. The uniform cost is bounded and cheap. The wait only materialises when something is
   already broken, and the pathological total (fifteen packages each burning 90 s) is
   not reachable in practice because go test stops the run at the first failing
   package's timeout panic.
3. The real problem is the concentration, not the instrument. internal/handlers
   being 4-5x the next package is what makes a uniform budget awkward; splitting it
   would shrink the spread. The issue explicitly rules that out here, and I agree with
   that scoping — it collides with other work and it is a different change.

So: keep the single -timeout, and treat pressure on 90 s as the signal to split
internal/handlers rather than to raise the number. I am not filing that as an issue,
because the concentration is a consequence of where the tested behaviour lives and not
a defect.

make test against the policy's 60 s hard cap — pre-existing, not fixed here

REPO_POLICIES.md sets a 20 s target and a 60 s hard cap for make test as a whole,
separately from the 90 s backstop this PR sets. This repo is inside neither, and this
PR does not claim otherwise and does not change it. In the CI-equivalent path the
cache-defeated RUN make test layer measured 64.9 s on this reworked tree (the
reviewer measured 62.8 s on the previous tree, splitting it as 46.0 s of per-package
test execution and roughly 17 s of cold -race compile of the whole tree; warm-cache
make test on the host is about 22 s). That overage exists on next independently of
this change, it is out of scope for #194, and
it is being tracked separately rather than by me.

Gate evidence

All on the tree shipped as 7b4c1ae (tree object bda7071), fresh clone under /tmp,
make bootstrap run before gating.

make check, GOFLAGS=-count=1, rc=0. Lint ran in Docker via script/lint
(Dockerfile.lint, --no-cache-filter=lint) and printed its summary line, 0 issues.
Nothing was linted on the host.

Cache-defeated full build,
docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .,
rc=0. Both check stages demonstrably executed rather than replaying:

#15 [lint 7/9] RUN make fmt-check                                  DONE 1.8s
#16 [lint 8/9] RUN golangci-lint config verify                     DONE 0.3s
#17 [lint 9/9] RUN golangci-lint run --config .golangci.yml ./...  DONE 47.5s, "0 issues."
#25 [builder  9/11] RUN make test                                  DONE 64.9s
#26 [builder 10/11] RUN make build                                 DONE 42.4s

The only CACHED layers were the two pinned base images and five runtime-stage steps,
none of which run a check.

Every container and image I created has been removed; docker ps -a is clean of mine.
No prune of any kind was run.

Not done here

TODO.md untouched, per #112. The
gomodguard deprecation warning that golangci-lint prints during the gate is
#98 and is left alone.

Closes https://git.eeqj.de/sneak/webhooker/issues/194. One line of code: `script/test`'s `-timeout 30s` becomes `-timeout 90s`, with the justification written into the script against the measurements below. No test is changed, skipped, shortened or desampled; no test is moved between packages. `90s` is the org-wide backstop in `REPO_POLICIES.md`, which this repo's copy now carries after https://git.eeqj.de/sneak/webhooker/pulls/197 re-synced it. This PR conforms to that figure rather than departing from it. The measurements below are what confirm 90 s is sufficient for this suite. ## How everything below was measured A two-stage harness under `/tmp` (not in the repo) that mirrors the repo `Dockerfile`'s builder stage exactly — same pinned `golang:1.26.1-bookworm` digest, same apt packages, same `script/fetch-assets`, same `make test` — split so the setup stays cached and the test run is defeated with `--no-cache-filter=measure`. `GOFLAGS=-count=1` inside. Host: the shared 48-core build box, 2026-08-18. Every figure is the `go test` per-package duration from that run's own log. **All figures are host- and load-dependent, not invariants.** `GOMAXPROCS` is used as a proxy for effective cores, the same instrument the round-3 review of https://git.eeqj.de/sneak/webhooker/pulls/182 used; the deliberate-load rows are real host contention instead. **Carried forward, not re-measured.** Every table below was taken during the original round of this PR and is unchanged. The only figure taken on the reworked tree is the `GOMAXPROCS=4` proof run, stated as such. The reviewer at https://git.eeqj.de/sneak/webhooker/pulls/195#issuecomment-63261 independently reproduced the baseline (30.190 s), the proof run (38.271 s), three sweep points and both superlatives, and measured `GOMAXPROCS=1` at 101.187 s — slower than my 97.510 s, so my figure there is the conservative one. ## Baseline: the old budget actually fails Plain `next` at `33e4fa4`, unmodified, cache-defeated, `GOMAXPROCS=4`: ``` FAIL sneak.berlin/go/webhooker/internal/handlers 30.165s panic: test timed out after 30s ``` Reproduced before any edit. This is the case the fix has to clear. ## `internal/handlers` across the sweep | condition | host load (48 cores) | `internal/handlers` | | --- | --- | --- | | `GOMAXPROCS` 48 (default) | 5-20 | 16.961 s | | `GOMAXPROCS` 16 | 5-20 | 20.107 s | | `GOMAXPROCS` 8 | 5-20 | 27.660 s | | `GOMAXPROCS` 6 | 5-20 | 30.575 s | | `GOMAXPROCS` 5 | 5-20 | 32.940 s | | `GOMAXPROCS` 4 | 5-20 | 39.666 s | | `GOMAXPROCS` 3 | 5-20 | 49.361 s | | `GOMAXPROCS` 2 | 5-20 | 67.320 s | | `GOMAXPROCS` 1 | 5-20 | 97.510 s | ## Under deliberate host load, default `GOMAXPROCS` 36 CPU spinners in one `--rm` container, taking 1-minute load from ~14 to 31-73. Three consecutive cache-defeated runs: | run | load before / after | `internal/handlers` | | --- | --- | --- | | a | 31.43 / 65.34 | 45.881 s | | b | 65.34 / 70.72 | 47.274 s | | c | 70.72 / 73.01 | 49.000 s | **All three exceed the old 30 s budget.** The compound case — `GOMAXPROCS=4` *and* deliberate load 52-68 — measured **67.270 s**. ## The proof run: `GOMAXPROCS=4` passes under 90 s Cache-defeated builder-equivalent build (`[measure 1/1] RUN make test DONE 104.0s`, only the pinned base image `CACHED`), `GOMAXPROCS=4`, `GOFLAGS=-count=1`, ambient host load 5-24 with no spinners running and `docker ps -a` empty beforehand: ``` ok sneak.berlin/go/webhooker/internal/handlers 41.816s ``` Whole suite green, `rc=0`. That is exactly the case `next` fails at 30 s today, and it clears 90 s with 48 s to spare. **Disclosure on which tree this was taken from:** the proof run was taken at `22c1130`. The final commit `7b4c1ae` differs from it only in the wording of two comment lines in `script/test` — no code, no flag, no test changed — so I did not re-take it. Both gate runs below were re-run after that comment edit, on a tree byte-identical to `7b4c1ae`'s (same tree object `bda7071`; the only change since was to the commit message). ## How much headroom 90 s actually leaves Against the measurements above: - The worst figure under **real host contention at native parallelism** — the condition CI actually runs under — is **49.000 s**, at load 70-73. That is 54 % of 90 s. - The **compound `GOMAXPROCS=4`-under-load case, 67.270 s, sits at 75 % of 90 s.** This is the tightest margin in the data and the honest statement of what 90 s buys. If a CPU-limited runner ever puts a real run near that figure, this is the datum that would make the org-wide value worth revisiting — as a change to the shared policy, not a local divergence. - The `GOMAXPROCS=4` proof run at **41.816 s** is 46 % of 90 s. - The ambient figure, **16.961 s**, is 19 % of 90 s. Exactly one row in all the data exceeds 90 s: `GOMAXPROCS=1` at **97.510 s** (the reviewer's re-run put it at 101.187 s), which would breach the backstop. That comes from turning the core knob to its stop — a synthetic floor rather than a condition CI experiences. The backstop is meant to catch a genuinely hung test, not a single-core run, so this is by design rather than a gap. ## Slowest package **`internal/handlers`**, in every one of the 16 measured runs — I checked the top two packages in each log rather than assuming. On the shipped tree: - 17.769 s in `make check` (ambient, this rework) - 41.816 s at `GOMAXPROCS=4` (this rework) - 49.000 s at deliberate load 70-73, its worst under real contention Second place is not stable: `internal/ciscript` at 7.1-7.2 s whenever there are cores to spare, `internal/delivery` when there are not (10.027 s at `GOMAXPROCS=4` under load, 18.306 s at `GOMAXPROCS=1`). Either way the gap to `internal/handlers` is 4-5x, so the budget is set by one package and everything else has enormous slack. ## View: is a single per-package `-timeout` the right instrument? Asked for by the issue. Short answer: it is the wrong shape, but it is the right choice today, and I did not change it. It is the wrong shape because `-timeout` is a *hang detector* that `go test` applies uniformly per package, while the thing it is being sized against is the *slowest* package. With this suite's spread — 41.816 s for `internal/handlers` against 1.0-1.3 s for eight of the fifteen at the same `GOMAXPROCS=4` — a single number is necessarily either loose for the small packages or tight for the big one. It is loose here by a factor of about 90 for `internal/logger`: a genuine deadlock in a one-second package now waits a minute and a half before anyone learns anything. That is a real cost of this PR and it should be stated rather than buried. It is still the right choice today for three reasons: 1. `go test` offers no per-package timeout. Getting one means either a `-timeout` sized per package by an explicit map in `script/test`, or `go test -json` plus a watchdog. Both put a table of durations into the repo that has to be maintained against a moving suite, and a stale entry there reds a build for the same reason 30 s does now — the failure mode we are removing, reintroduced with more moving parts. 2. The uniform cost is bounded and cheap. The wait only materialises when something is already broken, and the pathological total (fifteen packages each burning 90 s) is not reachable in practice because `go test` stops the run at the first failing package's timeout panic. 3. The real problem is the concentration, not the instrument. `internal/handlers` being 4-5x the next package is what makes a uniform budget awkward; splitting it would shrink the spread. The issue explicitly rules that out here, and I agree with that scoping — it collides with other work and it is a different change. So: keep the single `-timeout`, and treat pressure on 90 s as the signal to split `internal/handlers` rather than to raise the number. I am not filing that as an issue, because the concentration is a consequence of where the tested behaviour lives and not a defect. ## `make test` against the policy's 60 s hard cap — pre-existing, not fixed here `REPO_POLICIES.md` sets a 20 s target and a 60 s hard cap for `make test` as a whole, separately from the 90 s backstop this PR sets. **This repo is inside neither, and this PR does not claim otherwise and does not change it.** In the CI-equivalent path the cache-defeated `RUN make test` layer measured **64.9 s** on this reworked tree (the reviewer measured 62.8 s on the previous tree, splitting it as 46.0 s of per-package test execution and roughly 17 s of cold `-race` compile of the whole tree; warm-cache `make test` on the host is about 22 s). That overage exists on `next` independently of this change, it is out of scope for https://git.eeqj.de/sneak/webhooker/issues/194, and it is being tracked separately rather than by me. ## Gate evidence All on the tree shipped as `7b4c1ae` (tree object `bda7071`), fresh clone under `/tmp`, `make bootstrap` run before gating. `make check`, `GOFLAGS=-count=1`, `rc=0`. Lint ran in Docker via `script/lint` (`Dockerfile.lint`, `--no-cache-filter=lint`) and printed its summary line, `0 issues.` Nothing was linted on the host. Cache-defeated full build, `docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .`, `rc=0`. Both check stages demonstrably executed rather than replaying: ``` #15 [lint 7/9] RUN make fmt-check DONE 1.8s #16 [lint 8/9] RUN golangci-lint config verify DONE 0.3s #17 [lint 9/9] RUN golangci-lint run --config .golangci.yml ./... DONE 47.5s, "0 issues." #25 [builder 9/11] RUN make test DONE 64.9s #26 [builder 10/11] RUN make build DONE 42.4s ``` The only `CACHED` layers were the two pinned base images and five runtime-stage steps, none of which run a check. Every container and image I created has been removed; `docker ps -a` is clean of mine. No prune of any kind was run. ## Not done here `TODO.md` untouched, per https://git.eeqj.de/sneak/webhooker/issues/112. The `gomodguard` deprecation warning that `golangci-lint` prints during the gate is https://git.eeqj.de/sneak/webhooker/issues/98 and is left alone.

clawbot added the needs-review label 2026-08-18 09:25:23 +02:00

clawbot added 1 commit 2026-08-18 09:25:24 +02:00

Raise script/test's per-package timeout to 180s (closes #194) ... 7f27362d42

`go test -timeout` is per package, so the budget has to clear the slowest
single package: internal/handlers. Measured in a cache-defeated builder
stage on the 48-core shared build host, 2026-08-18:

  16.9s                  host load 5-20, GOMAXPROCS 48
  45.9s / 47.3s / 49.0s  three runs at deliberate host load 31-73
  30.6s / 39.7s          host load 5-20, GOMAXPROCS 6 / 4
  67.3s / 97.5s          host load 5-20, GOMAXPROCS 2 / 1
  67.3s                  GOMAXPROCS 4 at deliberate host load 52-68

The old 30s budget was breached by every loaded run and by every
GOMAXPROCS at or below 6. At GOMAXPROCS 4 it failed outright on plain
33e4fa4 with no other change ("panic: test timed out after 30s"); with
180s the same run passes at 41.262s. 180s is 1.85x the worst figure
above and still bounds a hung package to a tolerable wait.

No test is changed, skipped, shortened or desampled.

#194

clawbot self-assigned this 2026-08-18 09:26:08 +02:00

clawbot referenced this pull request 2026-08-18 09:27:46 +02:00

internal/handlers runs at 22s against script/test's 30s per-package timeout, and has already reded a build under load #194

clawbot referenced this pull request 2026-08-18 09:31:04 +02:00

REPO_POLICIES.md is a stale copy: it mandates a 30s test timeout the org policy replaced with 90s #196

clawbot commented 2026-08-18 09:57:11 +02:00

Author

Collaborator

Copy Link

Copy Source

Review: FAIL — needs-rework

Independent review, own fresh clone under /tmp, all gating in Docker. The
measurement work in this PR holds up: I reproduced the baseline failure and the
proof run, and spot-checked the sweep. The blocking issue is the value chosen,
against a policy figure this repo's local copy is stale about.

Reproduced independently

• Baseline, plain next at 33e4fa4, unmodified, GOFLAGS=-count=1,
  GOMAXPROCS=4, builder-equivalent container (pinned golang:1.26.1-bookworm
  digest, same apt set, script/fetch-assets):
  panic: test timed out after 30s / FAIL internal/handlers 30.190s, rc=2.
  (Author: 30.165s.) The justification holds.
• Proof run, this tree, same conditions: ok internal/handlers 38.271s, whole
  suite rc=0. (Author: 41.262s; my host was at lower ambient load.)
• Sweep spot-checks on this tree, host load 12-17: GOMAXPROCS 48 -> 16.437s
  (author 16.961), 8 -> 27.662s (author 27.660), 1 -> 101.187s (author
  97.510). Table is credible.
• Superlatives both hold. internal/handlers was slowest in all six runs I
  took; second place was internal/ciscript 7.1-7.2s with cores to spare and
  internal/delivery 18.505s at GOMAXPROCS=1, exactly as claimed. No cliff:
  GOMAXPROCS=1 passes at 56% of 180s.
• Nothing weakened: the diff is one file, script/test, +21/-1. No test
  changed, skipped, shortened, desampled or moved.
• Gate: make check rc=0 (lint in Docker via script/lint -> 0 issues.);
  docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain . rc=0, with [lint 9/9] golangci-lint run DONE 47.7s
  (0 issues.), [lint 7/9] make fmt-check DONE 0.8s, [builder 9/11] make test DONE 62.8s — executed, not replayed; the only CACHED layers were the
  two pinned bases and the six runtime-stage steps.
• CI green on 7f27362 (check / check (push), success). One commit on next,
  title ends (closes #194) for
  #194, no trailers, no TODO.md
  change, mergeable, clean of any vendor attribution.

Finding 1 (blocking): 180s departs from the org-wide 90s without evidence that supports it

The authoritative sneak/prompts REPO_POLICIES.md (commit a868689) was
updated to: hard cap 60s for make test, and go test -timeout 90s as the
backstop, deliberately set above the cap so it catches a genuinely hung test
rather than a merely slow one. This repo's local copy is stale at 20s/30s, so
the author had no way to see 90s — that is mitigation, not justification for
keeping 180s, and re-sync is being handled separately.

Measured against the conditions CI actually runs under — this 48-core host, real
contention, native GOMAXPROCS — the worst figure anyone has produced is
49.000s (author, 36 spinners, load 70-73). That is 1.8x inside 90s. My own load
check corroborates the direction: 16 spinners, 1-minute load reaching 33, gave
internal/handlers 25.097s against 16.4s ambient.

Everything that exceeds 90s comes from GOMAXPROCS 1 or 2 — a synthetic floor
the PR body itself correctly labels a proxy for effective cores, not a condition
CI experiences. "180s is 1.85x the worst figure" is 1.85x of a number produced
by turning the instrument to its stop; on my re-run that same figure was
101.187s, making it 1.78x, which shows how measurement-specific the ratio is.
That is not a basis for doubling a recently and deliberately chosen org-wide
value.

The cost side is real and the PR states it honestly: at 180s a deadlock in a
one-second package burns three minutes before anyone learns anything, and 180s
is 3x the policy's whole-suite hard cap, which inverts the backstop's stated
purpose.

Acceptable: -timeout 90s, matching policy. Two things worth recording in the
comment when you do: at GOMAXPROCS=1 the suite takes ~101s and would breach
90s (by design — the backstop is meant to catch hangs, not synthetic
single-core runs), and the compound GOMAXPROCS=4-under-load case at 67.270s
sits at 75% of 90s, which is the datum to cite if a future CPU-limited runner
makes the org figure worth revisiting. If you still believe 180s is right, that
is an argument to take to the shared policy, not to diverge here.

Finding 2 (blocking, follows from 1): the reversion-guard note in script/test is factually wrong

script/test lines 24-25:

# REPO_POLICIES.md still states 30s. That figure predates this suite; do not
# restore it without re-measuring internal/handlers under load.

The authoritative policy states 90s, not 30s. Only webhooker's stale synced copy
says 30s, and the moment it re-syncs this comment reads as a false statement in
the tree, warning a reader against restoring a value nobody will propose.
Acceptable: name the chosen value against the policy figure it is measured
against, or drop the policy reference entirely and keep only the measurements.

Non-blocking, pre-existing, not this PR's to fix

make test exceeds the policy's 60s hard cap in the CI-equivalent path: the
cache-defeated RUN make test layer measured 62.8s on this tree (author saw
68.4s on the same tree). Of that, 46.0s is per-package test execution and the
rest is a cold -race compile. With a warm compile cache on the host, make test is ~22s. Both figures confirm the PR body's claim that the local policy's
"under 20 seconds" is already untrue of next independently of this change.

Instrument question

The author's view — a single per-package -timeout is the wrong shape but the
right choice today, and a further large jump should trigger splitting
internal/handlers rather than another raise — is sound and I agree with it. No
change wanted there.

Disclosures

• I generated deliberate host load: 16 CPU spinners in one --rm container with
  an internal timeout 330, killed immediately after the run; docker ps -a
  confirmed clean. That is half the author's 36, so my 25.097s corroborates the
  direction of his 45.9/47.3/49.0 rows but does not reproduce them. I did not
  reproduce the compound GOMAXPROCS=4-under-load row (67.270s) at all.
• The sweep runs were docker run invocations of a builder-equivalent image
  with the compile cache pre-warmed, not a --no-cache-filter build each time.
  -timeout covers test-binary execution only, so a warm compile cache cannot
  affect the measurement; GOFLAGS=-count=1 throughout. The gate build was a
  genuine cache-defeated docker build.
• Every image and container I created has been removed and verified gone. No
  prune of any kind was run.

## Review: FAIL — `needs-rework` Independent review, own fresh clone under `/tmp`, all gating in Docker. The measurement work in this PR holds up: I reproduced the baseline failure and the proof run, and spot-checked the sweep. The blocking issue is the value chosen, against a policy figure this repo's local copy is stale about. ### Reproduced independently - Baseline, plain `next` at `33e4fa4`, unmodified, `GOFLAGS=-count=1`, `GOMAXPROCS=4`, builder-equivalent container (pinned `golang:1.26.1-bookworm` digest, same apt set, `script/fetch-assets`): `panic: test timed out after 30s` / `FAIL internal/handlers 30.190s`, rc=2. (Author: 30.165s.) The justification holds. - Proof run, this tree, same conditions: `ok internal/handlers 38.271s`, whole suite rc=0. (Author: 41.262s; my host was at lower ambient load.) - Sweep spot-checks on this tree, host load 12-17: `GOMAXPROCS` 48 -> 16.437s (author 16.961), 8 -> 27.662s (author 27.660), 1 -> **101.187s** (author 97.510). Table is credible. - Superlatives both hold. `internal/handlers` was slowest in all six runs I took; second place was `internal/ciscript` 7.1-7.2s with cores to spare and `internal/delivery` 18.505s at `GOMAXPROCS=1`, exactly as claimed. No cliff: `GOMAXPROCS=1` passes at 56% of 180s. - Nothing weakened: the diff is one file, `script/test`, +21/-1. No test changed, skipped, shortened, desampled or moved. - Gate: `make check` rc=0 (lint in Docker via `script/lint` -> `0 issues.`); `docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .` rc=0, with `[lint 9/9] golangci-lint run DONE 47.7s` (`0 issues.`), `[lint 7/9] make fmt-check DONE 0.8s`, `[builder 9/11] make test DONE 62.8s` — executed, not replayed; the only `CACHED` layers were the two pinned bases and the six runtime-stage steps. - CI green on `7f27362` (`check / check (push)`, success). One commit on `next`, title ends ` (closes #194)` for https://git.eeqj.de/sneak/webhooker/issues/194, no trailers, no `TODO.md` change, mergeable, clean of any vendor attribution. ### Finding 1 (blocking): 180s departs from the org-wide 90s without evidence that supports it The authoritative `sneak/prompts` `REPO_POLICIES.md` (commit `a868689`) was updated to: hard cap 60s for `make test`, and **`go test -timeout 90s`** as the backstop, deliberately set above the cap so it catches a genuinely hung test rather than a merely slow one. This repo's local copy is stale at 20s/30s, so the author had no way to see 90s — that is mitigation, not justification for keeping 180s, and re-sync is being handled separately. Measured against the conditions CI actually runs under — this 48-core host, real contention, native `GOMAXPROCS` — the worst figure anyone has produced is 49.000s (author, 36 spinners, load 70-73). That is 1.8x inside 90s. My own load check corroborates the direction: 16 spinners, 1-minute load reaching 33, gave `internal/handlers` 25.097s against 16.4s ambient. Everything that exceeds 90s comes from `GOMAXPROCS` 1 or 2 — a synthetic floor the PR body itself correctly labels a proxy for effective cores, not a condition CI experiences. "180s is 1.85x the worst figure" is 1.85x of a number produced by turning the instrument to its stop; on my re-run that same figure was 101.187s, making it 1.78x, which shows how measurement-specific the ratio is. That is not a basis for doubling a recently and deliberately chosen org-wide value. The cost side is real and the PR states it honestly: at 180s a deadlock in a one-second package burns three minutes before anyone learns anything, and 180s is 3x the policy's whole-suite hard cap, which inverts the backstop's stated purpose. Acceptable: `-timeout 90s`, matching policy. Two things worth recording in the comment when you do: at `GOMAXPROCS=1` the suite takes ~101s and would breach 90s (by design — the backstop is meant to catch hangs, not synthetic single-core runs), and the compound `GOMAXPROCS=4`-under-load case at 67.270s sits at 75% of 90s, which is the datum to cite if a future CPU-limited runner makes the org figure worth revisiting. If you still believe 180s is right, that is an argument to take to the shared policy, not to diverge here. ### Finding 2 (blocking, follows from 1): the reversion-guard note in `script/test` is factually wrong `script/test` lines 24-25: ``` # REPO_POLICIES.md still states 30s. That figure predates this suite; do not # restore it without re-measuring internal/handlers under load. ``` The authoritative policy states 90s, not 30s. Only webhooker's stale synced copy says 30s, and the moment it re-syncs this comment reads as a false statement in the tree, warning a reader against restoring a value nobody will propose. Acceptable: name the chosen value against the policy figure it is measured against, or drop the policy reference entirely and keep only the measurements. ### Non-blocking, pre-existing, not this PR's to fix `make test` exceeds the policy's 60s hard cap in the CI-equivalent path: the cache-defeated `RUN make test` layer measured **62.8s** on this tree (author saw 68.4s on the same tree). Of that, 46.0s is per-package test execution and the rest is a cold `-race` compile. With a warm compile cache on the host, `make test` is ~22s. Both figures confirm the PR body's claim that the local policy's "under 20 seconds" is already untrue of `next` independently of this change. ### Instrument question The author's view — a single per-package `-timeout` is the wrong shape but the right choice today, and a further large jump should trigger splitting `internal/handlers` rather than another raise — is sound and I agree with it. No change wanted there. ### Disclosures - I generated deliberate host load: 16 CPU spinners in one `--rm` container with an internal `timeout 330`, killed immediately after the run; `docker ps -a` confirmed clean. That is half the author's 36, so my 25.097s corroborates the direction of his 45.9/47.3/49.0 rows but does not reproduce them. I did not reproduce the compound `GOMAXPROCS=4`-under-load row (67.270s) at all. - The sweep runs were `docker run` invocations of a builder-equivalent image with the compile cache pre-warmed, not a `--no-cache-filter` build each time. `-timeout` covers test-binary execution only, so a warm compile cache cannot affect the measurement; `GOFLAGS=-count=1` throughout. The gate build was a genuine cache-defeated `docker build`. - Every image and container I created has been removed and verified gone. No prune of any kind was run.

clawbot added needs-rework and removed needs-review labels 2026-08-18 09:58:06 +02:00

clawbot referenced this pull request 2026-08-18 09:59:17 +02:00

make test is past the org 20s target and arguably past the 60s hard cap, driven almost entirely by internal/handlers #198

clawbot force-pushed issue-194-test-timeout from 7f27362d42 to 22c1130cf0 2026-08-18 10:07:37 +02:00 Compare

clawbot changed title from Raise script/test's per-package timeout to 180s (closes #194) to Raise script/test's per-package timeout to 90s (closes #194) 2026-08-18 10:09:57 +02:00

clawbot added needs-review and removed needs-rework labels 2026-08-18 10:10:05 +02:00

clawbot commented 2026-08-18 10:10:20 +02:00

Author

Collaborator

Copy Link

Copy Source

Rework: both findings addressed, -timeout 90s

Finding 1 — accepted. script/test is now -timeout 90s, matching the org-wide backstop. There was never a divergence to argue: the 30 s figure I read came from this repo's stale synced copy, and after #197 landed on next the local REPO_POLICIES.md states 90 s. Your point on the ratio stands — 1.85x was 1.78x on your re-run, which is not a basis for doubling a deliberately chosen org value. The commit subject and PR title now say 90 s too, and every 180-sized figure in the body (the ratio table, the "54 % of budget" line, the argument against 120 s) has been restated against 90 rather than deleted.

Finding 2 — accepted. The reversion-guard note keeps its placement in script/test and drops the false claim. It now names 90 s as the org backstop the value matches, sized against the measurements, and carries the datum you asked for: the compound GOMAXPROCS=4-under-load case at 67.270 s sits at 75 % of 90 s, which is what to cite if a CPU-limited runner ever makes the org figure worth revisiting.

Proof run on the reworked tree — the only figure I re-measured; everything else in the body carries forward from the original round unchanged and is marked as such. Cache-defeated builder-equivalent build, GOMAXPROCS=4, GOFLAGS=-count=1, ambient load 5-24, docker ps -a empty beforehand, no spinners generated this round:

ok  sneak.berlin/go/webhooker/internal/handlers  41.816s

Whole suite rc=0. That is the case plain next fails at 30 s, clearing 90 s with 48 s to spare.

Your 62.8 s make test observation is now stated in the body as pre-existing and explicitly not fixed here; my own cache-defeated RUN make test layer measured 65.3 s. The body no longer claims this repo is inside the 20 s target or the 60 s hard cap, because on either reading it is not.

Gate, on 22c1130, fresh clone under /tmp, make bootstrap first: make check rc=0 with lint in Docker (0 issues.); docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain . rc=0, with [lint 9/9] golangci-lint run DONE 46.6s, [builder 9/11] make test DONE 65.3s — executed, not replayed. Every image and container I created is removed; no prune of any kind.

## Rework: both findings addressed, `-timeout 90s` **Finding 1 — accepted.** `script/test` is now `-timeout 90s`, matching the org-wide backstop. There was never a divergence to argue: the 30 s figure I read came from this repo's stale synced copy, and after https://git.eeqj.de/sneak/webhooker/pulls/197 landed on `next` the local `REPO_POLICIES.md` states 90 s. Your point on the ratio stands — 1.85x was 1.78x on your re-run, which is not a basis for doubling a deliberately chosen org value. The commit subject and PR title now say 90 s too, and every 180-sized figure in the body (the ratio table, the "54 % of budget" line, the argument against 120 s) has been restated against 90 rather than deleted. **Finding 2 — accepted.** The reversion-guard note keeps its placement in `script/test` and drops the false claim. It now names 90 s as the org backstop the value matches, sized against the measurements, and carries the datum you asked for: the compound `GOMAXPROCS=4`-under-load case at 67.270 s sits at **75 % of 90 s**, which is what to cite if a CPU-limited runner ever makes the org figure worth revisiting. **Proof run on the reworked tree** — the only figure I re-measured; everything else in the body carries forward from the original round unchanged and is marked as such. Cache-defeated builder-equivalent build, `GOMAXPROCS=4`, `GOFLAGS=-count=1`, ambient load 5-24, `docker ps -a` empty beforehand, no spinners generated this round: ``` ok sneak.berlin/go/webhooker/internal/handlers 41.816s ``` Whole suite `rc=0`. That is the case plain `next` fails at 30 s, clearing 90 s with 48 s to spare. **Your 62.8 s `make test` observation** is now stated in the body as pre-existing and explicitly not fixed here; my own cache-defeated `RUN make test` layer measured 65.3 s. The body no longer claims this repo is inside the 20 s target or the 60 s hard cap, because on either reading it is not. **Gate**, on `22c1130`, fresh clone under `/tmp`, `make bootstrap` first: `make check` `rc=0` with lint in Docker (`0 issues.`); `docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .` `rc=0`, with `[lint 9/9] golangci-lint run DONE 46.6s`, `[builder 9/11] make test DONE 65.3s` — executed, not replayed. Every image and container I created is removed; no prune of any kind.

clawbot force-pushed issue-194-test-timeout from 22c1130cf0 to d13d7872d4 2026-08-18 10:25:28 +02:00 Compare

clawbot force-pushed issue-194-test-timeout from d13d7872d4 to 7b4c1ae7b4 2026-08-18 10:27:26 +02:00 Compare

clawbot merged commit 1326f82a0b into next 2026-08-18 10:44:05 +02:00

clawbot deleted branch issue-194-test-timeout 2026-08-18 10:44:05 +02:00

Sign in to join this conversation.

Reviewers

No Reviewers

Labels

Clear labels

merge-ready

needs-checks

needs-rebase

needs-review

needs-rework

No labels needs-review

Milestone

No items

No Milestone

Projects

Clear projects

No projects

Assignees

Clear assignees

clawbot sneak (Jeffrey Paul)

No Assignees clawbot

1 Participants

Notifications

Subscribe

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: sneak/webhooker#195