rbrooks/Iris-WLED

Watch

Fork 0

Flaky E2E: season preview's caption sometimes doesn't appear within 10 s #177

New issue

Open

opened 2026-09-26 11:06:20 +00:00 by claude-bot · 1 comment

claude-bot commented

2026-09-26 11:06:20 +00:00

Collaborator

What happened

In PR #174's first CI run (run 10973, job 56007), e2e/season-preview.spec.ts › "stepping and playing move the caption" failed: getByTestId('season-caption') was not visible after 10 s. The page heading had rendered, so the page was up but its data hadn't arrived. The same test passed in #172's CI, in local runs, and in #174's rerun after rebasing. Nothing in #174 touches the frontend.

Evidence

No 500s and no tracebacks in the container log, so the request didn't fail outright.
The page shows "Planning the season…" while for-range is in flight, and it has no error branch that hides the caption other than the error message.
The E2E suite runs 8 workers in parallel against one container, and other specs create and delete events (each triggers an event-cache refresh) at the same moment. SQLite is in its default rollback-journal mode, not WAL, so readers wait on writers. Planning 60 nights is a few hundred small queries.

This is a working theory: a slow for-range response under write contention, outlasting the 10 s wait. It isn't proven. The container log doesn't show the page's own for-range request at all, which fits a request still blocked when the test gave up.

Options

Test side (cheap): wait for the for-range response explicitly (page.waitForResponse) with a longer timeout, and then for the caption. A longer timeout alone would hide a real slowdown.
App side (worth measuring): time plan_for_range(60) on a realistic database, and consider WAL mode (PRAGMA journal_mode=WAL) so reads don't block on writes. WAL has backup implications, because a snapshot must include or checkpoint the -wal file. services/backup.py would need checking, and so would the production spec's backup advice (Rhoving/iac-repo#527 §9, which says the database uses rollback-journal mode).

Record every recurrence here, with its run id.

## What happened In PR #174's first CI run (run 10973, job 56007), `e2e/season-preview.spec.ts` › "stepping and playing move the caption" failed: `getByTestId('season-caption')` was not visible after 10 s. The page heading had rendered, so the page was up but its data hadn't arrived. The same test passed in #172's CI, in local runs, and in #174's rerun after rebasing. Nothing in #174 touches the frontend. ## Evidence - **No 500s and no tracebacks in the container log,** so the request didn't fail outright. - **The page shows "Planning the season…" while `for-range` is in flight,** and it has no error branch that hides the caption other than the error message. - **The E2E suite runs 8 workers in parallel against one container,** and other specs create and delete events (each triggers an event-cache refresh) at the same moment. SQLite is in its default rollback-journal mode, not WAL, so readers wait on writers. Planning 60 nights is a few hundred small queries. This is a working theory: a slow `for-range` response under write contention, outlasting the 10 s wait. It isn't proven. The container log doesn't show the page's own `for-range` request at all, which fits a request still blocked when the test gave up. ## Options 1. **Test side (cheap):** wait for the `for-range` response explicitly (`page.waitForResponse`) with a longer timeout, and then for the caption. A longer timeout alone would hide a real slowdown. 2. **App side (worth measuring):** time `plan_for_range(60)` on a realistic database, and consider WAL mode (`PRAGMA journal_mode=WAL`) so reads don't block on writes. WAL has backup implications, because a snapshot must include or checkpoint the `-wal` file. `services/backup.py` would need checking, and so would the production spec's backup advice (Rhoving/iac-repo#527 §9, which says the database uses rollback-journal mode). Record every recurrence here, with its run id.

claude-bot added this to the v1.2.0 milestone

2026-09-26 11:06:45 +00:00

claude-bot added the

labels

2026-09-26 11:06:45 +00:00

claude-bot commented

2026-09-26 13:31:13 +00:00

Author

Collaborator

Probable root cause found, while investigating a similar E2E failure on #180 (the watchdog Settings test).

GET /api/v1/schemes?year= had an N+1 settings read. list_schemes called _enrich_scheme(s, db) without runtime, so each of a year's ~108 schemes re-queried the settings table and re-validated RuntimeSettings. Both the calendar and the Settings page call that endpoint.

Profile: py-spy on the app during a parallel E2E run put list_schemes at 77.8% of CPU samples, with settings_service._load_rows the innermost hot frame at 57.9%.
Effect: every other request queued behind it. A settings PUT that takes 0.03 s when idle took 5–22 s. That's the same shape as this issue: a page whose data request didn't answer within 10 s, with no 500s.
Fix: in #180 (commit 96bd1f2), settings are read once per request, and a regression test counts the reads. At 1 CPU with 8 workers, the season-preview "stepping and playing" test stopped failing after the fix, across 13 fresh-container runs.

I'll close this once #180 is merged and a few more CI runs pass without it recurring. The profile also named the next costs under heavier contention: list_schemes pydantic validation, review_summary, and get_recurrence_horizon, which re-reads YAML on every call. Those are filed separately.

**Probable root cause found**, while investigating a similar E2E failure on #180 (the watchdog Settings test). `GET /api/v1/schemes?year=` had an **N+1 settings read**. `list_schemes` called `_enrich_scheme(s, db)` without `runtime`, so each of a year's ~108 schemes re-queried the settings table and re-validated `RuntimeSettings`. Both the calendar and the Settings page call that endpoint. - **Profile:** py-spy on the app during a parallel E2E run put `list_schemes` at **77.8% of CPU samples**, with `settings_service._load_rows` the innermost hot frame at 57.9%. - **Effect:** every other request queued behind it. A settings PUT that takes 0.03 s when idle took 5–22 s. That's the same shape as this issue: a page whose data request didn't answer within 10 s, with no 500s. - **Fix:** in #180 (commit `96bd1f2`), settings are read once per request, and a regression test counts the reads. At 1 CPU with 8 workers, the season-preview "stepping and playing" test stopped failing after the fix, across 13 fresh-container runs. I'll close this once #180 is merged and a few more CI runs pass without it recurring. The profile also named the next costs under heavier contention: `list_schemes` pydantic validation, `review_summary`, and `get_recurrence_horizon`, which re-reads YAML on every call. Those are filed separately.

claude-bot referenced this issue

2026-09-26 15:14:49 +00:00

Show what the lights used and cost this season (#153), and keep Settings edits until saved (#181) #180

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

rbrooks/Iris-WLED#177

No description provided.

Rows
Columns