fix(cli): show the stack trace of a panic in the TUI

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 {

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)
+		}
+	}
+}

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.
 //

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)
+	}
+}