OpenCode/Flight-Ops
2
0
Fork 0
Code Issues Pull Requests Actions Activity

Transient /api/state (and /api/test/*) HTTP 500s under scale-1000 e2e load — undiagnosable, flaking CI repeatedly #127

New Issue
Closed
opened 2026-09-22 18:16:40 +02:00 by kamilkrzywda · 2 comments
kamilkrzywda commented 2026-09-22 18:16:40 +02:00
Owner
Copy Link
Copy Source

Symptom

Intermittent HTTP 500 from the app server during the CI e2e suite (isolated dind stack), always under scale-1000 load. Self-heals: retries pass, so it flakes rather than fails hard — but it has now failed whole runs multiple times.

Recurring across runs (all on otherwise-green code):

  • run 160 (v0.52.0): right-pane.spec.ts:257, two-planes.spec.ts:404 — /api/state 500 inside expect.poll(getState) arrival waits
  • run 167 (favicon #1): hover.spec.ts:506 attempt 1, right-pane.spec.ts:188 — same signature
  • run 168 (favicon #2): two-planes.spec.ts:341 both attempts (POST /api/test/set-fuel → 500; retry /api/state → 500 in heal helper), hover.spec.ts:503 attempt 1

What we know

  • Transient, load-correlated (scale 1000 ticks), no deterministic repro locally
  • No server-side trace is captured: the CI e2e step's docker compose logs -f captures zero app output (no Next.js ready banner, no error stacks) — so every occurrence is undiagnosable from the run log
  • Suspected area: tick/persist path in the sim engine under fast-forward load (unhandled error → 500), but that's a guess without logs

Suggested next steps (diagnosis, not guessing)

  1. Fix CI log capture — figure out why docker compose logs -f on the flight-ci app container yields no Next.js output in the e2e step (log driver buffering? stream interleaving? wrong service name?) so future 500s leave a stack trace
  2. Server-side error logging — ensure unhandled errors in the tick/persist path are logged with context (clockMs, scale, plane count) before becoming HTTP 500s

Related: state.spec.ts:42 also flakes on a silent fresh-seed at boot (ENOENT/empty DB path); v0.52.0 added a console.warn there so the next occurrence is diagnosable — same log-capture gap applies.

## Symptom Intermittent `HTTP 500` from the app server during the CI e2e suite (isolated dind stack), always under scale-1000 load. Self-heals: retries pass, so it flakes rather than fails hard — but it has now failed whole runs multiple times. Recurring across runs (all on otherwise-green code): - **run 160** (v0.52.0): `right-pane.spec.ts:257`, `two-planes.spec.ts:404` — `/api/state` 500 inside `expect.poll(getState)` arrival waits - **run 167** (favicon #1): `hover.spec.ts:506` attempt 1, `right-pane.spec.ts:188` — same signature - **run 168** (favicon #2): `two-planes.spec.ts:341` both attempts (`POST /api/test/set-fuel` → 500; retry `/api/state` → 500 in heal helper), `hover.spec.ts:503` attempt 1 ## What we know - Transient, load-correlated (scale 1000 ticks), no deterministic repro locally - No server-side trace is captured: the CI e2e step's `docker compose logs -f` captures zero app output (no Next.js ready banner, no error stacks) — so every occurrence is undiagnosable from the run log - Suspected area: tick/persist path in the sim engine under fast-forward load (unhandled error → 500), but that's a guess without logs ## Suggested next steps (diagnosis, not guessing) 1. **Fix CI log capture** — figure out why `docker compose logs -f` on the flight-ci app container yields no Next.js output in the e2e step (log driver buffering? stream interleaving? wrong service name?) so future 500s leave a stack trace 2. **Server-side error logging** — ensure unhandled errors in the tick/persist path are logged with context (clockMs, scale, plane count) before becoming HTTP 500s Related: `state.spec.ts:42` also flakes on a silent fresh-seed at boot (ENOENT/empty DB path); v0.52.0 added a `console.warn` there so the next occurrence is diagnosable — same log-capture gap applies.
kamilkrzywda commented 2026-09-23 08:12:10 +02:00
Author
Owner
Copy Link
Copy Source

Closing on evidence — the symptom has not recurred since v0.57.0:

  • Root-cause hypothesis (v0.57.0): pre-v0.57.0, Next.js module-instance splitting gave instrumentation.ts and route handlers separate sql.js DB instances (two worlds per process) → transient 500s + silent reseeds under load. The SSE work unified the singletons on globalThis, so every code path now shares one DB instance.
  • Mitigation already in place (v0.55.0): all e2e specs retry transient /api/state 500s ×3/500 ms, so even a recurrence would flake far less.
  • Evidence: runs 175–183 (9 consecutive CI runs, each with the full e2e suite under scale-1000 load) — zero infra failures; every failure in that window was test-side and diagnosed separately.

The issue's suggested hardening (CI log capture for docker compose logs -f silence + server-side error logging on the tick/persist path) remains valid if it recurs — reopen with a run number and we'll do that diagnosis work then rather than speculatively now.

Closing on evidence — the symptom has not recurred since v0.57.0: - **Root-cause hypothesis (v0.57.0):** pre-v0.57.0, Next.js module-instance splitting gave `instrumentation.ts` and route handlers *separate* sql.js DB instances (two worlds per process) → transient 500s + silent reseeds under load. The SSE work unified the singletons on `globalThis`, so every code path now shares one DB instance. - **Mitigation already in place (v0.55.0):** all e2e specs retry transient `/api/state` 500s ×3/500 ms, so even a recurrence would flake far less. - **Evidence:** runs 175–183 (9 consecutive CI runs, each with the full e2e suite under scale-1000 load) — zero infra failures; every failure in that window was test-side and diagnosed separately. The issue's suggested hardening (CI log capture for `docker compose logs -f` silence + server-side error logging on the tick/persist path) remains valid *if it recurs* — reopen with a run number and we'll do that diagnosis work then rather than speculatively now.
kamilkrzywda commented 2026-09-23 10:28:52 +02:00
Author
Owner
Copy Link
Copy Source

Recurrence evidence (reopening per the close condition): CI run 185 (PR #136, head 799365e — a two-line color change that cannot affect server routes) got transient 500s from POST /api/test/set-fuel and POST /api/test/create-package within a ~2 s window at the end of the e2e run (two-planes.spec.ts: "two planes fly in parallel" failed on set-fuel 500; "two grounded planes" flaked on create-package 500, passed on retry). All other 57 tests passed. The v0.55.0 mitigation only retries getState() copies — the test-hook POST helpers have no retry wrapper. Root cause still unknown (CI stack torn down with logs); candidates: same class as before (DB singleton / transient handler error) or CI-box load at suite end.

Recurrence evidence (reopening per the close condition): CI run 185 (PR #136, head 799365e — a two-line color change that cannot affect server routes) got transient 500s from `POST /api/test/set-fuel` and `POST /api/test/create-package` within a ~2 s window at the end of the e2e run (two-planes.spec.ts: "two planes fly in parallel" failed on set-fuel 500; "two grounded planes" flaked on create-package 500, passed on retry). All other 57 tests passed. The v0.55.0 mitigation only retries `getState()` copies — the test-hook POST helpers have no retry wrapper. Root cause still unknown (CI stack torn down with logs); candidates: same class as before (DB singleton / transient handler error) or CI-box load at suite end.
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
bug
Something is not working
 duplicate
This issue or pull request already exists
 enhancement
New feature
 help wanted
Need some help
 invalid
Something is wrong
 question
More information is needed
 wontfix
This won't be fixed
No labels
Milestone
No items
No Milestone
Assignees
Clear assignees
kamilkrzywda (Kamil Krzywda) smysakowski
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: OpenCode/Flight-Ops#127