diff --git a/internal/k8s/credplugin.go b/internal/k8s/credplugin.go index 5a37624..2367bad 100644 --- a/internal/k8s/credplugin.go +++ b/internal/k8s/credplugin.go @@ -58,17 +58,31 @@ func nonInteractive(ep *clientcmdapi.ExecConfig) { } // stderrTap is os.Stderr rerouted through a pipe k10s reads (rule 2). It -// remembers only the last non-empty line and when it arrived: plugins say -// one useful thing, at the end, and a message from a different attempt -// must not be pinned on this one. +// remembers the last non-empty line and when it arrived: plugins say one +// useful thing, at the end, and a message from a different attempt must not +// be pinned on this one. It also keeps the last tailSize bytes of what was +// written, line by line, for the one reader that needs more than a line: +// main, after a panic in the TUI, whose stack trace Bubble Tea writes to +// os.Stderr. type stderrTap struct { mu sync.Mutex terminal *os.File // what os.Stderr was before the swap pipe *os.File // the write end now in os.Stderr last string at time.Time + tail []byte // the last tailSize bytes read, line by line + read int64 // bytes read so far, for drain to see the pipe go quiet + done chan struct{} // closed when the reader stops } +// tailSize bounds stderrTap.tail. A stack trace from inside Bubble Tea is a +// few KiB. +const tailSize = 64 << 10 + +// quietFor is how long drain waits for a write before it takes the pipe as +// quiet. +const quietFor = 50 * time.Millisecond + var ( captureOnce sync.Once tap = &stderrTap{} @@ -81,17 +95,21 @@ func (t *stderrTap) start() error { return err } t.terminal, t.pipe = os.Stderr, w + t.done = make(chan struct{}) os.Stderr = w go func() { + defer close(t.done) sc := bufio.NewScanner(r) sc.Buffer(make([]byte, 0, 64*1024), 1<<20) for sc.Scan() { - line := strings.TrimSpace(sc.Text()) - if line == "" { - continue - } + raw := sc.Text() + line := strings.TrimSpace(raw) t.mu.Lock() - t.last, t.at = line, time.Now() + t.keep(raw) + t.read += int64(len(raw)) + 1 + if line != "" { + t.last, t.at = line, time.Now() + } t.mu.Unlock() } // A line too long for the buffer ends the scan; nothing to do about @@ -102,6 +120,50 @@ func (t *stderrTap) start() error { return nil } +// keep adds one line to the tail and drops the oldest bytes past tailSize. +// The line is as the scanner gives it, plus a newline: a \r before the +// newline is gone, and a last line written without one gets one. Neither +// changes a stack trace. The caller holds t.mu. +func (t *stderrTap) keep(line string) { + t.tail = append(append(t.tail, line...), '\n') + if over := len(t.tail) - tailSize; over > 0 { + t.tail = append(t.tail[:0], t.tail[over:]...) + } +} + +// drain waits, up to wait, until nothing new has come through the pipe for +// quietFor. Then it closes the write end, so that the reader can finish what +// is still in the pipe, and returns the tail once it has, or once wait is up +// again: a credential plugin that is still running holds the pipe open too. +// +// The quiet comes first because Run does not wait for a command's goroutine. +// After a panic in one, Bubble Tea ends the program and only then writes the +// stack trace, from that goroutine, which can be after Run has returned; a +// write after the close fails and the trace is lost. +func (t *stderrTap) drain(wait time.Duration) []byte { + if t.pipe == nil { + return nil + } + deadline := time.Now().Add(wait) + for prev := int64(-1); time.Now().Before(deadline); time.Sleep(quietFor) { + t.mu.Lock() + n := t.read + t.mu.Unlock() + if n == prev { + break + } + prev = n + } + _ = t.pipe.Close() + select { + case <-t.done: + case <-time.After(wait): + } + t.mu.Lock() + defer t.mu.Unlock() + return append([]byte(nil), t.tail...) +} + // said returns the last line written at or after since, "" if none. The // pipe is read on another goroutine, so a line the plugin wrote just before // exiting may still be in flight when its error arrives; said waits a @@ -148,6 +210,17 @@ func ReleaseStderr() { } } +// DrainStderr ends the capture and returns the last 64 KiB of what it read, +// line by line, for main when the TUI ended in a panic: Bubble Tea prints +// the panic to stdout but its stack trace to os.Stderr, which was the pipe. +// It waits up to wait for the pipe to go quiet, and up to wait again for the +// reader to finish (see stderrTap.drain). Call it after ReleaseStderr, at +// the end of the process: a credential plugin started after it would find +// its stderr closed. Without a capture it returns nil. +func DrainStderr(wait time.Duration) []byte { + return tap.drain(wait) +} + // TerminalStderr is the terminal's stderr whether or not CaptureStderr has // run: the right destination for a process that takes the terminal over. func TerminalStderr() *os.File { diff --git a/internal/k8s/credplugin_test.go b/internal/k8s/credplugin_test.go index 0e79987..279e36b 100644 --- a/internal/k8s/credplugin_test.go +++ b/internal/k8s/credplugin_test.go @@ -3,6 +3,7 @@ package k8s import ( "errors" "fmt" + "io" "net/http" "net/http/httptest" "os" @@ -13,6 +14,7 @@ import ( "testing" "time" + tea "github.com/charmbracelet/bubbletea" clientcmdapi "k8s.io/client-go/tools/clientcmd/api" ) @@ -251,3 +253,94 @@ func TestCredentialPluginNamesTheContextsPlugin(t *testing.T) { } } } + +// What the tap read comes back line by line, tabs and blank lines kept: a +// stack trace without its indentation is hard to read. +func TestDrainStderrGivesBackWhatWasWritten(t *testing.T) { + captureStderrForTest(t) + want := "earlier\n\ngoroutine 1 [running]:\nmain.main()\n\t/src/main.go:10 +0x1d\n" + if _, err := os.Stderr.WriteString(want); err != nil { + t.Fatal(err) + } + if got := string(tap.drain(time.Second)); got != want { + t.Errorf("drain = %q, want %q", got, want) + } +} + +// The tail keeps the newest tailSize bytes and drops the oldest. +func TestStderrTailKeepsTheNewestBytes(t *testing.T) { + captureStderrForTest(t) + var all strings.Builder + for i := 0; all.Len() < 3*tailSize; i++ { + fmt.Fprintf(&all, "line %06d %s\n", i, strings.Repeat("x", 80)) + } + if _, err := os.Stderr.WriteString(all.String()); err != nil { + t.Fatal(err) + } + got := string(tap.drain(time.Second)) + if len(got) != tailSize { + t.Errorf("tail is %d bytes, want %d", len(got), tailSize) + } + if !strings.HasSuffix(all.String(), got) { + t.Error("the tail is not the end of what was written") + } +} + +// panicsInUpdate panics on Bubble Tea's event loop, and panicsInCommand in a +// command's own goroutine: the two kinds of panic Bubble Tea recovers. +type panicsInUpdate struct{} + +type boom struct{} + +func (panicsInUpdate) Init() tea.Cmd { + return func() tea.Msg { return boom{} } +} + +func (m panicsInUpdate) Update(msg tea.Msg) (tea.Model, tea.Cmd) { + if _, ok := msg.(boom); ok { + panic("boom in Update") + } + return m, nil +} + +func (panicsInUpdate) View() string { return "" } + +type panicsInCommand struct{} + +func panicInCommand() tea.Msg { panic("boom in a command") } + +func (panicsInCommand) Init() tea.Cmd { return panicInCommand } + +func (m panicsInCommand) Update(tea.Msg) (tea.Model, tea.Cmd) { return m, nil } + +func (panicsInCommand) View() string { return "" } + +// Bubble Tea writes a recovered panic's stack trace to os.Stderr, which is the +// pipe while the TUI runs, so after either kind of panic the trace is in the +// tail that main writes out. +func TestBubbleTeaPanicStackTracesReachTheTail(t *testing.T) { + devNull, err := os.OpenFile(os.DevNull, os.O_WRONLY, 0) + if err != nil { + t.Fatal(err) + } + stdout := os.Stdout + os.Stdout = devNull // Bubble Tea prints the panic itself there + t.Cleanup(func() { + os.Stdout = stdout + _ = devNull.Close() + }) + captureStderrForTest(t) + + for _, m := range []tea.Model{panicsInUpdate{}, panicsInCommand{}} { + p := tea.NewProgram(m, tea.WithInput(nil), tea.WithOutput(io.Discard), tea.WithoutSignalHandler()) + if _, err := p.Run(); !errors.Is(err, tea.ErrProgramPanic) { + t.Fatalf("Run(%T) = %v, want %v", m, err, tea.ErrProgramPanic) + } + } + tail := string(tap.drain(time.Second)) + for _, frame := range []string{"k8s.panicsInUpdate.Update(", "k8s.panicInCommand("} { + if !strings.Contains(tail, frame) { + t.Errorf("no %s in the tail:\n%s", frame, tail) + } + } +} diff --git a/main.go b/main.go index f570d20..d1a282a 100644 --- a/main.go +++ b/main.go @@ -2,7 +2,9 @@ package main import ( "context" + "errors" "fmt" + "io" "os" "strings" "time" @@ -140,7 +142,7 @@ func main() { // The TUI is gone; whatever is said from here belongs on the screen. k8s.ReleaseStderr() if runErr != nil { - fmt.Fprintln(os.Stderr, "k10s:", runErr) + tuiFailed(os.Stderr, runErr) os.Exit(1) } @@ -159,6 +161,21 @@ func main() { } } +// tuiFailed reports the error the TUI ended with. After a panic it first +// writes what the stderr pipe caught: Bubble Tea prints the panic itself to +// stdout but its stack trace to os.Stderr, which was the pipe until Run +// returned, and a crash report needs the trace to say where it happened. +func tuiFailed(w io.Writer, runErr error) { + if errors.Is(runErr, tea.ErrProgramPanic) { + _, _ = w.Write(drainStderr(time.Second)) + } + fmt.Fprintln(w, "k10s:", runErr) +} + +// drainStderr is k8s.DrainStderr. A variable so a test can stand in for the +// pipe, which a process captures only once. +var drainStderr = k8s.DrainStderr + // selfUpdate is `k10s update`: the same install the TUI's /update performs, // with a progress line instead of a modal. // diff --git a/main_test.go b/main_test.go index 2606616..6488f96 100644 --- a/main_test.go +++ b/main_test.go @@ -1,13 +1,17 @@ package main import ( + "bytes" "errors" + "fmt" "net/http" "net/http/httptest" "path/filepath" "strings" "testing" + "time" + tea "github.com/charmbracelet/bubbletea" "k8s.io/client-go/tools/clientcmd" clientcmdapi "k8s.io/client-go/tools/clientcmd/api" @@ -109,3 +113,31 @@ func TestNoClusterReasonKeepsACredentialPluginsWords(t *testing.T) { t.Errorf("noClusterReason = %q\n want %q", got, want) } } + +// After a panic tuiFailed writes what the stderr pipe caught ahead of its own +// line; after any other error it leaves the pipe alone. +func TestTUIFailedPutsTheStackTraceFirst(t *testing.T) { + prev := drainStderr + t.Cleanup(func() { drainStderr = prev }) + drained := 0 + drainStderr = func(time.Duration) []byte { + drained++ + return []byte("goroutine 1 [running]:\n\tmain.go:10\n") + } + + panicked := fmt.Errorf("%w: %w", tea.ErrProgramKilled, tea.ErrProgramPanic) + var out bytes.Buffer + tuiFailed(&out, panicked) + if want := "goroutine 1 [running]:\n\tmain.go:10\nk10s: " + panicked.Error() + "\n"; out.String() != want { + t.Errorf("after a panic tuiFailed wrote %q, want %q", out.String(), want) + } + + out.Reset() + tuiFailed(&out, tea.ErrProgramKilled) + if want := "k10s: " + tea.ErrProgramKilled.Error() + "\n"; out.String() != want { + t.Errorf("after a kill tuiFailed wrote %q, want %q", out.String(), want) + } + if drained != 1 { + t.Errorf("the pipe was drained %d times, want 1: after the panic only", drained) + } +}