chore: import upstream snapshot with attribution

internal/procio/stderrlog.go

@@ -0,0 +1,190 @@
+// Package procio routes a spawned subprocess's stderr into structured
+// zap logging instead of letting it write raw text wherever the
+// parent's own os.Stderr happens to point. For a detached daemon that
+// IS its own log file (daemon.log), an inherited raw stderr means a
+// crashing child (a language server panic backtrace, hundreds of
+// llama.cpp load-time trace lines) interleaves unstructured text with
+// structured JSON log lines forever. StderrWatcher scans, bounds, and
+// rate-limits each child's stderr into normal Warn-level log entries.
+package procio
+
+import (
+	"bytes"
+	"io"
+	"time"
+
+	"go.uber.org/zap"
+)
+
+const (
+	// DefaultMaxLineBytes bounds a single logged stderr line. Longer
+	// lines (or lines with no newline in sight, e.g. a JSON blob) are
+	// truncated rather than growing the scan buffer without bound or
+	// aborting the scan.
+	DefaultMaxLineBytes = 8 * 1024
+
+	// DefaultBurstLimit is how many stderr lines are logged verbatim
+	// within one rate-limit window before the rest of the window's
+	// lines are counted and suppressed. A crash-looping subprocess
+	// (rust-analyzer panicking repeatedly) must not flood the log.
+	DefaultBurstLimit = 100
+
+	// DefaultBurstWindow is the rate-limit window duration. Once a
+	// window elapses, the burst counter resets and any suppressed count
+	// from the previous window is flushed as one summary line.
+	DefaultBurstWindow = 10 * time.Second
+)
+
+// StderrWatcher scans a subprocess's stderr stream and routes it into
+// a zap.Logger at Warn, bounded and rate-limited. Zero value uses the
+// package defaults; construct with the fields you want to override.
+type StderrWatcher struct {
+	// Logger receives one Warn per (unsuppressed) line, plus a
+	// suppression summary at each window boundary. A nil Logger drains
+	// the stream silently (so the child's write doesn't block) without
+	// logging anything.
+	Logger *zap.Logger
+	// Tag identifies the subprocess in every log entry (e.g. the LSP
+	// server name or command).
+	Tag string
+	// MaxLineBytes bounds a single line; <= 0 uses DefaultMaxLineBytes.
+	MaxLineBytes int
+	// BurstLimit is the per-window verbatim line cap; <= 0 uses
+	// DefaultBurstLimit.
+	BurstLimit int
+	// BurstWindow is the rate-limit window; <= 0 uses
+	// DefaultBurstWindow.
+	BurstWindow time.Duration
+}
+
+// Watch starts a goroutine that reads r until EOF (i.e. until the
+// owning subprocess closes/dies) or a read error, logging lines as
+// they arrive. It returns immediately; the goroutine is panic-safe and
+// requires no further cleanup from the caller — closing/killing the
+// subprocess is enough to end it.
+func (w StderrWatcher) Watch(r io.Reader) {
+	go w.run(r)
+}
+
+func (w StderrWatcher) run(r io.Reader) {
+	defer func() { _ = recover() }()
+
+	if w.Logger == nil {
+		// Still drain so the child never blocks on a full pipe buffer,
+		// we just don't log any of it.
+		_, _ = io.Copy(io.Discard, r)
+		return
+	}
+
+	maxLine := w.MaxLineBytes
+	if maxLine <= 0 {
+		maxLine = DefaultMaxLineBytes
+	}
+	burst := w.BurstLimit
+	if burst <= 0 {
+		burst = DefaultBurstLimit
+	}
+	window := w.BurstWindow
+	if window <= 0 {
+		window = DefaultBurstWindow
+	}
+
+	lr := &lineReader{r: r, maxLine: maxLine}
+
+	var (
+		windowStart = time.Now()
+		count       int
+		suppressed  int
+	)
+	flush := func() {
+		if suppressed > 0 {
+			w.Logger.Warn("subprocess stderr suppressed",
+				zap.String("tag", w.Tag),
+				zap.Int("suppressed_lines", suppressed),
+				zap.Duration("window", window),
+			)
+			suppressed = 0
+		}
+	}
+
+	for {
+		line, ok := lr.next()
+		if !ok {
+			break
+		}
+		now := time.Now()
+		if now.Sub(windowStart) > window {
+			flush()
+			windowStart = now
+			count = 0
+		}
+		count++
+		if count > burst {
+			suppressed++
+			continue
+		}
+		w.Logger.Warn("subprocess stderr", zap.String("tag", w.Tag), zap.String("line", line))
+	}
+	flush()
+}
+
+// lineReader splits r into newline-delimited (or forced-length)
+// strings, capped at maxLine bytes each. Unlike bufio.Scanner with a
+// fixed Buffer, it never errors out on an over-long line (bufio's
+// ErrTooLong would silently end the whole scan mid-stream) — an
+// oversized line is simply truncated and the read continues.
+type lineReader struct {
+	r       io.Reader
+	maxLine int
+	buf     []byte // pending, not-yet-newline-terminated bytes
+	chunk   [4096]byte
+	err     error
+}
+
+// next returns the next line (without its trailing newline), or
+// ok=false once the underlying reader is exhausted/erroring and no
+// buffered data remains.
+func (lr *lineReader) next() (string, bool) {
+	for {
+		if i := bytes.IndexByte(lr.buf, '\n'); i >= 0 {
+			line := lr.buf[:i]
+			lr.buf = lr.buf[i+1:]
+			return lr.emit(line), true
+		}
+		if len(lr.buf) >= lr.maxLine {
+			// No newline yet but already over the cap — force a token
+			// now instead of buffering an unbounded fragment.
+			line := lr.buf[:lr.maxLine]
+			lr.buf = lr.buf[lr.maxLine:]
+			return lr.emit(line), true
+		}
+		if lr.err != nil {
+			if len(lr.buf) == 0 {
+				return "", false
+			}
+			line := lr.buf
+			lr.buf = nil
+			return lr.emit(line), true
+		}
+		n, err := lr.r.Read(lr.chunk[:])
+		if n > 0 {
+			lr.buf = append(lr.buf, lr.chunk[:n]...)
+		}
+		if err != nil {
+			lr.err = err
+		}
+	}
+}
+
+// emit trims a trailing '\r' (CRLF streams) and truncates to maxLine,
+// copying out of the shared buf so the caller can keep it past the
+// next Read.
+func (lr *lineReader) emit(line []byte) string {
+	line = bytes.TrimSuffix(line, []byte{'\r'})
+	if len(line) > lr.maxLine {
+		line = line[:lr.maxLine]
+	}
+	out := make([]byte, len(line))
+	copy(out, line)
+	return string(out)
+}

internal/procio/stderrlog_test.go

@@ -0,0 +1,167 @@
+package procio
+
+import (
+	"io"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/require"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest/observer"
+)
+
+// waitForEntries polls obs until at least n entries have been recorded
+// or the deadline elapses.
+func waitForEntries(t *testing.T, obs *observer.ObservedLogs, n int) []observer.LoggedEntry {
+	t.Helper()
+	deadline := time.Now().Add(2 * time.Second)
+	for time.Now().Before(deadline) {
+		if obs.Len() >= n {
+			return obs.All()
+		}
+		time.Sleep(5 * time.Millisecond)
+	}
+	t.Fatalf("timed out waiting for %d log entries, got %d", n, obs.Len())
+	return nil
+}
+
+func TestStderrWatcher_LogsLines(t *testing.T) {
+	core, obs := observer.New(zapcore.DebugLevel)
+	logger := zap.New(core)
+
+	r, w := io.Pipe()
+	StderrWatcher{Logger: logger, Tag: "testproc"}.Watch(r)
+
+	go func() {
+		_, _ = w.Write([]byte("line one\nline two\n"))
+		_ = w.Close()
+	}()
+
+	entries := waitForEntries(t, obs, 2)
+	require.Equal(t, "subprocess stderr", entries[0].Message)
+	require.Equal(t, "testproc", entries[0].ContextMap()["tag"])
+	require.Equal(t, "line one", entries[0].ContextMap()["line"])
+	require.Equal(t, "line two", entries[1].ContextMap()["line"])
+}
+
+func TestStderrWatcher_NilLoggerDrainsSilently(t *testing.T) {
+	r, w := io.Pipe()
+	StderrWatcher{Logger: nil, Tag: "testproc"}.Watch(r)
+
+	done := make(chan struct{})
+	go func() {
+		_, _ = w.Write([]byte(strings.Repeat("x", 1<<20)))
+		_ = w.Close()
+		close(done)
+	}()
+
+	select {
+	case <-done:
+	case <-time.After(2 * time.Second):
+		t.Fatal("write to a nil-logger watcher blocked — pipe was not drained")
+	}
+}
+
+func TestStderrWatcher_TruncatesOverlongLines(t *testing.T) {
+	core, obs := observer.New(zapcore.DebugLevel)
+	logger := zap.New(core)
+
+	r, w := io.Pipe()
+	StderrWatcher{Logger: logger, Tag: "t", MaxLineBytes: 16}.Watch(r)
+
+	go func() {
+		_, _ = w.Write([]byte(strings.Repeat("a", 100) + "\nshort\n"))
+		_ = w.Close()
+	}()
+
+	entries := waitForEntries(t, obs, 2)
+	line0, _ := entries[0].ContextMap()["line"].(string)
+	require.LessOrEqual(t, len(line0), 16)
+	require.Equal(t, "short", entries[1].ContextMap()["line"])
+}
+
+func TestStderrWatcher_BurstSuppressionSummary(t *testing.T) {
+	core, obs := observer.New(zapcore.DebugLevel)
+	logger := zap.New(core)
+
+	r, w := io.Pipe()
+	StderrWatcher{
+		Logger:      logger,
+		Tag:         "spam",
+		BurstLimit:  5,
+		BurstWindow: 24 * time.Hour, // never rolls over during the test
+	}.Watch(r)
+
+	go func() {
+		var sb strings.Builder
+		for i := 0; i < 20; i++ {
+			sb.WriteString("boom\n")
+		}
+		_, _ = w.Write([]byte(sb.String()))
+		_ = w.Close()
+	}()
+
+	// 5 verbatim lines + 1 suppression summary flushed at EOF.
+	entries := waitForEntries(t, obs, 6)
+
+	var logged, summaries int
+	var suppressedCount int64
+	for _, e := range entries {
+		switch e.Message {
+		case "subprocess stderr":
+			logged++
+		case "subprocess stderr suppressed":
+			summaries++
+			if v, ok := e.ContextMap()["suppressed_lines"]; ok {
+				suppressedCount, _ = toInt64(v)
+			}
+		}
+	}
+	require.Equal(t, 5, logged)
+	require.Equal(t, 1, summaries)
+	require.EqualValues(t, 15, suppressedCount)
+}
+
+func toInt64(v any) (int64, bool) {
+	switch n := v.(type) {
+	case int64:
+		return n, true
+	case int:
+		return int64(n), true
+	default:
+		return 0, false
+	}
+}
+
+func TestStderrWatcher_ExitsOnEOF(t *testing.T) {
+	core, _ := observer.New(zapcore.DebugLevel)
+	logger := zap.New(core)
+
+	r, w := io.Pipe()
+
+	var wg sync.WaitGroup
+	wg.Add(1)
+	orig := StderrWatcher{Logger: logger, Tag: "t"}
+	// Wrap run in a goroutine we can join on directly (Watch itself
+	// fires an untracked goroutine, so re-implement the same call here
+	// to observe completion).
+	go func() {
+		defer wg.Done()
+		orig.run(r)
+	}()
+
+	_, _ = w.Write([]byte("bye\n"))
+	_ = w.Close()
+
+	done := make(chan struct{})
+	go func() { wg.Wait(); close(done) }()
+
+	select {
+	case <-done:
+	case <-time.After(2 * time.Second):
+		t.Fatal("watcher goroutine did not exit after EOF")
+	}
+}