| 1 | package cli |
| 2 | |
| 3 | import ( |
| 4 | "fmt" |
| 5 | "io" |
| 6 | "log/slog" |
| 7 | "os" |
| 8 | "path/filepath" |
| 9 | "runtime" |
| 10 | "strings" |
| 11 | "sync" |
| 12 | "sync/atomic" |
| 13 | "time" |
| 14 | |
| 15 | tea "charm.land/bubbletea/v2" |
| 16 | ) |
| 17 | |
| 18 | const ( |
| 19 | tuiDiagnosticLogLimit = 4 << 20 |
| 20 | tuiDiagnosticLogRetention = 7 * 24 * time.Hour |
| 21 | tuiWatchdogInterval = time.Second |
| 22 | tuiWatchdogStall = 10 * time.Second |
| 23 | ) |
| 24 | |
| 25 | // tuiDiagnostics owns process-level diagnostics while an interactive terminal |
| 26 | // UI is alive. Bubble Tea owns the terminal screen, so background logs and |
| 27 | // plugin stderr must go to a private file instead of bypassing its renderer. |
| 28 | // Failure to create that file degrades to io.Discard: typed event.Notice values |
| 29 | // still carry user-facing warnings through the TUI. |
| 30 | // |
| 31 | // Milestones and a 1s heartbeat keep the log non-empty during hangs so Windows |
| 32 | // ConPTY freezes (#7435) and stuck D-Bus startups leave recoverable evidence. |
| 33 | type tuiDiagnostics struct { |
| 34 | previous *slog.Logger |
| 35 | logger *slog.Logger |
| 36 | writer io.Writer |
| 37 | file *os.File |
| 38 | path string |
| 39 | close sync.Once |
| 40 | |
| 41 | lastProgress atomic.Int64 // unix nano of last Update/View progress |
| 42 | stopWatch chan struct{} |
| 43 | watchOnce sync.Once |
| 44 | watchWG sync.WaitGroup |
| 45 | killed atomic.Bool |
| 46 | } |
| 47 | |
| 48 | func startTUIDiagnostics(reasonixHome string) *tuiDiagnostics { |
| 49 | d := &tuiDiagnostics{previous: slog.Default(), writer: io.Discard, stopWatch: make(chan struct{})} |
| 50 | if logDir := tuiDiagnosticLogDir(reasonixHome); logDir != "" { |
| 51 | if err := os.MkdirAll(logDir, 0o700); err == nil { |
| 52 | pruneTUIDiagnosticLogs(logDir, time.Now()) |
| 53 | if file, err := os.CreateTemp(logDir, "cli-tui-*.log"); err == nil { |
| 54 | d.file = file |
| 55 | d.path = file.Name() |
| 56 | d.writer = &boundedDiagnosticWriter{dst: file, remaining: tuiDiagnosticLogLimit} |
| 57 | } |
| 58 | } |
| 59 | } |
| 60 | d.logger = slog.New(slog.NewTextHandler(d.writer, &slog.HandlerOptions{Level: slog.LevelInfo})) |
| 61 | slog.SetDefault(d.logger) |
| 62 | d.markProgress() |
| 63 | d.Milestone("diagnostics_started") |
| 64 | return d |
| 65 | } |
| 66 | |
| 67 | // Milestone records a startup/runtime phase and flushes the log immediately so a |
| 68 | // subsequent hang still leaves a non-zero diagnostic file. |
| 69 | func (d *tuiDiagnostics) Milestone(name string) { |
| 70 | if d == nil { |
| 71 | return |
| 72 | } |
| 73 | d.markProgress() |
| 74 | msg := fmt.Sprintf("milestone=%s t=%s", strings.TrimSpace(name), time.Now().UTC().Format(time.RFC3339Nano)) |
| 75 | _, _ = fmt.Fprintln(d.Writer(), msg) |
| 76 | d.Sync() |
| 77 | } |
| 78 | |
| 79 | // Sync flushes the diagnostic file to disk when possible. |
| 80 | func (d *tuiDiagnostics) Sync() { |
| 81 | if d == nil || d.file == nil { |
| 82 | return |
| 83 | } |
| 84 | _ = d.file.Sync() |
| 85 | } |
| 86 | |
| 87 | // markProgress records that the TUI event loop is alive. |
| 88 | func (d *tuiDiagnostics) markProgress() { |
| 89 | if d == nil { |
| 90 | return |
| 91 | } |
| 92 | d.lastProgress.Store(time.Now().UnixNano()) |
| 93 | } |
| 94 | |
| 95 | // Path returns the diagnostic log path (empty when falling back to Discard). |
| 96 | func (d *tuiDiagnostics) Path() string { |
| 97 | if d == nil { |
| 98 | return "" |
| 99 | } |
| 100 | return d.path |
| 101 | } |
| 102 | |
| 103 | func (d *tuiDiagnostics) Writer() io.Writer { |
| 104 | if d == nil || d.writer == nil { |
| 105 | return io.Discard |
| 106 | } |
| 107 | return d.writer |
| 108 | } |
| 109 | |
| 110 | // StartWatchdog arms a 1s heartbeat. If the TUI event loop makes no progress for |
| 111 | // 10s, it dumps all goroutines, syncs the log, and kills the Bubble Tea program |
| 112 | // so the terminal is restored instead of remaining frozen (#7435). |
| 113 | func (d *tuiDiagnostics) StartWatchdog(p *tea.Program) { |
| 114 | if d == nil || p == nil { |
| 115 | return |
| 116 | } |
| 117 | d.watchOnce.Do(func() { |
| 118 | d.markProgress() |
| 119 | d.watchWG.Add(1) |
| 120 | go func() { |
| 121 | defer d.watchWG.Done() |
| 122 | d.watch(p) |
| 123 | }() |
| 124 | }) |
| 125 | } |
| 126 | |
| 127 | func (d *tuiDiagnostics) watch(p *tea.Program) { |
| 128 | ticker := time.NewTicker(tuiWatchdogInterval) |
| 129 | defer ticker.Stop() |
| 130 | for { |
| 131 | select { |
| 132 | case <-d.stopWatch: |
| 133 | return |
| 134 | case now := <-ticker.C: |
| 135 | last := time.Unix(0, d.lastProgress.Load()) |
| 136 | age := now.Sub(last) |
| 137 | _, _ = fmt.Fprintf(d.Writer(), "heartbeat t=%s last_progress_age=%s\n", |
| 138 | now.UTC().Format(time.RFC3339Nano), age.Round(time.Millisecond)) |
| 139 | d.Sync() |
| 140 | if age < tuiWatchdogStall || d.killed.Load() { |
| 141 | continue |
| 142 | } |
| 143 | d.killed.Store(true) |
| 144 | d.dumpGoroutines("watchdog_stall") |
| 145 | d.Sync() |
| 146 | // Kill restores the terminal; Quit alone can hang if Update is blocked. |
| 147 | p.Kill() |
| 148 | return |
| 149 | } |
| 150 | } |
| 151 | } |
| 152 | |
| 153 | func (d *tuiDiagnostics) dumpGoroutines(reason string) { |
| 154 | if d == nil { |
| 155 | return |
| 156 | } |
| 157 | buf := make([]byte, 1<<20) |
| 158 | for { |
| 159 | n := runtime.Stack(buf, true) |
| 160 | if n < len(buf) { |
| 161 | buf = buf[:n] |
| 162 | break |
| 163 | } |
| 164 | buf = make([]byte, len(buf)*2) |
| 165 | } |
| 166 | _, _ = fmt.Fprintf(d.Writer(), "goroutine_dump reason=%s bytes=%d\n%s\n", reason, len(buf), buf) |
| 167 | } |
| 168 | |
| 169 | func (d *tuiDiagnostics) Close() { |
| 170 | if d == nil { |
| 171 | return |
| 172 | } |
| 173 | d.close.Do(func() { |
| 174 | select { |
| 175 | case <-d.stopWatch: |
| 176 | default: |
| 177 | close(d.stopWatch) |
| 178 | } |
| 179 | // Wait for the watchdog to fully exit before closing the log. A timed |
| 180 | // wait left a window where runtime.Stack / Sync / Kill could still write |
| 181 | // the file after Close returned. |
| 182 | d.watchWG.Wait() |
| 183 | // Do not overwrite a logger deliberately installed by another owner |
| 184 | // after the TUI started. |
| 185 | if slog.Default() == d.logger && d.previous != nil { |
| 186 | slog.SetDefault(d.previous) |
| 187 | } |
| 188 | if d.file != nil { |
| 189 | _ = d.file.Sync() |
| 190 | _ = d.file.Close() |
| 191 | } |
| 192 | }) |
| 193 | } |
| 194 | |
| 195 | func tuiDiagnosticLogDir(reasonixHome string) string { |
| 196 | if strings.TrimSpace(reasonixHome) == "" { |
| 197 | return "" |
| 198 | } |
| 199 | return filepath.Join(reasonixHome, "logs") |
| 200 | } |
| 201 | |
| 202 | func pruneTUIDiagnosticLogs(logDir string, now time.Time) { |
| 203 | entries, err := os.ReadDir(logDir) |
| 204 | if err != nil { |
| 205 | return |
| 206 | } |
| 207 | cutoff := now.Add(-tuiDiagnosticLogRetention) |
| 208 | for _, entry := range entries { |
| 209 | if entry.IsDir() || !strings.HasPrefix(entry.Name(), "cli-tui-") || !strings.HasSuffix(entry.Name(), ".log") { |
| 210 | continue |
| 211 | } |
| 212 | info, err := entry.Info() |
| 213 | if err != nil || !info.ModTime().Before(cutoff) { |
| 214 | continue |
| 215 | } |
| 216 | _ = os.Remove(filepath.Join(logDir, entry.Name())) |
| 217 | } |
| 218 | } |
| 219 | |
| 220 | type boundedDiagnosticWriter struct { |
| 221 | mu sync.Mutex |
| 222 | dst io.Writer |
| 223 | remaining int64 |
| 224 | truncated bool |
| 225 | } |
| 226 | |
| 227 | func (w *boundedDiagnosticWriter) Write(p []byte) (int, error) { |
| 228 | w.mu.Lock() |
| 229 | defer w.mu.Unlock() |
| 230 | |
| 231 | total := len(p) |
| 232 | if total == 0 || w.dst == nil || w.remaining <= 0 { |
| 233 | return total, nil |
| 234 | } |
| 235 | n := total |
| 236 | if int64(n) > w.remaining { |
| 237 | n = int(w.remaining) |
| 238 | } |
| 239 | written, err := w.dst.Write(p[:n]) |
| 240 | if written > 0 { |
| 241 | w.remaining -= int64(written) |
| 242 | } |
| 243 | if err != nil || written != n { |
| 244 | w.remaining = 0 |
| 245 | return total, nil |
| 246 | } |
| 247 | if n < total && !w.truncated { |
| 248 | w.truncated = true |
| 249 | _, _ = io.WriteString(w.dst, "\nreasonix: CLI TUI diagnostic log limit reached; further diagnostics omitted\n") |
| 250 | w.remaining = 0 |
| 251 | } |
| 252 | return total, nil |
| 253 | } |
| 254 |