From 7a5b914265780b99674722d42ac33571f37207ec Mon Sep 17 00:00:00 2001 From: Denver2828 <215248980+Denver2828@users.noreply.github.com> Date: Mon, 31 Aug 2026 15:01:09 -0300 Subject: [PATCH 1/2] fix(bench): kill a TTY exchange on inactivity instead of total time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit j121-rdd-tui-controls-global-mode fails intermittently in the CI transition-axis run while passing the core run minutes earlier (#3971): under that run's CPU contention the TUI keeps painting, but the whole four-screen exchange outlives the fixed 10s deadline that context.WithTimeout applied to the entire runTTY call, so the child is killed mid-read ("read TUI before ...: input/output error; context deadline exceeded; signal: killed"). Of the two shapes the issue admits — a load-reflecting deadline or a read that tolerates the slower first frame — this takes the second: a ttyWatchdog now expires the exchange only after ttyTimeout (still 10s) WITHOUT receiving a single PTY byte, and every received byte resets that timer, so a slow, trickling frame under load survives while a hung TUI still dies after exactly the old budget. A new generous ttyOverallTimeout (2min) caps the whole exchange so a TUI that paints forever without reaching the expected screen still terminates deterministically. Both causes unwrap to context.DeadlineExceeded, so callers classify them exactly as before. A blind bump of the total budget was rejected because it would slow every genuinely hung exchange by the same factor without removing the load sensitivity. TestRunTTYToleratesASlowFirstFrameUnderLoad is the CI failure scaled down: a scripted terminal keeps making progress (every silence shorter than the budget) but completes the j121 banner only after more than the budget in total, read through j121's own waitForReviewModeTTY helper. On the previous commit it fails with the CI shape ("read TUI before \"RDD is currently ENABLED globally.\" ... context deadline exceeded"); with this change it passes. TestRunTTYOverallCapKillsAForeverChattering- Exchange and TestRunTTYInactivityBudgetStillKillsASilentExchange pin the two new budgets without real 10s waits. Native-Windows bar: the bench module's failing-test set is byte-for-byte identical before and after this change (the #3934 pair plus the ten pre-existing fixture failures matching #2603); this commit fixes none of them and introduces no new failure. The driven journey corpus itself is deferred to CI. --- bench/runner.go | 93 +++++++++++++++++++++++++--- bench/runner_test.go | 143 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 229 insertions(+), 7 deletions(-) diff --git a/bench/runner.go b/bench/runner.go index 07e9797c07..ee3fc648bf 100644 --- a/bench/runner.go +++ b/bench/runner.go @@ -13,6 +13,7 @@ import ( "path/filepath" "strings" "sync" + "sync/atomic" "time" "github.com/charmbracelet/x/xpty" @@ -238,7 +239,21 @@ func (s *Sandbox) invokeAt(dir string, args []string) Observation { } } +// ttyTimeout is the inactivity budget for one TTY exchange: how long the +// exchange may go without receiving a single PTY byte before the child is +// killed. It is deliberately NOT a whole-exchange deadline. In the CI +// transition-axis run (#3971) the TUI keeps painting under CPU contention but +// the whole multi-screen exchange outlives a fixed total budget, so the same +// journey that passed the core run minutes earlier dies mid-read. Progress +// resets this timer; a hung TUI that emits nothing still dies after exactly +// this long. const ttyTimeout = 10 * time.Second + +// ttyOverallTimeout caps one whole TTY exchange however chatty the child is, +// so a TUI that paints forever without ever reaching the expected screen +// still terminates deterministically. +const ttyOverallTimeout = 2 * time.Minute + const ttyCleanupGrace = 250 * time.Millisecond var errTTYWaitCleanupTimeout = errors.New("TTY wait cleanup timed out") @@ -270,17 +285,81 @@ func awaitTTYResult(result <-chan error) (error, bool) { } } -// runTTYWithTimeout owns every reader worker it starts. Exchange callbacks are -// package-local and must return when terminal.Close unblocks their pending I/O. +// runTTYWithTimeout runs one exchange with the given inactivity budget and +// the default overall cap. func runTTYWithTimeout(cmd *exec.Cmd, terminal io.ReadWriteCloser, args []string, exchange func(*bufio.Reader, io.WriteCloser) error, timeout time.Duration, wait func(context.Context, *exec.Cmd) error) (Observation, error) { + return runTTYWithDeadlines(cmd, terminal, args, exchange, timeout, ttyOverallTimeout, wait) +} + +// ttyWatchdog expires an exchange on either of two budgets: inactivity — +// this long without receiving a PTY byte, refreshed by every byte the +// terminal yields — or overall, a cap on the whole exchange. Both causes +// unwrap to context.DeadlineExceeded so callers classify them exactly as the +// old fixed deadline. +type ttyWatchdog struct { + ctx context.Context + cancel context.CancelCauseFunc + epoch time.Time + last atomic.Int64 // nanoseconds since epoch of the last PTY byte + done chan struct{} + once sync.Once +} + +func newTTYWatchdog(inactivity, overall time.Duration) *ttyWatchdog { + ctx, cancel := context.WithCancelCause(context.Background()) + watchdog := &ttyWatchdog{ctx: ctx, cancel: cancel, epoch: time.Now(), done: make(chan struct{})} + go watchdog.run(inactivity, overall) + return watchdog +} + +func (w *ttyWatchdog) run(inactivity, overall time.Duration) { + for { + elapsed := time.Since(w.epoch) + idle := elapsed - time.Duration(w.last.Load()) + if idle >= inactivity { + w.cancel(fmt.Errorf("no PTY output for %s: %w", inactivity, context.DeadlineExceeded)) + return + } + if elapsed >= overall { + w.cancel(fmt.Errorf("TTY exchange exceeded its overall %s budget: %w", overall, context.DeadlineExceeded)) + return + } + select { + case <-time.After(min(inactivity-idle, overall-elapsed)): + case <-w.done: + return + } + } +} + +func (w *ttyWatchdog) stop() { w.once.Do(func() { close(w.done); w.cancel(nil) }) } + +// ttyProgressReader marks every received byte as watchdog progress. +type ttyProgressReader struct { + watchdog *ttyWatchdog + reader io.Reader +} + +func (r *ttyProgressReader) Read(p []byte) (int, error) { + read, err := r.reader.Read(p) + if read > 0 { + r.watchdog.last.Store(int64(time.Since(r.watchdog.epoch))) + } + return read, err +} + +// runTTYWithDeadlines owns every reader worker it starts. Exchange callbacks are +// package-local and must return when terminal.Close unblocks their pending I/O. +func runTTYWithDeadlines(cmd *exec.Cmd, terminal io.ReadWriteCloser, args []string, exchange func(*bufio.Reader, io.WriteCloser) error, inactivity, overall time.Duration, wait func(context.Context, *exec.Cmd) error) (Observation, error) { var closed sync.Once var closeErr error closePTY := func() { closed.Do(func() { closeErr = terminal.Close() }) } defer closePTY() var output bytes.Buffer - reader := bufio.NewReader(io.TeeReader(terminal, &output)) - ctx, cancel := context.WithTimeout(context.Background(), timeout) - defer cancel() + watchdog := newTTYWatchdog(inactivity, overall) + defer watchdog.stop() + reader := bufio.NewReader(io.TeeReader(&ttyProgressReader{watchdog: watchdog, reader: terminal}, &output)) + ctx := watchdog.ctx waitResult := make(chan error, 1) go func() { waitResult <- wait(context.Background(), cmd) }() exchangeResult := make(chan error, 1) @@ -298,7 +377,7 @@ func runTTYWithTimeout(cmd *exec.Cmd, terminal io.ReadWriteCloser, args []string terminate() } case <-ctx.Done(): - timeoutErr = ctx.Err() + timeoutErr = context.Cause(ctx) terminate() } if !exchangeDone { @@ -323,7 +402,7 @@ func runTTYWithTimeout(cmd *exec.Cmd, terminal io.ReadWriteCloser, args []string waitDone = true case <-ctx.Done(): if timeoutErr == nil { - timeoutErr = ctx.Err() + timeoutErr = context.Cause(ctx) terminate() } waitErr, waitDone = awaitTTYResult(waitResult) diff --git a/bench/runner_test.go b/bench/runner_test.go index b95ae69ff6..0066c27a86 100644 --- a/bench/runner_test.go +++ b/bench/runner_test.go @@ -10,6 +10,7 @@ import ( "os/exec" "path/filepath" "strings" + "sync" "testing" "time" @@ -230,6 +231,148 @@ func TestRunTTYCleansUpAfterARealExchangeFailure(t *testing.T) { } } +// ttyFrame is one scripted burst of terminal output preceded by silence. +type ttyFrame struct { + silence time.Duration + text string +} + +// slowFrameTTY replays scripted frames the way a loaded runner's TUI paints +// them: silence, then a partial screen, then more silence. It stands in for +// the real PTY so the #3971 timing can be reproduced deterministically and +// fast, without a real child or a real 10s budget. Writing anything +// containing "q" — the j121 quit key — makes the fake child exit, and Close +// unblocks any pending read exactly as runTTY requires of a terminal. +type slowFrameTTY struct { + mu sync.Mutex + frames []ttyFrame + loop bool + closed chan struct{} + quit chan struct{} + closeOnce sync.Once + quitOnce sync.Once +} + +func newSlowFrameTTY(frames []ttyFrame, loop bool) *slowFrameTTY { + return &slowFrameTTY{frames: frames, loop: loop, closed: make(chan struct{}), quit: make(chan struct{})} +} + +func (terminal *slowFrameTTY) Read(p []byte) (int, error) { + terminal.mu.Lock() + if len(terminal.frames) == 0 { + terminal.mu.Unlock() + return 0, io.EOF + } + frame := terminal.frames[0] + if !terminal.loop || len(terminal.frames) > 1 { + terminal.frames = terminal.frames[1:] + } + terminal.mu.Unlock() + select { + case <-time.After(frame.silence): + case <-terminal.closed: + return 0, os.ErrClosed + } + return copy(p, frame.text), nil +} + +func (terminal *slowFrameTTY) Write(p []byte) (int, error) { + if strings.Contains(string(p), "q") { + terminal.quitOnce.Do(func() { close(terminal.quit) }) + } + return len(p), nil +} + +func (terminal *slowFrameTTY) Close() error { + terminal.closeOnce.Do(func() { close(terminal.closed) }) + return nil +} + +// wait exits the fake child when the exchange quits it or the PTY is closed, +// exactly as the real TUI child behaves. +func (terminal *slowFrameTTY) wait(context.Context, *exec.Cmd) error { + select { + case <-terminal.quit: + case <-terminal.closed: + } + return nil +} + +// TestRunTTYToleratesASlowFirstFrameUnderLoad is #3971 with every duration +// scaled down: in the CI transition-axis run, j121's TUI keeps painting under +// CPU contention but the whole exchange outlives the fixed 10s budget, so the +// step deadline kills the child mid-read ("read TUI before ... input/output +// error; context deadline exceeded"). Here the budget passed to +// runTTYWithTimeout stands in for the old fixed 10s total: the terminal keeps +// making progress — every silence is shorter than the budget — but the +// expected banner only completes after more than the budget in total. A +// fixed whole-exchange deadline kills this exchange; a deadline that treats +// PTY bytes as progress lets it finish. +func TestRunTTYToleratesASlowFirstFrameUnderLoad(t *testing.T) { + terminal := newSlowFrameTTY([]ttyFrame{ + {silence: 400 * time.Millisecond, text: "\x1b[2J\x1b[HReceipt-Driven Development\r\n"}, + {silence: 400 * time.Millisecond, text: "RDD is currently "}, + {silence: 700 * time.Millisecond, text: "ENABLED globally.\r\n"}, + }, false) + observation, err := runTTYWithTimeout(&exec.Cmd{}, terminal, []string{"review-mode"}, func(reader *bufio.Reader, writer io.WriteCloser) error { + return waitForReviewModeTTY(reader, "RDD is currently ENABLED globally.", "", "", func() error { + _, err := io.WriteString(writer, "q") + return err + }) + }, time.Second, terminal.wait) + if err != nil { + t.Fatalf("runTTY killed an exchange that never stopped making progress: %v", err) + } + if !strings.Contains(observation.Stdout, "RDD is currently ENABLED globally.") { + t.Fatalf("transcript = %q, want the banner the exchange waited for", observation.Stdout) + } + if observation.ExitCode != 0 { + t.Fatalf("exit code = %d, want 0", observation.ExitCode) + } +} + +// A TUI that paints forever without ever reaching the expected screen must +// not outlive the overall cap just because every byte resets the inactivity +// timer. +func TestRunTTYOverallCapKillsAForeverChatteringExchange(t *testing.T) { + terminal := newSlowFrameTTY([]ttyFrame{{silence: 25 * time.Millisecond, text: "tick "}}, true) + started := time.Now() + _, err := runTTYWithDeadlines(&exec.Cmd{}, terminal, []string{"review-mode"}, func(reader *bufio.Reader, _ io.WriteCloser) error { + _, err := reader.ReadString('\n') + return err + }, 5*time.Second, 300*time.Millisecond, terminal.wait) + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("runTTY error = %v, want the overall cap's deadline", err) + } + if !strings.Contains(err.Error(), "overall") { + t.Fatalf("runTTY error = %v, want it to name the overall budget", err) + } + if elapsed := time.Since(started); elapsed > 3*time.Second { + t.Fatalf("runTTY took %v, want bounded termination", elapsed) + } +} + +// A hung TUI still dies after exactly the inactivity budget — long before an +// eventual frame that would only arrive after the exchange stopped receiving +// bytes for that long — and the failure names the inactivity, not a total. +func TestRunTTYInactivityBudgetStillKillsASilentExchange(t *testing.T) { + terminal := newSlowFrameTTY([]ttyFrame{{silence: 5 * time.Second, text: "too late\r\n"}}, false) + started := time.Now() + _, err := runTTYWithDeadlines(&exec.Cmd{}, terminal, []string{"review-mode"}, func(reader *bufio.Reader, _ io.WriteCloser) error { + _, err := reader.ReadString('\n') + return err + }, 200*time.Millisecond, 10*time.Second, terminal.wait) + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("runTTY error = %v, want the inactivity deadline", err) + } + if !strings.Contains(err.Error(), "no PTY output") { + t.Fatalf("runTTY error = %v, want it to name the inactivity budget", err) + } + if elapsed := time.Since(started); elapsed > 2*time.Second { + t.Fatalf("runTTY took %v, want the inactivity budget to fire well before the frame", elapsed) + } +} + func TestInvokeTTYReportsPromptStartFailure(t *testing.T) { sandbox := fakeBinary(t, "") sandbox.Binary = filepath.Join(t.TempDir(), "missing-gentle-ai") From 662aaf87c986316e7d320aafa50d12655007e21e Mon Sep 17 00:00:00 2001 From: Denver2828 <215248980+Denver2828@users.noreply.github.com> Date: Mon, 31 Aug 2026 20:39:14 -0300 Subject: [PATCH 2/2] fix(bench): seed the update cooldown in j121's sandbox so the Update Available modal cannot cover the exchange The watchdog diagnostic from the previous commit exposed a second manifestation of #3971, distinct from the load-slowness that commit addresses: the bench sandbox gives each journey a fresh HOME with no state.json, so CheckAllWithCooldown (internal/update/cooldown.go) finds no LastUpdateCheck and runs the launch update check. When upstream main is newer than the CI-built binary, the TUI shows the Update Available modal (internal/tui/screens/update_prompt.go), which covers the menu j121's exchange waits for ("Start installation" never arrives), and after 10s of true silence the watchdog kills the run. Seed j121's sandbox HOME with a state.json carrying a current last_update_check before the TTY exchange, mirroring the precedent in bench/journeys_issue_3561.go (green in CI for the same reason). No state.json exists at that point and the journey runs against a not-installed state, so only the cooldown field is seeded. --- bench/journeys_issue3766.go | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/bench/journeys_issue3766.go b/bench/journeys_issue3766.go index d64e98cc24..eb194bccf3 100644 --- a/bench/journeys_issue3766.go +++ b/bench/journeys_issue3766.go @@ -4,10 +4,24 @@ import ( "bufio" "fmt" "io" + "path/filepath" "strings" "time" ) +// issue3766UpdateCooldownFixture seeds the sandbox HOME's state.json with a +// current last_update_check, mirroring issue3561DanglingAncestorFixture: a +// fresh sandbox HOME has no update cooldown, so when upstream is newer the +// launch update check pops an "Update Available" modal that covers the menu +// the TTY exchange waits for (#3971's second manifestation). No state.json +// exists at this point, so only the cooldown is seeded and the journey keeps +// running against a not-installed state. +func issue3766UpdateCooldownFixture(sandbox *Sandbox) error { + statePath := filepath.Join(sandbox.Home, ".gentle-ai", "state.json") + state := fmt.Sprintf(`{"last_update_check":%q}`, time.Now().UTC().Format(time.RFC3339Nano)) + return sandbox.write(statePath, state) +} + // issue3766Journeys drives #3766's switch under a real PTY. The sandbox supplies // an isolated HOME, so this proof cannot read or change a user's global config. func issue3766Journeys() []Journey { @@ -18,6 +32,7 @@ func issue3766Journeys() []Journey { Source: "#3766: the switch screen must expose resolved state and never touch a real user config", Steps: []Step{ {Name: "fixture: repository", Fixture: baseRepo}, + {Name: "fixture: update-check cooldown in the sandbox HOME", Fixture: issue3766UpdateCooldownFixture}, {Name: "Receipt-Driven Development toggles globally in the TUI", Composite: func(run *journeyRun) error { observation, err := run.runTTY(nil, false, reviewModeTTYExchange) if err != nil {