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