Repository navigation
test(load): complete WP-X.2 W5 binary load gate - #186
joseederangojr wants to merge 2 commits into
Conversation
Refs OZE-3217
66735ea to
8ad4cd5
Compare
🟡 Changes requestedAdds 7 open issues
What changed in this PRChanges:
Review effort: medium |
joseederangojr
left a comment
joseederangojr
left a comment
There was a problem hiding this comment.
Inline findings for the W5 load harness. Overview comment posted separately.
| const stderrText = new Response(curl.stderr).text(); | ||
| const [exitCode, headers] = await Promise.race([ | ||
| Promise.all([curl.exited, stdoutText, stderrText]).then(([code, out]) => [code, out] as const), | ||
| new Promise<never>((_, reject) => setTimeout(() => { curl.kill(); reject(new Error("curl request exceeded independent 4s deadline")); }, 4000)), |
There was a problem hiding this comment.
[Low] Per-request 4 s timers are never cleared
Location: apps/server/run-w5-load.ts:43
The setTimeout inside the Promise.race is never cleared when curl finishes first. Each of the 1000 requests leaves a live 4 s timer, so the process cannot exit until they all fire. Each one then calls curl.kill() on an exited process and rejects a promise nobody awaits. This adds up to about 4 s of shutdown delay and muddies the event loop during the run.
Suggested fix:
let deadline: ReturnType<typeof setTimeout> | undefined;
const [exitCode, headers] = await Promise.race([
Promise.all([curl.exited, stdoutText, stderrText]).then(([code, out]) => [code, out] as const),
new Promise<never>((_, reject) => {
deadline = setTimeout(() => { curl.kill(); reject(new Error("curl request exceeded independent 4s deadline")); }, 4000);
}),
]).finally(() => clearTimeout(deadline));| const ownedServers: ReturnType<typeof Bun.spawn>[] = []; | ||
| let serverExitCode: number | undefined; | ||
| const abortRun = new AbortController(); | ||
| const wholeRunTimeout = setTimeout(() => { console.error("whole-run deadline reached"); abortRun.abort(new Error("whole-run deadline exceeded")); }, 180_000); |
There was a problem hiding this comment.
[Low] Whole-run deadline does not cover setup or in-flight requests
Location: apps/server/run-w5-load.ts:55
abortRun is wired only to the Bun.sleep inside the request loop (line 121). The 180 s deadline therefore does not stop docker compose up --wait, migrate, or the warm-up loop, and it does not cancel a requestRedirect already in flight. A hung Compose start or migration can run past the deadline, and the message "whole-run deadline reached" is misleading because nothing is actually aborted. Either pass abortRun.signal into requestRedirect and the setup steps, or drop the timer and rely on the per-step timeouts.
| const wholeRunTimeout = setTimeout(() => { console.error("whole-run deadline reached"); abortRun.abort(new Error("whole-run deadline exceeded")); }, 180_000); | ||
| try { | ||
| run(["bun", "apps/server/build.ts"]); | ||
| for (const reservation of reservations) reservation.release(); |
There was a problem hiding this comment.
[Low] Ports are released before Compose starts, so they can be taken first
Location: apps/server/run-w5-load.ts:58
freePort() reserves each port by listening on port 0 and then releases it. Line 58 releases all five reservations before docker compose up, leaving a window where another process can bind the same port. Compose then fails with a bind error, or a second run's freePort races this one. The chance is low on a dev machine, but the failure is hard to diagnose. Retrying the whole Compose step on a bind error, or letting Compose pick the ports and reading them back, would close the gap.
| if (!view) throw new Error("seeded route missing from production route source"); | ||
| const cache = createRouteCache(redis); | ||
| const redisNow = await cache.readServerTime(); | ||
| const routeView = { linkId: view.link.id, destination: view.link.destinationUrl, state: view.link.status, eligible: view.eligible, allowedHosts: view.allowedHosts, decision: "allow", version: view.link.version }; |
There was a problem hiding this comment.
[Low] Seeded cache entry is hand-built, not written by the production cache path
Location: apps/server/run-w5-load.ts:85-87
The warm entry is built by hand (routeView, lines 85-86) with a fixed decision: "allow" and written with cache.put. The log line at line 87 calls this the "production route cache", but the production writer is the redirect handler, and it never runs during seeding. Any drift between this hand-built shape and what the handler stores would go unnoticed, and the "cache hit" would then describe the harness's own data. Priming the cache with a real request (cold miss, then the measured hit) would make the artifact reflect the production path.
| } | ||
| })); | ||
| const percentile = (p: number) => Number([...times].sort((a,b) => a-b)[Math.ceil(times.length*p)-1].toFixed(2)); | ||
| const measurements = { requests: times.length, concurrency: 16, status: 302, cacheHit: true, p95Ms: percentile(.95), p99Ms: percentile(.99), maxMs: Number(Math.max(...times).toFixed(2)) }; |
There was a problem hiding this comment.
[Medium] cacheHit is hard-coded to true, and the 3 s route-view freshness window can expire mid-run
Location: apps/server/run-w5-load.ts:129
cacheHit: true and status: 302 are constants in the measurements object, not observations. The request loop checks status and Location (lines 122-123), but nothing checks whether a request was served from cache. ROUTE_VIEW_MAX_AGE_MS is 3000 (packages/adapter-redis/src/route-cache.ts:6), and the GET_SCRIPT age check returns null past that. The seed is written once before the loop, so any part of the 1000-request run that runs past about 3 s is served from the primary. The artifact would still report cacheHit: true. The label is therefore not backed by the run.
Failure scenario: The machine is slow, or the run is delayed. Requests after 3 s miss Redis, hit Postgres, and still pass the status check. The JSON records "cacheHit": true and p95/p99 that mix hit and miss latencies.
Suggested fix: Derive cacheHit from the run, for example by counting cache.get results inside the loop, or by re-checking cache.get(ids.link) after the run and recording the result. If a hit can't be proven for every request, record the observed hit count instead of a boolean.
| profile: { token: "single hot token", requests: 1000, concurrency: 16, stack: "ops/docker-compose.yml", binary: "dist/moneytrap", timing: "HTTP round-trip including client overhead; manual redirect, response body consumed", targets: { p95Ms: 50, p99Ms: 150 } }, | ||
| measurements, builtBinary: { commit: sha, path: "dist/moneytrap", sha256: Bun.spawnSync(["sh", "-c", `shasum -a 256 '${target}'`], { stdout: "pipe" }).stdout.toString().split(/\s+/)[0] }, | ||
| }; | ||
| await Bun.write(resolve(root, "ops/load/results/wp-x2-w5.json"), `${JSON.stringify(result, null, 2)}\n`); |
There was a problem hiding this comment.
[Medium] Harness writes the results artifact before the latency gate runs
Location: apps/server/run-w5-load.ts:136-138
Line 136 overwrites ops/load/results/wp-x2-w5.json before line 138 checks the gate. When the gate fails, the script exits non-zero but the file already holds the failing numbers, with no pass/fail field and nothing that marks the run as failed. Anyone who commits the file without checking the exit code records a failing run as if it were the result. It also replaces a previous good artifact with no trace.
Suggested fix: Move the gate above the write, or add a gate: { passed, p95Ms, p99Ms } field and write only on success. Also add the omitted smtp and mailpit ports to environment.ports so the artifact records every port in use.
| child.kill(); | ||
| await child.exited; | ||
| } | ||
| run([...compose, "down", "-v", "--remove-orphans"]); |
There was a problem hiding this comment.
[Low] finally cleanup can throw and mask the original error
Location: apps/server/run-w5-load.ts:146-147
run() throws on any non-zero exit (line 30). If docker compose down -v fails, that error replaces the original failure, such as a failed latency gate, and the remaining container check on line 147 never runs. Catch the teardown error, record it, and always run the container check. Set process.exitCode and rethrow the original error afterward.
Refs OZE-3217
joseederangojr
left a comment
joseederangojr
left a comment
There was a problem hiding this comment.
Inline findings for the W5 load harness, rereview at 4134628.
| const ownedServers: ReturnType<typeof Bun.spawn>[] = []; | ||
| let serverExitCode: number | undefined; | ||
| const abortRun = new AbortController(); | ||
| const wholeRunTimeout = setTimeout(() => { |
There was a problem hiding this comment.
[Low] Whole-run deadline does not cover setup or in-flight requests
Location: apps/server/run-w5-load.ts:65
Prior finding 4 is still open. abortRun is only wired to the Bun.sleep inside the request loop (line 207). docker compose up --wait, migrate, the seed, and the warm-up loop are not aborted, and an in-flight requestRedirect is not cancelled. The message "whole-run deadline reached" therefore implies more than happens.
Suggested fix: pass abortRun.signal into the setup steps and requestRedirect, or drop the timer and rely on per-step timeouts.
| try { | ||
| run(["bun", "apps/server/build.ts"]); | ||
| run([...compose, "up", "-d", "--wait"]); | ||
| for (const reservation of reservations) reservation.release(); |
There was a problem hiding this comment.
[High] Port reservations are held through compose up, so Compose cannot bind them
Location: apps/server/run-w5-load.ts:74
The reservations are moved to after docker compose up -d --wait (line 73). Each reservation is a live Bun.listen on 127.0.0.1:<port>, and ops/docker-compose.yml publishes 127.0.0.1:${MONEYTRAP_PG_PORT}, …REDIS_PORT, …SMTP_PORT, and …MAILPIT_UI_PORT. Compose therefore tries to bind a port that this process is still holding. I checked the bind conflict locally: a port held by a Bun listener returns Address already in use to a second bind on the same address. Compose will fail at up --wait on every run.
The prior finding asked for the release to be closed off from other processes, not held longer. The fix needs the release before Compose, plus a retry on a bind failure, or Compose choosing the ports and the harness reading them back.
Suggested fix:
for (const reservation of reservations) reservation.release();
run([...compose, "up", "-d", "--wait"]);and retry the compose up step on a bind error.
| decision: "allow", | ||
| version: view.link.version, | ||
| }; | ||
| await cache.put(ids.link, routeView, redisNow); |
There was a problem hiding this comment.
[Low] Seeded cache entry is still hand-built, not written by the production cache path
Location: apps/server/run-w5-load.ts:146
Prior finding 6 is still open. The seed is built by hand (routeView, lines 137-145) with a fixed decision: "allow" and written with cache.put. The redirect handler is the production writer, and it never runs during seeding, so any drift between this shape and what the handler stores would go unnoticed.
Suggested fix: prime the cache with a real request to the server (cold miss, then the measured hit), so the artifact reflects the production path.
| const start = performance.now(); | ||
| const response = await Promise.race([ | ||
| requestRedirect(url), | ||
| Bun.sleep(5000, { signal: abortRun.signal }).then(() => { |
There was a problem hiding this comment.
[Low] Per-request Bun.sleep(5000) timers are never cleared
Location: apps/server/run-w5-load.ts:207
Prior finding 3 is fixed for the curl timer, but the same pattern remains here. Each of the 1000 requests creates a Bun.sleep(5000, { signal }) inside Promise.race that is never cancelled when the request finishes. The warm-up loop (line 180) has the same issue. The process cannot exit until these fire, and each rejects an unawaited promise.
Suggested fix: clear the sleep on completion, for example with an AbortController per request that is aborted in finally, or with a shared setTimeout that is cleared in finally.
| if (response.status !== 302 || response.location !== "https://shop.example.com/spring") | ||
| throw new Error(`unexpected redirect ${response.status} ${response.location}`); | ||
| times.push(performance.now() - start); | ||
| if (performance.now() - measuredStart >= 2500) |
There was a problem hiding this comment.
[Medium] Freshness guard is measured from measuredStart, not from the seed write
Location: apps/server/run-w5-load.ts:214
The cache entry is written at cache.put (line 146), and ROUTE_VIEW_MAX_AGE_MS is 3000 ms from that write (packages/adapter-redis/src/route-cache.ts:6). The guard counts from measuredStart (line 197), which is taken after the warm-up. The warm-up can take a meaningful part of the 3 s window, so the run can extend past put + 3000 ms while the guard still allows it: a run that starts at put + 1 s can finish a last request at about put + 3.5 s. Those requests can be served from Postgres and still pass the 302 and Location check.
Suggested fix: record the seed time (redisNow or Date.now() at put), and fail when Date.now() - seededAt reaches the window at any request, not just performance.now() - measuredStart.
| requests: times.length, | ||
| concurrency: 16, | ||
| status: 302, | ||
| cacheHit: "primed production route cache; 1000 requests completed within freshness window", |
There was a problem hiding this comment.
[Medium] cacheHit is still asserted, not observed
Location: apps/server/run-w5-load.ts:226
Prior finding 2 is only partly addressed. cacheHit changed from true to a string, but the value is still a constant claim ("primed production route cache; 1000 requests completed within freshness window"). Nothing in the loop checks whether a request was a cache hit, and the freshness guard above is anchored to the wrong origin. The artifact still asserts a cache hit the run did not record.
Suggested fix: count cache.get results inside the loop or re-check the cache after the run, and record the observed hit count (for example cacheHits: n), not a constant string.
| bun: Bun.version, | ||
| dockerCompose: Bun.spawnSync(["docker", "compose", "version"], { stdout: "pipe" }).stdout.toString().trim(), | ||
| host: "local Docker Compose", | ||
| ports: { postgres: pgPort, redis: redisPort, http: httpPort }, |
There was a problem hiding this comment.
[Medium] Committed artifact is stale and omits smtp/mailpit ports
Location: apps/server/run-w5-load.ts:242
ops/load/results/wp-x2-w5.json is unchanged in this PR. It was produced by the earlier harness at ebd4e35, with a boolean cacheHit, and it has no gate fields. The current harness produces a different measurements.cacheHit shape, so the committed file no longer matches what the harness writes, and the W5 gate evidence comes from code that is no longer here. The prior finding also asked for smtp and mailpit to be added to environment.ports; ports still lists only postgres, redis, and http.
Suggested fix: add the smtp and mailpit ports to environment.ports, re-run the harness on the final code, and commit the regenerated artifact with the commit that produced it.
| cleanupError = `Compose cleanup failed: ${String(error)}`; | ||
| } | ||
| } | ||
| if (cleanupError) throw new Error(cleanupError); |
There was a problem hiding this comment.
[Low] Teardown error is dropped when the body also throws
Location: apps/server/run-w5-load.ts:285
Prior finding 7 is mostly fixed: a teardown failure no longer replaces the original error. But cleanupError is only thrown after the try/finally (line 285). If the body threw (for example, the latency gate), that error propagates from finally, so line 285 is never reached and a failed compose down -v or a remaining container is silently dropped.
Suggested fix: when a primary error is already in flight, log cleanupError with console.error before rethrowing, or attach it to the primary error.
🔴 Changes requestedThe harness now writes the artifact only after the latency gate passes, and the curl timers are cleared. A new regression blocks the run: the port reservations are released after 7 open issues
Prior findings (7)
What changed in this PR Changes:
The committed Review effort: medium |
WP-X.2
Refs OZE-3217
W5 built-binary load gate passed: 1,000 requests, concurrency 16, cache-hit redirect p95 21.46 ms and p99 23.69 ms. Artifact records environment, signed profile, measurements, and exact built-binary source commit and SHA-256.
W8 measurement remains outstanding; keep OZE-3217 In Progress until the W8 gate also passes.