Skip to content

-race is red on clean dev: a fixture writes Steward.now while the wall clock reads it under the lock (TestADoneEndingNamesTheCheckItCouldNotRun) #957

Closed

Description

@santoshkumarradha

What happened

internal/session has a data race on clean dev that the ordinary gate cannot see,
because neither make check nor the pull-request job runs -race. Lane FLAKE met it
while proving PR #952 — its 211-test -race run reported two races, and it confirmed both
in a throwaway worktree of untouched origin/dev, same write site. Base at the time of
filing: dev@c742b8bc8.

The two sites are named below and both were verified on dev; the report the lane saw
pairs them (addresses and goroutine numbers elided — this is the shape, not a verbatim
capture):

go test -race -count=1 -run '^TestADoneEndingNamesTheCheckItCouldNotRun$' ./internal/session/

WARNING: DATA RACE
Write by the test goroutine:
  session.TestADoneEndingNamesTheCheckItCouldNotRun.func1
      internal/session/checkpoint_test.go:759          <- steward.now = func() time.Time { ... }
Previous read by the wall-clock goroutine:
  session.(*Steward).Budget
      internal/session/principal.go:1008               <- ... , now := ... , s.now   (under s.mu)
  session.(*Agent).watchTheWall
      internal/session/wallclock.go:68                 <- steward.Budget().Left()

The fixture reaches into an unexported field of a live *Steward and assigns it with no
lock, while a goroutine the product started reads the same field under s.mu. A lock on
only one side is no happens-before, so the detector is right.

Why this fixture and not the dozen others that poke the same field: stewardCheckpointAgent
builds an unattended session with Budget{Wall: time.Hour}, and New therefore calls
armWallClock, which starts watchTheWall; that goroutine's first act is
steward.Budget().Left(). nearWall then writes steward.now from the test goroutine a
moment later. Both subtests (stopped turn, and the handover twin) call it.

Replication

Deterministic (no model, no key, no box of ours).

git checkout dev && go test -race -count=1 -run '^TestADoneEndingNamesTheCheckItCouldNotRun$' ./internal/session/

What a developer sees today: WARNING: DATA RACE, the write inside nearWall and the read
in (*Steward).Budget beneath (*Agent).watchTheWall, and a non-zero exit. The test's own
assertions pass; it is the detector that fails the package. It is a window between a
goroutine's first line and the fixture's, so run it a few times (-count=5) if the first
run is quiet.

Field (real models). None, and deliberately: no product code writes this field after
construction, so there is nothing a person can run into. See below.

Where

All in internal/session, by searchable string (line numbers are at dev@c742b8bc8):

  • The unsynchronised write: nearWall, the closure inside
    TestADoneEndingNamesTheCheckItCouldNotRun in checkpoint_test.go — search
    steward.now = func() time.Time (line 759). It also reads steward.started and
    steward.wall in the same closure.
  • The synchronised read: (*Steward).Budget in principal.go — search
    wall, money, started, spent, now := s.wall, s.money, s.started, s.spent, s.now
    (line 1008), taken under s.mu.
  • The reading goroutine: (*Agent).watchTheWall in wallclock.go — search
    left, _ := steward.Budget().Left() (line 68), started by armWallClock
    (wallclock.go, search go a.watchTheWall) from New in agent.go (search
    THE WALL IS READ AFTER THE SESSION IS OPEN, line 414).
  • Why this fixture arms it: stewardCheckpointAgent in unattendeddoor_test.go —
    search config.Budget = Budget{Wall: time.Hour}.

Test-only, not a product race

Test-only. Steward.now is written by product code exactly once, where the Steward is
built (principal.go, now: time.Now), and never assigned again anywhere in the tree.
Every product read of it is under s.mu — (*Steward).Budget, (*Steward).since, and
wallIsUp in wallclock.go all take the lock before they copy the func value. So the
unsynchronised half belongs entirely to the fixtures, which reach past the lock into the
field: checkpoint_test.go, checkmemo_test.go (×4), principal_test.go,
turnwall_test.go (which writes steward.started the same way), wallclock_test.go (×3),
and the sibling shapes fixStore.now and graph.governor.now. Nothing a person meets is
wrong, so sev:papercut — but it is a standing red under -race on clean dev, which
means the next real race in this package arrives as the third line of a report somebody
has already learned to ignore.

The fix

The fixture sets time through the clock door the product uses. Give Steward one
setter that takes s.mu — setClock(func() time.Time), and setStarted(time.Time) beside
it for turnwall_test.go — and change every fixture that assigns steward.now /
steward.started to call it. The field then has exactly one lock guarding every access on
both sides, which is the same shape PR #952 used one package over when it gave the lane
stub lanestub.Server.SetClock instead of letting the rig poke the field. The alternative —
teaching watchTheWall to read the field some other way — is the wrong end: the product's
read is already correct.

Acceptance

  • e2e: none, and the reason is the finding above: this race has no road a person can
    open, so the honest acceptance is the detector, not a door. Stated here rather than
    omitted so nobody goes looking for one.
  • Race: go test -race -count=5 -run '^TestADoneEndingNamesTheCheckItCouldNotRun$' ./internal/session/ exits 0 with no WARNING: DATA RACE in the output, and both
    subtests still assert their ending line (checkpointDoneNote + " · unchecked: " + …) and
    their "unread":["tox -e py"] journal row.
  • Race (the family, so the fix is not one line deep): the same run over every test that
    moves the steward's clock — -run '^(TestADoneEndingNamesTheCheckItCouldNotRun|TestAMemoOfAnUnreadCheck.*|…)$',
    i.e. the tests in checkmemo_test.go, principal_test.go, turnwall_test.go and
    wallclock_test.go that assign now or started — exits 0 with no race report.
  • Unit (structural, on the laws gate): a go/ast test asserting that no test file in
    internal/session assigns .now or .started on a *Steward directly; every fixture
    goes through the one door. Without it the next fixture reopens this the day it is written.
  • The change entry's invalidates names the belief that -race is clean on dev, and
    docs/rules/ci.md says which gate does and does not run the detector.

Found by lane FLAKE while proving PR #952 (§5, "Found, not fixed"); not caused by it.


Drafted with CodeAF · reviewed and owned by the author

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

    area:sessionThe engine — turns, tasks, the toolbelt, checkpointsbugSomething the code does that it should notsev:papercutA wording, a hint, a small wrongness that costs a moment

    Type

    No type

    Projects

    No projects

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions