From 3d6d564e8a8f543b2182326bcb803922cbcc33fe Mon Sep 17 00:00:00 2001 From: Aric Camarata Date: Thu, 29 Oct 2026 14:10:22 -0400 Subject: [PATCH 1/3] fix(ci): go-test-ran ignores skips of tests it was not asked about A package run such as ./cmd/... always carries a few skips, so requiring zero skip events failed every verify line that used the script. It now requires a passing event for each named prefix, and still fails on any fail event, a non-JSON line, or a skipped test whose name starts with a named prefix. --- scripts/ci/go-test-ran.py | 12 +++- scripts/ci/tests/test_go_test_ran.py | 87 ++++++++++++++++++++++++++++ 2 files changed, 97 insertions(+), 2 deletions(-) create mode 100644 scripts/ci/tests/test_go_test_ran.py diff --git a/scripts/ci/go-test-ran.py b/scripts/ci/go-test-ran.py index a82ab00a9..deac73f1e 100644 --- a/scripts/ci/go-test-ran.py +++ b/scripts/ci/go-test-ran.py @@ -1,5 +1,11 @@ #!/usr/bin/env python3 -"""Require actual passing go test -json events for every named test prefix.""" +"""Require actual passing go test -json events for every named test prefix. + +Fails on: a non-JSON line, any fail event (test or package), a skipped test whose +name starts with a named prefix, and a named prefix with no passing test. +Skips of tests that were not named (and package-level skips such as "no test +files") are ignored, because a package run always carries some of them. +""" import json import sys @@ -15,7 +21,9 @@ def check(stream, prefixes): continue action = event.get("Action") name = event.get("Test", "") - if action in {"skip", "fail"}: + if action == "fail": + bad = True + if action == "skip" and name and any(name.startswith(p) for p in prefixes): bad = True if action == "pass" and name: for prefix in passed: diff --git a/scripts/ci/tests/test_go_test_ran.py b/scripts/ci/tests/test_go_test_ran.py new file mode 100644 index 000000000..a36eba072 --- /dev/null +++ b/scripts/ci/tests/test_go_test_ran.py @@ -0,0 +1,87 @@ +"""Tests for scripts/ci/go-test-ran.py. + +The script reads `go test -json` events on stdin and exits 0 only when every +named test prefix has a passing test. Unrelated skips must not fail it (a +package run such as ./cmd/... always carries some); a failure anywhere, or a +named test that was skipped, must. +Runs under unittest (no third-party packages) and under pytest. +""" +import json +import os +import subprocess +import sys +import unittest + +SCRIPT = os.path.join(os.path.dirname(os.path.abspath(__file__)), "..", + "go-test-ran.py") + + +def ev(action, test=None, package="example.com/p"): + event = {"Action": action, "Package": package} + if test: + event["Test"] = test + return json.dumps(event) + + +def run(lines, *prefixes): + proc = subprocess.run([sys.executable, SCRIPT, *prefixes], + input="\n".join(lines).encode(), + stdout=subprocess.PIPE, stderr=subprocess.PIPE) + return proc.returncode + + +class GoTestRan(unittest.TestCase): + def test_named_tests_pass(self): + lines = [ev("run", "TestA"), ev("pass", "TestA"), ev("pass")] + self.assertEqual(run(lines, "TestA"), 0) + + def test_unrelated_skips_do_not_fail(self): + lines = [ev("pass", "TestA"), ev("skip", "TestOther"), + ev("skip", "TestOther2/sub"), ev("skip", package="example.com/empty"), + ev("pass")] + self.assertEqual(run(lines, "TestA"), 0) + + def test_named_test_skipped_fails(self): + lines = [ev("skip", "TestA"), ev("pass", "TestB")] + self.assertEqual(run(lines, "TestA", "TestB"), 1) + + def test_named_subtest_skipped_fails(self): + lines = [ev("pass", "TestA/one"), ev("skip", "TestA/two"), ev("pass", "TestA")] + self.assertEqual(run(lines, "TestA"), 1) + + def test_named_test_never_ran_fails(self): + lines = [ev("pass", "TestB"), ev("pass")] + self.assertEqual(run(lines, "TestA"), 1) + + def test_every_prefix_needs_a_pass(self): + lines = [ev("pass", "TestA")] + self.assertEqual(run(lines, "TestA", "TestB"), 1) + + def test_prefix_matches_a_passing_subtest(self): + self.assertEqual(run([ev("pass", "TestLinuxLeak/found")], "TestLinux"), 0) + + def test_failed_named_test_fails(self): + lines = [ev("pass", "TestA/one"), ev("fail", "TestA")] + self.assertEqual(run(lines, "TestA"), 1) + + def test_failed_unrelated_test_fails(self): + lines = [ev("pass", "TestA"), ev("fail", "TestOther")] + self.assertEqual(run(lines, "TestA"), 1) + + def test_failed_package_fails(self): + lines = [ev("pass", "TestA"), ev("fail")] + self.assertEqual(run(lines, "TestA"), 1) + + def test_non_json_line_fails(self): + lines = [ev("pass", "TestA"), "# example.com/p [build failed]"] + self.assertEqual(run(lines, "TestA"), 1) + + def test_empty_input_fails(self): + self.assertEqual(run([], "TestA"), 1) + + def test_no_prefix_is_a_usage_error(self): + self.assertNotEqual(run([ev("pass", "TestA")]), 0) + + +if __name__ == "__main__": + unittest.main() From af6609252c4e589b765745f071ea2d894a16d85c Mon Sep 17 00:00:00 2001 From: Aric Camarata Date: Thu, 29 Oct 2026 14:10:38 -0400 Subject: [PATCH 2/3] test(ci): make TestRunsWait independent of host speed The capped-wait subtest gave a 200 ms budget to a run that had to open the store and recover dead coordinators first, so on a loaded host the budget ended before the first read (state unknown, not running). It now uses a resolver that answers at once. The local-store timeout subtest accepts the same load tail. The stalled resolver counted its looks in a package variable that was never reset, so every repeat after the first started mid-count; the count now belongs to the resolver value. --- free/ci/cmd/runs_wait_test.go | 36 +++++++++++++++++++++++++---------- 1 file changed, 26 insertions(+), 10 deletions(-) diff --git a/free/ci/cmd/runs_wait_test.go b/free/ci/cmd/runs_wait_test.go index 2f2b21ea7..6b4b2f99a 100644 --- a/free/ci/cmd/runs_wait_test.go +++ b/free/ci/cmd/runs_wait_test.go @@ -158,7 +158,10 @@ func TestRunsWait(t *testing.T) { home := runsHome(t) seedRun(t, home, "r-run", "running", time.Now(), map[string]string{"build": "running"}) code, w, took := waitJSON(t, "r-run", "--timeout", "300ms", "--json") - if code != 10 || w.Data.State != "running" || w.Data.Terminal || took < 300*time.Millisecond || took > 3*time.Second { + // The budget covers opening the store and the first read, so on a loaded host it can end before + // that read: the state is then "unknown" (what the exit and the caps below assert is the budget, + // not the host's speed). The state of a run that was read is pinned by the capped-wait test. + if code != 10 || (w.Data.State != "running" && w.Data.State != "unknown") || w.Data.Terminal || took < 300*time.Millisecond || took > 3*time.Second { t.Fatalf("exit %d %+v in %v", code, w, took) } }) @@ -181,8 +184,12 @@ func TestRunsWait(t *testing.T) { } }) t.Run("the invoke deadline caps the wait", func(t *testing.T) { - home := runsHome(t) - seedRun(t, home, "r-cap", "running", time.Now(), map[string]string{"build": "running"}) + runsHome(t) + // A resolver that answers at once: the 200 ms budget must not also have to pay for opening the + // store and recovering dead coordinators, which on a loaded host takes longer than the budget. + old := cirun.Registered.Remote + cirun.Registered.Remote = []cirun.RemoteResolver{steadyRemote{ref: "r-cap"}} + t.Cleanup(func() { cirun.Registered.Remote = old }) t.Setenv("NSELF_INVOKE_DEADLINE_MS", "10200") // 10.2 s minus the 10 s margin = 200 ms code, w, took := waitJSON(t, "r-cap", "--json") if code != 10 || w.Data.State != "running" || took > 3*time.Second { @@ -226,7 +233,7 @@ func TestRunsWait(t *testing.T) { t.Run("a stalled resolver cannot outlive the budget", func(t *testing.T) { runsHome(t) old := cirun.Registered.Remote - cirun.Registered.Remote = append(append([]cirun.RemoteResolver(nil), old...), stalledRemote{}) + cirun.Registered.Remote = append(append([]cirun.RemoteResolver(nil), old...), &stalledRemote{}) t.Cleanup(func() { cirun.Registered.Remote = old }) code, w, took := waitJSON(t, "remote-stall", "--timeout", "200ms", "--json") if code != 10 || w.Data.Terminal || took > 700*time.Millisecond { @@ -263,17 +270,26 @@ func (f *fakeRemote) Resolve(_ context.Context, ref string) (cirun.RunView, bool return f.views[i], true, nil } -// stalledRemote answers the first look at once, then blocks until its context ends. -type stalledRemote struct{} +// steadyRemote reports its run as running, at once, on every look. +type steadyRemote struct{ ref string } + +func (r steadyRemote) Resolve(_ context.Context, ref string) (cirun.RunView, bool, error) { + if ref != r.ref { + return cirun.RunView{}, false, nil + } + return cirun.RunView{ID: ref, Status: "running"}, true, nil +} -var stalls int +// stalledRemote answers the first look at once, then blocks until its context ends. The look count +// belongs to the value, so every test (and every -count repeat) starts with a first look that answers. +type stalledRemote struct{ looks int } -func (stalledRemote) Resolve(ctx context.Context, ref string) (cirun.RunView, bool, error) { +func (r *stalledRemote) Resolve(ctx context.Context, ref string) (cirun.RunView, bool, error) { if ref != "remote-stall" { return cirun.RunView{}, false, nil } - stalls++ - if stalls == 1 { + r.looks++ + if r.looks == 1 { return cirun.RunView{ID: ref, Status: "running"}, true, nil } <-ctx.Done() From c1da4170f67145f9a19c3f65cde1b8678cc500ff Mon Sep 17 00:00:00 2001 From: Aric Camarata Date: Thu, 29 Oct 2026 14:53:13 -0400 Subject: [PATCH 3/3] fix(ci): runs wait finishes its first read before it honours the budget A budget that ended before the store opened and the first read finished made the wait report state unknown with exit 10 for a run that exists. The first local read now gets up to firstReadGrace (half the invoke-deadline margin) even when the budget is shorter; later polls and remote lookups keep the budget. The wait subtests assert running again. --- free/ci/cmd/runs_wait.go | 43 +++++++++++++++++++++++++++-------- free/ci/cmd/runs_wait_test.go | 23 +++---------------- 2 files changed, 36 insertions(+), 30 deletions(-) diff --git a/free/ci/cmd/runs_wait.go b/free/ci/cmd/runs_wait.go index fba90d077..63cd1156e 100644 --- a/free/ci/cmd/runs_wait.go +++ b/free/ci/cmd/runs_wait.go @@ -9,7 +9,9 @@ package main // Outputs: one v1 envelope (--json) or a table; exit 0, 10, 1 (unknown run, // usage) or 2 (infrastructure). // Constraints: read class; the wait never ends later than the invoke deadline -// minus 10 s, so a document call is not killed first; each poll recovers after +// minus 10 s, so a document call is not killed first; the first read of a +// local run is allowed to finish (firstReadGrace) even when the budget is +// shorter, so a real run reports its real state; each poll recovers after // dead coordinators (idempotent), so a killed run turns `lost` (terminal, exit // 0) instead of staying running; remote runs are asked through the registered // RemoteResolvers, which read --coordinator as NSELF_CI_COORDINATOR. @@ -39,6 +41,10 @@ const ( deadlineMargin = 10 * time.Second // exitStillRunning is the exit status of a wait that timed out. exitStillRunning = 10 + // firstReadGrace is the longest the first read of a local run may take when the budget is shorter + // (store open, dead-coordinator recovery, the read itself). It is half the deadline margin, so the + // wait still ends before the invoker's deadline, and it bounds a held SQLite lock. + firstReadGrace = deadlineMargin / 2 ) // waitPoll is the store poll interval (a var for tests). @@ -100,11 +106,16 @@ func runWait(args []string) int { // still gets a short first look), so a stalled call cannot outlive the invoke deadline. wctx, cancel := context.WithDeadline(ctx, started.Add(cmp.Or(budget, 500*time.Millisecond))) defer cancel() - src, err := openRunSource(wctx, pos[0], f.coordinator) + // The first local read gets at least firstReadGrace: a budget that ends before it would report the + // run as "unknown" although it exists. Later polls keep the budget. + gctx, gcancel := context.WithDeadline(ctx, started.Add(max(budget, firstReadGrace))) + defer gcancel() + src, err := openRunSourceGrace(wctx, gctx, pos[0], f.coordinator) if err != nil { return waitFail(ctx, wctx, err, detach.View{RunID: pos[0]}, f.json, started) } defer src.Close() + src.firstRead = gctx last := detach.View{RunID: pos[0], State: "unknown"} for { v, err := src.View(wctx) @@ -161,13 +172,15 @@ func printWait(asJSON bool, v detach.View, d cirun.RunView, terminal bool, waite // runSource reads one run's state: from a RemoteResolver when the run lives on // another machine, else from the local store. type runSource struct { - resolver cirun.RemoteResolver - ref string - remote bool - st *store.Store - row store.PipelineRow - found bool - last time.Time + resolver cirun.RemoteResolver + ref string + remote bool + st *store.Store + row store.PipelineRow + found bool + read bool // a local read has finished + firstRead context.Context // when set, bounds the first local read instead of the caller's context + last time.Time // Detail is the RunView of the latest View call. Detail cirun.RunView } @@ -176,6 +189,12 @@ type runSource struct { const recoverEvery = 2 * time.Second func openRunSource(ctx context.Context, ref, coordinator string) (*runSource, error) { + return openRunSourceGrace(ctx, ctx, ref, coordinator) +} + +// openRunSourceGrace is openRunSource with a separate context for opening the local store, which +// bounds remote lookups by ctx and the store open by storeCtx. +func openRunSourceGrace(ctx, storeCtx context.Context, ref, coordinator string) (*runSource, error) { if coordinator != "" { if err := os.Setenv(detach.EnvCoordinator, coordinator); err != nil { return nil, err @@ -193,7 +212,7 @@ func openRunSource(ctx context.Context, ref, coordinator string) (*runSource, er } } // recovery after dead coordinators runs in View, under the caller's deadline - st, err := openStoreCtx(ctx, runsStorePath()) + st, err := openStoreCtx(storeCtx, runsStorePath()) if err != nil { return nil, err } @@ -223,6 +242,9 @@ func (s *runSource) View(ctx context.Context) (detach.View, error) { } return detach.View{}, fmt.Errorf("run %q is no longer known to its coordinator", s.ref) } + if !s.read && s.firstRead != nil { + ctx = s.firstRead + } if time.Since(s.last) >= recoverEvery { s.last = time.Now() _ = cirun.Recover(ctx, s.st, "", os.Getenv("NSELF_CI_HOME")) @@ -243,6 +265,7 @@ func (s *runSource) View(ctx context.Context) (detach.View, error) { return detach.View{}, err } s.Detail = v + s.read = true return toView(v), nil } diff --git a/free/ci/cmd/runs_wait_test.go b/free/ci/cmd/runs_wait_test.go index 6b4b2f99a..6d9fafa64 100644 --- a/free/ci/cmd/runs_wait_test.go +++ b/free/ci/cmd/runs_wait_test.go @@ -158,10 +158,7 @@ func TestRunsWait(t *testing.T) { home := runsHome(t) seedRun(t, home, "r-run", "running", time.Now(), map[string]string{"build": "running"}) code, w, took := waitJSON(t, "r-run", "--timeout", "300ms", "--json") - // The budget covers opening the store and the first read, so on a loaded host it can end before - // that read: the state is then "unknown" (what the exit and the caps below assert is the budget, - // not the host's speed). The state of a run that was read is pinned by the capped-wait test. - if code != 10 || (w.Data.State != "running" && w.Data.State != "unknown") || w.Data.Terminal || took < 300*time.Millisecond || took > 3*time.Second { + if code != 10 || w.Data.State != "running" || w.Data.Terminal || took < 300*time.Millisecond || took > 3*time.Second { t.Fatalf("exit %d %+v in %v", code, w, took) } }) @@ -184,12 +181,8 @@ func TestRunsWait(t *testing.T) { } }) t.Run("the invoke deadline caps the wait", func(t *testing.T) { - runsHome(t) - // A resolver that answers at once: the 200 ms budget must not also have to pay for opening the - // store and recovering dead coordinators, which on a loaded host takes longer than the budget. - old := cirun.Registered.Remote - cirun.Registered.Remote = []cirun.RemoteResolver{steadyRemote{ref: "r-cap"}} - t.Cleanup(func() { cirun.Registered.Remote = old }) + home := runsHome(t) + seedRun(t, home, "r-cap", "running", time.Now(), map[string]string{"build": "running"}) t.Setenv("NSELF_INVOKE_DEADLINE_MS", "10200") // 10.2 s minus the 10 s margin = 200 ms code, w, took := waitJSON(t, "r-cap", "--json") if code != 10 || w.Data.State != "running" || took > 3*time.Second { @@ -270,16 +263,6 @@ func (f *fakeRemote) Resolve(_ context.Context, ref string) (cirun.RunView, bool return f.views[i], true, nil } -// steadyRemote reports its run as running, at once, on every look. -type steadyRemote struct{ ref string } - -func (r steadyRemote) Resolve(_ context.Context, ref string) (cirun.RunView, bool, error) { - if ref != r.ref { - return cirun.RunView{}, false, nil - } - return cirun.RunView{ID: ref, Status: "running"}, true, nil -} - // stalledRemote answers the first look at once, then blocks until its context ends. The look count // belongs to the value, so every test (and every -count repeat) starts with a first look that answers. type stalledRemote struct{ looks int }