diff --git a/CHANGELOG.md b/CHANGELOG.md index e7830922a..09aaa2600 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -118,6 +118,15 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 than one open session is left as plain text too — the terminal has no way to tell which one was meant. +- **A bug report can now describe a lich that froze.** A window that stops + updating while the process is still there writes nothing to `lich.log` — + nothing crashed, so there is nothing to write, and the report arrived saying + only "it froze". `lich rage` now asks the running instance for every + goroutine's stack and carries it as `goroutines.txt`, so a hang can be read + the way a crash already could. An instance that holds its port and will not + answer within five seconds leaves that sentence in the file instead, which + says as much again. + ### Changed - **A session blocked on you says so in words.** Being asked a question looked diff --git a/docs/cli.md b/docs/cli.md index c00f9ceb8..1c3db751e 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -299,13 +299,16 @@ Read it before you attach it: it carries absolute paths, project and branch name It exists for the failure lich cannot report on itself: a window that never opened has no Settings › Help to ask through. So it needs no running instance — whether one is running, and whether it still answers, is one of the facts it -reports. +reports. It answers for the opposite failure too — a window still on screen that +stopped updating. Nothing crashed there, so the log holds nothing; the stacks it +collects say where the process is stuck. | Entry | What it holds | |-------|---------------| | `report.md` | Version and build, platform, instance state, browser, providers on PATH, plugin state per provider, and the config directory one level deep. | | `env.txt` | Every `LICH_*` variable plus a fixed allowlist (`SHELL`, `PATH`, `EDITOR`, the desktop ones). Anything named like a token, key, secret or password is `` / ``, never a value. | | `logs/` | `lich.log` and the rotated `lich.log.old`, each carrying at most its last 4 MiB. | +| `goroutines.txt` | Every stack in the running instance, blocked ones included — only when one is running. A lich that holds its port but will not answer within 5s leaves that sentence here instead, which is the finding. | Nothing is uploaded and no issue is filed: the archive sits on disk until the user attaches it to one they wrote. The loopback token is masked wherever it diff --git a/internal/rage/rage.go b/internal/rage/rage.go index 6fb303186..0c6afaf4c 100644 --- a/internal/rage/rage.go +++ b/internal/rage/rage.go @@ -14,6 +14,7 @@ import ( "compress/gzip" "fmt" "io" + "net/http" "os" "os/exec" "path/filepath" @@ -63,7 +64,7 @@ type Entry struct { Dir bool } -// Collector gathers a Report. The four probes are fields because each one +// Collector gathers a Report. The five probes are fields because each one // reaches the machine — PATH, the provider CLIs, the network, the running // instance — and a test must answer for all of them. type Collector struct { @@ -75,6 +76,7 @@ type Collector struct { detect func() []providers.Detected plugin func() []agentplugin.Status probe func() (*singleton.Info, bool) + dump func(port int, token string) ([]byte, error) } // New returns a Collector reading the real machine. configDir is the OS config @@ -101,9 +103,35 @@ func New(configDir, version string, environ []string) *Collector { } return info, singleton.Ping(info.Port, info.Token) }, + dump: fetchGoroutines, } } +// dumpTimeout bounds the goroutine fetch. A lich that stopped answering is the +// case this runs in, so the wait has to end on its own: what the file then +// carries is that it did not answer, which is the finding. +const dumpTimeout = 5 * time.Second + +// maxDumpBytes bounds the dump the bundle carries. A stack per goroutine stays +// far below this; a runaway instance with tens of thousands of them is +// diagnosed by the head of the file, not by its tail. +const maxDumpBytes = 8 << 20 + +// fetchGoroutines asks the running instance for its goroutine stacks (the +// transport's /debug/goroutines). +func fetchGoroutines(port int, token string) ([]byte, error) { + client := http.Client{Timeout: dumpTimeout} + resp, err := client.Get(fmt.Sprintf("http://127.0.0.1:%d/debug/goroutines?token=%s", port, token)) + if err != nil { + return nil, err + } + defer resp.Body.Close() + if resp.StatusCode != http.StatusOK { + return nil, fmt.Errorf("status %d", resp.StatusCode) + } + return io.ReadAll(io.LimitReader(resp.Body, maxDumpBytes)) +} + // pathBins resolves every provider to its default name on PATH. The real // resolver is the workspace database, and rage never opens it: the database // belongs to the running instance, and a bug report must not be the second @@ -116,7 +144,11 @@ func (pathBins) ProviderBin(_, _ string) string { return "" } // the directory every entry sits under, so extracting two bundles side by side // does not merge them. func (c *Collector) Bundle(w io.Writer, root string) (Report, error) { - report, token := c.collect() + report, live := c.collect() + token := "" + if live != nil { + token = live.Token + } gz := gzip.NewWriter(w) archive := tar.NewWriter(gz) @@ -126,6 +158,9 @@ func (c *Collector) Bundle(w io.Writer, root string) (Report, error) { {"env.txt", []byte(renderEnv(c.environ, token))}, } files = append(files, logFiles(report.LogPath, token)...) + if live != nil { + files = append(files, bundleFile{"goroutines.txt", c.goroutines(live)}) + } for _, f := range files { if err := writeEntry(archive, root+"/"+f.name, f.data); err != nil { @@ -167,10 +202,25 @@ func logFiles(logPath, token string) []bundleFile { return out } -// collect gathers every fact, and returns the running instance's token beside -// the report rather than inside it: the token is needed to mask the copies of -// itself that may sit in the log, and must reach nothing else. -func (c *Collector) collect() (Report, string) { +// goroutines is the running instance's stacks, or — when it will not answer — +// the record that it did not. The failure is the point: a lich still holding +// its port with a window that stopped updating leaves nothing in the log, and +// "did not answer in 5s" is already half the diagnosis. +func (c *Collector) goroutines(live *singleton.Info) []byte { + data, err := c.dump(live.Port, live.Token) + if err != nil { + return []byte(fmt.Sprintf( + "the running lich (pid %d, port %d) did not answer the goroutine dump: %v\n", live.PID, live.Port, err)) + } + return scrub(data, live.Token) +} + +// collect gathers every fact, and returns the running instance beside the +// report rather than inside it: its token is needed to mask the copies of +// itself that may sit in the log, and its port to reach it for the goroutine +// dump. Nil when nothing is running or the recorded instance does not answer — +// the report says which. +func (c *Collector) collect() (Report, *singleton.Info) { lichDir := filepath.Join(c.configDir, "lich") report := Report{ Version: c.version, @@ -195,20 +245,19 @@ func (c *Collector) collect() (Report, string) { report.Browser = err.Error() } - token := "" info, alive := c.probe() switch { case info == nil: report.Instance = "not running" case alive: - token = info.Token report.Instance = fmt.Sprintf("running (pid %d, port %d)", info.PID, info.Port) + return report, info default: // The file outlives a crash, so a recorded instance that does not answer // is itself a finding: lich died without closing its window. report.Instance = fmt.Sprintf("recorded but not answering (pid %d, port %d)", info.PID, info.Port) } - return report, token + return report, nil } // entries lists the lich config directory one level deep. Directories are named diff --git a/internal/rage/rage_test.go b/internal/rage/rage_test.go index 7612d7e96..8e7f2dbe8 100644 --- a/internal/rage/rage_test.go +++ b/internal/rage/rage_test.go @@ -35,6 +35,11 @@ func collector(t *testing.T, configDir string, info *singleton.Info, alive bool) return []agentplugin.Status{{Provider: "claude", Name: "Claude Code", Available: true, Installed: true, InstalledVersion: "0.2.0"}} } c.probe = func() (*singleton.Info, bool) { return info, alive } + // The stub dump carries the token on purpose: the bundle's masking answers + // for it like it answers for the log. + c.dump = func(int, string) ([]byte, error) { + return []byte("goroutine 1 [running]:\nmain.main()\n\ttoken=" + liveToken + "\n"), nil + } return c } @@ -186,6 +191,55 @@ func TestReportNamesEveryInstanceState(t *testing.T) { } } +func TestBundleCarriesTheStacksOfARunningInstance(t *testing.T) { + var gotPort int + var gotToken string + c := collector(t, lichDir(t, "x\n", ""), &singleton.Info{PID: 7, Port: 47821, Token: liveToken}, true) + inner := c.dump + c.dump = func(port int, token string) ([]byte, error) { + gotPort, gotToken = port, token + return inner(port, token) + } + + files, _ := bundle(t, c, "r") + + if gotPort != 47821 || gotToken != liveToken { + t.Errorf("dump asked port %d token %q, want the recorded instance's", gotPort, gotToken) + } + if !strings.Contains(files["r/goroutines.txt"], "goroutine 1 [running]") { + t.Errorf("goroutines.txt = %q", files["r/goroutines.txt"]) + } +} + +func TestBundleRecordsAnInstanceThatWillNotDump(t *testing.T) { + c := collector(t, lichDir(t, "x\n", ""), &singleton.Info{PID: 7, Port: 47821, Token: liveToken}, true) + c.dump = func(int, string) ([]byte, error) { return nil, fmt.Errorf("context deadline exceeded") } + + files, _ := bundle(t, c, "r") + + dump := files["r/goroutines.txt"] + if !strings.Contains(dump, "did not answer") || !strings.Contains(dump, "pid 7") { + t.Errorf("a lich that would not answer left %q", dump) + } + if !strings.Contains(dump, "context deadline exceeded") { + t.Errorf("the dump failure does not name its cause: %q", dump) + } +} + +func TestBundleHasNoStacksWithoutARunningInstance(t *testing.T) { + c := collector(t, lichDir(t, "x\n", ""), &singleton.Info{PID: 7, Port: 47821, Token: liveToken}, false) + c.dump = func(int, string) ([]byte, error) { + t.Error("a recorded but dead instance was asked for its stacks") + return nil, nil + } + + files, _ := bundle(t, c, "r") + + if _, ok := files["r/goroutines.txt"]; ok { + t.Error("bundle carries a goroutine dump with nothing running") + } +} + func TestBundleSurvivesAConfigDirWithNoLog(t *testing.T) { configDir := t.TempDir() t.Setenv("LICH_DEV", "") diff --git a/internal/terminal/transport.go b/internal/terminal/transport.go index ee1c43499..69fec8cf1 100644 --- a/internal/terminal/transport.go +++ b/internal/terminal/transport.go @@ -13,6 +13,7 @@ import ( "net" "net/http" "os" + "runtime/pprof" "strings" "sync" "time" @@ -146,6 +147,7 @@ func newTransport( mux := http.NewServeMux() mux.HandleFunc("/ws", t.handle) mux.HandleFunc("/ping", t.ping) + mux.HandleFunc("/debug/goroutines", t.goroutines) mux.HandleFunc("/hook", t.hook) mux.HandleFunc("/session-start", t.sessionStart) mux.HandleFunc("/session-title", t.sessionTitle) @@ -261,6 +263,26 @@ func (t *transport) ping(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusNoContent) } +// goroutines dumps every goroutine's stack, blocked ones included. It answers +// the failure a log cannot describe: the window stops updating while the +// process is still alive, so nothing panicked, nothing exited, and nothing was +// ever written. `lich rage` fetches this into the bug report; an instance that +// holds its port and will not answer here is itself the finding. Token-gated +// like every other endpoint, and deliberately not net/http/pprof: this is one +// dump of one thing, not a profiling surface. +func (t *transport) goroutines(w http.ResponseWriter, r *http.Request) { + if !t.authorized(r) { + http.Error(w, "invalid token", http.StatusUnauthorized) + return + } + w.Header().Set("Content-Type", "text/plain; charset=utf-8") + // debug level 2 is the readable form — the same layout a panic prints, so a + // hang and a crash are read side by side. + if err := pprof.Lookup("goroutine").WriteTo(w, 2); err != nil { + slog.Warn("goroutine dump", "err", err) + } +} + // mount adds a handler to the transport listener behind the same token check // every endpoint uses. ServeMux registration is safe after Serve started, so // callers wire extra surfaces (RPC, the events push socket) post-construction. diff --git a/internal/terminal/transport_test.go b/internal/terminal/transport_test.go index 487c78178..368aa5ce8 100644 --- a/internal/terminal/transport_test.go +++ b/internal/terminal/transport_test.go @@ -6,6 +6,7 @@ import ( "encoding/json" "errors" "fmt" + "io" "net" "net/http" "os" @@ -295,6 +296,46 @@ func TestPingRejectsBadToken(t *testing.T) { } } +func TestGoroutineDumpAnswersWithTheStacks(t *testing.T) { + tr, err := newTransport(func(string, []byte) {}, nil, nil, nil, nil) + if err != nil { + t.Fatalf("newTransport: %v", err) + } + resp, err := http.Get(fmt.Sprintf("http://127.0.0.1:%d/debug/goroutines?token=%s", tr.port, tr.token)) + if err != nil { + t.Fatalf("get: %v", err) + } + defer resp.Body.Close() + if resp.StatusCode != http.StatusOK { + t.Fatalf("status = %d, want 200", resp.StatusCode) + } + body, err := io.ReadAll(resp.Body) + if err != nil { + t.Fatalf("read: %v", err) + } + // The dump this very request is served by is in there, stack and all: the + // hang it exists for is read off the frames, not off the count. + if !strings.Contains(string(body), "terminal.(*transport).goroutines") || + !strings.Contains(string(body), "TestGoroutineDumpAnswersWithTheStacks") { + t.Errorf("dump carries no stacks: %q", string(body)) + } +} + +func TestGoroutineDumpRejectsBadToken(t *testing.T) { + tr, err := newTransport(func(string, []byte) {}, nil, nil, nil, nil) + if err != nil { + t.Fatalf("newTransport: %v", err) + } + resp, err := http.Get(fmt.Sprintf("http://127.0.0.1:%d/debug/goroutines?token=wrong", tr.port)) + if err != nil { + t.Fatalf("get: %v", err) + } + _ = resp.Body.Close() + if resp.StatusCode != http.StatusUnauthorized { + t.Fatalf("status = %d, want 401", resp.StatusCode) + } +} + func TestHookForwardsStatus(t *testing.T) { got := make(chan hookRequest, 1) tr, err := newTransport(func(string, []byte) {}, func(req hookRequest) {