test(build): deflake graph scheduler test with synchronization

[reyreavman]

Summary

The unit CI job could fail with nothing failing in its log: Build Suite - 148/148 specs ... SUCCESS!, no --- FAIL anywhere, then There were failures detected in the following suites: build ./pkg/build and exit code 201. Two plain tests in pkg/build asserted scheduling properties through racing sleep budgets and could lose those races on a loaded runner, and ginkgo -p — which task test:unit uses — swallows the stdout of plain go tests, so a loss left no trace. No werf behavior changes.

What

• TestDoImagesInParallel_DependentImageDoesNotWaitForUnrelatedSlowImage enforces its ordering by synchronization: slow is held on a gate released only once c has been recorded, so the observed order is [a, b, c, slow] regardless of how loaded the machine is. It previously budgeted three sequential 10ms images against one 150ms image and required the chain to win.
• TestDoImagesInParallel_AnnotatesEachImageWithARealWorkerID enforces "both workers were used" by holding every image on a barrier that opens once two are in the phase at once, replacing four 20ms sleeps and a require.Len(seenWorkers, 2) that nothing guaranteed. runWorkers spawns worker goroutines without a handshake, so worker 0 could drain the whole queue before worker 1 was scheduled. VERIFIED: with the sleeps removed under GOMAXPROCS=1, the old form fails 38 of 50 runs with "map[0:true]" should have 2 item(s), but has 1.
• Under a regression both tests now fail on the 10s context deadline rather than on an inverted order: image "slow" gave up waiting for its gate and image "w1" waited for 2 images to build concurrently, never reached.
• The three tests pass a per-test home dir to werf.Init. With an empty homeDirOption it falls back to ~/.werf and creates the host locker and run-timestamp files there, which under ginkgo -p is 15 processes on one path and on a self-hosted runner is shared with every concurrent job.
• Neither test sleeps any more; the two together drop from ~410ms to ~210ms.
• TestDoImagesInParallel_AssignsBuildOrderIndexByRealDequeueNotStaticTopology is deliberately unchanged: both slow and a are queued in newGraphScheduler before any worker starts, so indices 0/1 are theirs by construction under any load.
• No production code changes: pkg/build/graph_scheduler.go and pkg/build/conveyor.go are untouched, so nothing about real build scheduling differs.

Why

Both assertions were races dressed as properties. Sleeps are wall-clock and complete on time under any load, while the work they were being raced against pays scheduling and dispatch overhead that grows with contention: the a→b→c chain completes in ~35ms idle and ~84ms under 8-way concurrency, over half its 150ms budget, and the unit job runs 15 ginkgo processes on a shared runner. The worker-ID test was the same shape, and its sleeps were the only reason it ever saw two workers.

Leaving them costs more than a retry. Because ginkgo -p discards plain test output, a failure surfaces as a green suite with a bare exit code 201 naming no test, so every occurrence costs a full investigation before it can even be attributed.

Widening the gaps instead — a 1s delay on slow, say — was rejected: it is the same racing budget with a larger constant, it only moves the threshold at which load inverts the result, and it makes the suite slower for the privilege.

[reyreavman]

Verification

• Masking reproduced: adding func TestPhantomRepro(t *testing.T) { t.Fatal("boom") } to pkg/build and running task test:unit paths="./pkg/build" exits 201 with every spec green, no --- FAIL marker, and no occurrence of boom anywhere in the output — the CI signature exactly.
• Signature attributed to this test: temporarily setting the chain delays to 60ms each (chain 180ms > slow 150ms) forces the inversion, and task test:unit paths="./pkg/build" reproduces the same green-but-201 output naming build ./pkg/build.
• Timing margin measured with a temporary instrumented copy of the scenario: chain completes in ~35ms idle, ~84ms under 8 concurrent runs, against the 150ms budget. The first measurement run was discarded — all eight concurrent runs reported byte-identical timings, i.e. go test had served them from cache; re-measured with -count=1.
• Mutation: made graphScheduler.complete hold newly-ready dependents until every dispatched task finished, i.e. a wave/level barrier → --- FAIL: TestDoImagesInParallel_DependentImageDoesNotWaitForUnrelatedSlowImage (10.10s), unable to process images in parallel: context deadline exceeded. Scheduler restored from a file copy, not git checkout, since the test change was uncommitted at the time.
• Stress after the fix: 12 concurrent runs x 25 iterations x 3 tests, zero failures.
• Not run: the order inversion itself was never reproduced on this hardware — 240 executions under 24-way concurrency stayed green, since a 10-core machine cannot stretch the chain's overhead to the ~120ms the inversion needs. The fix does not rest on that reproduction: the assertion is a timing race by construction, and the mutation above shows the reworked test still catches the regression it exists for.

Review focus

• recordingPhase.AfterImageStages now blocks before recording. This is safe only because ParallelTasksLimit: -1 resolves to one worker per image in doImagesInParallel, so gating slow cannot starve the chain — worth confirming that reading holds for any future caller that sets a positive limit and also uses waitFor.
• The two ordering assertions in the reworked test are now true by construction; the signal that catches a reintroduced barrier is the context deadline on require.NoError, not those assertions.

Follow-up

• Vanilla Test* output is discarded under ginkgo -p, so any failing vanilla test in pkg/build reports as a green suite with a bare exit code 201 and names no test. This masking is independent of the flake fixed here and still hides the next one.
• CI resolves a stale ginkgo CLI (2.20.1) while go.mod pins 2.28.1, because the Linux-go-tools-... cache key does not include the ginkgo version — a fix for werf/common-ci. Not related to this failure.

[reyreavman]

Reviewed this after spending a full investigation on exactly the failure it fixes: unit on #326 failed 13 consecutive attempts on an unchanged commit (attempts 1–4 of the same run passed, 8–13 failed on four different runners), each time as Build Suite - 154/154 specs … SUCCESS! followed by There were failures detected in the following suites: build ./pkg/build and exit 201. The diagnosis in this PR is correct and the gate is the right shape. Four suggestions, one of which I think should land here.

1. The masking is the expensive half, and it is still unfixed

The description names it ("every occurrence costs a full investigation before it can even be attributed") but nothing in the diff addresses it, so the next plain-test failure in pkg/build will cost the same investigation again. I measured the options before suggesting one, on a two-file reproduction (one Ginkgo spec + one func TestPlainFails that calls t.Fatal):

run	plain-test failure visible?
ginkgo -p	no
ginkgo -p -v	no
ginkgo -p --keep-going	no
ginkgo -p --output-interceptor-mode=none	no
ginkgo (serial)	yes — --- FAIL: TestPlainFails

All on CLI v2.28.1, so this is not a CLI-version artifact. Worth knowing separately: CI runs CLI 2.20.1 against library 2.28.1 — every unit log starts with Ginkgo's version-mismatch warning — because set-up-ci-base caches ~/go/bin/ginkgo and the install step is command -v ginkgo >/dev/null || task deps:install:ginkgo, so a cached binary is never upgraded. That is worth fixing on its own, but it would not have made this failure visible.

The only fix that needs no workflow change is to stop having plain tests in a Ginkgo package: convert the 17 func TestXxx in pkg/build (graph_scheduler_test.go, graph_scheduler_integration_test.go, content_tag_race_test.go, anchor_dispatch_test.go, build_report_test.go, stages_iterator_test.go) into specs, or at minimum the three TestDoImagesInParallel_* this PR already owns. testify/require works inside It unchanged if t is replaced by GinkgoT(). Then a failure names the test in the suite report like every other failure in this repo.

If that is too large for this PR, please split it out and link it here rather than leaving the trap armed.

2. TestDoImagesInParallel_AnnotatesEachImageWithARealWorkerID is the same racing budget

It builds 4 images with ParallelTasksLimit: 2 and 20 ms delays, then asserts require.Len(seenWorkers, 2). Nothing forces the second worker to dequeue anything — with the queue drained fast enough, or worker 1 scheduled late on a loaded runner, worker 0 can take all four and the assertion fails. "240 executions, no failures" on a developer machine is precisely the evidence the 150 ms budget had before it started failing on the runners.

The same technique settles it deterministically: make the first two images block on a barrier that only opens once both have entered (waitFor already gives you the primitive — a chan closed by the second arrival, or a sync.WaitGroup of 2 waited under ctx). Two images held simultaneously is the property "both workers were used", and it cannot pass on one worker: with ParallelTasksLimit: 2 and a barrier of 2, a single-worker regression deadlocks and fails on the context deadline.

TestDoImagesInParallel_AssignsBuildOrderIndexByRealDequeueNotStaticTopology I agree needs no change — both slow and a are ready before any worker starts, so indices 0/1 are theirs by construction, whatever the load.

3. werf.Init(t.TempDir(), "") leaves the home dir shared

All three tests pass "" as homeDirOption, so werf.Init falls back to ~/.werf (pkg/werf/main.go:109-114) and then creates the host locker and writes first_run_at/last_run_at there. Under ginkgo -p that is 15 processes on one path, and on a self-hosted runner it is also shared with every other job running concurrently. Not the flake being fixed here, but it is shared mutable state in tests that are otherwise hermetic, and it is a one-word fix while this file is open:

require.NoError(t, werf.Init(t.TempDir(), t.TempDir()))

4. After the gate, the final assertion is tautological — say so

require.Less(t, indexOf("c"), indexOf("slow")) can no longer fail: slow is held until c is recorded, so if control reaches that line the order already holds. The real detector is now require.NoError(t, conveyor.doImages(...)) failing on the 10 s deadline, with image "slow" gave up waiting for its gate in the wrapped error. That is a better test, but the comment above the assertion still presents the Less as "the core regression check", which invites the next reader to keep the assertion and drop the gate — restoring the flake. Please state in the comment that the gate is the detector and the deadline is how a barrier regression surfaces.

Minor, optional: close(ch) in the signal branch panics if an image is ever recorded twice. A sync.Once per channel costs nothing and removes a failure mode that would look like an unrelated panic.

Rebase

The branch is 48 commits behind main and has been open since 10 Sep; e2e_extra on its last run failed. Given how many branches this flake is currently blocking, it would help to bring it up to date and land it ahead of the queue.

[reyreavman]

Verification

• Masking reproduced: adding func TestPhantomRepro(t *testing.T) { t.Fatal("boom") } to pkg/build and running task test:unit paths="./pkg/build" exits 201 with every spec green, no --- FAIL marker, and no occurrence of boom in the output. The same run with parallel=false prints --- FAIL: TestPhantomRepro and boom, confirming the serial/parallel split in the review table on CLI v2.28.1.
• Signature attributed to the ordering test: temporarily setting its chain delays to 60ms each (chain 180ms > slow 150ms) forces the inversion, and task test:unit paths="./pkg/build" reproduces the same green-but-201 output naming build ./pkg/build.
• Worker-ID race reproduced: zeroing the four 20ms delays and running -count=50 -cpu=1 fails 38 times with "map[0:true]" should have 2 item(s), but has 1 — worker 0 took all four images. An earlier attempt at this measurement was discarded: the perl substitution had not matched, so the run exercised the unmodified test and its green result meant nothing.
• Timing margin measured with a temporary instrumented copy: the chain completes in ~35ms idle, ~84ms under 8 concurrent runs, against a 150ms budget. The first such measurement was also discarded — all eight concurrent runs reported byte-identical timings, i.e. go test served them from cache; re-measured with -count=1.
• Mutation (ordering test): made graphScheduler.complete hold newly-ready dependents until every dispatched task finished, i.e. a wave/level barrier → --- FAIL ... (10.10s), unable to process images in parallel: context deadline exceeded.
• Mutation (worker-ID test): forced numberOfWorkers := 1 in doImagesInParallel → --- FAIL ... (10.10s), image "w1" waited for 2 images to build concurrently, never reached: context deadline exceeded.
• Both mutations reverted from file copies rather than git checkout, since the test changes were uncommitted at the time.
• Stress after the fix: all three tests, 50 runs at GOMAXPROCS=1 — the exact condition that broke the old worker-ID test 38 times out of 50 — plus 12 concurrent runs x 25 iterations, zero failures.
• Not run: the ordering inversion itself was never reproduced on this hardware — 240 executions under 24-way concurrency stayed green, since a 10-core machine cannot stretch the chain's overhead to the ~120ms it needs. The fix does not rest on that reproduction: the assertion is a timing race by construction, and the mutation above shows the reworked test still catches the regression it exists for.

Review focus

• concurrencyBarrier is held by images inside the phase, so it is safe only while the barrier target does not exceed the worker count. Here that is 2 images against ParallelTasksLimit: 2, and the ordering test's gate relies on ParallelTasksLimit: -1 resolving to one worker per image — worth confirming that reading holds for any future caller that combines a positive limit with waitFor or barrier.
• Every ordering assertion in both tests is now true by construction; the detectors are the gate and the barrier, and a regression surfaces as a context deadline on require.NoError. The comments say so explicitly so the next reader does not keep the assertions and drop the synchronization.

Follow-up

• Convert the 17 plain func TestXxx in pkg/build to Ginkgo specs so a failure names the test instead of vanishing into a green suite with exit 201. Out of scope here: it spans six files and the whole package, and this PR's brief explicitly excluded the conversion. Needs its own issue, linked back here.
• CI resolves a stale ginkgo CLI (2.20.1) against library 2.28.1 — set-up-ci-base caches ~/go/bin/ginkgo and the install step is guarded by command -v ginkgo, so a cached binary is never upgraded. A fix for werf/common-ci. It would not have made this failure visible.

Not addressed, deliberately: a sync.Once around close(ch) in the signal branch. An image cannot currently be recorded twice, so the panic it guards is unreachable, and AGENTS.md asks for the simplest solution that works until a concrete requirement justifies more. Happy to add it if you would rather have the guard.

e2e_extra on the previous run is not analyzed here.