Skip to content

tests: internal/session has load-dependent reds on dev — a different test each full run #959

Open

Description

@santoshkumarradha

What is true

A full go test ./internal/session/ -count=1 on dev alone fails, and fails a different test each run. Every one of them passes in isolation.

Three runs on the Spark this evening, all at d726ff259 or a branch off it:

run what was red
branch, session beside tui3 TestTheRunningModelIsNeverSentTheCheckpoint, TestASplitIsNeverDroppedByTheRunningModelsDeclaration, TestACoordinationSketchStartsNothingAndRealPartsStillConvert, TestOnlyASpentBudgetSealsOverWorkThatIsMoving
branch, session alone TestTheCeilingsQuickNodeHasTheToolsShape, TestAnsweringLetAforgeDecideTwiceStandsRatherThanRefusing, TestATurnThatCannotBeCheckedBeforeTheWallIsNotMoved
dev, session alone TestASplitIsNeverDroppedByTheRunningModelsDeclaration

The third row is the one that matters: a clean dev worktree, nothing else in that go test invocation, still red. None of these names is in .github/known-red.txt.

An earlier run of the same branch reported ok internal/session 173.896s, so it is not reliably red either.

Why this is filed rather than re-run

CLAUDE.md is explicit: "A internal/session test that fails only when other suites are running beside it is now a bug report, not a known shape: reproduce it, do not rerun it in isolation and move on." I reproduced it, and the reproduction is above.

The failure shape, where it is legible

TestOnlyASpentBudgetSealsOverWorkThatIsMoving sets config.Budget = Budget{Wall: time.Nanosecond} and then expects the notice to say the running work was left where it was. Under load it got:

stopping here · the 1ns this was given are up

and no stopLeftItMovingTail. A one-nanosecond wall is already expired before the work can be observed as moving, so whether the test passes depends on whether the scheduler let the node start first. That is a race between the fixture's deadline and the goroutine it is meant to catch mid-flight, not a property of the code under test.

I have not checked whether the other six share that shape. They may not; what they share is being timing-sensitive enough to flip under load.

Replication

# on the Spark, a clean worktree at origin/dev
go test ./internal/session/ -count=1 -timeout 20m
# expect a red; expect a different name next time

Acceptance

go test ./internal/session/ -count=1 green on dev ten times running on a loaded box, with no test skipped and no name added to .github/known-red.txt — the ledger only shrinks. A fixture that needs a deadline gets one it can actually lose to, or a synchronisation point instead of a duration.

Why it is urgent now

Several aforge lanes are landing work through this package. A package that is red at random makes every lane's proof unreadable: you cannot tell a lane that broke something from a lane that ran on the wrong evening. I hit exactly that confusion tonight on #951 and had to run dev separately to clear the lane.

🤖 Generated with Claude Code


Drafted with CodeAF · reviewed and owned by the author

Activity

  1. santoshkumarradha commented on Sep 11, 2026

    @santoshkumarradha
    MemberAuthor

    Strategy note for whoever takes this, so the grant is not spent re-running a 190-second suite.

    Do not start by running the full package repeatedly. The acceptance asks for ten green runs, but that is how you finish, not how you find it. Each full run is about 190 seconds and only tells you one bit.

    Start with -race and -count on the named tests instead. All seven pass in isolation, so the cheap question is whether they pass repeatedly in isolation:

    go test ./internal/session/ -run 'TestASplitIsNeverDroppedByTheRunningModelsDeclaration' -count=50 -race
    go test ./internal/session/ -run 'TestOnlyASpentBudgetSealsOverWorkThatIsMoving' -count=50 -race

    If -count=50 in isolation is green and the full package is red, the interaction is with other tests in the package, not inside the test. Then -shuffle=on with a recorded seed is the tool:

    go test ./internal/session/ -count=1 -shuffle=on        # prints the seed it used
    go test ./internal/session/ -count=1 -shuffle=<seed>    # replays exactly that order

    A seed that reproduces a red is worth more than any amount of re-running, because it makes the failure a thing you can hold still.

    The suspicion to test first, from the one failure whose text I read. TestOnlyASpentBudgetSealsOverWorkThatIsMoving sets config.Budget = Budget{Wall: time.Nanosecond} and then expects to catch work mid-flight. A one-nanosecond wall has already expired before anything can be observed moving, so whether it passes depends on whether the scheduler let the node start first. Under load it does not, and the notice comes back stopping here · the 1ns this was given are up with no stopLeftItMovingTail.

    If that is the shape, the fix is a synchronisation point, not a bigger duration. The fixture already has one: started is a channel and waitStarted reads it. Making the deadline fire only after the node is known to be running is a real fix; raising time.Nanosecond to time.Millisecond is the same race with a longer fuse, and it will come back.

    Check whether the other six share that shape before assuming they do. They may have different causes. What they demonstrably share is being timing-sensitive enough to flip under load.

    Two rules from CLAUDE.md that bind this work. Never add a name to .github/known-red.txt — the ledger only shrinks. And do not "fix" a test by making its assertion weaker; the assertion is what the test is for.

    Report honestly. If you find the cause for two of the seven and not the rest, say exactly that and fix the two. A partial fix with a clear account of what is left is worth far more than a sweep that makes the reds disappear without explaining them.

  2. santoshkumarradha commented on Sep 11, 2026

    @santoshkumarradha
    MemberAuthor

    Cross-reference from the task-start integrator: PR #952 (fix/load-sensitive-reds, reviewed MERGE, Spark gate queued) fixes five other load-dependent internal/session reds with two mechanisms a lane on this issue should build on rather than re-derive:

    • readBeside now tells a besideWatch when each reading beside the work starts and lands, so a fixture waits on the fact instead of a guessed count of rounds (internal/session/sidecar.go, agent_test.go). Three of tests: a reading beside the work is waited on, not guessed at #952's reds were exactly "the mark's drawing raced the boundary under load".
    • eventHub.send reports whether a line landed and Agent.sayMemory holds the line when it did not (a real product race: the recall wrote to a hub a closer had cleared).

    Several of the seven named here (TestACoordinationSketchStartsNothingAndRealPartsStillConvert, TestATurnThatCannotBeCheckedBeforeTheWallIsNotMoved, TestTheRunningModelIsNeverSentTheCheckpoint) sit on the same mark-drawing road. Start from origin/fix/load-sensitive-reds (or dev once it merges) and re-measure with -count=50 -race under burners before touching anything.

  3. santoshkumarradha commented on Sep 12, 2026

    @santoshkumarradha
    MemberAuthor

    Two more instances, and a likely cause for the whole family.

    The instances

    2026-09-11 22:35Z on the Spark, make test-touched on af/issue-953 (base dev c495991a4; the branch touches only consent.go and questionPointerStart, neither of which either test reads):

    --- FAIL: TestARacedYesIsLookedAtEarlyAndTheLookConvertsTheTurn (0.01s)
        route_judge_test.go:1074: the turn ground on for 4 rounds before the race converted it
    --- FAIL: TestAConversationThatSpentNothingStampsNoFigure (0.01s)
        testing.go:1464: TempDir RemoveAll cleanup: unlinkat /tmp/TestAConversationThatSpentNothingStampsNoFigure1851406232/001: directory not empty
    FAIL	github.com/Agent-Field/aforge-v2/internal/session	174.524s
    ok  	github.com/Agent-Field/aforge-v2/internal/tui3	309.718s
    

    Both pass -count=5 in isolation on the same branch, and on clean dev 9a7ab78cc. Two different tests again, which is this issue's shape.

    The likely cause: the lock does not cover a hand-typed go test

    My run held the one-suite.sh lock and was still not alone. While it ran, this was also running on the box:

    1921267 go test ./internal/session/ -count=1 -timeout 20m
    

    scripts/one-suite.sh is reached from the Makefile only for make test / test-report when PKGS contains ./..., ./internal/tui3 or ./internal/session. A person or agent who types go test ./internal/session/ directly never touches the lock — so the lock's guarantee is "no two Makefile heavy runs", not "one heavy suite per box", which is what its own first line claims and what every reader believes.

    That turns this issue from "a flake nobody can reproduce" into something with a mechanism: the runs that go red are the ones that had an unlocked go test beside them, and the lock-holder has no way to know.

    Worth checking against the other instances in this issue — if each red run had an unlocked sibling, that is the whole story.

    The second failure is a real defect, not only load

    TempDir RemoveAll cleanup: directory not empty is not a timing assertion. It means something was still writing into the test's temp directory after the test returned — a goroutine the test did not wait for. Load only widens the window in which the leaked writer gets scheduled before RemoveAll. That one deserves its own hunt (TestAConversationThatSpentNothingStampsNoFigure, what it starts that outlives it) regardless of what happens to the lock.

    Suggested acceptance

    • go test on a heavy package takes the lock however it is invoked, or the tree stops pretending it does — a TestMain in internal/session and internal/tui3 that takes it is one way, and it cannot be bypassed by typing a different command.
    • The leaked writer in TestAConversationThatSpentNothingStampsNoFigure is found and joined.
  4. santoshkumarradha commented on Sep 12, 2026

    @santoshkumarradha
    MemberAuthor

    Measured: the fix does not close this, and the problem is wider than the seven names

    Ten full runs of internal/session on each arm, both worktrees on 9a7ab78cc, run detached on the Spark.

    arm pass fail
    branch af/issue-959 6 4
    dev, unchanged 6 4

    Identical. The fix does not move the pass rate.

    The reds, and why the comparison cannot yet judge the fix

    fix  run 2   TestTheAnswerReadsTheSameWhetherTheTurnWaitedOrNot
    fix  run 5   TestACoordinationSketchStartsNothingAndRealPartsStillConvert
    fix  run 8   TestAPickTakenByTheClockReadsAsProvisionalAndRunsWithNobodyParked
    fix  run 9   TestTheSecondAnswerToOneQuestionRecordsNothing
    
    dev  run 1   TestAMarkNobodyCouldReadIsJournaledAsAFailure
    dev  run 6   TestACoordinationSketchStartsNothingAndRealPartsStillConvert
    dev  run 7   TestTheSecondAnswerToOneQuestionRecordsNothing
    dev  run 10  TestASplitSketchAtTheFirstMarkHandsTheTurnOver
    

    None of the five fixtures the branch repaired went red in either arm, across all twenty runs. So those five are rarer flakes than these, and twenty runs is too small a sample to show the repair helping. The repair is not disproved here; it is unmeasured.

    What this changes about the issue

    The original seven names were a sample, not the population. Counting these, at least thirteen distinct tests in this package flip under load. Thirteen independently badly-written fixtures is not a plausible story. That points at one cause underneath them — a genuine race in the engine, or shared state between tests — rather than thirteen separate repairs.

    go test ./internal/session/ -count=1 -race is running on dev now and will say whether the detector sees a real data race. That answer changes what the fix should be.

    What the branch is worth

    The two commits on af/issue-959 are test-only and their reasoning holds regardless. Budget{Wall: time.Nanosecond} and then expecting to catch work mid-flight is indefensible on its own terms: the wall is up before the scheduler can start the node. Replacing it with the steward's own clock, held still while the work is known to be moving, is right whether or not it moves this pass rate. The shared collectUntil helper is likewise better than five copies of a wait.

    So the branch is a real improvement that does not close this issue. I will land it on that basis, with this issue left open, rather than let a correct change sit unlanded or let a partial fix claim a close.

    Revised acceptance

    Ten consecutive green runs is still the bar, but it now has to be reached by finding the shared cause. Chasing thirteen fixtures one at a time would be the symptom, not the cause.

    🤖 Generated with Claude Code

  5. santoshkumarradha commented on Sep 12, 2026

    @santoshkumarradha
    MemberAuthor

    One of the thirteen is held still, and it was never an assertion

    Taking the advice in this thread — a seed that reproduces a red is worth more than any amount of re-running — I hammered one name from the last comment's table instead of running the package again: TestAPickTakenByTheClockReadsAsProvisionalAndRunsWithNobodyParked, alone, 5000 times, on the Spark at GOMAXPROCS=2 under load.

    go test ./internal/session/ -run '^TestAPickTakenByTheClockReadsAsProvisionalAndRunsWithNobodyParked$' -count=5000
    

    13 red in 5000. Every one of them:

    --- FAIL: TestAPickTakenByTheClockReadsAsProvisionalAndRunsWithNobodyParked (0.00s)
        testing.go:1464: TempDir RemoveAll cleanup: unlinkat /tmp/TestAPickTaken…/001: directory not empty
    

    Not one assertion failed. And 490 of the run's temp directories were still on disk afterwards, each holding exactly one file: told.json.

    The writer

    Agent.refreshElsewhere (taskdelta.go) — the reading that tells the model what the other windows on this project have been doing — was started from the turn loop as a bare go of its own. Nothing joins it, and Agent.Close does not wait for it: it cancels the turn and goes. So the reading stamps told.json into the conversation's folder after the session has closed, which in a test is a t.TempDir() mid-RemoveAll — and the red then names whichever test happened to own that directory, which is this issue's whole shape.

    This is the same failure text already recorded here for TestAConversationThatSpentNothingStampsNoFigure, and I met it again on TestC1AProposalCannotPutRepositoryWorkInTheCheckout in a -race run.

    It is also a product defect. The stamp claims this session's model was told, and it advanced before the block was assembled — so a session closing with the reading in flight moves the stamp over a day of other windows' landings no model ever read, and that conversation never mentions them again.

    PR #997 fixes it: the reading goes through readBeside (sidecar.go's one door for a reading beside the work — that file exists because four such readings each had their own idea of a cancellation, and this was a fifth with none), and the stamp is written in the same locked step as the assignment, refused when the session has closed. After it: 0 red in 5000, 0 directories left behind, and go test ./internal/session/ -count=1 green beside ./internal/tui3/ (189.8s).

    Two more faces, still open

    Met on the way, not fixed by #997:

    1. TestHandingTheSameDecisionOverTwiceSaysItIsAlreadyHandedOver — tools_tasks_test.go:638: the second press enqueued -2 more lines for the model. A negative count: the fixture reads len(steeringQueue(agent)) twice and a turn woken in between drains the queue. Same family as tests: a reading beside the work is waited on, not guessed at #952's three.
    2. A real data race under -race, cross-test:
    WARNING: DATA RACE
    Write at 0x000002d60c30 by goroutine 149875:
      session.TestAHeldPhaseKeepsSayingItselfAndStopsWhenItEnds() phasenews_test.go:389
    Previous read at 0x000002d60c30 by goroutine 149869:
      session.(*Agent).beatHeldPhase()  phasenews.go:508
      session.(*Agent).tellPhaseThen.func1() phasenews.go:437
    

    A test writing a package-level variable that a previous test's phase-beat goroutine is still reading. Same shape as #997's bug — an unowned goroutine outliving the session that armed it — in another file.

    So the shared cause this issue is after has a name: work started beside a turn that no door owns, still running after Agent.Close returned. Each instance is small; the class is the thing. Close already cancels-and-joins the memory pass, the namer, the turn, the graph, the jobs and the presence beat — every one of those was written because the same failure was met once. The readings beside the work are the set that has no such join, and besideWatch (from #952) is the machinery that could give them one.

    🤖 Generated with Claude Code

  6. santoshkumarradha commented on Sep 12, 2026

    @santoshkumarradha
    MemberAuthor

    One more member, seen 2026-09-12 09:15 on the Spark running make pr-ready BASE=origin/dev for #935 at 18ef9c007c3dc9785e9eb3a1ec4b769dd2790f4b (session beside manual/provider/remote/tui3, -p 1):

    --- FAIL: TestARecallThatLandsBeforeTheFirstWordIsAskedAgainWithIt (10.05s)
        loop_speed_test.go:332: turn did not finish; events so far: []
    

    Same head, same test, -count=20 alone: 20/20 green in 0.87 s. CI's touched packages at the same sha: internal/session ok 203 s. Spark full internal/session at the parent 9b16df175: ok 179.9 s. So one red in three full runs, none in isolation. events so far: [] means the turn emitted nothing in ten seconds: the first request blocks on its own context waiting for the recall to cut it, and under load the cut (or the routed reading it waits on) never arrived. Log: spark:~/af-suite-935.log lines 49–50.

  7. santoshkumarradha commented on Sep 12, 2026

    @santoshkumarradha
    MemberAuthor

    Another member, a different shape — a writer that outlives Agent.Close, not a reading that failed to land. CI touched packages run 34696537215 attempt 1 (PR #935 at e99d910470e1edf675ae593dd4f61f095f36364e, dev 3143fefaa + the branch), internal/session 207 s:

    --- FAIL: TestClosingTheSessionClearsWhatWasKeptForARevision (0.00s)
        testing.go:1464: TempDir RemoveAll cleanup: unlinkat /tmp/aforge-ci/TestClosingTheSessionClearsWhatWasKeptForARevision72794179/001: directory not empty
    

    The test body passed (no assertion fired); the temp dir gained a file between RemoveAll's readdir and its rmdir, so something under the agent was still writing after Close returned and after the test returned. Same test alone: green at that head and on plain dev 3143fefaa (0.65 s each, make test-focus). #935 changes nothing in Close, the ask book, the state card or the journal writers (asklane_test.go:625 is untouched), so this is dev's. Closest earlier shapes: #532 and #583 (both closed). Parent #814.

  8. santoshkumarradha commented on Sep 12, 2026

    @santoshkumarradha
    MemberAuthor

    Attempt 2 of the same CI run (34696537215, #935 at e99d91047, re-run of the failed jobs only) went red on a third, different test — the ran.await 60 s shape L13 met on TestASplitSketchAtTheFirstMarkHandsTheTurnOver:

    --- FAIL: TestAPersonsTurnIsNeverBoundedByTheWall (60.01s)
        turnwall_test.go:220: waited 1m0s for a node to run and nothing arrived:
    FAIL	github.com/Agent-Field/aforge-v2/internal/session	250.931s
    

    stubbedGraph's node never started inside a minute under the constrained runner. #935 does not touch turnwall.go, task_run.go or task_node.go. Tally for this branch's heads so far, one full internal/session per run: CI 18ef9c0 green (203 s); Spark 18ef9c0 red TestARecallThatLandsBeforeTheFirstWordIsAskedAgainWithIt; CI e99d910 #1 red TestClosingTheSessionClearsWhatWasKeptForARevision; CI e99d910 #2 red this one. Three runs, three different tests, every one green alone. The -race runs on dev 82624af79 in spark:~/af-959-race.log / race2.log report WARNING: DATA RACE (4 and 1) with four and one reds respectively, so the family is live on dev without any branch on top.

  9. added
    bugSomething the code does that it should not
    area:testsThe suite itself — flakes, harnesses, laws, CI reds
    sev:papercutA wording, a hint, a small wrongness that costs a moment
    on Sep 21, 2026
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:testsThe suite itself — flakes, harnesses, laws, CI redsbugSomething 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