From c87d20f7f9a3c172cf04197e658c8126d5b4dfce Mon Sep 17 00:00:00 2001 From: German Meza Date: Mon, 13 Jul 2026 16:32:43 -0600 Subject: [PATCH] fix(graph): resolve status-footer stuck-progress, log clobbering, and rewalk loop MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The `tusk graph` status footer had three related defects (see issue): 1. It rendered `index gen N` — the reindex_gen walk counter, bumped on every walk including no-op walks — which reads as N stuck pending items on a quiet, fully-indexed workspace. A new goroutine-safe WalkStatus tracker (shared across runtime swaps and updated by the walk sites) drives a stateful footer: `synced` / `indexing…` / `walk error`, plus a `last walk 1ms (0 changed)` summary. reindex_gen semantics are unchanged (still load-bearing for orphan reap); it is simply no longer surfaced as the prominent number. 2. Under `-v`, background slog lines glued onto the sticky footer on an interactive TTY (footer and logs share the terminal; the `\r`+erase-line footer leaves the cursor mid-line). A new footerWriter multiplexes the footer and the logs onto one stream, erasing and redrawing the footer around each log line under a mutex. 3. `tusk graph -v > graph.log` inside the workspace armed a permanent ~500ms rewalk loop: each walk's own log write was a MODIFY the watcher turned into the next walk. The watcher now schedules a reindex only for paths that can affect the index — node files, the manifest, or (via os.Stat, so a dotted directory name is not mistaken for a file) a directory. This also closes the same footgun in `tusk watch`. --- cmd/tusk/cmd_graph.go | 31 ++++-- cmd/tusk/cmd_graph_console.go | 86 ++++++++++++----- cmd/tusk/cmd_graph_test.go | 76 ++++++++++++++- cmd/tusk/footer_writer.go | 102 ++++++++++++++++++++ cmd/tusk/footer_writer_test.go | 156 +++++++++++++++++++++++++++++++ internal/mcp/runtime.go | 10 +- internal/mcp/server.go | 7 +- internal/mcp/walkstatus.go | 117 +++++++++++++++++++++++ internal/mcp/walkstatus_test.go | 120 ++++++++++++++++++++++++ internal/mcp/watch.go | 4 +- internal/watcher/watcher.go | 46 ++++++++- internal/watcher/watcher_test.go | 153 ++++++++++++++++++++++++++++++ 12 files changed, 869 insertions(+), 39 deletions(-) create mode 100644 cmd/tusk/footer_writer.go create mode 100644 cmd/tusk/footer_writer_test.go create mode 100644 internal/mcp/walkstatus.go create mode 100644 internal/mcp/walkstatus_test.go diff --git a/cmd/tusk/cmd_graph.go b/cmd/tusk/cmd_graph.go index bce62f06..4d7cd962 100644 --- a/cmd/tusk/cmd_graph.go +++ b/cmd/tusk/cmd_graph.go @@ -3,6 +3,7 @@ package main import ( "context" "fmt" + "log" "net" "net/http" "os" @@ -94,9 +95,20 @@ func serveGraph(ctx context.Context, cmd *cobra.Command, cfg graphConfig) error return cwdErr } - opts := []mcp.Option{mcp.WithAliasIntrospector(buildVerbIntrospector(cmd.Root()))} - if logger := mcpLoggerFromFlags(cmd); logger != nil { - opts = append(opts, mcp.WithLogger(logger)) + // footer coordinates the interactive status footer with the background logs + // so a -v log line never glues onto the footer. It wraps stderr (where the + // logs already go) and stays a transparent passthrough until runConsole + // activates it on an interactive terminal. Building one logger over it and + // sharing it between the runtime and the view server keeps every background + // component's output flowing through the same coordinator. + footer := newFooterWriter(cmd.ErrOrStderr()) + + verbose, _ := cmd.Flags().GetBool("verbose") + logger := newLogger(footer, verbose) + + opts := []mcp.Option{ + mcp.WithAliasIntrospector(buildVerbIntrospector(cmd.Root())), + mcp.WithLogger(logger), } runtime, openErr := mcp.Open(cwd, opts...) @@ -115,7 +127,7 @@ func serveGraph(ctx context.Context, cmd *cobra.Command, cfg graphConfig) error Changes: graphview.NewChangeSource(runtime.Root, runtime.Meta), Manifest: runtime.Manifest, Embeddings: runtime.Embeddings, - Logger: mcpLoggerFromFlags(cmd), + Logger: logger, AllowedHosts: graphAllowedHosts(cfg.addr), } @@ -143,7 +155,14 @@ func serveGraph(ctx context.Context, cmd *cobra.Command, cfg graphConfig) error cfg.ready(listener.Addr().String()) } - httpServer := &http.Server{Handler: viewServer.Handler(), ReadHeaderTimeout: 10 * time.Second} + // Route the HTTP server's own error log through the footer coordinator too, + // so a stray net/http error line (default destination: os.Stderr) does not + // glue onto the interactive footer either. + httpServer := &http.Server{ + Handler: viewServer.Handler(), + ReadHeaderTimeout: 10 * time.Second, + ErrorLog: log.New(footer, "", 0), + } serveErrCh := make(chan error, 1) go func() { serveErrCh <- httpServer.Serve(listener) }() @@ -153,7 +172,7 @@ func serveGraph(ctx context.Context, cmd *cobra.Command, cfg graphConfig) error } // Tilt-style foreground console (status line + keypress loop). - runConsole(ctx, cancel, cmd, viewServer, runtime, boundURL) + runConsole(ctx, cancel, cmd, viewServer, runtime, boundURL, footer) cancel() // unblock RunBackground + viewServer.Run before draining diff --git a/cmd/tusk/cmd_graph_console.go b/cmd/tusk/cmd_graph_console.go index a84961fa..42cfe246 100644 --- a/cmd/tusk/cmd_graph_console.go +++ b/cmd/tusk/cmd_graph_console.go @@ -17,44 +17,52 @@ import ( // runConsole sets up raw-mode key reading (when stdin is a TTY) and drives the // live console loop. It restores the terminal on return; on a quit key it calls -// cancel so background work unwinds. -func runConsole(ctx context.Context, cancel context.CancelFunc, cmd *cobra.Command, viewServer *graphview.Server, rt *mcp.Runtime, url string) { - out := cmd.OutOrStdout() - _, _ = fmt.Fprintf(out, "tusk graph — serving on %s\n", url) - - status := func() { printStatus(out, viewServer, rt) } - +// cancel so background work unwinds. footer is the shared coordinated writer the +// background verbose logs also flow through; runConsole activates it only on an +// interactive terminal so the sticky footer and log lines never collide. +func runConsole(ctx context.Context, cancel context.CancelFunc, cmd *cobra.Command, viewServer *graphview.Server, rt *mcp.Runtime, url string, footer *footerWriter) { fd := int(os.Stdin.Fd()) + if !term.IsTerminal(fd) { - // No TTY (CI/pipe): print status once and idle until ctx is cancelled. - status() + // No TTY (CI/pipe): print a plain status line once and idle. The footer + // stays passive, so background logs pass straight through to stderr. + printPlainStatus(cmd.OutOrStdout(), viewServer, rt, url) <-ctx.Done() - _, _ = fmt.Fprintln(out) return } oldState, makeRawErr := term.MakeRaw(fd) if makeRawErr != nil { - status() + printPlainStatus(cmd.OutOrStdout(), viewServer, rt, url) <-ctx.Done() - _, _ = fmt.Fprintln(out) return } defer func() { _ = term.Restore(fd, oldState) }() + // Interactive: route the intro line, the sticky footer, and the background + // verbose logs through the one coordinated writer so a -v log line never glues + // onto the footer text. finish() leaves the cursor on a fresh line for the + // shell prompt. + _, _ = fmt.Fprintf(footer, "tusk graph — serving on %s\n", url) + footer.activate() + + defer footer.finish() + + status := func() { footer.setFooter(statusLine(viewServer, rt)) } keys := readKeys(ctx) - consoleLoop(ctx, cancel, out, keys, status, func() { _ = openBrowser(url) }) + consoleLoop(ctx, cancel, keys, status, func() { _ = openBrowser(url) }) } // consoleLoop runs the status+keypress loop until ctx is done or a quit key // (q/Q/Ctrl-C byte 3) arrives. On a quit key it calls cancel() so background // goroutines unwind, then returns. Space invokes openURL. Pure and testable: -// the keys channel and side effects are injected. -func consoleLoop(ctx context.Context, cancel context.CancelFunc, out io.Writer, keys <-chan rune, status func(), openURL func()) { +// the keys channel and side effects are injected. Terminal cleanup (the final +// newline) is the caller's responsibility via footerWriter.finish. +func consoleLoop(ctx context.Context, cancel context.CancelFunc, keys <-chan rune, status func(), openURL func()) { ticker := time.NewTicker(time.Second) defer ticker.Stop() @@ -63,13 +71,10 @@ func consoleLoop(ctx context.Context, cancel context.CancelFunc, out io.Writer, select { case <-ctx.Done(): - _, _ = fmt.Fprintln(out) - return case key, ok := <-keys: if !ok { <-ctx.Done() - _, _ = fmt.Fprintln(out) return } @@ -79,7 +84,6 @@ func consoleLoop(ctx context.Context, cancel context.CancelFunc, out io.Writer, openURL() case 'q', 'Q', 3: // 3 = Ctrl-C in raw mode (ISIG disabled) cancel() - _, _ = fmt.Fprintln(out) return } @@ -88,16 +92,48 @@ func consoleLoop(ctx context.Context, cancel context.CancelFunc, out io.Writer, } } -func printStatus(out interface{ Write([]byte) (int, error) }, viewServer *graphview.Server, rt *mcp.Runtime) { - gen := "?" - if value, err := rt.Meta.Get("reindex_gen"); err == nil && value != "" { - gen = value - } +// printPlainStatus writes the intro and a single newline-terminated status line +// for the non-interactive path (CI, a pipe, or a failed raw-mode setup), where +// there is no sticky footer to redraw. +func printPlainStatus(out io.Writer, viewServer *graphview.Server, rt *mcp.Runtime, url string) { + _, _ = fmt.Fprintf(out, "tusk graph — serving on %s\n", url) + _, _ = fmt.Fprintln(out, statusLine(viewServer, rt)) +} +// statusLine builds the one-line status text from live counts and the current +// reindex-walk state. +func statusLine(viewServer *graphview.Server, rt *mcp.Runtime) string { nodeCount, _ := rt.Nodes.CountFileNodes() edges, _ := rt.Edges.ListAll() - _, _ = fmt.Fprintf(out, "\r\033[Kindex gen %s · %d nodes · %d edges · %d clients [space] open [q] quit", gen, nodeCount, len(edges), viewServer.ClientCount()) + return formatStatus(rt.WalkStatus.Snapshot(), nodeCount, len(edges), viewServer.ClientCount()) +} + +// formatStatus renders the graph console's one-line status footer from the +// current reindex-walk state and live counts. It deliberately does NOT surface +// the raw reindex generation counter: that counter bumps on every walk — +// including walks that change nothing — so a quiet, fully-indexed workspace +// leaves it frozen at some N, which readers mistake for N stuck pending items +// (the bug report this fixes was filed for exactly that). Instead it names the +// state — synced / indexing… / walk error — and, once a walk has completed, +// summarizes it (duration + nodes changed) so "idle and synced" is visibly +// distinct from "a walk is running" or "the last walk failed". +func formatStatus(snap mcp.WalkStatusSnapshot, nodeCount, edgeCount, clientCount int) string { + counts := fmt.Sprintf("%d nodes · %d edges · %d clients", nodeCount, edgeCount, clientCount) + + const keys = "[space] open [q] quit" + + switch { + case snap.Walking: + return fmt.Sprintf("indexing… · %s %s", counts, keys) + case snap.Last.Err != "": + return fmt.Sprintf("walk error · %s %s", counts, keys) + case snap.EverWalked: + return fmt.Sprintf("synced · %s · last walk %dms (%d changed) %s", + counts, snap.Last.DurationMs, snap.Last.Changed(), keys) + default: + return fmt.Sprintf("synced · %s %s", counts, keys) + } } // readKeys spawns a goroutine that reads single bytes from stdin and forwards diff --git a/cmd/tusk/cmd_graph_test.go b/cmd/tusk/cmd_graph_test.go index e768d969..affee96e 100644 --- a/cmd/tusk/cmd_graph_test.go +++ b/cmd/tusk/cmd_graph_test.go @@ -2,11 +2,13 @@ package main import ( "context" - "io" "net/http" "slices" + "strings" "testing" "time" + + "github.com/germanamz/tusk/internal/mcp" ) func TestGraphAllowedHosts(test *testing.T) { @@ -83,6 +85,72 @@ func TestServeGraph_Integration(t *testing.T) { } } +func TestFormatStatus(test *testing.T) { + cases := []struct { + name string + snap mcp.WalkStatusSnapshot + wantContains []string + wantAbsent []string + }{ + { + name: "walking shows an active indicator", + snap: mcp.WalkStatusSnapshot{Walking: true}, + wantContains: []string{"indexing…", "2 nodes", "3 edges", "1 clients"}, + wantAbsent: []string{"synced", "index gen", "last walk"}, + }, + { + name: "idle synced with a completed no-op walk", + snap: mcp.WalkStatusSnapshot{ + EverWalked: true, + Last: mcp.WalkSummary{DurationMs: 2}, + }, + wantContains: []string{"synced", "last walk 2ms (0 changed)"}, + wantAbsent: []string{"indexing", "index gen", "walk error"}, + }, + { + name: "idle synced summarizes real changes", + snap: mcp.WalkStatusSnapshot{ + EverWalked: true, + Last: mcp.WalkSummary{Indexed: 3, Removed: 1, DurationMs: 12}, + }, + wantContains: []string{"synced", "last walk 12ms (4 changed)"}, + }, + { + name: "failed walk is not reported as synced", + snap: mcp.WalkStatusSnapshot{ + EverWalked: true, + Last: mcp.WalkSummary{Err: "read error"}, + }, + wantContains: []string{"walk error"}, + wantAbsent: []string{"synced", "last walk"}, + }, + { + name: "before the first walk it is not stuck", + snap: mcp.WalkStatusSnapshot{}, + wantContains: []string{"synced"}, + wantAbsent: []string{"index gen", "last walk", "indexing"}, + }, + } + + for _, testCase := range cases { + test.Run(testCase.name, func(subtest *testing.T) { + got := formatStatus(testCase.snap, 2, 3, 1) + + for _, want := range testCase.wantContains { + if !strings.Contains(got, want) { + subtest.Errorf("formatStatus = %q, want it to contain %q", got, want) + } + } + + for _, absent := range testCase.wantAbsent { + if strings.Contains(got, absent) { + subtest.Errorf("formatStatus = %q, want it to NOT contain %q", got, absent) + } + } + }) + } +} + func TestConsoleLoop_QuitKeyCancels(test *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() @@ -93,7 +161,7 @@ func TestConsoleLoop_QuitKeyCancels(test *testing.T) { done := make(chan struct{}) go func() { - consoleLoop(ctx, func() { cancelled = true }, io.Discard, keys, func() {}, func() {}) + consoleLoop(ctx, func() { cancelled = true }, keys, func() {}, func() {}) close(done) }() @@ -114,7 +182,7 @@ func TestConsoleLoop_CtxDoneReturns(test *testing.T) { done := make(chan struct{}) go func() { - consoleLoop(ctx, cancel, io.Discard, keys, func() {}, func() {}) + consoleLoop(ctx, cancel, keys, func() {}, func() {}) close(done) }() @@ -136,7 +204,7 @@ func TestConsoleLoop_SpaceOpens(test *testing.T) { keys <- ' ' keys <- 'q' - consoleLoop(ctx, cancel, io.Discard, keys, func() {}, func() { opened++ }) + consoleLoop(ctx, cancel, keys, func() {}, func() { opened++ }) if opened != 1 { test.Fatalf("openURL called %d times, want 1", opened) diff --git a/cmd/tusk/footer_writer.go b/cmd/tusk/footer_writer.go new file mode 100644 index 00000000..805fbfb7 --- /dev/null +++ b/cmd/tusk/footer_writer.go @@ -0,0 +1,102 @@ +package main + +import ( + "io" + "sync" +) + +// eraseLine returns the cursor to column 0 and clears to end of line. +const eraseLine = "\r\033[K" + +// footerWriter multiplexes a sticky one-line status footer and interleaved log +// lines onto a single terminal stream. `tusk graph`'s interactive footer redraws +// in place with a carriage-return + erase-line and leaves the cursor mid-line +// (no trailing newline); an asynchronous slog line written to the same terminal +// would otherwise glue onto the footer text ("…[q] quittime=2026-…"). Routing +// both the footer and the verbose background logs through this writer makes a log +// write erase the footer, print its line, and redraw the footer, with every write +// serialized under one mutex so the two can never interleave mid-sequence. +// +// Until activated it is a transparent passthrough: Write forwards bytes unchanged +// and setFooter is a no-op. A non-interactive run (CI, a pipe, or a raw-mode +// setup that failed) never activates it, so background logging behaves exactly as +// an unwrapped stderr logger. +type footerWriter struct { + mu sync.Mutex + out io.Writer + footer string + active bool +} + +// newFooterWriter wraps out. The writer starts passive; call activate once an +// interactive terminal is confirmed. +func newFooterWriter(out io.Writer) *footerWriter { + return &footerWriter{out: out} +} + +// activate turns on sticky-footer coordination. +func (writer *footerWriter) activate() { + writer.mu.Lock() + writer.active = true + writer.mu.Unlock() +} + +// setFooter replaces the footer text and redraws it in place. A no-op while +// passive (there is no sticky footer to coordinate). +func (writer *footerWriter) setFooter(text string) { + writer.mu.Lock() + defer writer.mu.Unlock() + + if !writer.active { + return + } + + writer.footer = text + writer.drawLocked() +} + +// Write is the io.Writer the verbose slog handler (and the HTTP error log) target. +// While passive it forwards p unchanged. Once active it erases the footer, writes +// the already-newline-terminated log line, then redraws the footer beneath it, so +// the log line and the footer never glue together. The returned count reflects +// bytes written from p — the erase/redraw control bytes are not counted — so the +// io.Writer contract holds for the caller. +func (writer *footerWriter) Write(payload []byte) (int, error) { + writer.mu.Lock() + defer writer.mu.Unlock() + + if !writer.active { + return writer.out.Write(payload) + } + + _, _ = io.WriteString(writer.out, eraseLine) + written, writeErr := writer.out.Write(payload) + writer.drawLocked() + + return written, writeErr +} + +// finish disables coordination and moves the cursor to a fresh line below the +// final footer so the shell prompt starts cleanly. Called once when the console +// loop returns. It writes a carriage-return + newline rather than a bare newline +// because it runs while the terminal is still in raw mode (ONLCR disabled), where +// a lone "\n" drops a row without returning to column 0 — leaving the next shell +// prompt indented to the end of the footer. +func (writer *footerWriter) finish() { + writer.mu.Lock() + defer writer.mu.Unlock() + + if !writer.active { + return + } + + writer.active = false + _, _ = io.WriteString(writer.out, "\r\n") +} + +// drawLocked writes the footer in place (erase current line, then the footer with +// no trailing newline). The caller must hold the mutex. +func (writer *footerWriter) drawLocked() { + _, _ = io.WriteString(writer.out, eraseLine) + _, _ = io.WriteString(writer.out, writer.footer) +} diff --git a/cmd/tusk/footer_writer_test.go b/cmd/tusk/footer_writer_test.go new file mode 100644 index 00000000..5325cedc --- /dev/null +++ b/cmd/tusk/footer_writer_test.go @@ -0,0 +1,156 @@ +package main + +import ( + "bytes" + "io" + "strings" + "sync" + "testing" +) + +func TestFooterWriter_PassiveIsPassthrough(test *testing.T) { + var buf bytes.Buffer + + writer := newFooterWriter(&buf) + + writer.setFooter("footer") // no-op before activate + _, _ = io.WriteString(writer, "log line\n") + + if got := buf.String(); got != "log line\n" { + test.Errorf("passive footerWriter wrote %q, want a clean passthrough %q", got, "log line\n") + } +} + +// TestFooterWriter_ActiveNeverGluesLogOntoFooter pins the defect-2 fix: a log +// line written while a footer is displayed must never be concatenated onto the +// footer text. The writer erases the footer, prints the line, and redraws. +func TestFooterWriter_ActiveNeverGluesLogOntoFooter(test *testing.T) { + var buf bytes.Buffer + + writer := newFooterWriter(&buf) + writer.activate() + writer.setFooter("FOOTER") + + _, _ = io.WriteString(writer, "logged\n") + + got := buf.String() + + if !strings.Contains(got, "logged\n") { + test.Errorf("output %q missing the log line", got) + } + + // The bug is "FOOTER" immediately followed by log text. An erase-line must + // sit between them, so the glued substring must never appear. + if strings.Contains(got, "FOOTERlogged") { + test.Errorf("log line glued onto footer: %q", got) + } + + // After a log line the footer is redrawn beneath it (erase + text), so the + // footer stays visible at the bottom. + if !strings.HasSuffix(got, eraseLine+"FOOTER") { + test.Errorf("footer not redrawn after the log line: %q", got) + } +} + +func TestFooterWriter_SetFooterRedrawsInPlace(test *testing.T) { + var buf bytes.Buffer + + writer := newFooterWriter(&buf) + writer.activate() + + writer.setFooter("first") + writer.setFooter("second") + + got := buf.String() + + // Each redraw is prefixed by an erase-line, and the latest footer wins. + if strings.Count(got, eraseLine) != 2 { + test.Errorf("expected two in-place redraws (erase-line prefixes), got %q", got) + } + + if !strings.HasSuffix(got, "second") { + test.Errorf("latest footer should be %q, got %q", "second", got) + } +} + +func TestFooterWriter_FinishEndsBelowFooter(test *testing.T) { + var buf bytes.Buffer + + writer := newFooterWriter(&buf) + writer.activate() + writer.setFooter("done") + writer.finish() + + // Raw-mode safe: carriage-return + newline so the cursor lands at column 0 of + // a fresh line, not indented to the end of the footer. + if !strings.HasSuffix(buf.String(), "done\r\n") { + test.Errorf("finish should end with a raw-mode-safe CRLF below the footer, got %q", buf.String()) + } + + // After finish the writer is passive again: further writes pass through. + buf.Reset() + _, _ = io.WriteString(writer, "after\n") + + if got := buf.String(); got != "after\n" { + test.Errorf("post-finish write should pass through, got %q", got) + } +} + +// TestFooterWriter_SlogLinesNeverGlueOntoFooter is the defect-2 integration +// check: a slog logger built over the coordinated writer (exactly how serveGraph +// wires the background logger) must never glue a log record onto the footer text. +// This exercises the real slog handler, which emits one Write per record. +func TestFooterWriter_SlogLinesNeverGlueOntoFooter(test *testing.T) { + var buf bytes.Buffer + + footer := newFooterWriter(&buf) + logger := newLogger(footer, true) // verbose: Debug level + + footer.activate() + footer.setFooter("synced · 2 nodes · 2 edges · 0 clients [space] open [q] quit") + + logger.Info("reindex walk complete", "indexed", 0, "duration_ms", 1) + + got := buf.String() + + if !strings.Contains(got, "reindex walk complete") { + test.Fatalf("log record missing from output: %q", got) + } + + // The regression: the footer's trailing "[q] quit" concatenated with the log + // record's leading "time=" ("…[q] quittime=2026-…"). An erase-line must sit + // between them. + if strings.Contains(got, "quittime=") { + test.Errorf("log record glued onto footer text: %q", got) + } +} + +// TestFooterWriter_ConcurrentWritesAndFooter pins goroutine safety: background +// log writes and console footer updates run on different goroutines. CI runs +// go test -race. +func TestFooterWriter_ConcurrentWritesAndFooter(test *testing.T) { + writer := newFooterWriter(io.Discard) + writer.activate() + + var waitGroup sync.WaitGroup + + waitGroup.Add(2) + + go func() { + defer waitGroup.Done() + + for iter := 0; iter < 500; iter++ { + _, _ = io.WriteString(writer, "background log\n") + } + }() + + go func() { + defer waitGroup.Done() + + for iter := 0; iter < 500; iter++ { + writer.setFooter("tick") + } + }() + + waitGroup.Wait() +} diff --git a/internal/mcp/runtime.go b/internal/mcp/runtime.go index f9eebccc..c801e515 100644 --- a/internal/mcp/runtime.go +++ b/internal/mcp/runtime.go @@ -54,6 +54,13 @@ type Runtime struct { aliasIntrospector manifest.VerbIntrospector Logger *slog.Logger // optional; nil silences output + + // WalkStatus records reindex-walk activity for the `tusk graph` status + // footer. It is a shared pointer carried across runtime swaps (like Logger), + // so a console holding the original runtime keeps observing live walk state + // after a reset or reload swaps srv.runtime underneath it. May be nil (tests + // that build a Runtime by hand); the walk sites and console tolerate nil. + WalkStatus *WalkStatus } // Option mutates a Runtime during Open. @@ -94,7 +101,7 @@ func Open(workspaceRoot string, opts ...Option) (*Runtime, error) { manifest.MergeBuiltinPacks(loaded) - rt := &Runtime{} + rt := &Runtime{WalkStatus: NewWalkStatus()} for _, opt := range opts { opt(rt) @@ -214,6 +221,7 @@ func (rt *Runtime) buildReloaded() (*Runtime, *ManifestDiff, error) { IndexPath: rt.IndexPath, Logger: rt.Logger, aliasIntrospector: rt.aliasIntrospector, + WalkStatus: rt.WalkStatus, } if buildErr := fresh.buildFromStore(rt.Index, loaded); buildErr != nil { diff --git a/internal/mcp/server.go b/internal/mcp/server.go index 191b27b7..863bfccf 100644 --- a/internal/mcp/server.go +++ b/internal/mcp/server.go @@ -154,6 +154,7 @@ func (srv *Server) installStoreLocked(store *index.Index, manifestOverride *mani IndexPath: old.IndexPath, Logger: old.Logger, aliasIntrospector: old.aliasIntrospector, + WalkStatus: old.WalkStatus, } if buildErr := fresh.buildFromStore(store, manifestOverride); buildErr != nil { @@ -562,7 +563,9 @@ func (srv *Server) reindexOnBoot(logger *slog.Logger) error { srv.reindexMu.Lock() defer srv.reindexMu.Unlock() - _, runErr := reindex.Run(reindex.Config{ + rt.WalkStatus.Begin() + + report, runErr := reindex.Run(reindex.Config{ Root: rt.Root, Repo: rt.Nodes, Edges: rt.Edges, @@ -579,6 +582,8 @@ func (srv *Server) reindexOnBoot(logger *slog.Logger) error { Async: true, }) + rt.WalkStatus.End(report, runErr) + return runErr } diff --git a/internal/mcp/walkstatus.go b/internal/mcp/walkstatus.go new file mode 100644 index 00000000..46b90ce1 --- /dev/null +++ b/internal/mcp/walkstatus.go @@ -0,0 +1,117 @@ +package mcp + +import ( + "sync" + "time" + + "github.com/germanamz/tusk/internal/reindex" +) + +// WalkStatus is a goroutine-safe record of reindex-walk activity. It is shared +// across runtime swaps (carried like Logger through installStoreLocked and +// buildReloaded) so a long-running console — `tusk graph`'s status footer — +// can render a live idle/walking indicator and a last-walk summary instead of +// the bare, ever-climbing generation counter, which reads as stuck pending work +// on a quiet workspace even when every walk completes in milliseconds and +// changes nothing. +// +// A nil *WalkStatus is safe: every method no-ops (Snapshot returns the zero +// value), so the walk sites need no nil guards. +type WalkStatus struct { + mu sync.Mutex + walking bool + startedAt time.Time + completed int64 + everWalked bool + lastWalk WalkSummary +} + +// WalkSummary is the outcome of the most recently completed walk. +type WalkSummary struct { + Indexed int + Removed int + Skipped int + DurationMs int64 + Err string // non-empty when the walk returned an error +} + +// Changed reports how many nodes the walk added or removed — the count that +// distinguishes a no-op walk (0 changed) from real work. +func (summary WalkSummary) Changed() int { + return summary.Indexed + summary.Removed +} + +// WalkStatusSnapshot is an immutable point-in-time view for the console. +type WalkStatusSnapshot struct { + Walking bool + Completed int64 + EverWalked bool + Last WalkSummary +} + +// NewWalkStatus returns a ready-to-use tracker. +func NewWalkStatus() *WalkStatus { + return &WalkStatus{} +} + +// Begin marks a walk as in progress and starts its timer. +func (status *WalkStatus) Begin() { + if status == nil { + return + } + + status.mu.Lock() + status.walking = true + status.startedAt = time.Now() + status.mu.Unlock() +} + +// End records a completed walk's outcome and clears the in-progress flag. report +// may be nil (the walk errored before producing one); walkErr may be nil (the +// walk succeeded). Duration is measured from the paired Begin. +func (status *WalkStatus) End(report *reindex.Report, walkErr error) { + if status == nil { + return + } + + status.mu.Lock() + defer status.mu.Unlock() + + summary := WalkSummary{} + + if status.walking { + summary.DurationMs = time.Since(status.startedAt).Milliseconds() + } + + if report != nil { + summary.Indexed = report.Indexed + summary.Removed = report.Removed + summary.Skipped = report.Skipped + } + + if walkErr != nil { + summary.Err = walkErr.Error() + } + + status.walking = false + status.everWalked = true + status.completed++ + status.lastWalk = summary +} + +// Snapshot returns the current state under the lock. +func (status *WalkStatus) Snapshot() WalkStatusSnapshot { + if status == nil { + return WalkStatusSnapshot{} + } + + status.mu.Lock() + defer status.mu.Unlock() + + return WalkStatusSnapshot{ + Walking: status.walking, + Completed: status.completed, + EverWalked: status.everWalked, + Last: status.lastWalk, + } +} diff --git a/internal/mcp/walkstatus_test.go b/internal/mcp/walkstatus_test.go new file mode 100644 index 00000000..141b920f --- /dev/null +++ b/internal/mcp/walkstatus_test.go @@ -0,0 +1,120 @@ +package mcp + +import ( + "errors" + "sync" + "testing" + + "github.com/germanamz/tusk/internal/reindex" +) + +func TestWalkStatus_NilIsSafe(test *testing.T) { + var status *WalkStatus // nil + + status.Begin() + status.End(&reindex.Report{Indexed: 3}, nil) + + if snap := status.Snapshot(); snap != (WalkStatusSnapshot{}) { + test.Fatalf("nil WalkStatus Snapshot = %+v, want zero value", snap) + } +} + +func TestWalkStatus_BeginSetsWalking(test *testing.T) { + status := NewWalkStatus() + + if status.Snapshot().Walking { + test.Fatal("fresh WalkStatus should not be walking") + } + + status.Begin() + + snap := status.Snapshot() + + if !snap.Walking { + test.Error("after Begin, Walking should be true") + } + + if snap.EverWalked { + test.Error("EverWalked should stay false until a walk completes") + } +} + +func TestWalkStatus_EndRecordsSummary(test *testing.T) { + status := NewWalkStatus() + + status.Begin() + status.End(&reindex.Report{Indexed: 2, Removed: 1, Skipped: 4}, nil) + + snap := status.Snapshot() + + if snap.Walking { + test.Error("after End, Walking should be false") + } + + if !snap.EverWalked { + test.Error("after End, EverWalked should be true") + } + + if snap.Completed != 1 { + test.Errorf("Completed = %d, want 1", snap.Completed) + } + + if snap.Last.Indexed != 2 || snap.Last.Removed != 1 || snap.Last.Skipped != 4 { + test.Errorf("Last = %+v, want Indexed=2 Removed=1 Skipped=4", snap.Last) + } + + if got := snap.Last.Changed(); got != 3 { + test.Errorf("Changed() = %d, want 3 (indexed+removed)", got) + } +} + +func TestWalkStatus_EndRecordsError(test *testing.T) { + status := NewWalkStatus() + + status.Begin() + status.End(nil, errors.New("boom")) + + snap := status.Snapshot() + + if snap.Walking { + test.Error("after a failed walk, Walking should be false") + } + + if snap.Last.Err != "boom" { + test.Errorf("Last.Err = %q, want %q", snap.Last.Err, "boom") + } +} + +// TestWalkStatus_ConcurrentAccess pins goroutine safety: CI runs go test -race, +// so a walk-writing goroutine and a console-reading goroutine must never race on +// the tracker's fields. +func TestWalkStatus_ConcurrentAccess(test *testing.T) { + status := NewWalkStatus() + + var waitGroup sync.WaitGroup + + waitGroup.Add(2) + + go func() { + defer waitGroup.Done() + + for iter := 0; iter < 1000; iter++ { + status.Begin() + status.End(&reindex.Report{Indexed: iter}, nil) + } + }() + + go func() { + defer waitGroup.Done() + + for iter := 0; iter < 1000; iter++ { + _ = status.Snapshot() + } + }() + + waitGroup.Wait() + + if snap := status.Snapshot(); snap.Completed != 1000 { + test.Errorf("Completed = %d, want 1000", snap.Completed) + } +} diff --git a/internal/mcp/watch.go b/internal/mcp/watch.go index 08ad28b1..eb676ee6 100644 --- a/internal/mcp/watch.go +++ b/internal/mcp/watch.go @@ -61,7 +61,8 @@ func RunWatcher(ctx context.Context, config WatchConfig) error { // drift to the drainer for retry (issue #677: a deletion or unrelated edit // must wake refs waiting on the changed node set). config.Server.reindexMu.Lock() - _, runErr := reindex.Run(reindex.Config{ + rt.WalkStatus.Begin() + report, runErr := reindex.Run(reindex.Config{ Root: rt.Root, Repo: rt.Nodes, Edges: rt.Edges, @@ -77,6 +78,7 @@ func RunWatcher(ctx context.Context, config WatchConfig) error { Logger: config.Logger, Async: true, }) + rt.WalkStatus.End(report, runErr) config.Server.reindexMu.Unlock() if runErr != nil && config.Logger != nil { diff --git a/internal/watcher/watcher.go b/internal/watcher/watcher.go index 652710fb..4200d52c 100644 --- a/internal/watcher/watcher.go +++ b/internal/watcher/watcher.go @@ -13,6 +13,8 @@ import ( "github.com/fsnotify/fsnotify" "github.com/germanamz/tusk/internal/ignore" + "github.com/germanamz/tusk/internal/index" + "github.com/germanamz/tusk/internal/workspace" ) // maxLoggedWatchDirs caps how many failed-to-watch directory paths the @@ -210,11 +212,24 @@ func (instance *Watcher) Run(ctx context.Context, handler EventHandler) error { // Watch directories created after boot, else edits inside subtrees // added to a long-running daemon are never observed (kqueue/inotify - // watch a single directory per Add, not recursively). + // watch a single directory per Add, not recursively). This runs before + // the reindex-relevance filter below so a moved-in subtree of nodes is + // still watched even though the create event names the (extensionless) + // directory. if kind == EventCreate { instance.watchNewDir(raw.Name) } + // Drop events on paths that can never change the index — a redirected + // .log, a .txt, an image. Scheduling a reindex for them is wasted work + // at best and, when the write lands inside the watched tree (e.g. + // `tusk graph -v > graph.log`), a self-sustaining walk loop at worst: + // each walk's own log line is a MODIFY that would schedule the next + // walk. Node files, the manifest, and directories still pass. + if !triggersReindex(raw.Name, relPath) { + continue + } + scheduled := WatchEvent{Kind: kind, Path: relPath} mu.Lock() @@ -280,6 +295,35 @@ func (instance *Watcher) watchNewDir(absPath string) { }) } +// triggersReindex reports whether a filesystem event should schedule a reindex +// walk. Only paths that can affect the index qualify: node files +// (.md/.html/.htm), the manifest (tusk.toml), and directories — whose +// create/rename/delete can move whole subtrees of nodes in or out. Any other +// existing regular file (a redirected .log, a .txt, an image, an extensionless +// Makefile) can never become a node, so its events are dropped; this closes the +// self-sustaining reindex loop a redirected log inside the tree would otherwise +// arm (each walk's own log write is a MODIFY that would schedule the next walk). +// +// The file-vs-directory split is decided by os.Stat rather than the extension so +// a directory whose name contains a dot ("archive.v2") is not mistaken for a +// foreign file. A vanished path (a delete or a rename's source) cannot be +// stat'd; those reindex conservatively so an orphaned subtree is reaped — and +// they can never loop, since a read-only walk never deletes or renames a vault +// file, so no delete/rename event is ever self-caused. +func triggersReindex(absPath, relPath string) bool { + if relPath == workspace.ManifestFilename || index.IsIndexableExt(relPath) { + return true + } + + info, statErr := os.Stat(absPath) + + if statErr != nil { + return true + } + + return info.IsDir() +} + func classify(op fsnotify.Op) EventKind { switch { case op&fsnotify.Create != 0: diff --git a/internal/watcher/watcher_test.go b/internal/watcher/watcher_test.go index 7faf6e96..a8919dac 100644 --- a/internal/watcher/watcher_test.go +++ b/internal/watcher/watcher_test.go @@ -165,6 +165,159 @@ func TestWatcher_SkipsIgnoredPaths(test *testing.T) { } } +// TestWatcher_DropsNonNodeFileEvents pins the fix for the redirect-into-tree +// rewalk loop: a write to a file whose extension can never be a node (a +// redirected .log, a .txt, an image) must NOT be delivered — otherwise +// `tusk graph -v > graph.log` inside the workspace arms a self-sustaining loop +// (each walk's log line is a MODIFY that schedules the next walk). Node files +// (.md/.html), the manifest (tusk.toml), and directory creates must still flow. +func TestWatcher_DropsNonNodeFileEvents(test *testing.T) { + root := test.TempDir() + + watcherInstance, newErr := watcher.New(root, newMatcher(test, root), nil) + + if newErr != nil { + test.Fatalf("New: %v", newErr) + } + + defer watcherInstance.Close() + + var ( + mu sync.Mutex + events []watcher.WatchEvent + ) + + handler := func(event watcher.WatchEvent) error { + mu.Lock() + events = append(events, event) + mu.Unlock() + + return nil + } + + ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second) + defer cancel() + + go func() { + _ = watcherInstance.Run(ctx, handler) + }() + + time.Sleep(100 * time.Millisecond) // let watcher start + + // The loop trigger: a log redirected into the watched tree. A .log file can + // never become a node, so this MODIFY must be dropped. + if writeErr := os.WriteFile(filepath.Join(root, "graph.log"), []byte("walk complete\n"), 0o644); writeErr != nil { + test.Fatalf("write graph.log: %v", writeErr) + } + + // A manifest edit must still schedule a walk. + if writeErr := os.WriteFile(filepath.Join(root, "tusk.toml"), []byte("[workspace]\nname = \"x\"\n"), 0o644); writeErr != nil { + test.Fatalf("write tusk.toml: %v", writeErr) + } + + // A real markdown edit must still flow — this also serves as the sync barrier. + if writeErr := os.WriteFile(filepath.Join(root, "notes.md"), []byte("hi"), 0o644); writeErr != nil { + test.Fatalf("write notes.md: %v", writeErr) + } + + time.Sleep(700 * time.Millisecond) // > debounce window + + mu.Lock() + defer mu.Unlock() + + sawNotes, sawManifest := false, false + + for _, evt := range events { + if evt.Path == "graph.log" { + test.Errorf("watcher delivered non-node file %q (would self-trigger reindex loop)", evt.Path) + } + + if evt.Path == "notes.md" { + sawNotes = true + } + + if evt.Path == "tusk.toml" { + sawManifest = true + } + } + + if !sawNotes { + test.Errorf("expected event for notes.md, got %+v", events) + } + + if !sawManifest { + test.Errorf("expected event for tusk.toml (manifest edits must reindex), got %+v", events) + } +} + +// TestWatcher_ReindexesOnDottedNameDirCreate pins the fix for a regression the +// extension-only filter would introduce: a directory whose NAME contains a dot +// ("archive.v2", or a hidden ".notes") must still schedule a reindex — its +// create/rename can move a whole subtree of nodes in or out, and that directory +// event is the only signal for pre-existing contents moved in wholesale. An +// extension heuristic reads "archive.v2" as a ".v2" file and drops it; os.Stat +// classifies the directory correctly. +func TestWatcher_ReindexesOnDottedNameDirCreate(test *testing.T) { + root := test.TempDir() + + watcherInstance, newErr := watcher.New(root, newMatcher(test, root), nil) + + if newErr != nil { + test.Fatalf("New: %v", newErr) + } + + defer watcherInstance.Close() + + var ( + mu sync.Mutex + events []watcher.WatchEvent + ) + + handler := func(event watcher.WatchEvent) error { + mu.Lock() + events = append(events, event) + mu.Unlock() + + return nil + } + + ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second) + defer cancel() + + go func() { + _ = watcherInstance.Run(ctx, handler) + }() + + time.Sleep(100 * time.Millisecond) // let watcher start + + // A directory with a dot in its name — the extension-only trap. + if mkErr := os.Mkdir(filepath.Join(root, "archive.v2"), 0o755); mkErr != nil { + test.Fatalf("mkdir archive.v2: %v", mkErr) + } + + // A real markdown edit as the sync barrier. + if writeErr := os.WriteFile(filepath.Join(root, "real.md"), []byte("hi"), 0o644); writeErr != nil { + test.Fatalf("write real.md: %v", writeErr) + } + + time.Sleep(700 * time.Millisecond) // > debounce window + + mu.Lock() + defer mu.Unlock() + + sawArchive := false + + for _, evt := range events { + if evt.Path == "archive.v2" { + sawArchive = true + } + } + + if !sawArchive { + test.Errorf("expected a reindex-triggering event for the dotted-name dir archive.v2, got %+v", events) + } +} + // TestWatcher_StopsTimersOnShutdown pins the A3 leak fix: a debounce timer // scheduled before shutdown must NOT fire afterwards. Before A3 the AfterFunc // timers were never stopped, so a cancelled watcher could still run a full