diff --git a/docs/changes/unreleased/986-steward-clock-locked-door.md b/docs/changes/unreleased/986-steward-clock-locked-door.md new file mode 100644 index 0000000000..0a660be146 --- /dev/null +++ b/docs/changes/unreleased/986-steward-clock-locked-door.md @@ -0,0 +1,20 @@ +--- +kind: fixed +title: the goal owner's clock moves through a locked door, and -race is green on dev again +pr: 986 +surface: [engine] +invalidates: + - "`go test -race` was believed clean on `dev`. It was not: `internal/session` reported two data races on `TestADoneEndingNamesTheCheckItCouldNotRun` on untouched `dev`, and no gate in this repository runs the detector, so nothing said so. Both are gone. `Steward.now` and `Steward.started` now move only through `setClock` and `setStarted`, which take the same `s.mu` the product's reads take, and `internal/session/stewardclock_law_test.go` fails any caller — fixture or product — that assigns either field directly." + - "The setters were introduced as a fixtures-only door, and a comment said the product writes neither field after the goal owner is built. That was never true: `makePrincipal` in `principal_wire.go` handed over the session's own start by assigning the field. It uses the door as well now, so the door is the only way in." +--- +The race had no road a person could open — nothing reads the goal owner's clock +before `makePrincipal` returns, and every product read afterwards is under one +lock — so it was the fixtures that reached past it, on live sessions whose wall +clock was already reading those fields. What that cost was a standing red under +the detector, which teaches the next real race report to be ignored. Nothing a +person sees changes, and there is no e2e; the detector is the acceptance, and it +is green at `-count=5` over the headline test and the whole clock-moving family +in `checkpoint_test.go`, `checkmemo_test.go`, `principal_test.go`, +`turnwall_test.go` and `wallclock_test.go`. `docs/rules/ci.md` now says plainly +which gates do not run the detector — all of them — so a green gate is never +again read as a clean `-race`. diff --git a/docs/rules/ci.md b/docs/rules/ci.md index f2ff3fa3be..5471045f03 100644 --- a/docs/rules/ci.md +++ b/docs/rules/ci.md @@ -131,6 +131,37 @@ builds the shipped binary and enforces its size budget. first agreeing which architecture the budget is measured on. `make check` on your own machine still enforces it, and `PERF.md` still governs changing it. +## The race detector, which no gate runs + +No gate in this repository runs `go test -race`. Not the light gate, not +`touched packages` (so not `check`), not `full tests` on the nightly or on the +way into `staging`, not the release surface tests. The greps say so plainly: +`grep -rn race .github/workflows/ Makefile scripts/laws.sh` finds the word only +inside "traces", in a comment about panic output — there is no `-race` flag in +CI to find, and no gate to name. + +**So a green gate proves nothing about data races, and this page is where that +is said rather than assumed.** The detector makes a test run two to twenty +times slower and five to ten times fatter, by Go's own estimate, and `full +tests` is already split three ways to stay inside the free-plan runner's seven +gigabytes. It is also not the light gate's kind of question: a race is a window +between two goroutines, so its answer is not the same on every machine — #957 +needed `-count=5` to be sure its quiet first run was quiet. What that trade +cost is on the record there: the detector went red on clean `dev`, on a fixture +that moved the goal owner's clock past its lock while the wall clock read it +under the lock, through a merge whose every check was green. That race was +test-only, and no gate output anywhere said so or said otherwise. + +So the detector is run by hand, over the package and the tests a report names: + +```sh +go test -race -count=5 -run '^TestADoneEndingNamesTheCheckItCouldNotRun$' ./internal/session/ +``` + +It answers for that package at that moment and nothing else. The known-red +ledger below does not cover this either: it holds tests that fail, not checks +that never run. + ## The known-red ledger `.github/known-red.txt` lists tests that fail on a clean tree. `make test` skips diff --git a/internal/session/checkmemo_test.go b/internal/session/checkmemo_test.go index 19b9961f71..403e7dd96c 100644 --- a/internal/session/checkmemo_test.go +++ b/internal/session/checkmemo_test.go @@ -85,7 +85,7 @@ func TestATreeThatMovedMakesTheCheckRunAgain(t *testing.T) { func TestASessionCheckWindowIsBoundedByWhatIsLeftOfTheWall(t *testing.T) { agent, tree := checkMemoryAgent(t, Budget{Wall: 10 * time.Minute}) steward := agent.steward() - steward.now = func() time.Time { return steward.started.Add(7 * time.Minute) } + steward.setClock(func() time.Time { return steward.started.Add(7 * time.Minute) }) window, fits := agent.checkWindow(tree, "go test ./...") if !fits || window != 3*time.Minute { @@ -99,11 +99,11 @@ func TestTheAuditWindowIsBoundedByWhatIsLeftOfTheWall(t *testing.T) { agent, _ := checkMemoryAgent(t, Budget{Wall: 10 * time.Minute}) steward := agent.steward() door := auditDoor{checks: []string{"go test ./..."}} - steward.now = func() time.Time { return steward.started.Add(7 * time.Minute) } + steward.setClock(func() time.Time { return steward.started.Add(7 * time.Minute) }) if window := agent.auditWindowFor(door); window != 3*time.Minute { t.Fatalf("the audit got %s, want the three minutes left", window) } - steward.now = func() time.Time { return steward.started.Add(10 * time.Minute) } + steward.setClock(func() time.Time { return steward.started.Add(10 * time.Minute) }) if window := agent.auditWindowFor(door); window != auditReadingDeadline { t.Fatalf("the spent wall gave the audit %s, want the reading floor %s", window, auditReadingDeadline) } @@ -123,9 +123,9 @@ func TestACheckThatCannotFitTheWallIsNotStarted(t *testing.T) { agent, tree := checkMemoryAgent(t, Budget{Wall: 10 * time.Minute}) command, counter := countedCheck(t) steward := agent.steward() - steward.now = func() time.Time { + steward.setClock(func() time.Time { return steward.started.Add(10*time.Minute - verify.ShortestUsefulReading/2) - } + }) run, moved := agent.checkNow(context.Background(), tree, command) if moved || run.Ran || run.Unread != notEnoughTimeToRun+command { @@ -142,7 +142,7 @@ func TestACheckThatCannotFitTheWallIsNotStarted(t *testing.T) { state := treeStateNow(tree) agent.sessionCheckMemories().remember(tree, command, state, CheckRun{Command: command, Ran: true}, 2*time.Minute, true) steward := agent.steward() - steward.now = func() time.Time { return steward.started.Add(8*time.Minute + 30*time.Second) } + steward.setClock(func() time.Time { return steward.started.Add(8*time.Minute + 30*time.Second) }) run, _ := agent.checkNow(context.Background(), tree, command) if run.Ran || run.Unread == "" { diff --git a/internal/session/checkpoint_test.go b/internal/session/checkpoint_test.go index 5585bd34b9..0766943d26 100644 --- a/internal/session/checkpoint_test.go +++ b/internal/session/checkpoint_test.go @@ -756,9 +756,9 @@ func TestADoneEndingNamesTheCheckItCouldNotRun(t *testing.T) { steward := agent.steward() steward.hear(ask) steward.setAcceptanceContract(steward.Ask(), "the parser is ported and the declared check passes", []string{check}) - steward.now = func() time.Time { + steward.setClock(func() time.Time { return steward.started.Add(steward.wall - verify.ShortestUsefulReading/2) - } + }) } t.Run("stopped turn", func(t *testing.T) { diff --git a/internal/session/principal.go b/internal/session/principal.go index 7a55916206..fa5507808b 100644 --- a/internal/session/principal.go +++ b/internal/session/principal.go @@ -1081,6 +1081,34 @@ func (s *Steward) since(moment time.Time) time.Duration { return now().Sub(moment) } +// setClock and setStarted are the ONE DOOR to the two fields of the Steward's +// clock that ever move, and both take s.mu. EVERY WRITE TO NOW OR STARTED AFTER +// CONSTRUCTION GOES THROUGH THEM: the product reads both fields under this same +// lock ([Steward.Budget], [Steward.since], wallIsUp in wallclock.go), so a write +// that skips it is a data race the detector catches the moment the clock is +// moved on a live session whose wall clock is already reading it (#957 — go +// test -race red on clean dev through nearWall in checkpoint_test.go). +// +// Almost every caller is a fixture winding the clock forward; the one that is +// not is makePrincipal in principal_wire.go, handing over the session's own +// start. It uses the door too, and stewardclock_law_test.go is what keeps every +// caller on it. + +// setClock replaces the clock the wall and the turn's share are measured with. +func (s *Steward) setClock(now func() time.Time) { + s.mu.Lock() + defer s.mu.Unlock() + s.now = now +} + +// setStarted moves when the run began, which winds the wall's remainder without +// moving a turn's own stretch, because both are read off the one clock. +func (s *Steward) setStarted(at time.Time) { + s.mu.Lock() + defer s.mu.Unlock() + s.started = at +} + // Report turns one landing into the next attempt's brief, and it is the road a // failed unit of work now has instead of a sentence addressed to nobody. // diff --git a/internal/session/principal_test.go b/internal/session/principal_test.go index 55178e68ec..2710825ec2 100644 --- a/internal/session/principal_test.go +++ b/internal/session/principal_test.go @@ -923,7 +923,7 @@ func TestABudgetNobodySetIsNeverExhausted(t *testing.T) { // longer than its ceiling stops even if it never spent a penny. func TestTheWallClockStopsARunThatSpentNothing(t *testing.T) { steward := NewSteward("port the parser", Budget{Wall: time.Hour}, nil) - steward.now = func() time.Time { return steward.started.Add(90 * time.Minute) } + steward.setClock(func() time.Time { return steward.started.Add(90 * time.Minute) }) decision := steward.Decide(Remains{Reader: "there is plenty left", Landed: true}) if decision.Verb != DecideStop { t.Fatalf("a run past its hours did not stop: %+v", decision) diff --git a/internal/session/principal_wire.go b/internal/session/principal_wire.go index 8b6e75789b..88eaa3c615 100644 --- a/internal/session/principal_wire.go +++ b/internal/session/principal_wire.go @@ -81,8 +81,10 @@ func newPrincipalFor(a *Agent) Principal { // started for itself a microsecond later. There is one wall clock in this // package ([Agent.startedAt]) and this is where it is handed over; a // [Steward] built by a test starts its own, which is what a type nobody - // wired should do. - steward.started = a.startedAt + // wired should do. It goes through [Steward.setStarted] like every other + // move of that clock: nothing is reading this one yet, and a second door + // that happens to be safe today is how the first one stops being the door. + steward.setStarted(a.startedAt) return steward } diff --git a/internal/session/stewardclock_law_test.go b/internal/session/stewardclock_law_test.go new file mode 100644 index 0000000000..61b942af47 --- /dev/null +++ b/internal/session/stewardclock_law_test.go @@ -0,0 +1,205 @@ +package session + +import ( + "fmt" + "go/ast" + "go/parser" + "go/token" + "path/filepath" + "sort" + "strings" + "testing" +) + +// ── THE STEWARD'S CLOCK MOVES THROUGH ITS LOCK, NEVER PAST IT ─────────────── +// +// [Steward.now] and [Steward.started] are read by the product under `s.mu` — +// [Steward.Budget], [Steward.since], and wallIsUp in wallclock.go all take the +// lock before they copy either field. #957 is what happens when something +// writes one of them without it on a live session: the wall-clock goroutine +// (armWallClock → watchTheWall → Budget) is reading the same field under the +// lock, one side of a pair is no happens-before, and `go test -race` went red +// on clean `dev`. +// +// [Steward.setClock] and [Steward.setStarted] take the same lock on the write +// side, so the field has exactly one door and both sides of every access go +// through it. This law is what keeps that true after the fixtures that opened +// the race are fixed, because the next fixture that assigns the field reopens +// it the day it is written — on whichever session already has a wall clock +// running. +// +// IT IS ON THE PULL-REQUEST GATE through scripts/laws.sh, which finds laws by +// their go/ast import. + +// stewardClockFields are the two fields of the Steward that ever move after it +// is built. Nothing else on the type is written twice. +var stewardClockFields = map[string]bool{"now": true, "started": true} + +// stewardClockDoor is the one file that may assign them: it declares the type, +// builds it, and holds the two setters that take the lock. Everywhere else — +// product and fixture alike — goes through the door. +const stewardClockDoor = "principal.go" + +// TestTheStewardsClockIsOnlyMovedThroughItsLockedDoor reads this package for +// anything that assigns the Steward's clock fields directly. +// +// IT FINDS ITS SUBJECTS BY TYPE AND NOT BY NAME. A gate that looked for a +// variable spelled `steward` would pass the first fixture that called its own +// `owner`, which is the same hand-kept list the race came out of. Instead the +// walk reads the package's own declarations for every function that hands back +// a `*Steward` — [NewSteward] and the three helpers that wrap it today — and +// tracks the variables they are assigned to, plus the receiver of any method on +// the type. Add a fourth producer and it is tracked the day it is written. +// +// WHAT IT CANNOT SEE is a Steward that reaches an assignment without passing +// through a call this package declares: out of a struct field, a slice, or an +// interface asserted somewhere else. Those are not shapes this package's +// fixtures use, and the failure below says which door to use rather than +// merely refusing. +func TestTheStewardsClockIsOnlyMovedThroughItsLockedDoor(t *testing.T) { + paths, err := filepath.Glob("*.go") + if err != nil { + t.Fatal(err) + } + fset := token.NewFileSet() + parsed := map[string]*ast.File{} + for _, path := range paths { + file, err := parser.ParseFile(fset, path, nil, 0) + if err != nil { + t.Fatalf("parse %s: %v", path, err) + } + parsed[path] = file + } + producers := stewardProducers(parsed) + if len(producers) == 0 { + t.Fatal("nothing in this package hands back a *Steward — this law has nothing to hold") + } + + var reached []string + for path, file := range parsed { + if filepath.Base(path) == stewardClockDoor { + continue + } + holders := stewardHolders(file, producers) + ast.Inspect(file, func(node ast.Node) bool { + assign, ok := node.(*ast.AssignStmt) + if !ok { + return true + } + for _, lhs := range assign.Lhs { + field, ok := lhs.(*ast.SelectorExpr) + if !ok || !stewardClockFields[field.Sel.Name] { + continue + } + held, ok := field.X.(*ast.Ident) + if !ok || !holders[held.Name] { + continue + } + reached = append(reached, fmt.Sprintf("%s: %s.%s is assigned directly", + fset.Position(field.Pos()), held.Name, field.Sel.Name)) + } + return true + }) + } + if len(reached) > 0 { + sort.Strings(reached) + t.Fatalf("the Steward's clock is read under s.mu and must be written under it too — "+ + "call setClock or setStarted instead of reaching past the lock (#957):\n%s", + strings.Join(reached, "\n")) + } +} + +// stewardProducers is every function and method in this package whose one +// result is a `*Steward`, by the name a caller writes at the call site. +func stewardProducers(files map[string]*ast.File) map[string]bool { + producers := map[string]bool{} + for _, file := range files { + for _, decl := range file.Decls { + fn, ok := decl.(*ast.FuncDecl) + if !ok || fn.Type.Results == nil || len(fn.Type.Results.List) != 1 { + continue + } + if pointsAtSteward(fn.Type.Results.List[0].Type) { + producers[fn.Name.Name] = true + } + } + } + return producers +} + +// stewardHolders is every variable in one file that holds a `*Steward`: one +// assigned from a producer, and the receiver of a method on the type. +func stewardHolders(file *ast.File, producers map[string]bool) map[string]bool { + holders := map[string]bool{} + for _, decl := range file.Decls { + fn, ok := decl.(*ast.FuncDecl) + if !ok || fn.Recv == nil { + continue + } + for _, receiver := range fn.Recv.List { + if !pointsAtSteward(receiver.Type) { + continue + } + for _, name := range receiver.Names { + holders[name.Name] = true + } + } + } + ast.Inspect(file, func(node ast.Node) bool { + var names []ast.Expr + var values []ast.Expr + switch bound := node.(type) { + case *ast.AssignStmt: + names, values = bound.Lhs, bound.Rhs + case *ast.ValueSpec: + for _, name := range bound.Names { + names = append(names, name) + } + values = bound.Values + default: + return true + } + // ONE NAME AND ONE CALL, which is how every fixture takes a steward. + // A multiple assignment spreads one call's results over several names + // and none of them is the whole `*Steward`. + if len(names) != 1 || len(values) != 1 { + return true + } + call, ok := values[0].(*ast.CallExpr) + if !ok { + return true + } + if !producers[calleeName(call.Fun)] { + return true + } + if name, ok := names[0].(*ast.Ident); ok { + holders[name.Name] = true + } + return true + }) + return holders +} + +// pointsAtSteward reports whether a type expression is `*Steward`. +func pointsAtSteward(typ ast.Expr) bool { + pointer, ok := typ.(*ast.StarExpr) + if !ok { + return false + } + named, ok := pointer.X.(*ast.Ident) + return ok && named.Name == "Steward" +} + +// calleeName is the name a call is written with, either way it can be written: +// bare inside the package that declares it, and through a receiver otherwise. +func calleeName(fun ast.Expr) string { + switch named := fun.(type) { + case *ast.Ident: + return named.Name + case *ast.SelectorExpr: + if named.Sel != nil { + return named.Sel.Name + } + } + return "" +} diff --git a/internal/session/turnwall_test.go b/internal/session/turnwall_test.go index 32ec7e7fc7..0a617da086 100644 --- a/internal/session/turnwall_test.go +++ b/internal/session/turnwall_test.go @@ -318,9 +318,7 @@ func moveTheStewardsClock(t *testing.T, agent *Agent, past time.Duration) { t.Helper() on := shareOfTheWall(t, agent) + past steward := agent.steward() - steward.mu.Lock() - defer steward.mu.Unlock() - steward.now = func() time.Time { return time.Now().Add(on) } + steward.setClock(func() time.Time { return time.Now().Add(on) }) } // leaveOfTheWall winds the RUN's clock forward so that `left` of the wall is in @@ -332,8 +330,9 @@ func leaveOfTheWall(t *testing.T, agent *Agent, left time.Duration) { t.Helper() steward := agentWithGoalOwner(t, agent) steward.mu.Lock() - defer steward.mu.Unlock() - steward.started = steward.now().Add(left - steward.wall) + fresh := steward.now().Add(left - steward.wall) + steward.mu.Unlock() + steward.setStarted(fresh) } // holdTheStewardsClock STOPS the session's goal owner at one instant and hands @@ -344,9 +343,7 @@ func holdTheStewardsClock(t *testing.T, agent *Agent) time.Time { t.Helper() steward := agentWithGoalOwner(t, agent) at := time.Now() - steward.mu.Lock() - defer steward.mu.Unlock() - steward.now = func() time.Time { return at } + steward.setClock(func() time.Time { return at }) return at } diff --git a/internal/session/wallclock_test.go b/internal/session/wallclock_test.go index 7320aff789..06addb5ae9 100644 --- a/internal/session/wallclock_test.go +++ b/internal/session/wallclock_test.go @@ -77,8 +77,8 @@ func spendWall(t *testing.T, agent *Agent) string { } steward.mu.Lock() started, wall := steward.started, steward.wall - steward.now = func() time.Time { return started.Add(wall) } steward.mu.Unlock() + steward.setClock(func() time.Time { return started.Add(wall) }) spent, why := steward.Budget().Exhausted() if !spent { t.Fatal("the moved wall clock did not exhaust the budget") @@ -325,14 +325,12 @@ func TestATaskUnderAWallInheritsWhatIsLeftOfIt(t *testing.T) { steward := agent.steward() steward.mu.Lock() started := steward.started - steward.now = func() time.Time { return started.Add(90 * time.Minute) } steward.mu.Unlock() + steward.setClock(func() time.Time { return started.Add(90 * time.Minute) }) if got := agent.taskLimits(node).deadline; got != 30*time.Minute { t.Fatalf("the task got %s, want the 30 minutes left of the wall", got) } - steward.mu.Lock() - steward.now = func() time.Time { return started.Add(2*time.Hour - taskAllowance/2) } - steward.mu.Unlock() + steward.setClock(func() time.Time { return started.Add(2*time.Hour - taskAllowance/2) }) if got := agent.taskLimits(node).deadline; got != taskAllowance { t.Fatalf("the task got %s inside the wall margin, want the %s allowance", got, taskAllowance) }