Merge pull request #7832 from esengine/fix/tui-watchdog-lifecycle

fix(cli): prevent TUI watchdog false kills and recover active stalls
This commit is contained in:
SivanCola authored and GitHub committed 2026-08-07 12:25:15 +08:00
commit 38e4702e87
9 files changed
+1092 -59

No files matched your search

+17 -3
View File
@@ -874,10 +874,11 @@ func suspendWithMouseReset() tea.Cmd {
}
func (m chatTUI) Update(msg tea.Msg) (tea.Model, tea.Cmd) {
// Feed the startup/stall watchdog so freezes leave a goroutine dump and
// recover the terminal instead of a zero-byte log (#7435).
// Confirm booting → idle on the first Update. User input (keys/mouse/focus)
// must NOT refresh the active-turn heartbeat; only elapsedTick and work
// events do, so interaction cannot mask a stuck event loop (#7809).
if m.diagnostics != nil {
m.diagnostics.markProgress()
m.diagnostics.NoteBooted()
}
logFirstFrame := false
if m.diagnostics != nil && !m.firstFrameLogged {
@@ -1491,6 +1492,7 @@ func (m chatTUI) update(msg tea.Msg) (tea.Model, tea.Cmd) {
if !m.ctrl.Running() {
m.state = tuiIdle
m.confirmBubbleSent()
m.noteWatchdogIdle()
}
default:
// Idle (any mode): a double-Esc on an empty composer opens the
@@ -1690,6 +1692,7 @@ func (m chatTUI) update(msg tea.Msg) (tea.Model, tea.Cmd) {
m.bubblePending = true
m.turnDiscarded = false
m.confirmBubbleSent() // shell events arrive instantly
m.noteWatchdogRunning()
m.ctrl.RunShell(cmd)
return m, tea.Batch(m.spinner.Tick, elapsedTick())
}
@@ -1730,6 +1733,9 @@ func (m chatTUI) update(msg tea.Msg) (tea.Model, tea.Cmd) {
case agentEventMsg:
e := event.Event(msg)
// Agent/shell/controller work events prove the event loop is servicing
// the active turn. Record before ingest so TurnDone still counts.
m.noteWatchdogHeartbeat(watchdogAgentSource(e.Kind))
m.ingestEvent(e)
turnDone := e.Kind == event.TurnDone
gitMaybeChanged := e.Kind == event.ToolResult && !e.Tool.ReadOnly
@@ -1743,6 +1749,7 @@ func (m chatTUI) update(msg tea.Msg) (tea.Model, tea.Cmd) {
for drained := 0; drained < maxEventDrain; drained++ {
select {
case e2 := <-m.eventCh:
m.noteWatchdogHeartbeat(watchdogAgentSource(e2.Kind))
m.ingestEvent(e2)
if e2.Kind == event.TurnDone {
turnDone = true
@@ -1822,6 +1829,7 @@ func (m chatTUI) update(msg tea.Msg) (tea.Model, tea.Cmd) {
m.followSessionLease()
} else {
m.ctrl = msg.ctrl
m.updateWatchdogStatusProvider()
m.label = msg.label
m.commands = msg.commands
m.skills = msg.skills
@@ -1970,6 +1978,9 @@ func (m chatTUI) update(msg tea.Msg) (tea.Model, tea.Cmd) {
case elapsedTickMsg:
if m.state == tuiRunning {
// elapsedTick is the primary active-turn heartbeat: long turns that
// emit no agent events still prove the Bubble Tea loop is alive.
m.noteWatchdogHeartbeat("elapsed_tick")
m.elapsed = int(time.Since(m.runStart).Seconds())
m.tickToolRunning()
m.tickSubagentProgress()
@@ -4210,6 +4221,7 @@ func (m *chatTUI) startControllerTurn(displayed, restore string, start func()) t
m.turnTokens = 0
// The controller owns the run goroutine, its context, and cancellation; it
// streams events to eventCh and emits TurnDone when the turn settles.
m.noteWatchdogRunning()
start()
return tea.Batch(m.spinner.Tick, elapsedTick())
}
@@ -4275,6 +4287,7 @@ func (m *chatTUI) ingestEvent(e event.Event) {
if e.Kind == event.TurnDone {
m.turnDiscarded = false
m.state = tuiIdle
m.noteWatchdogIdle()
}
return
}
@@ -4508,6 +4521,7 @@ func (m *chatTUI) ingestEvent(e event.Event) {
// just clear the un-sendable flag.
m.confirmBubbleSent()
m.state = tuiIdle
m.noteWatchdogIdle()
m.queueEditCursor = -1
m.queueEditDraft = ""
m.clearSubmittedPastes()
+49
View File
@@ -0,0 +1,49 @@
package cli
import (
"fmt"
"reasonix/internal/event"
)
func (m *chatTUI) noteWatchdogRunning() {
if m == nil || m.diagnostics == nil {
return
}
ctrl := m.ctrl
m.diagnostics.NoteRunning(func() {
if ctrl != nil {
ctrl.Cancel()
}
})
}
func (m *chatTUI) noteWatchdogIdle() {
if m == nil || m.diagnostics == nil {
return
}
m.diagnostics.NoteIdle()
}
func (m *chatTUI) noteWatchdogHeartbeat(source string) {
if m == nil || m.diagnostics == nil {
return
}
m.diagnostics.NoteActiveHeartbeat(source)
}
func watchdogAgentSource(kind event.Kind) string {
return fmt.Sprintf("agent:%d", kind)
}
func (m *chatTUI) updateWatchdogStatusProvider() {
if m == nil || m.diagnostics == nil || m.ctrl == nil {
return
}
ctrl := m.ctrl
m.diagnostics.SetStatusProvider(func() string {
st := ctrl.RuntimeStatus()
return fmt.Sprintf("running=%v pending_prompt=%v cancel_requested=%v cancellable=%v background_jobs=%d",
st.Running, st.PendingPrompt, st.CancelRequested, st.Cancellable, st.BackgroundJobs)
})
}
+1
View File
@@ -1273,6 +1273,7 @@ func chatREPL(args []string, version string) int {
m := newChatTUI(ctrl, missing, eventCh, termW)
m.diagnostics = diagnostics
m.updateWatchdogStatusProvider()
m.planMode = permissions.plan
m.leases = leases
if cfg != nil {
+441 -48
View File
@@ -20,16 +20,40 @@ const (
tuiDiagnosticLogRetention = 7 * 24 * time.Hour
tuiWatchdogInterval = time.Second
tuiWatchdogStall = 10 * time.Second
tuiWatchdogCancelGrace = 2 * time.Second
)
// tuiDiagnostics owns process-level diagnostics while an interactive terminal
// UI is alive. Bubble Tea owns the terminal screen, so background logs and
// plugin stderr must go to a private file instead of bypassing its renderer.
// Failure to create that file degrades to io.Discard: typed event.Notice values
// still carry user-facing warnings through the TUI.
//
// Milestones and a 1s heartbeat keep the log non-empty during hangs so Windows
// ConPTY freezes (#7435) and stuck D-Bus startups leave recoverable evidence.
// Watchdog lifecycle phases. Only booting (no first Update) and running
// (active turn / shell with no event-loop heartbeat) can escalate to kill.
// Idle never terminates the process — that was the #7809 false-kill path.
type tuiWatchdogPhase int
const (
watchdogBooting tuiWatchdogPhase = iota
watchdogIdle
watchdogRunning
watchdogClosed
)
func (p tuiWatchdogPhase) String() string {
switch p {
case watchdogBooting:
return "booting"
case watchdogIdle:
return "idle"
case watchdogRunning:
return "running"
case watchdogClosed:
return "closed"
default:
return fmt.Sprintf("phase(%d)", int(p))
}
}
// tuiDiagnostics owns diagnostics for the interactive terminal UI. Logs and
// plugin stderr use a private file; typed notices remain user-facing if it
// cannot be created. The watchdog uses booting/idle/running/closed: idle never
// kills, while running stalls escalate through dump, cancel, grace, and kill.
type tuiDiagnostics struct {
previous *slog.Logger
logger *slog.Logger
@@ -38,15 +62,65 @@ type tuiDiagnostics struct {
path string
close sync.Once
lastProgress atomic.Int64 // unix nano of last Update/View progress
stopWatch chan struct{}
watchOnce sync.Once
watchWG sync.WaitGroup
killed atomic.Bool
stopWatch chan struct{}
watchOnce sync.Once
watchWG sync.WaitGroup
mu sync.Mutex
phase tuiWatchdogPhase
generation uint64 // increments on each idle→running transition
lastHeartbeat time.Time
lastHeartbeatSource string
// escalatedGeneration is the generation currently inside dump/cancel/grace
// (0 means none). Cleared when a heartbeat aborts the grace window so a
// later stall can re-enter escalation for hard-kill only.
escalatedGeneration uint64
// cancelIssuedGeneration is sticky for the Turn: Cancel() runs at most once
// per generation even if the grace window is aborted and the turn stalls
// again.
cancelIssuedGeneration uint64
cancelDeadline time.Time // zero until escalated for current generation
// hardKillIssued is true after a hard-kill for hardKilledGen.
hardKillIssued bool
hardKilledGen uint64
// cancelFn is the non-blocking controller cancel for the active generation.
// Cleared on idle/closed. Invoked under mu after a generation check.
cancelFn func()
// statusFn optionally returns Controller RuntimeStatus text for dumps.
statusFn func() string
// Injectable seams for deterministic tests (nil = production defaults).
nowFn func() time.Time
newTicker func(d time.Duration) watchdogTicker
dumpFn func(reason string)
killFn func()
logFn func(format string, args ...any)
// Test observation counters (safe under mu).
cancelCalls atomic.Int32
killCalls atomic.Int32
dumpCalls atomic.Int32
}
// watchdogTicker is the subset of time.Ticker used by the watch loop.
type watchdogTicker interface {
C() <-chan time.Time
Stop()
}
type realTicker struct{ *time.Ticker }
func (t realTicker) C() <-chan time.Time { return t.Ticker.C }
func startTUIDiagnostics(reasonixHome string) *tuiDiagnostics {
d := &tuiDiagnostics{previous: slog.Default(), writer: io.Discard, stopWatch: make(chan struct{})}
d := &tuiDiagnostics{
previous: slog.Default(),
writer: io.Discard,
stopWatch: make(chan struct{}),
phase: watchdogBooting,
}
if logDir := tuiDiagnosticLogDir(reasonixHome); logDir != "" {
if err := os.MkdirAll(logDir, 0o700); err == nil {
pruneTUIDiagnosticLogs(logDir, time.Now())
@@ -59,19 +133,20 @@ func startTUIDiagnostics(reasonixHome string) *tuiDiagnostics {
}
d.logger = slog.New(slog.NewTextHandler(d.writer, &slog.HandlerOptions{Level: slog.LevelInfo}))
slog.SetDefault(d.logger)
d.markProgress()
d.lastHeartbeat = d.now()
d.lastHeartbeatSource = "diagnostics_started"
d.Milestone("diagnostics_started")
return d
}
// Milestone records a startup/runtime phase and flushes the log immediately so a
// subsequent hang still leaves a non-zero diagnostic file.
// subsequent hang still leaves a non-zero diagnostic file. Milestones do not
// count as active event-loop heartbeats.
func (d *tuiDiagnostics) Milestone(name string) {
if d == nil {
return
}
d.markProgress()
msg := fmt.Sprintf("milestone=%s t=%s", strings.TrimSpace(name), time.Now().UTC().Format(time.RFC3339Nano))
msg := fmt.Sprintf("milestone=%s t=%s", strings.TrimSpace(name), d.now().UTC().Format(time.RFC3339Nano))
_, _ = fmt.Fprintln(d.Writer(), msg)
d.Sync()
}
@@ -84,14 +159,6 @@ func (d *tuiDiagnostics) Sync() {
_ = d.file.Sync()
}
// markProgress records that the TUI event loop is alive.
func (d *tuiDiagnostics) markProgress() {
if d == nil {
return
}
d.lastProgress.Store(time.Now().UnixNano())
}
// Path returns the diagnostic log path (empty when falling back to Discard).
func (d *tuiDiagnostics) Path() string {
if d == nil {
@@ -107,46 +174,329 @@ func (d *tuiDiagnostics) Writer() io.Writer {
return d.writer
}
// StartWatchdog arms a 1s heartbeat. If the TUI event loop makes no progress for
// 10s, it dumps all goroutines, syncs the log, and kills the Bubble Tea program
// so the terminal is restored instead of remaining frozen (#7435).
// NoteBooted transitions booting → idle after the first valid chatTUI.Update.
// Subsequent calls are no-ops until the watchdog is closed.
func (d *tuiDiagnostics) NoteBooted() {
if d == nil {
return
}
d.mu.Lock()
defer d.mu.Unlock()
if d.phase != watchdogBooting {
return
}
d.phase = watchdogIdle
d.lastHeartbeat = d.now()
d.lastHeartbeatSource = "booted"
d.logfLocked("watchdog_state phase=%s gen=%d source=booted", d.phase, d.generation)
}
// NoteRunning transitions idle/booting → running for a new Turn/shell generation.
// cancel must be non-blocking (context cancel / queue a cancel); it is invoked
// under the watchdog lifecycle lock after checking the active generation.
func (d *tuiDiagnostics) NoteRunning(cancel func()) {
if d == nil {
return
}
d.mu.Lock()
defer d.mu.Unlock()
if d.phase == watchdogClosed {
return
}
d.generation++
d.phase = watchdogRunning
d.lastHeartbeat = d.now()
d.lastHeartbeatSource = "enter_running"
d.cancelFn = cancel
d.cancelDeadline = time.Time{}
d.logfLocked("watchdog_state phase=%s gen=%d source=enter_running", d.phase, d.generation)
}
// NoteIdle transitions running → idle after TurnDone, shell completion, or
// synchronous cancel. Clears the active cancel hook and cancels any pending
// hard-kill for the previous generation.
func (d *tuiDiagnostics) NoteIdle() {
if d == nil {
return
}
d.mu.Lock()
defer d.mu.Unlock()
if d.phase == watchdogClosed || d.phase == watchdogIdle {
return
}
prev := d.phase
d.phase = watchdogIdle
d.cancelFn = nil
d.cancelDeadline = time.Time{}
d.lastHeartbeat = d.now()
d.lastHeartbeatSource = "enter_idle"
d.logfLocked("watchdog_state phase=%s gen=%d prev=%s source=enter_idle", d.phase, d.generation, prev)
}
// NoteActiveHeartbeat records event-loop progress that proves a running turn
// is still being serviced. Only elapsedTick, agent/shell/controller work
// events, and explicitly marked work progress should call this. Keyboard,
// mouse, and focus activity must not refresh the active heartbeat.
func (d *tuiDiagnostics) NoteActiveHeartbeat(source string) {
if d == nil {
return
}
d.mu.Lock()
defer d.mu.Unlock()
if d.phase != watchdogRunning {
return
}
d.lastHeartbeat = d.now()
if source == "" {
source = "active"
}
d.lastHeartbeatSource = source
// Fresh heartbeat aborts the in-flight grace window for this gen so a later
// stall may re-enter dump/grace/hard-kill. Cancel stays sticky via
// cancelIssuedGeneration (at most one Cancel per Turn).
if d.escalatedGeneration == d.generation && d.generation != 0 && !d.cancelDeadline.IsZero() {
d.cancelDeadline = time.Time{}
d.escalatedGeneration = 0
d.logfLocked("watchdog_escalation_aborted phase=%s gen=%d source=%s reason=heartbeat cancel_issued=%v",
d.phase, d.generation, d.lastHeartbeatSource, d.cancelIssuedGeneration == d.generation)
}
}
// SetStatusProvider installs an optional Controller RuntimeStatus snapshot for
// structured stall dumps. Safe to call at any time.
func (d *tuiDiagnostics) SetStatusProvider(fn func() string) {
if d == nil {
return
}
d.mu.Lock()
d.statusFn = fn
d.mu.Unlock()
}
// StartWatchdog arms the lifecycle watchdog. p may be nil in tests that inject killFn.
// The booting timer starts here (not at diagnostics construction) so slow config /
// controller setup before terminal takeover cannot trip a false boot stall.
func (d *tuiDiagnostics) StartWatchdog(p *tea.Program) {
if d == nil || p == nil {
if d == nil {
return
}
d.watchOnce.Do(func() {
d.markProgress()
if d.killFn == nil && p != nil {
d.killFn = p.Kill
}
d.mu.Lock()
if d.phase == watchdogBooting {
d.lastHeartbeat = d.now()
d.lastHeartbeatSource = "watchdog_armed"
}
d.mu.Unlock()
d.watchWG.Add(1)
go func() {
defer d.watchWG.Done()
d.watch(p)
d.watch()
}()
})
}
func (d *tuiDiagnostics) watch(p *tea.Program) {
ticker := time.NewTicker(tuiWatchdogInterval)
func (d *tuiDiagnostics) watch() {
newTicker := d.newTicker
if newTicker == nil {
newTicker = func(interval time.Duration) watchdogTicker {
return realTicker{time.NewTicker(interval)}
}
}
ticker := newTicker(tuiWatchdogInterval)
defer ticker.Stop()
for {
select {
case <-d.stopWatch:
return
case now := <-ticker.C:
last := time.Unix(0, d.lastProgress.Load())
age := now.Sub(last)
_, _ = fmt.Fprintf(d.Writer(), "heartbeat t=%s last_progress_age=%s\n",
now.UTC().Format(time.RFC3339Nano), age.Round(time.Millisecond))
d.Sync()
if age < tuiWatchdogStall || d.killed.Load() {
continue
}
d.killed.Store(true)
d.dumpGoroutines("watchdog_stall")
d.Sync()
// Kill restores the terminal; Quit alone can hang if Update is blocked.
p.Kill()
case now := <-ticker.C():
d.onTick(now)
}
}
}
// onTick is the pure escalation step. Tests drive it directly with a fake clock
// so no real sleeps are required.
func (d *tuiDiagnostics) onTick(now time.Time) {
if d == nil {
return
}
d.mu.Lock()
phase := d.phase
if phase == watchdogClosed {
d.mu.Unlock()
return
}
gen := d.generation
last := d.lastHeartbeat
if last.IsZero() {
last = now
}
age := now.Sub(last)
source := d.lastHeartbeatSource
cancelDeadline := d.cancelDeadline
escalatedGen := d.escalatedGeneration
hardKillIssued := d.hardKillIssued
hardKilledGen := d.hardKilledGen
statusFn := d.statusFn
cancelFn := d.cancelFn
d.logfLocked("heartbeat t=%s phase=%s gen=%d last_progress_age=%s last_source=%s cancel_requested=%v hard_kill_phase=%v",
now.UTC().Format(time.RFC3339Nano),
phase,
gen,
age.Round(time.Millisecond),
source,
escalatedGen == gen && gen != 0 && !cancelDeadline.IsZero(),
hardKillIssued && hardKilledGen == gen,
)
d.Sync()
// Idle: never dump/cancel/kill. Heartbeat log above is the only activity.
if phase == watchdogIdle {
d.mu.Unlock()
return
}
// Grace window follow-up: same generation still running after cancel.
// Wait until the deadline; only then hard-kill if there is still no heartbeat.
if phase == watchdogRunning && escalatedGen == gen && gen != 0 && !cancelDeadline.IsZero() {
if now.Before(cancelDeadline) {
d.mu.Unlock()
return
}
// Deadline reached. Re-check heartbeat under the same lock before kill.
if now.Sub(d.lastHeartbeat) >= tuiWatchdogStall && !(d.hardKillIssued && d.hardKilledGen == gen) {
d.hardKillIssued = true
d.hardKilledGen = gen
d.cancelDeadline = time.Time{}
diag := d.formatDiagLocked(now, "watchdog_hard_kill")
d.mu.Unlock()
d.killCalls.Add(1)
d.doDump("watchdog_hard_kill")
d.writeLine(diag)
d.Sync()
d.doKill()
return
}
// Heartbeat recovered (or phase raced) before hard-kill — clear grace.
d.cancelDeadline = time.Time{}
d.mu.Unlock()
return
}
if age < tuiWatchdogStall {
d.mu.Unlock()
return
}
// Already hard-killed this generation — stay quiet.
if hardKillIssued && hardKilledGen == gen {
d.mu.Unlock()
return
}
// Already escalated (dump+cancel) for this generation; waiting on grace.
// gen==0 is booting (no generation yet); use a dedicated escalated flag path.
if phase == watchdogRunning && escalatedGen == gen && gen != 0 {
d.mu.Unlock()
return
}
if phase == watchdogBooting && hardKillIssued {
d.mu.Unlock()
return
}
// First escalation for this stall (or re-entry after a grace abort).
diag := d.formatDiagLocked(now, "watchdog_stall")
if phase == watchdogRunning {
d.escalatedGeneration = gen
d.cancelDeadline = now.Add(tuiWatchdogCancelGrace)
// Cancel at most once per generation; re-stalls after recovery still
// get dump + grace + hard-kill, but not a second Cancel().
issueCancel := cancelFn != nil && d.cancelIssuedGeneration != gen
if issueCancel {
d.cancelIssuedGeneration = gen
}
// Snapshot cancel under lock; invoke after the dump outside this critical
// section, with a second generation check immediately before the call.
d.mu.Unlock()
d.dumpCalls.Add(1)
d.doDump("watchdog_stall")
d.writeLine(diag)
if statusFn != nil {
if st := statusFn(); st != "" {
d.writeLine("controller_status " + st)
}
}
d.Sync()
if issueCancel {
d.cancelCurrentGeneration(gen, cancelFn)
}
return
}
// Booting stall: dump + hard-kill (no controller turn to cancel).
d.hardKillIssued = true
d.hardKilledGen = gen
d.mu.Unlock()
d.dumpCalls.Add(1)
d.killCalls.Add(1)
d.doDump("watchdog_boot_stall")
d.writeLine(diag)
d.Sync()
d.doKill()
}
func (d *tuiDiagnostics) cancelCurrentGeneration(gen uint64, cancelFn func()) {
if d == nil || cancelFn == nil {
return
}
d.mu.Lock()
defer d.mu.Unlock()
if d.phase != watchdogRunning || d.generation != gen || d.cancelIssuedGeneration != gen {
return
}
d.cancelCalls.Add(1)
cancelFn()
}
func (d *tuiDiagnostics) formatDiagLocked(now time.Time, reason string) string {
age := now.Sub(d.lastHeartbeat)
if d.lastHeartbeat.IsZero() {
age = 0
}
return fmt.Sprintf(
"watchdog_diag reason=%s phase=%s gen=%d last_heartbeat_age=%s last_event=%s cancel_requested=%v hard_kill_phase=%v",
reason,
d.phase,
d.generation,
age.Round(time.Millisecond),
d.lastHeartbeatSource,
d.escalatedGeneration == d.generation && d.generation != 0 && !d.cancelDeadline.IsZero(),
d.hardKillIssued && d.hardKilledGen == d.generation,
)
}
func (d *tuiDiagnostics) doDump(reason string) {
if d == nil {
return
}
if d.dumpFn != nil {
d.dumpFn(reason)
return
}
d.dumpGoroutines(reason)
}
func (d *tuiDiagnostics) doKill() {
if d == nil {
return
}
if d.killFn != nil {
d.killFn()
}
}
@@ -166,11 +516,54 @@ func (d *tuiDiagnostics) dumpGoroutines(reason string) {
_, _ = fmt.Fprintf(d.Writer(), "goroutine_dump reason=%s bytes=%d\n%s\n", reason, len(buf), buf)
}
func (d *tuiDiagnostics) writeLine(line string) {
if d == nil {
return
}
_, _ = fmt.Fprintln(d.Writer(), line)
}
func (d *tuiDiagnostics) now() time.Time {
if d != nil && d.nowFn != nil {
return d.nowFn()
}
return time.Now()
}
func (d *tuiDiagnostics) logfLocked(format string, args ...any) {
if d.logFn != nil {
d.logFn(format, args...)
return
}
_, _ = fmt.Fprintf(d.Writer(), format+"\n", args...)
}
// phaseForTest returns the current phase under lock (test helper).
func (d *tuiDiagnostics) phaseForTest() tuiWatchdogPhase {
d.mu.Lock()
defer d.mu.Unlock()
return d.phase
}
// generationForTest returns the current generation under lock (test helper).
func (d *tuiDiagnostics) generationForTest() uint64 {
d.mu.Lock()
defer d.mu.Unlock()
return d.generation
}
func (d *tuiDiagnostics) Close() {
if d == nil {
return
}
d.close.Do(func() {
d.mu.Lock()
d.phase = watchdogClosed
d.cancelFn = nil
d.cancelDeadline = time.Time{}
d.logfLocked("watchdog_state phase=%s gen=%d source=closed", d.phase, d.generation)
d.mu.Unlock()
select {
case <-d.stopWatch:
default:
+325
View File
@@ -8,7 +8,9 @@ import (
"os"
"path/filepath"
"strings"
"sync/atomic"
"testing"
"time"
"reasonix/internal/control"
"reasonix/internal/event"
@@ -167,3 +169,326 @@ func TestTUIDiagnosticsMilestoneFlushesNonEmptyLog(t *testing.T) {
}
}
}
// fakeWatchClock drives the stall watchdog without real sleeps.
type fakeWatchClock struct {
now time.Time
}
func newWatchdogForTest(t *testing.T, clock *fakeWatchClock) *tuiDiagnostics {
t.Helper()
d := &tuiDiagnostics{
writer: io.Discard,
stopWatch: make(chan struct{}),
phase: watchdogBooting,
nowFn: func() time.Time { return clock.now },
dumpFn: func(string) {},
killFn: func() {},
logFn: func(string, ...any) {},
}
d.lastHeartbeat = clock.now
d.lastHeartbeatSource = "test_start"
t.Cleanup(d.Close)
return d
}
func TestWatchdogIdleNeverEscalates(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
if d.phaseForTest() != watchdogIdle {
t.Fatalf("phase = %s, want idle", d.phaseForTest())
}
// Idle for well over the stall threshold.
for i := 0; i < 30; i++ {
clock.now = clock.now.Add(time.Second)
d.onTick(clock.now)
}
if got := d.dumpCalls.Load(); got != 0 {
t.Fatalf("idle dumpCalls = %d, want 0", got)
}
if got := d.cancelCalls.Load(); got != 0 {
t.Fatalf("idle cancelCalls = %d, want 0", got)
}
if got := d.killCalls.Load(); got != 0 {
t.Fatalf("idle killCalls = %d, want 0", got)
}
}
func TestWatchdogBootStallDumpsAndKills(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
// Stay in booting; no NoteBooted.
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now)
if d.dumpCalls.Load() != 1 {
t.Fatalf("boot dumpCalls = %d, want 1", d.dumpCalls.Load())
}
if d.killCalls.Load() != 1 {
t.Fatalf("boot killCalls = %d, want 1", d.killCalls.Load())
}
if d.cancelCalls.Load() != 0 {
t.Fatalf("boot cancelCalls = %d, want 0 (no controller)", d.cancelCalls.Load())
}
// Repeat ticks must not re-kill.
clock.now = clock.now.Add(time.Second)
d.onTick(clock.now)
if d.killCalls.Load() != 1 {
t.Fatalf("boot re-kill = %d, want 1", d.killCalls.Load())
}
}
func TestWatchdogRunningElapsedHeartbeatPreventsKill(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
d.NoteRunning(func() {})
// Simulate a long turn with a heartbeat every second.
for i := 0; i < 60; i++ {
clock.now = clock.now.Add(time.Second)
d.NoteActiveHeartbeat("elapsed_tick")
d.onTick(clock.now)
}
if d.dumpCalls.Load() != 0 || d.cancelCalls.Load() != 0 || d.killCalls.Load() != 0 {
t.Fatalf("healthy running escalated: dump=%d cancel=%d kill=%d",
d.dumpCalls.Load(), d.cancelCalls.Load(), d.killCalls.Load())
}
}
func TestWatchdogRunningStallEscalatesDumpCancelThenKill(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
cancelCh := make(chan struct{}, 1)
d.NoteRunning(func() {
select {
case cancelCh <- struct{}{}:
default:
}
})
// Stall for 10s with no heartbeat.
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now)
if d.dumpCalls.Load() != 1 {
t.Fatalf("stall dumpCalls = %d, want 1", d.dumpCalls.Load())
}
// Cancel is invoked from a goroutine; wait briefly via channel without sleep-loops
// that depend on wall clock beyond a generous select timeout for scheduling.
select {
case <-cancelCh:
case <-time.After(2 * time.Second):
t.Fatal("cancel was not invoked after stall dump")
}
if d.cancelCalls.Load() != 1 {
t.Fatalf("cancelCalls = %d, want 1", d.cancelCalls.Load())
}
if d.killCalls.Load() != 0 {
t.Fatalf("killCalls = %d before grace, want 0", d.killCalls.Load())
}
// Still within grace window — no kill.
clock.now = clock.now.Add(tuiWatchdogCancelGrace - 100*time.Millisecond)
d.onTick(clock.now)
if d.killCalls.Load() != 0 {
t.Fatalf("killCalls during grace = %d, want 0", d.killCalls.Load())
}
// Grace expires, still no heartbeat → hard-kill once.
clock.now = clock.now.Add(200 * time.Millisecond)
d.onTick(clock.now)
if d.killCalls.Load() != 1 {
t.Fatalf("killCalls after grace = %d, want 1", d.killCalls.Load())
}
// Repeat tick does not re-kill.
clock.now = clock.now.Add(time.Second)
d.onTick(clock.now)
if d.killCalls.Load() != 1 || d.cancelCalls.Load() != 1 {
t.Fatalf("duplicate escalation: cancel=%d kill=%d", d.cancelCalls.Load(), d.killCalls.Load())
}
}
func TestWatchdogGraceHeartbeatAbortsKill(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
d.NoteRunning(func() {})
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now)
if d.dumpCalls.Load() != 1 {
t.Fatalf("dumpCalls = %d, want 1", d.dumpCalls.Load())
}
// Heartbeat during grace aborts hard-kill.
clock.now = clock.now.Add(time.Second)
d.NoteActiveHeartbeat("elapsed_tick")
clock.now = clock.now.Add(tuiWatchdogCancelGrace)
d.onTick(clock.now)
if d.killCalls.Load() != 0 {
t.Fatalf("killCalls after heartbeat = %d, want 0", d.killCalls.Load())
}
}
// TestWatchdogCancelOncePerGeneration pins "one Cancel per Turn": after a grace
// abort via heartbeat, a later stall on the same generation may dump/kill but
// must not invoke Cancel() again.
func TestWatchdogCancelOncePerGeneration(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
// cancelCalls is incremented before the hook body, so assertions below do not
// need to wait for a separate scheduler turn.
d.NoteRunning(func() {})
// First stall → cancel once.
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now)
if d.cancelCalls.Load() != 1 {
t.Fatalf("first cancelCalls = %d, want 1", d.cancelCalls.Load())
}
// Heartbeat aborts grace (cancelIssued stays sticky).
clock.now = clock.now.Add(time.Second)
d.NoteActiveHeartbeat("elapsed_tick")
// Second stall on the same generation.
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now)
if d.cancelCalls.Load() != 1 {
t.Fatalf("second stall re-canceled: cancelCalls=%d, want 1", d.cancelCalls.Load())
}
if d.dumpCalls.Load() != 2 {
t.Fatalf("second stall dumpCalls = %d, want 2 (re-dump allowed)", d.dumpCalls.Load())
}
// Grace after second escalation still hard-kills once.
clock.now = clock.now.Add(tuiWatchdogCancelGrace)
d.onTick(clock.now)
if d.killCalls.Load() != 1 {
t.Fatalf("killCalls after second grace = %d, want 1", d.killCalls.Load())
}
}
func TestWatchdogStaleCancelCannotAffectNewGeneration(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
var oldCancelCalls atomic.Int32
d.NoteRunning(func() { oldCancelCalls.Add(1) })
oldGeneration := d.generationForTest()
d.NoteIdle()
d.NoteRunning(func() {})
d.cancelCurrentGeneration(oldGeneration, func() { oldCancelCalls.Add(1) })
if got := oldCancelCalls.Load(); got != 0 {
t.Fatalf("stale cancellation invoked old callback %d times, want 0", got)
}
}
func TestWatchdogTurnDoneDuringGraceAbortsKill(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
d.NoteRunning(func() {})
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now)
// TurnDone → idle before grace expires.
d.NoteIdle()
if d.phaseForTest() != watchdogIdle {
t.Fatalf("phase = %s, want idle", d.phaseForTest())
}
clock.now = clock.now.Add(tuiWatchdogCancelGrace + time.Second)
d.onTick(clock.now)
if d.killCalls.Load() != 0 {
t.Fatalf("kill after TurnDone = %d, want 0", d.killCalls.Load())
}
}
func TestWatchdogClosedStopsAllActions(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
d.NoteRunning(func() {})
d.Close()
if d.phaseForTest() != watchdogClosed {
t.Fatalf("phase = %s, want closed", d.phaseForTest())
}
clock.now = clock.now.Add(tuiWatchdogStall + time.Second)
d.onTick(clock.now)
if d.dumpCalls.Load() != 0 || d.cancelCalls.Load() != 0 || d.killCalls.Load() != 0 {
t.Fatalf("closed watchdog still acted: dump=%d cancel=%d kill=%d",
d.dumpCalls.Load(), d.cancelCalls.Load(), d.killCalls.Load())
}
}
func TestWatchdogStaleGenerationCannotKillNewTurn(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
d.NoteRunning(func() {}) // gen 1
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now) // escalate gen 1
if d.cancelCalls.Load() != 1 {
t.Fatalf("cancelCalls = %d, want 1", d.cancelCalls.Load())
}
// New turn starts (generation bumps); old grace must not kill it.
d.NoteIdle()
d.NoteRunning(func() {}) // gen 2
clock.now = clock.now.Add(tuiWatchdogCancelGrace + time.Second)
// Heartbeat keeps gen 2 healthy.
d.NoteActiveHeartbeat("elapsed_tick")
d.onTick(clock.now)
if d.killCalls.Load() != 0 {
t.Fatalf("stale kill hit new generation: killCalls=%d", d.killCalls.Load())
}
if d.generationForTest() != 2 {
t.Fatalf("generation = %d, want 2", d.generationForTest())
}
}
func TestWatchdogUserActivityDoesNotCountAsActiveHeartbeat(t *testing.T) {
// NoteBooted / NoteIdle paths are the only non-active transitions; keyboard
// never calls NoteActiveHeartbeat. Prove that without it, a running stall
// still escalates even if "time passes" via booted-style idle marks.
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
d.NoteBooted()
d.NoteRunning(func() {})
// Simulate only user-facing updates that do not call NoteActiveHeartbeat.
clock.now = clock.now.Add(tuiWatchdogStall)
d.onTick(clock.now)
if d.dumpCalls.Load() != 1 {
t.Fatalf("stall without active heartbeat dumpCalls = %d, want 1", d.dumpCalls.Load())
}
}
func TestChatTUIWatchdogHelpersAreNilSafe(t *testing.T) {
var m chatTUI
m.noteWatchdogRunning()
m.noteWatchdogIdle()
m.noteWatchdogHeartbeat("elapsed_tick")
}
func TestChatTUIWatchdogLifecycleHelpers(t *testing.T) {
clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)}
d := newWatchdogForTest(t, clock)
m := chatTUI{diagnostics: d}
// Boot confirmation (first Update path).
m.diagnostics.NoteBooted()
if d.phaseForTest() != watchdogIdle {
t.Fatalf("after NoteBooted phase = %s, want idle", d.phaseForTest())
}
// Shell / controller turn entry.
m.noteWatchdogRunning()
if d.phaseForTest() != watchdogRunning {
t.Fatalf("phase = %s, want running", d.phaseForTest())
}
m.noteWatchdogHeartbeat("elapsed_tick")
// TurnDone / shell completion.
m.noteWatchdogIdle()
if d.phaseForTest() != watchdogIdle {
t.Fatalf("phase after idle = %s, want idle", d.phaseForTest())
}
}
+1
View File
@@ -774,6 +774,7 @@ func sendChunk(ctx context.Context, out chan<- provider.Chunk, chunk provider.Ch
return true
default:
}
notifySendChunkEnterBlocking()
select {
case out <- chunk:
return true
+244
View File
@@ -0,0 +1,244 @@
package responses
import (
"context"
"crypto/tls"
"io"
"net/http"
"net/http/httptest"
"strings"
"sync"
"sync/atomic"
"testing"
"time"
"reasonix/internal/provider"
)
func flush(w http.ResponseWriter) {
if f, ok := w.(http.Flusher); ok {
f.Flush()
}
}
// startHTTP2TLSServer returns an httptest TLS server with HTTP/2 enabled and a
// client that trusts its certificate. The handler must keep the connection
// open long enough for the client to negotiate h2 (verified via sawHTTP2).
func startHTTP2TLSServer(t *testing.T, handler http.HandlerFunc) (*httptest.Server, *http.Client, *atomic.Bool) {
t.Helper()
var sawHTTP2 atomic.Bool
srv := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
if r.ProtoMajor == 2 {
sawHTTP2.Store(true)
}
handler(w, r)
}))
srv.EnableHTTP2 = true
srv.StartTLS()
t.Cleanup(srv.Close)
client := srv.Client()
// Force HTTP/2 negotiation on the TLS transport (httptest enables h2 on the
// server; the client must also advertise it).
if tr, ok := client.Transport.(*http.Transport); ok {
tr.TLSClientConfig = &tls.Config{InsecureSkipVerify: true} //nolint:gosec // test-only self-signed cert
if err := http2ConfigureTransport(tr); err != nil {
t.Fatalf("configure HTTP/2 transport: %v", err)
}
}
return srv, client, &sawHTTP2
}
// http2ConfigureTransport enables HTTP/2 on tr without importing golang.org/x/net/http2
// when the stdlib transport already supports it via ForceAttemptHTTP2.
func http2ConfigureTransport(tr *http.Transport) error {
tr.ForceAttemptHTTP2 = true
return nil
}
// TestStreamStallTimesOutHTTP2 covers a half-open HTTP/2 body (headers received,
// then silence without RST). The idle watchdog must close the body and surface
// an idle_timeout StreamInterrupt so the Controller can emit a single TurnDone
// (#7811, HTTP/2 path).
func TestStreamStallTimesOutHTTP2(t *testing.T) {
release := make(chan struct{})
srv, httpClient, sawHTTP2 := startHTTP2TLSServer(t, func(w http.ResponseWriter, _ *http.Request) {
w.Header().Set("Content-Type", "text/event-stream")
w.WriteHeader(http.StatusOK)
flush(w)
// One comment keeps the connection "alive" once, then stall forever.
_, _ = io.WriteString(w, ": keep-alive\n\n")
flush(w)
<-release
})
defer close(release)
p := New(Config{Name: "responses", BaseURL: srv.URL, Model: "model", APIKey: "k"}).(*client)
p.http = httpClient
p.idleTimeout = 150 * time.Millisecond
ch, err := p.Stream(context.Background(), provider.Request{
Messages: []provider.Message{{Role: provider.RoleUser, Content: "hi"}},
})
if err != nil {
t.Fatalf("Stream: %v", err)
}
deadline := time.After(5 * time.Second)
for {
select {
case chunk, ok := <-ch:
if !ok {
t.Fatal("stream closed without surfacing a stall error")
}
if chunk.Type == provider.ChunkError {
if !sawHTTP2.Load() {
t.Fatal("stall path did not run over HTTP/2 (ProtoMajor != 2)")
}
if !strings.Contains(chunk.Err.Error(), "idle timeout") {
t.Fatalf("error = %v, want idle timeout", chunk.Err)
}
if provider.StreamInterruptReason(chunk.Err) != provider.StreamInterruptIdleTimeout {
t.Fatalf("reason = %q, want %q", provider.StreamInterruptReason(chunk.Err), provider.StreamInterruptIdleTimeout)
}
return
}
case <-deadline:
t.Fatal("stream did not time out on a stalled HTTP/2 body")
}
}
}
// TestMissingTerminalEventSurfacesPrematureEOF ensures connection close before
// response.completed/failed/incomplete is not treated as a successful turn.
func TestMissingTerminalEventSurfacesPrematureEOF(t *testing.T) {
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.Header().Set("Content-Type", "text/event-stream")
w.WriteHeader(http.StatusOK)
// Partial text delta, then close the body without a terminal event.
_, _ = io.WriteString(w, "data: {\"type\":\"response.output_text.delta\",\"delta\":\"hi\"}\n\n")
flush(w)
}))
defer srv.Close()
p := New(Config{Name: "responses", BaseURL: srv.URL, Model: "model", APIKey: "k"}).(*client)
p.idleTimeout = time.Second
ch, err := p.Stream(context.Background(), provider.Request{
Messages: []provider.Message{{Role: provider.RoleUser, Content: "hi"}},
})
if err != nil {
t.Fatalf("Stream: %v", err)
}
var sawError bool
for chunk := range ch {
if chunk.Type == provider.ChunkError {
sawError = true
if provider.StreamInterruptReason(chunk.Err) != provider.StreamInterruptPrematureEOF {
t.Fatalf("reason = %q, want %q (err=%v)",
provider.StreamInterruptReason(chunk.Err), provider.StreamInterruptPrematureEOF, chunk.Err)
}
}
}
if !sawError {
t.Fatal("expected premature-EOF error when terminal event is missing")
}
}
// TestSendChunkUnblocksOnContextCancel covers the path where the consumer stops
// reading and the stream must not hang forever inside sendChunk. Timing uses a
// blocking-hook channel — no fixed sleep.
func TestSendChunkUnblocksOnContextCancel(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background())
// Unbuffered channel so sendChunk blocks on the second select branch.
out := make(chan provider.Chunk)
done := make(chan struct{})
enteredBlocking := make(chan struct{})
prev := sendChunkEnterBlocking
sendChunkEnterBlocking = func() { close(enteredBlocking) }
t.Cleanup(func() { sendChunkEnterBlocking = prev })
go func() {
ok := sendChunk(ctx, out, provider.Chunk{Type: provider.ChunkText, Text: "blocked"})
if ok {
t.Error("sendChunk returned true after cancel")
}
close(done)
}()
select {
case <-enteredBlocking:
case <-time.After(2 * time.Second):
t.Fatal("sendChunk never entered the blocking select")
}
cancel()
select {
case <-done:
case <-time.After(2 * time.Second):
t.Fatal("sendChunk remained blocked after context cancellation")
}
}
// TestReadStreamContextCancelClosesBody ensures Cancel mid-stream unblocks the
// scanner and closes the response body without leaking the goroutine. Timing is
// driven by the first delivered chunk — no fixed sleep.
func TestReadStreamContextCancelClosesBody(t *testing.T) {
var bodyClosed sync.WaitGroup
bodyClosed.Add(1)
pr, pw := io.Pipe()
resp := &http.Response{Body: &closeNotifyBody{ReadCloser: pr, onClose: bodyClosed.Done}}
ctx, cancel := context.WithCancel(context.Background())
out := make(chan provider.Chunk, 4)
done := make(chan struct{})
go func() {
(&client{idleTimeout: time.Minute}).readStream(ctx, resp, out, nil)
close(done)
}()
// Write a non-terminal event and wait until it is delivered — proves the
// scanner is live before we cancel.
_, _ = io.WriteString(pw, "data: {\"type\":\"response.output_text.delta\",\"delta\":\"x\"}\n\n")
select {
case chunk := <-out:
if chunk.Type != provider.ChunkText || chunk.Text != "x" {
t.Fatalf("first chunk = %+v, want text delta x", chunk)
}
case <-time.After(2 * time.Second):
t.Fatal("timed out waiting for first stream chunk before cancel")
}
cancel()
select {
case <-done:
case <-time.After(2 * time.Second):
t.Fatal("readStream did not exit after context cancel")
}
closed := make(chan struct{})
go func() {
bodyClosed.Wait()
close(closed)
}()
select {
case <-closed:
case <-time.After(2 * time.Second):
t.Fatal("response body was not closed after context cancel")
}
_ = pw.Close()
}
type closeNotifyBody struct {
io.ReadCloser
onClose func()
once sync.Once
}
func (b *closeNotifyBody) Close() error {
err := b.ReadCloser.Close()
b.once.Do(b.onClose)
return err
}
@@ -0,0 +1,9 @@
package responses
var sendChunkEnterBlocking func()
func notifySendChunkEnterBlocking() {
if sendChunkEnterBlocking != nil {
sendChunkEnterBlocking()
}
}
+5 -8
View File
@@ -2,8 +2,8 @@
"limits": {
"banner": 312,
"commented-code": 0,
"essay": 4102,
"file-size": 73664,
"essay": 4099,
"file-size": 73680,
"layering": 1,
"marker": 0,
"narrative": 66,
@@ -667,7 +667,7 @@
},
"internal/cli/chat_tui.go": {
"essay": 111,
"file-size": 4576
"file-size": 4590
},
"internal/cli/chat_tui_paste.go": {
"essay": 9
@@ -682,7 +682,7 @@
},
"internal/cli/cli.go": {
"essay": 60,
"file-size": 2007
"file-size": 2008
},
"internal/cli/cli_test.go": {
"essay": 9,
@@ -804,9 +804,6 @@
"essay": 1,
"file-size": 2
},
"internal/cli/tui_diagnostics.go": {
"essay": 3
},
"internal/cli/upgrade.go": {
"essay": 2
},
@@ -1420,7 +1417,7 @@
},
"internal/provider/responses/responses.go": {
"essay": 26,
"file-size": 80
"file-size": 81
},
"internal/provider/responses/responses_test.go": {
"essay": 6,