Skip to content

A session's CI failures are five separate defects, not one starved runner #1141

Description

@ExtraToast

What prompted this

Five CI failures in one working session looked like one problem — a runner too
busy to meet a five second budget — because they share a symptom: a wait that
expires. This is the measurement of that belief. It does not hold. The failures
have five distinct causes, four of which were already diagnosed and fixed on the
same day, and the load hypothesis fails the one test that would confirm it.

What was measured

gh run list --workflow validate.yml --limit 100, covering 2026-09-04T12:01Z to
2026-09-05T18:42Z, roughly 31 hours. 79 of those runs reached a conclusion, for
1297 jobs. Every job's conclusion, queue wait and duration was read from
repos/ESA-Blueshell/website/actions/runs/{id}/jobs, and the logs of all 13
failing jobs were read in full.

System-test shard jobs: 4 failures in 403 concluded jobs, 1.0%. They fall on
shards 2, 4 and 6; shards 1, 3 and 5 did not fail once.

job failures / concluded
Frontend unit tests with coverage 4 / 79
Frontend end-to-end tests 2 / 79
System tests, all six shards 4 / 403
Everything else 3 / 758

The sample is a day and a half. It is enough to say the system-test shards fail
about one job in a hundred, and enough to separate the causes, because every
failing log names its own. It is not enough to rank rare causes against each
other.

Why it is not starvation

A starved runner makes everything slow. These runs are not slow.

Failing shard jobs took 210s, 251s, 277s and 300s. Passing shard jobs run 175s
to 334s, median 231s. The failures sit inside the passing distribution, and the
four slowest shard jobs in the window all passed. Queue wait is the same for
both: median 3s for failures, median 3s for successes, so neither queue depth
nor concurrent runs separate them.

Within a failing job the pattern is the same. In job 101279996039,
EventPageSystemTest > logged-in user can delete existing event sign-up fails at
08:51:09, and the next seven tests in the same class pass at 2.2s to 3.2s each,
ending at 08:51:44. Only the awaited step was slow. Nothing around it was.

The +11307ms reading of the committee trace, which looked like an eleven second
page load, is a misreading of the log format, and that is a defect in its own
right — see below. The committee trace's own numbers say the opposite of slow:
the login page arrives at +13333ms and the submit click happens at +14883ms,
so the whole test spent 1.55s on the wire.

The concurrency picture, since it was asked

The Kotlin system suite does not oversubscribe anything. tests/system/build.gradle.kts
sets no maxParallelForks, there is no junit-platform.properties, and no
parallel execution is configured, so Gradle runs one test JVM.
tests/system/src/test/kotlin/net/blueshell/systemtests/PlaywrightTestBase.kt
launches one Chromium per class under Lifecycle.PER_CLASS and gives each test
one context and one page. The suite is strictly sequential. Each of the six
shards is its own ubuntu-latest runner — 4 vCPU, 16 GB — carrying one browser,
one JVM and the three containers .github/scripts/start-system-test-stack.sh
brings up.

The eight-workers-on-four-vCPUs figure is real but belongs elsewhere: it is
services/frontend/playwright.config.ts:19, the frontend e2e job, which is a
different suite in a different job and does show load sensitivity.

The 5000ms is a decision, not a default

tests/system/src/test/kotlin/net/blueshell/systemtests/Polling.kt:12 sets
POLL_TIMEOUT_MS = 5_000, and PlaywrightTestBase.DEFAULT_TIMEOUT_MS is that
same constant, so page actions, navigations and polls share one budget. Both
carry a written rationale that raising it hides the defect rather than fixing it.
It arrived with the suite in 40c6c6d (#739). The cold start it would otherwise
have to absorb is paid separately by COLD_START_BUDGET_MS = 90_000, before any
test runs.

So the number is not incidental, and the evidence gives no reason to move it.

The five causes

One. CommitteeManagerPageSystemTest > updates committee name and description(),
shard 2, run 33955468019. This is #1042's mechanism: the request log shows
GET /users?size=500 at +14560ms and the submit click 323ms later, with no
PUT /committees/{id} after it. Worth noting for #1042's sake — both of its
fixes, 6c82c5b (#1045) and dfeffc8 (#1100), were already in that commit, so the
flake recurred after the defect was fixed, as expected. ec07271 (#1138) landed
later the same day. #1139 covers the page size the picker still guesses.

Two. EventPageSystemTest > logged-in user can delete existing event sign-up(),
shard 6, runs 33953657648 and 33955963162, 49 minutes apart, same test, same
shard. This is #1125: a page.waitForResponse wrapped around the click, with the
line after it asserting the same outcome against the database. Fixed by 89a6f16
(#1135), which removed nineteen instances of that shape across the suite.

Three. EventCreatePageSystemTest > events page fetches banner for newly created event()
and EventEditPageSystemTest > events page fetches banner after editing event banner(),
shard 4, run 33896091168. These are not flakes. The branch is
feat/association-statistics-and-public-event-art, titled "make event banners
public", and the failures time out at 30000ms rather than 5000ms. The diff caused
them.

Four. Two of the four frontend-unit failures, runs 33955797056 and 33955963162,
report Error: enableAutoUnmount cannot be called more than once with 178 of 178
test files failing. That is deterministic breakage on the branch, not a flake, and
later runs on the same branch are green.

Five. The other two, runs 33909208129 and 33952519126, pass everything —
176/176 files, 1515/1515 tests — and go red on three unhandled
ReferenceError: window is not defined raised from Timeout.poll in
vuetify/src/components/VImg/VImg.tsx:260 after teardown. That is #1126, closed
at 08:33Z on 2026-09-05.

Two others sit alongside. The frontend e2e failure in run 33951798737 is
boards.spec.ts › does not trip the pencil the drag started on, which is #1134,
open. #804 is closed, and JobManager.test.ts did not fail once in this window.

The corepack/yarn crash in a Docker build stage does not appear here: Build Image
failed 0 times in 73 concluded jobs, and no run of any workflow in the last 60
failed for that reason. It is not ruled out, only unobserved in this window.

The shared shape is real, and it is not a wait budget

Three of the four browser failures wrap a click in page.waitForResponse and
assert the real outcome on the next line. The wait then caps the browser's view
of a request whose success re-renders the element that was clicked. #1135 wrote
that rule into Polling.kt and swept all 62 call sites. #1134 is the same idea
one layer down: a click that scrolls the page it then needs to be still. Load
makes both more likely to lose. Neither is caused by load.

What is actually left to do

The request log's timestamps are measured from the wrong origin. This is the
one unfixed thing this investigation turned up, and it is what made the failures
look like starvation in the first place.
tests/system/src/test/kotlin/net/blueshell/systemtests/HttpFailureLog.kt:38
holds private val start = System.currentTimeMillis() as an object property, set
once when the class first loads, and clear() at line 17 resets the entry lists
but not that origin. So +13333ms on a request means thirteen seconds since the
shard's first test, not since this test began. Every trace in a shard's later
tests reads as though the page took ten seconds to load. Reset the origin in
clear(), so the number means what a reader takes it to mean.

Nothing else here needs a change. Four of the five causes are fixed, one was
the PR's own diff, and #1134 is open with a plan already written. Raising the
5000ms budget would have hidden #1042, #1125 and #1126 — three real defects, one
of them a bug a board member would hit — and is not supported by any measurement
in this window.

If the flake rate is still worth attacking, the honest next step is not a
timeout but a count: the suite has no record of which test failed on which run,
so every question like this one costs a day of log reading. Recording the failing
test name and duration per shard job would make the next rate measurable in
minutes.

Related

#1042, #1125, #1126, #1134, #1138, #1139, #804, #1095.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions