| 1 | package cli |
| 2 | |
| 3 | import ( |
| 4 | "bytes" |
| 5 | "fmt" |
| 6 | "io" |
| 7 | "log/slog" |
| 8 | "os" |
| 9 | "path/filepath" |
| 10 | "strings" |
| 11 | "sync/atomic" |
| 12 | "testing" |
| 13 | "time" |
| 14 | |
| 15 | "reasonix/internal/control" |
| 16 | "reasonix/internal/event" |
| 17 | "reasonix/internal/i18n" |
| 18 | ) |
| 19 | |
| 20 | func TestTUIDiagnosticsKeepProcessAndPluginLogsOffTerminal(t *testing.T) { |
| 21 | var terminal bytes.Buffer |
| 22 | beforeTest := slog.Default() |
| 23 | terminalLogger := slog.New(slog.NewTextHandler(&terminal, nil)) |
| 24 | slog.SetDefault(terminalLogger) |
| 25 | t.Cleanup(func() { slog.SetDefault(beforeTest) }) |
| 26 | |
| 27 | d := startTUIDiagnostics(t.TempDir()) |
| 28 | t.Cleanup(d.Close) |
| 29 | slog.Warn("controller: snapshot conflict", "path", "private-session.jsonl") |
| 30 | fmt.Fprintln(d.Writer(), "plugin diagnostic") |
| 31 | if got := terminal.String(); got != "" { |
| 32 | t.Fatalf("terminal received diagnostics while TUI owned it: %q", got) |
| 33 | } |
| 34 | |
| 35 | logPath := d.path |
| 36 | d.Close() |
| 37 | data, err := os.ReadFile(logPath) |
| 38 | if err != nil { |
| 39 | t.Fatalf("read TUI diagnostic log: %v", err) |
| 40 | } |
| 41 | got := string(data) |
| 42 | for _, want := range []string{"controller: snapshot conflict", "private-session.jsonl", "plugin diagnostic"} { |
| 43 | if !strings.Contains(got, want) { |
| 44 | t.Fatalf("diagnostic log = %q, want %q", got, want) |
| 45 | } |
| 46 | } |
| 47 | |
| 48 | slog.Warn("after TUI") |
| 49 | if got := terminal.String(); !strings.Contains(got, "after TUI") { |
| 50 | t.Fatalf("previous logger was not restored after TUI close: %q", got) |
| 51 | } |
| 52 | } |
| 53 | |
| 54 | func TestTUIDiagnosticsFallBackToDiscardWithoutLeakingToTerminal(t *testing.T) { |
| 55 | var terminal bytes.Buffer |
| 56 | beforeTest := slog.Default() |
| 57 | terminalLogger := slog.New(slog.NewTextHandler(&terminal, nil)) |
| 58 | slog.SetDefault(terminalLogger) |
| 59 | t.Cleanup(func() { slog.SetDefault(beforeTest) }) |
| 60 | |
| 61 | blockedHome := filepath.Join(t.TempDir(), "not-a-directory") |
| 62 | if err := os.WriteFile(blockedHome, []byte("file"), 0o600); err != nil { |
| 63 | t.Fatalf("seed blocked home: %v", err) |
| 64 | } |
| 65 | d := startTUIDiagnostics(blockedHome) |
| 66 | defer d.Close() |
| 67 | |
| 68 | slog.Warn("must stay off terminal") |
| 69 | fmt.Fprintln(d.Writer(), "plugin must stay off terminal") |
| 70 | if got := terminal.String(); got != "" { |
| 71 | t.Fatalf("fallback leaked diagnostics to terminal: %q", got) |
| 72 | } |
| 73 | if d.path != "" { |
| 74 | t.Fatalf("fallback diagnostic path = %q, want empty", d.path) |
| 75 | } |
| 76 | } |
| 77 | |
| 78 | func TestBoundedDiagnosticWriterStopsAtLimit(t *testing.T) { |
| 79 | var dst bytes.Buffer |
| 80 | w := &boundedDiagnosticWriter{dst: &dst, remaining: 8} |
| 81 | payload := strings.Repeat("x", 32) |
| 82 | n, err := io.WriteString(w, payload) |
| 83 | if err != nil || n != len(payload) { |
| 84 | t.Fatalf("Write = (%d, %v), want (%d, nil)", n, err, len(payload)) |
| 85 | } |
| 86 | if !strings.HasPrefix(dst.String(), strings.Repeat("x", 8)) { |
| 87 | t.Fatalf("bounded output = %q, want eight payload bytes first", dst.String()) |
| 88 | } |
| 89 | if !strings.Contains(dst.String(), "diagnostic log limit reached") { |
| 90 | t.Fatalf("bounded output = %q, want truncation marker", dst.String()) |
| 91 | } |
| 92 | before := dst.Len() |
| 93 | if _, err := io.WriteString(w, "more"); err != nil { |
| 94 | t.Fatalf("discard after cap: %v", err) |
| 95 | } |
| 96 | if dst.Len() != before { |
| 97 | t.Fatalf("writer grew after cap: before=%d after=%d", before, dst.Len()) |
| 98 | } |
| 99 | } |
| 100 | |
| 101 | func TestCLIProfileBuildOptionsPropagateInteractiveOwners(t *testing.T) { |
| 102 | var diagnostic bytes.Buffer |
| 103 | recovered := false |
| 104 | onRecovered := func(control.SessionRecoveryInfo) error { |
| 105 | recovered = true |
| 106 | return nil |
| 107 | } |
| 108 | opts := cliProfileBuildOptions("provider/model", 9, false, event.Discard, cliBuildOverrides{ |
| 109 | WorkspaceRoot: "/workspace", |
| 110 | HeadlessApprovalMode: control.ToolApprovalAuto, |
| 111 | Stderr: &diagnostic, |
| 112 | OnSessionRecovered: onRecovered, |
| 113 | }) |
| 114 | |
| 115 | if opts.Stderr != &diagnostic { |
| 116 | t.Fatalf("Stderr = %T, want caller-owned diagnostic writer", opts.Stderr) |
| 117 | } |
| 118 | if opts.OnSessionRecovered == nil { |
| 119 | t.Fatal("OnSessionRecovered was dropped from CLI build options") |
| 120 | } |
| 121 | if err := opts.OnSessionRecovered(control.SessionRecoveryInfo{RecoveryPath: "recovery.jsonl"}); err != nil { |
| 122 | t.Fatalf("OnSessionRecovered: %v", err) |
| 123 | } |
| 124 | if !recovered { |
| 125 | t.Fatal("propagated recovery callback was not invoked") |
| 126 | } |
| 127 | if opts.HeadlessApprovalMode != control.ToolApprovalAuto { |
| 128 | t.Fatalf("HeadlessApprovalMode = %q, want %q", opts.HeadlessApprovalMode, control.ToolApprovalAuto) |
| 129 | } |
| 130 | } |
| 131 | |
| 132 | func TestCLIProfileBuildOptionsDoNotResolveLocalePricing(t *testing.T) { |
| 133 | defer i18n.DetectLanguage("en") |
| 134 | for _, tt := range []struct { |
| 135 | language string |
| 136 | want string |
| 137 | }{ |
| 138 | {language: "en", want: ""}, |
| 139 | {language: "zh", want: ""}, |
| 140 | {language: "zh-TW", want: ""}, |
| 141 | } { |
| 142 | i18n.DetectLanguage(tt.language) |
| 143 | opts := cliProfileBuildOptions("provider/model", 0, false, event.Discard, cliBuildOverrides{}) |
| 144 | _ = opts |
| 145 | _ = tt.want |
| 146 | } |
| 147 | } |
| 148 | |
| 149 | func TestTUIDiagnosticsMilestoneFlushesNonEmptyLog(t *testing.T) { |
| 150 | home := t.TempDir() |
| 151 | d := startTUIDiagnostics(home) |
| 152 | t.Cleanup(d.Close) |
| 153 | d.Milestone("config_load_begin") |
| 154 | d.Milestone("controller_build_done") |
| 155 | if d.Path() == "" { |
| 156 | t.Fatal("expected diagnostic log path") |
| 157 | } |
| 158 | body, err := os.ReadFile(d.Path()) |
| 159 | if err != nil { |
| 160 | t.Fatal(err) |
| 161 | } |
| 162 | if len(body) == 0 { |
| 163 | t.Fatal("diagnostic log must not be empty after milestones") |
| 164 | } |
| 165 | for _, want := range []string{"diagnostics_started", "config_load_begin", "controller_build_done"} { |
| 166 | if !strings.Contains(string(body), want) { |
| 167 | t.Fatalf("log missing %q:\n%s", want, body) |
| 168 | } |
| 169 | } |
| 170 | } |
| 171 | |
| 172 | // fakeWatchClock drives the stall watchdog without real sleeps. |
| 173 | type fakeWatchClock struct { |
| 174 | now time.Time |
| 175 | } |
| 176 | |
| 177 | type fakeWatchTicker struct { |
| 178 | ticks chan time.Time |
| 179 | } |
| 180 | |
| 181 | func (t *fakeWatchTicker) C() <-chan time.Time { return t.ticks } |
| 182 | func (t *fakeWatchTicker) Stop() {} |
| 183 | |
| 184 | func newWatchdogForTest(t *testing.T, clock *fakeWatchClock) *tuiDiagnostics { |
| 185 | t.Helper() |
| 186 | d := &tuiDiagnostics{ |
| 187 | writer: io.Discard, |
| 188 | stopWatch: make(chan struct{}), |
| 189 | phase: watchdogBooting, |
| 190 | nowFn: func() time.Time { return clock.now }, |
| 191 | dumpFn: func(string) {}, |
| 192 | killFn: func() {}, |
| 193 | logFn: func(string, ...any) {}, |
| 194 | } |
| 195 | d.lastHeartbeat = clock.now |
| 196 | d.lastHeartbeatSource = "test_start" |
| 197 | t.Cleanup(d.Close) |
| 198 | return d |
| 199 | } |
| 200 | |
| 201 | func TestWatchdogIdleNeverEscalates(t *testing.T) { |
| 202 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 203 | d := newWatchdogForTest(t, clock) |
| 204 | d.NoteBooted() |
| 205 | if d.phaseForTest() != watchdogIdle { |
| 206 | t.Fatalf("phase = %s, want idle", d.phaseForTest()) |
| 207 | } |
| 208 | // Idle for well over the stall threshold. |
| 209 | for range 30 { |
| 210 | clock.now = clock.now.Add(time.Second) |
| 211 | d.onTick(clock.now) |
| 212 | } |
| 213 | if got := d.dumpCalls.Load(); got != 0 { |
| 214 | t.Fatalf("idle dumpCalls = %d, want 0", got) |
| 215 | } |
| 216 | if got := d.cancelCalls.Load(); got != 0 { |
| 217 | t.Fatalf("idle cancelCalls = %d, want 0", got) |
| 218 | } |
| 219 | if got := d.killCalls.Load(); got != 0 { |
| 220 | t.Fatalf("idle killCalls = %d, want 0", got) |
| 221 | } |
| 222 | } |
| 223 | |
| 224 | func TestWatchdogBootStallDumpsAndKills(t *testing.T) { |
| 225 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 226 | d := newWatchdogForTest(t, clock) |
| 227 | // Stay in booting; no NoteBooted. |
| 228 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 229 | d.onTick(clock.now) |
| 230 | if d.dumpCalls.Load() != 1 { |
| 231 | t.Fatalf("boot dumpCalls = %d, want 1", d.dumpCalls.Load()) |
| 232 | } |
| 233 | if d.killCalls.Load() != 1 { |
| 234 | t.Fatalf("boot killCalls = %d, want 1", d.killCalls.Load()) |
| 235 | } |
| 236 | if d.cancelCalls.Load() != 0 { |
| 237 | t.Fatalf("boot cancelCalls = %d, want 0 (no controller)", d.cancelCalls.Load()) |
| 238 | } |
| 239 | // Repeat ticks must not re-kill. |
| 240 | clock.now = clock.now.Add(time.Second) |
| 241 | d.onTick(clock.now) |
| 242 | if d.killCalls.Load() != 1 { |
| 243 | t.Fatalf("boot re-kill = %d, want 1", d.killCalls.Load()) |
| 244 | } |
| 245 | } |
| 246 | |
| 247 | func TestWatchdogRunningElapsedHeartbeatPreventsKill(t *testing.T) { |
| 248 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 249 | d := newWatchdogForTest(t, clock) |
| 250 | d.NoteBooted() |
| 251 | d.NoteRunning(func() {}) |
| 252 | // Simulate a long turn with a heartbeat every second. |
| 253 | for range 60 { |
| 254 | clock.now = clock.now.Add(time.Second) |
| 255 | d.NoteActiveHeartbeat("elapsed_tick") |
| 256 | d.onTick(clock.now) |
| 257 | } |
| 258 | if d.dumpCalls.Load() != 0 || d.cancelCalls.Load() != 0 || d.killCalls.Load() != 0 { |
| 259 | t.Fatalf("healthy running escalated: dump=%d cancel=%d kill=%d", |
| 260 | d.dumpCalls.Load(), d.cancelCalls.Load(), d.killCalls.Load()) |
| 261 | } |
| 262 | } |
| 263 | |
| 264 | func TestWatchdogRunningStallEscalatesDumpCancelThenKill(t *testing.T) { |
| 265 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 266 | d := newWatchdogForTest(t, clock) |
| 267 | d.NoteBooted() |
| 268 | cancelCh := make(chan struct{}, 1) |
| 269 | d.NoteRunning(func() { |
| 270 | select { |
| 271 | case cancelCh <- struct{}{}: |
| 272 | default: |
| 273 | } |
| 274 | }) |
| 275 | |
| 276 | // Stall for 10s with no heartbeat. |
| 277 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 278 | d.onTick(clock.now) |
| 279 | if d.dumpCalls.Load() != 1 { |
| 280 | t.Fatalf("stall dumpCalls = %d, want 1", d.dumpCalls.Load()) |
| 281 | } |
| 282 | // Cancel is invoked from a goroutine; wait briefly via channel without sleep-loops |
| 283 | // that depend on wall clock beyond a generous select timeout for scheduling. |
| 284 | select { |
| 285 | case <-cancelCh: |
| 286 | case <-time.After(2 * time.Second): |
| 287 | t.Fatal("cancel was not invoked after stall dump") |
| 288 | } |
| 289 | if d.cancelCalls.Load() != 1 { |
| 290 | t.Fatalf("cancelCalls = %d, want 1", d.cancelCalls.Load()) |
| 291 | } |
| 292 | if d.killCalls.Load() != 0 { |
| 293 | t.Fatalf("killCalls = %d before grace, want 0", d.killCalls.Load()) |
| 294 | } |
| 295 | |
| 296 | // Still within grace window — no kill. |
| 297 | clock.now = clock.now.Add(tuiWatchdogCancelGrace - 100*time.Millisecond) |
| 298 | d.onTick(clock.now) |
| 299 | if d.killCalls.Load() != 0 { |
| 300 | t.Fatalf("killCalls during grace = %d, want 0", d.killCalls.Load()) |
| 301 | } |
| 302 | |
| 303 | // Grace expires, still no heartbeat → hard-kill once. |
| 304 | clock.now = clock.now.Add(200 * time.Millisecond) |
| 305 | d.onTick(clock.now) |
| 306 | if d.killCalls.Load() != 1 { |
| 307 | t.Fatalf("killCalls after grace = %d, want 1", d.killCalls.Load()) |
| 308 | } |
| 309 | // Repeat tick does not re-kill. |
| 310 | clock.now = clock.now.Add(time.Second) |
| 311 | d.onTick(clock.now) |
| 312 | if d.killCalls.Load() != 1 || d.cancelCalls.Load() != 1 { |
| 313 | t.Fatalf("duplicate escalation: cancel=%d kill=%d", d.cancelCalls.Load(), d.killCalls.Load()) |
| 314 | } |
| 315 | } |
| 316 | |
| 317 | func TestWatchdogGraceHeartbeatAbortsKill(t *testing.T) { |
| 318 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 319 | d := newWatchdogForTest(t, clock) |
| 320 | d.NoteBooted() |
| 321 | d.NoteRunning(func() {}) |
| 322 | |
| 323 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 324 | d.onTick(clock.now) |
| 325 | if d.dumpCalls.Load() != 1 { |
| 326 | t.Fatalf("dumpCalls = %d, want 1", d.dumpCalls.Load()) |
| 327 | } |
| 328 | |
| 329 | // Heartbeat during grace aborts hard-kill. |
| 330 | clock.now = clock.now.Add(time.Second) |
| 331 | d.NoteActiveHeartbeat("elapsed_tick") |
| 332 | clock.now = clock.now.Add(tuiWatchdogCancelGrace) |
| 333 | d.onTick(clock.now) |
| 334 | if d.killCalls.Load() != 0 { |
| 335 | t.Fatalf("killCalls after heartbeat = %d, want 0", d.killCalls.Load()) |
| 336 | } |
| 337 | } |
| 338 | |
| 339 | // TestWatchdogCancelOncePerGeneration pins "one Cancel per Turn": after a grace |
| 340 | // abort via heartbeat, a later stall on the same generation may dump/kill but |
| 341 | // must not invoke Cancel() again. |
| 342 | func TestWatchdogCancelOncePerGeneration(t *testing.T) { |
| 343 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 344 | d := newWatchdogForTest(t, clock) |
| 345 | d.NoteBooted() |
| 346 | // cancelCalls is incremented before the hook body, so assertions below do not |
| 347 | // need to wait for a separate scheduler turn. |
| 348 | d.NoteRunning(func() {}) |
| 349 | |
| 350 | // First stall → cancel once. |
| 351 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 352 | d.onTick(clock.now) |
| 353 | if d.cancelCalls.Load() != 1 { |
| 354 | t.Fatalf("first cancelCalls = %d, want 1", d.cancelCalls.Load()) |
| 355 | } |
| 356 | // Heartbeat aborts grace (cancelIssued stays sticky). |
| 357 | clock.now = clock.now.Add(time.Second) |
| 358 | d.NoteActiveHeartbeat("elapsed_tick") |
| 359 | // Second stall on the same generation, accumulated with 1s ticks — a |
| 360 | // single >stall clock step would read as a suspend/resume clock jump. |
| 361 | for range int(tuiWatchdogStall / time.Second) { |
| 362 | clock.now = clock.now.Add(time.Second) |
| 363 | d.onTick(clock.now) |
| 364 | } |
| 365 | if d.cancelCalls.Load() != 1 { |
| 366 | t.Fatalf("second stall re-canceled: cancelCalls=%d, want 1", d.cancelCalls.Load()) |
| 367 | } |
| 368 | if d.dumpCalls.Load() != 2 { |
| 369 | t.Fatalf("second stall dumpCalls = %d, want 2 (re-dump allowed)", d.dumpCalls.Load()) |
| 370 | } |
| 371 | // Grace after second escalation still hard-kills once. |
| 372 | clock.now = clock.now.Add(tuiWatchdogCancelGrace) |
| 373 | d.onTick(clock.now) |
| 374 | if d.killCalls.Load() != 1 { |
| 375 | t.Fatalf("killCalls after second grace = %d, want 1", d.killCalls.Load()) |
| 376 | } |
| 377 | } |
| 378 | |
| 379 | func TestWatchdogStaleCancelCannotAffectNewGeneration(t *testing.T) { |
| 380 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 381 | d := newWatchdogForTest(t, clock) |
| 382 | d.NoteBooted() |
| 383 | var oldCancelCalls atomic.Int32 |
| 384 | d.NoteRunning(func() { oldCancelCalls.Add(1) }) |
| 385 | oldGeneration := d.generationForTest() |
| 386 | d.NoteIdle() |
| 387 | d.NoteRunning(func() {}) |
| 388 | |
| 389 | d.cancelCurrentGeneration(oldGeneration, func() { oldCancelCalls.Add(1) }) |
| 390 | if got := oldCancelCalls.Load(); got != 0 { |
| 391 | t.Fatalf("stale cancellation invoked old callback %d times, want 0", got) |
| 392 | } |
| 393 | } |
| 394 | |
| 395 | func TestWatchdogTurnDoneDuringGraceAbortsKill(t *testing.T) { |
| 396 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 397 | d := newWatchdogForTest(t, clock) |
| 398 | d.NoteBooted() |
| 399 | d.NoteRunning(func() {}) |
| 400 | |
| 401 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 402 | d.onTick(clock.now) |
| 403 | // TurnDone → idle before grace expires. |
| 404 | d.NoteIdle() |
| 405 | if d.phaseForTest() != watchdogIdle { |
| 406 | t.Fatalf("phase = %s, want idle", d.phaseForTest()) |
| 407 | } |
| 408 | clock.now = clock.now.Add(tuiWatchdogCancelGrace + time.Second) |
| 409 | d.onTick(clock.now) |
| 410 | if d.killCalls.Load() != 0 { |
| 411 | t.Fatalf("kill after TurnDone = %d, want 0", d.killCalls.Load()) |
| 412 | } |
| 413 | } |
| 414 | |
| 415 | func TestWatchdogClosedStopsAllActions(t *testing.T) { |
| 416 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 417 | d := newWatchdogForTest(t, clock) |
| 418 | d.NoteBooted() |
| 419 | d.NoteRunning(func() {}) |
| 420 | d.Close() |
| 421 | if d.phaseForTest() != watchdogClosed { |
| 422 | t.Fatalf("phase = %s, want closed", d.phaseForTest()) |
| 423 | } |
| 424 | clock.now = clock.now.Add(tuiWatchdogStall + time.Second) |
| 425 | d.onTick(clock.now) |
| 426 | if d.dumpCalls.Load() != 0 || d.cancelCalls.Load() != 0 || d.killCalls.Load() != 0 { |
| 427 | t.Fatalf("closed watchdog still acted: dump=%d cancel=%d kill=%d", |
| 428 | d.dumpCalls.Load(), d.cancelCalls.Load(), d.killCalls.Load()) |
| 429 | } |
| 430 | } |
| 431 | |
| 432 | func TestWatchdogStaleGenerationCannotKillNewTurn(t *testing.T) { |
| 433 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 434 | d := newWatchdogForTest(t, clock) |
| 435 | d.NoteBooted() |
| 436 | d.NoteRunning(func() {}) // gen 1 |
| 437 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 438 | d.onTick(clock.now) // escalate gen 1 |
| 439 | if d.cancelCalls.Load() != 1 { |
| 440 | t.Fatalf("cancelCalls = %d, want 1", d.cancelCalls.Load()) |
| 441 | } |
| 442 | |
| 443 | // New turn starts (generation bumps); old grace must not kill it. |
| 444 | d.NoteIdle() |
| 445 | d.NoteRunning(func() {}) // gen 2 |
| 446 | clock.now = clock.now.Add(tuiWatchdogCancelGrace + time.Second) |
| 447 | // Heartbeat keeps gen 2 healthy. |
| 448 | d.NoteActiveHeartbeat("elapsed_tick") |
| 449 | d.onTick(clock.now) |
| 450 | if d.killCalls.Load() != 0 { |
| 451 | t.Fatalf("stale kill hit new generation: killCalls=%d", d.killCalls.Load()) |
| 452 | } |
| 453 | if d.generationForTest() != 2 { |
| 454 | t.Fatalf("generation = %d, want 2", d.generationForTest()) |
| 455 | } |
| 456 | } |
| 457 | |
| 458 | func TestWatchdogUserActivityDoesNotCountAsActiveHeartbeat(t *testing.T) { |
| 459 | // NoteBooted / NoteIdle paths are the only non-active transitions; keyboard |
| 460 | // never calls NoteActiveHeartbeat. Prove that without it, a running stall |
| 461 | // still escalates even if "time passes" via booted-style idle marks. |
| 462 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 463 | d := newWatchdogForTest(t, clock) |
| 464 | d.NoteBooted() |
| 465 | d.NoteRunning(func() {}) |
| 466 | // Simulate only user-facing updates that do not call NoteActiveHeartbeat. |
| 467 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 468 | d.onTick(clock.now) |
| 469 | if d.dumpCalls.Load() != 1 { |
| 470 | t.Fatalf("stall without active heartbeat dumpCalls = %d, want 1", d.dumpCalls.Load()) |
| 471 | } |
| 472 | } |
| 473 | |
| 474 | func TestChatTUIWatchdogHelpersAreNilSafe(t *testing.T) { |
| 475 | var m chatTUI |
| 476 | m.noteWatchdogRunning() |
| 477 | m.noteWatchdogIdle() |
| 478 | m.noteWatchdogHeartbeat("elapsed_tick") |
| 479 | } |
| 480 | |
| 481 | func TestChatTUIWatchdogLifecycleHelpers(t *testing.T) { |
| 482 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 483 | d := newWatchdogForTest(t, clock) |
| 484 | m := chatTUI{diagnostics: d} |
| 485 | |
| 486 | // Boot confirmation (first Update path). |
| 487 | m.diagnostics.NoteBooted() |
| 488 | if d.phaseForTest() != watchdogIdle { |
| 489 | t.Fatalf("after NoteBooted phase = %s, want idle", d.phaseForTest()) |
| 490 | } |
| 491 | |
| 492 | // Shell / controller turn entry. |
| 493 | m.noteWatchdogRunning() |
| 494 | if d.phaseForTest() != watchdogRunning { |
| 495 | t.Fatalf("phase = %s, want running", d.phaseForTest()) |
| 496 | } |
| 497 | m.noteWatchdogHeartbeat("elapsed_tick") |
| 498 | // TurnDone / shell completion. |
| 499 | m.noteWatchdogIdle() |
| 500 | if d.phaseForTest() != watchdogIdle { |
| 501 | t.Fatalf("phase after idle = %s, want idle", d.phaseForTest()) |
| 502 | } |
| 503 | } |
| 504 | |
| 505 | // TestWatchdogClockJumpAfterSuspendDoesNotKill pins the #9233 path: after a |
| 506 | // suspend/resume (or scheduler starvation) the first ticks see a stale |
| 507 | // heartbeat age, but the >=stall gap between consecutive ~1s ticks proves the |
| 508 | // process slept rather than the event loop wedging — refresh instead of |
| 509 | // dumping, canceling, and killing a healthy turn. |
| 510 | func TestWatchdogClockJumpAfterSuspendDoesNotKill(t *testing.T) { |
| 511 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 512 | d := newWatchdogForTest(t, clock) |
| 513 | d.NoteBooted() |
| 514 | d.NoteRunning(func() {}) |
| 515 | |
| 516 | // Healthy heartbeats for a while. |
| 517 | for range 5 { |
| 518 | clock.now = clock.now.Add(time.Second) |
| 519 | d.NoteActiveHeartbeat("elapsed_tick") |
| 520 | d.onTick(clock.now) |
| 521 | } |
| 522 | // Suspend: the next tick arrives a minute late with no heartbeats during |
| 523 | // sleep, then ticks resume at 1s cadence. |
| 524 | clock.now = clock.now.Add(time.Minute) |
| 525 | d.onTick(clock.now) |
| 526 | // Resumed: ticks and heartbeats continue at their normal cadence. |
| 527 | for range 12 { |
| 528 | clock.now = clock.now.Add(time.Second) |
| 529 | d.NoteActiveHeartbeat("elapsed_tick") |
| 530 | d.onTick(clock.now) |
| 531 | } |
| 532 | if got := d.dumpCalls.Load(); got != 0 { |
| 533 | t.Fatalf("post-resume dumpCalls = %d, want 0", got) |
| 534 | } |
| 535 | if got := d.cancelCalls.Load(); got != 0 { |
| 536 | t.Fatalf("post-resume cancelCalls = %d, want 0 (healthy turn survived the suspend)", got) |
| 537 | } |
| 538 | if got := d.killCalls.Load(); got != 0 { |
| 539 | t.Fatalf("post-resume killCalls = %d, want 0", got) |
| 540 | } |
| 541 | } |
| 542 | |
| 543 | func TestWatchdogFirstTickAfterSuspendDoesNotEscalate(t *testing.T) { |
| 544 | for _, gap := range []time.Duration{tuiWatchdogStall, time.Minute} { |
| 545 | t.Run(gap.String(), func(t *testing.T) { |
| 546 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 547 | d := newWatchdogForTest(t, clock) |
| 548 | ticker := &fakeWatchTicker{ticks: make(chan time.Time)} |
| 549 | d.newTicker = func(time.Duration) watchdogTicker { return ticker } |
| 550 | d.StartWatchdog(nil) |
| 551 | d.NoteBooted() |
| 552 | d.NoteRunning(func() {}) |
| 553 | |
| 554 | // Suspend before the watch goroutine receives its first ticker event. |
| 555 | clock.now = clock.now.Add(gap) |
| 556 | d.onTick(clock.now) |
| 557 | |
| 558 | if got := d.dumpCalls.Load(); got != 0 { |
| 559 | t.Fatalf("first post-resume tick dumped a healthy turn: dumpCalls=%d", got) |
| 560 | } |
| 561 | if got := d.cancelCalls.Load(); got != 0 { |
| 562 | t.Fatalf("first post-resume tick canceled a healthy turn: cancelCalls=%d", got) |
| 563 | } |
| 564 | if got := d.killCalls.Load(); got != 0 { |
| 565 | t.Fatalf("first post-resume tick killed a healthy turn: killCalls=%d", got) |
| 566 | } |
| 567 | }) |
| 568 | } |
| 569 | } |
| 570 | |
| 571 | // TestWatchdogKillRequestsGracefulShutdownFirst verifies the hard kill asks |
| 572 | // the program to snapshot and quit cleanly (the SIGHUP path) and only falls |
| 573 | // back to Kill when the graceful request goes nowhere (#9233). |
| 574 | func TestWatchdogKillRequestsGracefulShutdownFirst(t *testing.T) { |
| 575 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 576 | d := newWatchdogForTest(t, clock) |
| 577 | shutdowns := 0 |
| 578 | kills := 0 |
| 579 | var fallback func() |
| 580 | d.afterFunc = func(delay time.Duration, fn func()) { |
| 581 | if delay != watchdogKillFallbackDelay { |
| 582 | t.Fatalf("fallback delay = %s, want %s", delay, watchdogKillFallbackDelay) |
| 583 | } |
| 584 | fallback = fn |
| 585 | } |
| 586 | d.shutdownFn = func(completion *tuiShutdownCompletion) { |
| 587 | shutdowns++ |
| 588 | completion.complete() |
| 589 | } |
| 590 | d.killFn = func() { kills++ } |
| 591 | d.NoteBooted() |
| 592 | d.NoteRunning(func() {}) |
| 593 | |
| 594 | // Real stall: escalate, cancel, grace, kill decision. |
| 595 | clock.now = clock.now.Add(tuiWatchdogStall) |
| 596 | d.onTick(clock.now) |
| 597 | clock.now = clock.now.Add(time.Second) |
| 598 | d.onTick(clock.now) |
| 599 | clock.now = clock.now.Add(tuiWatchdogCancelGrace) |
| 600 | d.onTick(clock.now) |
| 601 | |
| 602 | if shutdowns != 1 { |
| 603 | t.Fatalf("graceful shutdown requests = %d, want 1", shutdowns) |
| 604 | } |
| 605 | if fallback == nil { |
| 606 | t.Fatal("hard-kill fallback was not scheduled") |
| 607 | } |
| 608 | if kills != 0 { |
| 609 | t.Fatalf("hard kill ran before fallback callback: kills=%d", kills) |
| 610 | } |
| 611 | fallback() |
| 612 | if kills != 0 { |
| 613 | t.Fatalf("fallback killed a completed graceful shutdown: kills=%d", kills) |
| 614 | } |
| 615 | } |
| 616 | |
| 617 | func TestWatchdogKillFallbackRunsWhileGracefulShutdownIsBlocked(t *testing.T) { |
| 618 | clock := &fakeWatchClock{now: time.Unix(1_700_000_000, 0)} |
| 619 | d := newWatchdogForTest(t, clock) |
| 620 | scheduled := make(chan func(), 1) |
| 621 | shutdownStarted := make(chan struct{}) |
| 622 | releaseShutdown := make(chan struct{}) |
| 623 | killed := make(chan struct{}, 1) |
| 624 | d.afterFunc = func(_ time.Duration, fn func()) { scheduled <- fn } |
| 625 | d.shutdownFn = func(_ *tuiShutdownCompletion) { |
| 626 | close(shutdownStarted) |
| 627 | <-releaseShutdown |
| 628 | } |
| 629 | d.killFn = func() { |
| 630 | close(releaseShutdown) |
| 631 | killed <- struct{}{} |
| 632 | } |
| 633 | |
| 634 | done := make(chan struct{}) |
| 635 | go func() { |
| 636 | d.doKill() |
| 637 | close(done) |
| 638 | }() |
| 639 | defer func() { |
| 640 | select { |
| 641 | case <-releaseShutdown: |
| 642 | default: |
| 643 | close(releaseShutdown) |
| 644 | } |
| 645 | }() |
| 646 | |
| 647 | var fallback func() |
| 648 | select { |
| 649 | case fallback = <-scheduled: |
| 650 | case <-time.After(time.Second): |
| 651 | t.Fatal("fallback was not scheduled before graceful shutdown blocked") |
| 652 | } |
| 653 | select { |
| 654 | case <-shutdownStarted: |
| 655 | case <-time.After(time.Second): |
| 656 | t.Fatal("graceful shutdown did not start") |
| 657 | } |
| 658 | fallback() |
| 659 | select { |
| 660 | case <-killed: |
| 661 | case <-time.After(time.Second): |
| 662 | t.Fatal("scheduled hard-kill fallback did not invoke killFn") |
| 663 | } |
| 664 | select { |
| 665 | case <-done: |
| 666 | case <-time.After(time.Second): |
| 667 | t.Fatal("doKill did not return after graceful shutdown unblocked") |
| 668 | } |
| 669 | } |
| 670 |