diff --git a/TODO.md b/TODO.md index 62c4046..36fd092 100644 --- a/TODO.md +++ b/TODO.md @@ -35,6 +35,76 @@ is finished. # Completed Steps +- 2026-08-09 `TestAutoSaveOnSignalRacesTurnLoop` de-flaked at the cause + (`fix/autosave-turn-budget-36`, closes #36). The failure text was captured + before anything was changed and it is **not** a data race: the assertion was + `driveUntilDone`'s + `t.Fatal("the turn loop ran out of turns before the saves were taken")`, with + no `WARNING: DATA RACE` anywhere in the log. The handoff fixed in #24 was + working; the test's own drive loop was running out of its fixed 1000-turn + budget first. + + Confirmed rather than taken on trust. Instrumenting the loop to report the + turns it actually used showed the count tracking scheduling pressure and + nothing else: about 60-120 turns at host load ~57 with the whole machine to + spread over, 418 at `GOMAXPROCS=4`, 539 and 655 at 2 and 1, and past 1000 — + the recorded failure — under the doubled load of the verbose rerun that the + test target performs after a failure. The turns between one save being + answered and the next request arriving are not work; they are the saving + goroutine's wake-up latency, so a fixed turn count is a wall-clock + assumption in disguise, which is why raising it would have hidden the flake + rather than fixed it. + + So the budget is gone rather than larger. `driveUntilDone` now drives until + the saving goroutine finishes and nothing else. Termination is not lost, it + just belongs to the code under test instead of to the test: every + `AutoSaveOnSignal` returns within the timeout it is handed, so the saving + goroutine always finishes. A handoff that has stopped answering costs one + `autoSaveWait` in total — `g.sigSave` is one deep, so an unserviced request + stays in the channel and every later call finds it full and fails at once — + and the failure is then the real assertion (`saves taken = 0, want 25`) + instead of "out of turns". The worst case is not that one: a handoff that + drains each request but slower than `autoSaveWait` costs one timeout per + save, `wantSaves × autoSaveWait` = 250s, which would run past the 30s + package timeout instead of reaching the assertion. It takes ~10s of + scheduler starvation per save against a measured 0.12s per 1000 turns, so it + is remote, and the turn cap did not bound it either. The comment in the test + states that bound rather than the optimistic one. + + Removing the cap exposed a second assumption underneath it, which is the + reason this is not a one-line diff. `testTerm` answers space and newline for + ever once its script is exhausted, and neither key takes a turn, so + `command()` — which loops until the player consumes one — never returns; the + old cap was silently sized to the script (4000 characters, two per turn, + against 1000 turns). An uncapped drive wedged inside a single `command()` + call. The two drive tests therefore use a new `driveTerm`, a headless + terminal whose script repeats. Repeating is necessary but not sufficient, + and the test says so: `' '` clears `After` outright and all eight movement + keys clear it on a refused step, so a script of only those keys wedges just + as `testTerm`'s tail did. What makes the wedge impossible is that the cycle + always holds an _unconditional_ turn-taker, and these scripts hold two — + `'.'` (empty handler) and `'s'` (`search`, which writes `After` on no path), + neither refusable by blocked-in-all-directions, `Held`, a bear trap, or + `NoCommand > 0`. Removing both would bring the wedge back. + + Both halves of the definition of done were demonstrated by mutation, with + the deliberately-broken tree reverted afterwards and `.golangci.yml` left + byte-identical (sha256 `021cc83f...46bcb`). Reverting #24 — + `AutoSaveOnSignal` replaced by a direct `g.autoSave()`, encoding on the + calling goroutine — still fails the test with 139 `WARNING: DATA RACE` + reports naming `snapshotHeader` reading what `executeCommand` writes, so the + guard is undiminished. Removing the `serviceAutoSaveRequest` call from + `command()` still fails it too, now in 10s with `saves taken = 0, want 25` + rather than by hanging. + + Under load, an A/B at `GOMAXPROCS=2` on a 48-core host at load ~150, with an + unrelated deliberate failure in the tree so that every run took the verbose + rerun: the old code failed 8 of 8 runs with "ran out of turns"; the new code + failed 0 of 8, the only failure being the planted one. Also green across 24 + concurrent unconstrained runs at load ~120, 10 runs alongside a spinner + load, and 5 runs each at `GOMAXPROCS` 1, 2 and 4. `make check` green, lint 0 + issues. + - 2026-08-09 Wizard commands under test (`test/wizard-coverage`, closes #7): the last of the three thin spots, so the coverage step is now closed rather than narrowed. `game/wizard.go`'s eight functions had no tests of their own, and diff --git a/game/autosave_test.go b/game/autosave_test.go index 9641161..55d4d4e 100644 --- a/game/autosave_test.go +++ b/game/autosave_test.go @@ -9,7 +9,6 @@ import ( "io" "os" "path/filepath" - "strings" "testing" "time" ) @@ -17,7 +16,9 @@ import ( // autoSaveWait is the deadline the tests hand AutoSaveOnSignal when they // expect the save to be taken. It is long enough that a loaded machine // cannot turn a working handoff into a spurious failure, and it is never -// actually waited out on a passing run. +// actually waited out on a passing run. It is also what bounds +// driveUntilDone, by way of the saving goroutine it waits for — see +// there for what that bound comes to. const autoSaveWait = 10 * time.Second // TestAutoSaveOnSignalRacesTurnLoop is the test issue #24 exists for: it @@ -34,12 +35,14 @@ const autoSaveWait = 10 * time.Second func TestAutoSaveOnSignalRacesTurnLoop(t *testing.T) { t.Parallel() - // Same mix as TestTurnLoopCrashSweep: the spaces answer any --More-- - // prompt, and the script is long enough that the drive never runs it - // out. - script := []byte(strings.Repeat("h j k l y u b n s . ", 400)) + // Same mix as TestTurnLoopCrashSweep — the spaces answer any --More-- + // prompt — on a driveTerm, so the drive can run for as long as the + // saves take rather than for as long as a script lasts. The '.' and + // the 's' are what make an unbounded drive safe, and at least one of + // the two has to stay in the cycle: see driveTerm. + term := &driveTerm{script: []byte("h j k l y u b n s . ")} - g := New(Params{Seed: 20260809, Term: &testTerm{input: script}}) + g := New(Params{Seed: 20260809, Term: term}) g.FileName = filepath.Join(t.TempDir(), "rogue.save") g.startLevel() g.prePlay() @@ -74,14 +77,50 @@ func TestAutoSaveOnSignalRacesTurnLoop(t *testing.T) { // driveUntilDone runs turns until the saving goroutine is finished, // fortifying the hero each turn so no death exits the test binary. The -// turn cap keeps a broken handoff from hanging the suite instead of -// failing it. +// condition it waits on is that goroutine finishing — nothing else. +// +// It used to stop after a fixed 1000 turns and fail, and that cap was a +// load-sensitive assumption wearing a counter's clothes (issue #36). The +// turns this loop spends between one save request being answered and the +// next arriving are not work; they are the saving goroutine's scheduling +// latency, so the turn count 25 saves costs is a function of how +// contended the machine is rather than of anything the code under test +// does. Measured here on a 48-core host at load ~57: about 60-120 turns +// with a whole machine to spread over, 418 to 655 as GOMAXPROCS was cut +// from 4 to 1, and past 1000 under the doubled load of the verbose +// rerun, which is the flake this replaces. A budget that has to be +// guessed cannot be guessed right, so there is no budget. +// +// Dropping it costs no termination guarantee, because the bound belongs +// to the code under test and not to this loop: each AutoSaveOnSignal +// call returns within the timeout the caller hands it, so the saving +// goroutine always finishes and done always closes. That bound is worth +// stating exactly, because it is not one autoSaveWait. +// +// A handoff that has stopped answering altogether costs one, in total, +// however many saves were asked for. g.sigSave +// is one deep, so the unserviced request stays in the channel and every +// later call finds it full and reports failure immediately — measured +// at 10.0s for 25 saves with the service point deleted from command(). +// What fails is then the caller's own assertion, the count of saves +// actually taken, which says far more than "out of turns" ever did. +// +// A handoff that still drains every request but takes longer than +// autoSaveWait to do it is the worst case, and costs one timeout per +// save: wantSaves * autoSaveWait, 250s at these constants, which would +// run past the package timeout rather than reach the assertion. It +// takes about ten seconds of scheduler starvation per save to get +// there, against a regime measured at 0.12s per 1000 turns, so it is +// remote — and the 1000-turn cap did not bound it either, a turn count +// being no kind of time bound. `go test -timeout 30s` is the backstop +// under all of it. +// +// The one thing the caller does have to supply is a terminal that can +// feed an unbounded drive: see driveTerm. func driveUntilDone(t *testing.T, g *RogueGame, done <-chan struct{}) { t.Helper() - const maxTurns = 1000 - - for range maxTurns { + for { select { case <-done: return @@ -91,8 +130,6 @@ func driveUntilDone(t *testing.T, g *RogueGame, done <-chan struct{}) { fortify(g) g.command() } - - t.Fatal("the turn loop ran out of turns before the saves were taken") } // TestAutoSaveOnSignalWhileBlockedOnInput is the case the fix is really @@ -266,9 +303,7 @@ func TestAutoSaveOnSignalTimesOutLeavingTheOldSave(t *testing.T) { func TestAutoSaveOnSignalWithoutASaveFile(t *testing.T) { t.Parallel() - g := New(Params{Seed: 5, Term: &testTerm{ - input: []byte(strings.Repeat("s . ", 200)), - }}) + g := New(Params{Seed: 5, Term: &driveTerm{script: []byte("s . ")}}) g.FileName = "" g.startLevel() g.prePlay() @@ -437,6 +472,66 @@ func mkBlockedGame(t *testing.T, term Terminal) *RogueGame { return g } +// driveTerm is a headless Terminal whose script repeats instead of +// running out, for the tests that drive the turn loop until something +// else finishes rather than for a set number of turns. +// +// testTerm cannot do that job. Once its script is exhausted it answers +// space and newline for ever, and neither takes a turn, so command() — +// which loops until the player does something that consumes one, the +// `if !g.After { ntimes++ }` in command.c — never returns. A drive with +// a turn cap sized to its script never notices; a drive that runs until +// the saves are taken wedges inside a single command() call, which is +// what a first attempt at issue #36 did. +// +// Repeating the script is necessary but nowhere near sufficient, and +// the difference is what anyone editing one of these scripts has to +// know. Most keys take a turn only conditionally. ' ' is the "legal +// illegal command" and clears After outright (tables.go). All eight +// movement keys clear it whenever the step is refused: a wall or the +// map edge (move.go moveResolve), an illegal diagonal (moveTarget), or +// a confused step that lands back in place (moveHero). A script of +// nothing but those keys wedges exactly the way testTerm's tail does, +// repetition or no repetition — with the script set to just " " this +// drive hits the 30s package timeout inside command(). +// +// What actually makes the wedge impossible is that the cycle always +// contains at least one *unconditional* turn-taker, and the scripts +// here carry two: '.', the rest command, whose handler is empty, and +// 's', search, which writes After on no path. Nothing refuses either +// one — not being blocked in all eight directions, not Held, not stuck +// in a bear trap, and not NoCommand > 0, where playTurn skips +// executeCommand altogether and After is simply left true. Trim both +// out and the wedge this test exists to remove comes straight back. +// +// One further precondition, from what this fake does not supply: +// testTerm's tail answered a newline every other read and this does +// not. Nothing reachable from these scripts asks for one — waitFor('\n') +// sits on the death and score paths (rip.go, score.go), which fortify +// prevents from ever being reached — but a script that could reach them +// would park in waitFor for ever. +type driveTerm struct { + script []byte + pos int +} + +func (t *driveTerm) Render(*Window) {} + +func (t *driveTerm) Repaint() {} + +func (t *driveTerm) Fini() {} + +// Interrupt has nothing to wake: this terminal's ReadChar never blocks. +func (t *driveTerm) Interrupt() {} + +// ReadChar hands out the next scripted key, wrapping at the end. +func (t *driveTerm) ReadChar() (byte, bool) { + ch := t.script[t.pos] + t.pos = (t.pos + 1) % len(t.script) + + return ch, true +} + // blockingTerm is a Terminal that genuinely blocks in ReadChar until a // key is pushed or Interrupt wakes it — which testTerm, whose reads never // block, cannot reproduce.