diff --git a/cmd/spinloop/remote_logs.go b/cmd/spinloop/remote_logs.go index 9a350145..2bb7081c 100644 --- a/cmd/spinloop/remote_logs.go +++ b/cmd/spinloop/remote_logs.go @@ -22,12 +22,6 @@ var logsFetchFn = remote.FetchLogs // on it. var logsFollowInterval = 5 * time.Second -// logsFollowOverlap is how far back of the last event a follow re-asks from. -// The shipping agent's delivery lag means an event can land with a timestamp -// slightly behind one already returned, so each poll deliberately re-reads a -// little and suppresses what it has already printed by event id. -const logsFollowOverlap = 10 * time.Second - // cmdRemoteLogs prints the logs an environment's instances shipped to // CloudWatch. It reads the durable store rather than the instance, so a boot // that failed and an instance that has since terminated are both still @@ -193,8 +187,7 @@ func followLogs(cfg remote.Config, q remote.LogQuery, format string) error { // caller so it can be driven directly. func followLogsLoop(ctx context.Context, cfg remote.Config, q remote.LogQuery, format string, w io.Writer) error { - printed := map[string]time.Time{} - newest := time.Time{} + cursor := remote.NewFollowCursor(remote.FollowOverlap) // Labelling is decided across the whole session, not per batch: a poll that // happened to return one instance's lines must not drop the prefix the // previous poll's lines carried. Once a second origin appears the output @@ -214,17 +207,9 @@ func followLogsLoop(ctx context.Context, cfg remote.Config, q remote.LogQuery, if first && res.Omitted > 0 && format != "json" { fmt.Fprintf(w, "... %d earlier events omitted (raise --limit to see more)\n", res.Omitted) } - fresh := make([]remote.LogEvent, 0, len(res.Events)) - for _, e := range res.Events { - if _, seen := printed[e.ID]; seen { - continue - } - printed[e.ID] = e.Timestamp + fresh := cursor.Advance(res.Events) + for _, e := range fresh { origins[e.Source+"/"+e.Instance] = true - fresh = append(fresh, e) - if e.Timestamp.After(newest) { - newest = e.Timestamp - } } if len(fresh) > 0 { if format == "json" { @@ -235,15 +220,8 @@ func followLogsLoop(ctx context.Context, cfg remote.Config, q remote.LogQuery, writeLogsText(w, fresh, len(origins) > 1) } } - // Only the overlap window can produce a duplicate, so ids older than - // it are forgotten and the map cannot grow with the session. - for id, ts := range printed { - if ts.Before(newest.Add(-2 * logsFollowOverlap)) { - delete(printed, id) - } - } - if !newest.IsZero() { - q.Start = newest.Add(-logsFollowOverlap) + if start := cursor.Start(); !start.IsZero() { + q.Start = start } select { case <-ctx.Done(): diff --git a/internal/fleet/remote_node.go b/internal/fleet/remote_node.go index ce46e029..088641ef 100644 --- a/internal/fleet/remote_node.go +++ b/internal/fleet/remote_node.go @@ -23,6 +23,12 @@ import ( type remoteNode struct { name string cfg remote.Config + // logs holds the position a follow of this node's engine log has reached. + // It is the same cursor `spinloop remote logs -f` uses, and for the same + // reason: CloudWatch has no resumable read position of its own, so a poll + // re-asks a little behind the newest event already seen and this + // suppresses what the overlap re-reads, by event id. + logs *remote.FollowCursor } // NewRemoteNode builds the live node for a named remote environment. The config @@ -35,7 +41,7 @@ func NewRemoteNode(name string, cfg remote.Config) (Node, error) { "remote environment %q is not fully configured: start_url, stop_url and region are all required", name) } - return &remoteNode{name: name, cfg: cfg}, nil + return &remoteNode{name: name, cfg: cfg, logs: remote.NewFollowCursor(remote.FollowOverlap)}, nil } func (n *remoteNode) Name() string { return n.name } @@ -96,18 +102,28 @@ func (n *remoteNode) Stop(ctx context.Context) (daemon.StatusResponse, error) { const remoteEngineTail = 1000 func (n *remoteNode) Logs(ctx context.Context, offset int64, limit int) (daemon.LogsResponse, error) { - // The offset is accepted to satisfy the node contract, but remote logs are a - // tail of the log store, not a position to resume from, so it is not a cursor. - _ = offset + // daemon.TailLog means a fresh open of the view: start the cursor over, + // so this open shows its own tail rather than having it suppressed as + // already seen by whatever this node last followed. + if offset == daemon.TailLog { + n.logs.Reset() + } + start := n.logs.Start() res, err := remote.FetchLogs(ctx, n.cfg, remote.LogQuery{ Environment: n.cfg.Environment, Source: remote.LogSourceEngine, Limit: remoteEngineTail, + Start: start, }) if err != nil { return daemon.LogsResponse{}, err } - return logsFromRemote(res), nil + fresh := n.logs.Advance(res.Events) + // Missing only on the read that had no lower bound yet finding nothing: + // that is genuinely no log, ever. A later poll with nothing new is a + // quiet log, not a missing one. + missing := start.IsZero() && len(res.Events) == 0 + return logsFromRemote(fresh, missing), nil } // statusFromRemote maps the control plane's status reply onto the node's status. @@ -142,22 +158,31 @@ func statsFromRemote(resp remote.StatsResponse) metrics.Stats { } } -// logsFromRemote maps a fetched log tail onto the node's log reply. Events arrive -// oldest first, so the content reads top to bottom. An empty tail is reported as -// a missing log rather than an empty one: that is the state a reader can act on -// (the engine has not run here, or has sent nothing). -func logsFromRemote(res remote.LogResult) daemon.LogsResponse { - if len(res.Events) == 0 { - return daemon.LogsResponse{Missing: true} +// logsFromRemote maps one poll's fresh events — the ones remoteNode.Logs's +// FollowCursor has not already returned — onto the node's log reply. Events +// arrive oldest first, so the content reads top to bottom. missing reports +// that this was a from-the-beginning read that found nothing: the state a +// reader can act on (the engine has not run here, or has sent nothing), +// distinct from a later poll simply having nothing new to add. NextOffset +// only needs to say "not a fresh open" to the next call — the real position +// lives in the node's own cursor — so it carries the newest event shown for +// whoever finds that useful to see, and 0 has the same effect when there is +// none. +func logsFromRemote(fresh []remote.LogEvent, missing bool) daemon.LogsResponse { + if len(fresh) == 0 { + return daemon.LogsResponse{Missing: missing} } - msgs := make([]string, len(res.Events)) - for i, e := range res.Events { + msgs := make([]string, len(fresh)) + for i, e := range fresh { msgs[i] = e.Message } - content := strings.Join(msgs, "\n") + // Each event is already one complete, discrete line — unlike a byte-stream + // tail, there is never a trailing partial line to leave unterminated — so + // the join ends in a newline the same way a local engine log's lines do. + content := strings.Join(msgs, "\n") + "\n" return daemon.LogsResponse{ Content: content, - NextOffset: int64(len(content)), + NextOffset: fresh[len(fresh)-1].Timestamp.UnixMilli(), Size: int64(len(content)), } } diff --git a/internal/fleet/remote_node_test.go b/internal/fleet/remote_node_test.go index c2c64e97..2ed8c729 100644 --- a/internal/fleet/remote_node_test.go +++ b/internal/fleet/remote_node_test.go @@ -2,13 +2,16 @@ package fleet import ( "context" + "encoding/json" "fmt" + "io" "net/http" "net/http/httptest" "path/filepath" "strings" "sync" "testing" + "time" "github.com/spinloop-ai/spinloop/internal/daemon" "github.com/spinloop-ai/spinloop/internal/metrics" @@ -89,18 +92,106 @@ func TestStatsFromRemote(t *testing.T) { } func TestLogsFromRemote(t *testing.T) { - if got := logsFromRemote(remote.LogResult{}); !got.Missing { - t.Errorf("an empty tail should be reported as a missing log, got %+v", got) + if got := logsFromRemote(nil, true); !got.Missing { + t.Errorf("no fresh events on a from-the-beginning read should be reported missing, got %+v", got) } - got := logsFromRemote(remote.LogResult{Events: []remote.LogEvent{ - {Message: "loading model"}, {Message: "server ready"}, - }}) - want := "loading model\nserver ready" + // No fresh events on a later poll — the common steady state once a follow + // is caught up — must not be reported missing: the log is not gone, it is + // just quiet right now. + if got := logsFromRemote(nil, false); got.Missing { + t.Errorf("no fresh events on a later poll should not be reported missing, got %+v", got) + } + + t1 := time.UnixMilli(1000) + t2 := time.UnixMilli(2000) + got := logsFromRemote([]remote.LogEvent{ + {Message: "loading model", Timestamp: t1}, {Message: "server ready", Timestamp: t2}, + }, false) + want := "loading model\nserver ready\n" if got.Content != want { t.Errorf("content = %q, want %q", got.Content, want) } - if got.NextOffset != int64(len(want)) || got.Size != int64(len(want)) { - t.Errorf("offset/size = %d/%d, want %d", got.NextOffset, got.Size, len(want)) + if got.NextOffset != t2.UnixMilli() { + t.Errorf("nextOffset = %d, want the newest event's millisecond %d", got.NextOffset, t2.UnixMilli()) + } + if got.Size != int64(len(want)) { + t.Errorf("size = %d, want %d", got.Size, len(want)) + } +} + +// A remote node's log follow uses the exact same cursor as `spinloop remote +// logs -f` (remote.FollowCursor, seeded with remote.FollowOverlap) — not a +// lookalike reimplementation — so a second poll bounds its query behind the +// newest event already shown by the same overlap window, and does not show +// that event again. The bug this guards is the tail being replayed in full +// on every poll regardless of what was already shown. +func TestRemoteNodeLogsSharesTheFollowCursorWithRemoteLogsCommand(t *testing.T) { + stubAWSCreds(t) + eventMs := time.Date(2026, 8, 9, 11, 30, 0, 0, time.UTC).UnixMilli() + + var mu sync.Mutex + served := map[string]bool{} + var starts []*int64 + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + body, _ := io.ReadAll(r.Body) + var in struct { + LogGroupName string `json:"logGroupName"` + StartTime *int64 `json:"startTime"` + } + json.Unmarshal(body, &in) + + mu.Lock() + starts = append(starts, in.StartTime) + first := !served[in.LogGroupName] + served[in.LogGroupName] = true + mu.Unlock() + + w.Header().Set("Content-Type", "application/x-amz-json-1.1") + if first { + // Each group ships the same one event, the first time it is asked — + // the fixture's stand-in for "the engine's log group has this". + fmt.Fprintf(w, `{"events":[{"eventId":"e1","timestamp":%d,"logStreamName":"env-1/i-1","message":"hello"}]}`, eventMs) + return + } + w.Write([]byte(`{"events":[]}`)) + })) + t.Cleanup(srv.Close) + t.Setenv("AWS_ENDPOINT_URL_CLOUDWATCH_LOGS", srv.URL) + cfg := remote.Config{StartURL: "http://x", StopURL: "http://x", Environment: "env-1", Region: "us-east-1"} + node, err := NewRemoteNode("env", cfg) + if err != nil { + t.Fatal(err) + } + + resp1, err := node.Logs(context.Background(), daemon.TailLog, 0) + if err != nil { + t.Fatalf("tail poll: %v", err) + } + if !strings.Contains(resp1.Content, "hello") { + t.Fatalf("the tail poll should show the event, got %+v", resp1) + } + for _, s := range starts { + if s != nil { + t.Errorf("the tail poll (offset TailLog) sent a start bound: %v", *s) + } + } + + starts = nil + resp2, err := node.Logs(context.Background(), 0, 0) + if err != nil { + t.Fatalf("follow-up poll: %v", err) + } + if resp2.Content != "" || resp2.Missing { + t.Errorf("the follow-up poll should show nothing new and not report missing, got %+v", resp2) + } + wantStart := eventMs - remote.FollowOverlap.Milliseconds() + for _, s := range starts { + if s == nil { + t.Fatal("the follow-up poll sent no start bound") + } + if *s != wantStart { + t.Errorf("start bound = %d, want the shared overlap behind the last event (%d)", *s, wantStart) + } } } diff --git a/internal/remote/follow.go b/internal/remote/follow.go new file mode 100644 index 00000000..86571ca5 --- /dev/null +++ b/internal/remote/follow.go @@ -0,0 +1,85 @@ +package remote + +import ( + "sync" + "time" +) + +// FollowOverlap is how far back of the newest event already seen a follow +// re-asks from by default. The shipping agent's delivery lag means an event +// can land with a timestamp slightly behind one already returned, so a poll +// deliberately re-reads a little; FollowCursor suppresses what it has +// already returned, by event id. Both `spinloop remote logs -f` and a fleet +// node's own log follow share this constant, so a fleet-dashboard poll and a +// standalone follow tolerate the same shipping lag. +const FollowOverlap = 10 * time.Second + +// FollowCursor turns repeated LogResult polls into a stream of events shown +// exactly once. CloudWatch offers no resumable read position — Start is a +// lower bound on a query, not a cursor a store can resume from — so a follow +// has to re-ask a little behind the newest event it has already seen, to +// catch anything the shipping agent delivered late, and then suppress by +// event id whatever that overlap re-reads. One cursor holds that state for +// the life of one follow, whether that follow is `spinloop remote logs -f` +// polling in a loop or a fleet node answering repeated Logs calls. +type FollowCursor struct { + overlap time.Duration + + mu sync.Mutex + printed map[string]time.Time + newest time.Time +} + +// NewFollowCursor starts an empty cursor that re-asks overlap behind the +// newest event seen on every poll. +func NewFollowCursor(overlap time.Duration) *FollowCursor { + return &FollowCursor{overlap: overlap, printed: map[string]time.Time{}} +} + +// Advance filters events down to the ones this cursor has not already +// returned, in the order given, and folds them into its state so a later +// poll that re-reads the overlap does not return them again. +func (c *FollowCursor) Advance(events []LogEvent) []LogEvent { + c.mu.Lock() + defer c.mu.Unlock() + fresh := make([]LogEvent, 0, len(events)) + for _, e := range events { + if _, seen := c.printed[e.ID]; seen { + continue + } + c.printed[e.ID] = e.Timestamp + fresh = append(fresh, e) + if e.Timestamp.After(c.newest) { + c.newest = e.Timestamp + } + } + // Only ids within the overlap window can ever be re-read, so anything + // older is forgotten and the map cannot grow across a long follow. + for id, ts := range c.printed { + if ts.Before(c.newest.Add(-2 * c.overlap)) { + delete(c.printed, id) + } + } + return fresh +} + +// Start is the query bound the next poll should use: zero until an event has +// been seen, then the overlap window behind the newest one. +func (c *FollowCursor) Start() time.Time { + c.mu.Lock() + defer c.mu.Unlock() + if c.newest.IsZero() { + return time.Time{} + } + return c.newest.Add(-c.overlap) +} + +// Reset drops everything the cursor has seen, as a follow restarted from the +// tail rather than continued needs: a fresh open should show its own tail +// again, not have it suppressed as already seen by a previous session. +func (c *FollowCursor) Reset() { + c.mu.Lock() + defer c.mu.Unlock() + c.printed = map[string]time.Time{} + c.newest = time.Time{} +} diff --git a/internal/remote/follow_test.go b/internal/remote/follow_test.go new file mode 100644 index 00000000..3b76317d --- /dev/null +++ b/internal/remote/follow_test.go @@ -0,0 +1,85 @@ +package remote + +import ( + "testing" + "time" +) + +func TestFollowCursorStartIsZeroUntilAnEventIsSeen(t *testing.T) { + c := NewFollowCursor(10 * time.Second) + if !c.Start().IsZero() { + t.Errorf("a fresh cursor's start bound = %v, want zero", c.Start()) + } +} + +func TestFollowCursorAdvanceSuppressesAlreadySeenIDs(t *testing.T) { + c := NewFollowCursor(10 * time.Second) + t1 := time.UnixMilli(1000) + t2 := time.UnixMilli(2000) + events := []LogEvent{{ID: "a", Timestamp: t1}, {ID: "b", Timestamp: t2}} + + fresh := c.Advance(events) + if len(fresh) != 2 { + t.Fatalf("first advance = %d fresh events, want 2", len(fresh)) + } + + // A later poll that re-reads the overlap window returns the same events — + // they must not come back as fresh a second time. + fresh = c.Advance(events) + if len(fresh) != 0 { + t.Errorf("re-advancing the same events returned %d as fresh, want 0", len(fresh)) + } + + t3 := time.UnixMilli(3000) + fresh = c.Advance([]LogEvent{{ID: "a", Timestamp: t1}, {ID: "c", Timestamp: t3}}) + if len(fresh) != 1 || fresh[0].ID != "c" { + t.Errorf("advancing a mixed batch = %+v, want only the new id", fresh) + } +} + +func TestFollowCursorStartTracksTheNewestEventBehindTheOverlap(t *testing.T) { + overlap := 10 * time.Second + c := NewFollowCursor(overlap) + newest := time.UnixMilli(50_000) + c.Advance([]LogEvent{{ID: "a", Timestamp: time.UnixMilli(10_000)}, {ID: "b", Timestamp: newest}}) + + want := newest.Add(-overlap) + if got := c.Start(); !got.Equal(want) { + t.Errorf("start = %v, want %v (the newest event minus the overlap)", got, want) + } +} + +func TestFollowCursorForgetsIDsOutsideTheOverlapWindow(t *testing.T) { + overlap := 10 * time.Second + c := NewFollowCursor(overlap) + old := time.UnixMilli(0) + c.Advance([]LogEvent{{ID: "old", Timestamp: old}}) + // Push the newest event far enough ahead that "old" falls outside twice + // the overlap window and is forgotten. + c.Advance([]LogEvent{{ID: "new", Timestamp: old.Add(3 * overlap)}}) + + // A duplicate delivery of the forgotten id now reads as fresh again — an + // acceptable, documented cost, since nothing that old should still be + // showing up in the overlap window a real poll re-reads. + fresh := c.Advance([]LogEvent{{ID: "old", Timestamp: old}}) + if len(fresh) != 1 { + t.Errorf("a forgotten id should be treated as fresh again, got %d fresh", len(fresh)) + } +} + +func TestFollowCursorResetForgetsEverything(t *testing.T) { + c := NewFollowCursor(10 * time.Second) + c.Advance([]LogEvent{{ID: "a", Timestamp: time.UnixMilli(1000)}}) + if c.Start().IsZero() { + t.Fatal("the cursor should have advanced past zero") + } + + c.Reset() + if !c.Start().IsZero() { + t.Errorf("a reset cursor's start bound = %v, want zero", c.Start()) + } + fresh := c.Advance([]LogEvent{{ID: "a", Timestamp: time.UnixMilli(1000)}}) + if len(fresh) != 1 { + t.Errorf("a reset cursor should show a previously-seen id again, got %d fresh", len(fresh)) + } +} diff --git a/openspec/changes/archive/2026-09-03-remote-node-log-follow/.openspec.yaml b/openspec/changes/archive/2026-09-03-remote-node-log-follow/.openspec.yaml new file mode 100644 index 00000000..9696e00f --- /dev/null +++ b/openspec/changes/archive/2026-09-03-remote-node-log-follow/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-09-03 diff --git a/openspec/changes/archive/2026-09-03-remote-node-log-follow/design.md b/openspec/changes/archive/2026-09-03-remote-node-log-follow/design.md new file mode 100644 index 00000000..86701d47 --- /dev/null +++ b/openspec/changes/archive/2026-09-03-remote-node-log-follow/design.md @@ -0,0 +1,83 @@ +## Context + +`internal/fleet.Node.Logs(ctx, offset, limit)` is the one method every node +kind — local daemon and remote environment — answers to serve `fleet logs` +and the dashboard's detail view. A local daemon node's `offset` is a real +byte position in a file, so the interface's int64 cursor maps onto it +directly. A remote environment's log store (CloudWatch, via +`internal/remote.FetchLogs`) has no equivalent resumable position: a query +only takes a `Start` time bound, and the shipping agent's delivery lag means +a bound alone can both miss events (bound set past them) and repeat events +(bound set before them, re-read on the next poll) — which is exactly why +`spinloop remote logs -f` already carries its own event-id dedup, keyed off +an overlap window behind the newest event seen, rather than using `Start` +as an exact cursor. See proposal.md for why the remote node's `Logs` skipped +all of this and what broke as a result. + +## Goals / Non-Goals + +**Goals:** +- One implementation of the dedup-by-id/overlap-window follow logic, used by + both `spinloop remote logs -f` and a remote fleet node's `Logs` call, so a + future change to that logic cannot fix one and leave the other broken. +- Keep `internal/fleet.Node`'s interface unchanged — the fix lives entirely + inside `remoteNode`. + +**Non-Goals:** +- Making a remote node's `Logs` cursor exact (immune to the rare + same-millisecond edge case the overlap window already tolerates for the + standalone command). Matching the standalone command's existing behavior + is the bar, not exceeding it. +- Changing anything about a local daemon node's log reading; it already + meets the no-duplicate requirement via a real byte offset. + +## Decisions + +**Extract the standalone follow's dedup state into `internal/remote.FollowCursor`, +and have `remoteNode` hold one per node instance.** + +`cmd/spinloop/remote_logs.go`'s `followLogsLoop` already carried exactly the +state needed (`printed map[string]time.Time`, `newest time.Time`) inline as +loop-local variables. Rather than reimplement similar logic against +`remoteNode`'s different lifetime (one `Logs` call per poll instead of one +loop), that state is lifted into a small exported type in `internal/remote` +— the package both call sites already depend on — with `Advance` (filter +events to the unseen ones, fold them into the cursor) and `Start` (the next +query's lower bound) as its interface. `followLogsLoop` now calls the same +two methods instead of its inline map. + +`remoteNode` holds its own `*FollowCursor` because the `Node.Logs(offset, +limit)` interface has nowhere else to keep it: the caller (`fleet.LogsCall`, +the dashboard's detail view) only threads back a single `int64`, which +cannot carry an id set. `remoteNode` is already a long-lived object — built +once per fleet session and called repeatedly across polls — so it is the +natural place for this state to live, the same way one `followLogsLoop` +invocation is the natural place for the standalone command's state to live. + +The `offset int64` the interface still passes is repurposed as a binary +signal rather than a position: `daemon.TailLog` means "start the cursor +over" (a fresh open of the view should show its own tail, not have it +suppressed as already seen by a previous open), anything else means +"continue". The real position lives in the node's own cursor. + +**Alternative considered**: encode the cursor as a plain millisecond +timestamp round-tripped through `offset`/`NextOffset`, bounding each query at +`offset+1ms` with no id-based dedup. This was the first fix attempted; it +removes the constant full-tail replay but reintroduces exactly the +same-millisecond duplicate/loss edge case the standalone command's overlap +window already solves, via a second, slightly different mechanism. Rejected +in favor of sharing the proven mechanism outright, which is also what the +user asked for directly. + +## Risks / Trade-offs + +- [The overlap window can still miss an event that shares its exact + millisecond with the event that set the window's edge, on both the + standalone command and the fleet node.] → Unchanged pre-existing behavior + of the mechanism being shared; not worsened by this change, and out of + scope per Non-Goals. +- [`remoteNode.Logs` fanning out over more than one engine log group + (`llamacpp`, `vllm`) can deliver the same event twice in one raw response + before dedup runs, if both groups happen to carry it.] → `FollowCursor.Advance` + dedupes by event id across the whole batch it is given, not per group, so + this collapses to one before any content is returned. diff --git a/openspec/changes/archive/2026-09-03-remote-node-log-follow/proposal.md b/openspec/changes/archive/2026-09-03-remote-node-log-follow/proposal.md new file mode 100644 index 00000000..8b404c85 --- /dev/null +++ b/openspec/changes/archive/2026-09-03-remote-node-log-follow/proposal.md @@ -0,0 +1,50 @@ +## Why + +A remote environment's `Logs` call ignored the resume position the fleet's +generic follow contract relies on (`fleet-client`'s "Following SHALL resume +each node from the position that node last returned, so a line already +printed is never printed twice"), always re-fetching and re-returning its +whole tail. Because `fleet dashboard`'s detail view and `fleet logs -f` +accumulate what a node returns rather than replacing it, this meant a remote +node's log pane or output repeated its most recent lines on every poll — +visibly, since a slow-loading engine's only output for minutes was the same +one or two startup lines, shown again every 3 seconds. The `remote-node` spec +names "read for logs" as one of the operations a remote environment answers +like any other node, but never states the resumption guarantee that +operation has to meet, so this gap went unwritten as well as unimplemented. + +## What Changes + +- A remote node's log read now resumes from where it last left off, sharing + the exact follow cursor (`internal/remote.FollowCursor`, dedup by event id + over an overlap window) that `spinloop remote logs -f` already used, so the + two follows behave identically and cannot drift apart. +- The `remote-node` spec gains an explicit requirement for the log-follow + guarantee a remote environment must meet, naming the shared cursor and the + "missing" vs. "quiet" distinction (no log ever vs. nothing new since the + last poll). + +## Capabilities + +### New Capabilities + +(none) + +### Modified Capabilities + +- `remote-node`: adds a requirement that reading a remote environment's logs + resumes from the position last returned — via the same follow cursor + `spinloop remote logs -f` uses — instead of re-reading its tail on every + poll, and that a from-the-beginning read finding nothing is reported + distinctly from a later poll finding nothing new. + +## Impact + +- `internal/fleet/remote_node.go`: `remoteNode.Logs` now holds and uses a + `*remote.FollowCursor`. +- `internal/remote/follow.go` (new): `FollowCursor` and `FollowOverlap`, + extracted from `cmd/spinloop/remote_logs.go`'s follow loop so both call + sites share one implementation. +- `cmd/spinloop/remote_logs.go`: `followLogsLoop` now uses `remote.FollowCursor` + instead of its own inline dedup map. +- No API or config surface changes; no breaking changes. diff --git a/openspec/changes/archive/2026-09-03-remote-node-log-follow/specs/remote-node/spec.md b/openspec/changes/archive/2026-09-03-remote-node-log-follow/specs/remote-node/spec.md new file mode 100644 index 00000000..4475b770 --- /dev/null +++ b/openspec/changes/archive/2026-09-03-remote-node-log-follow/specs/remote-node/spec.md @@ -0,0 +1,50 @@ +## ADDED Requirements + +### Requirement: Reading a remote environment's logs resumes without duplicating events + +A remote environment's log read SHALL resume from the position it last +returned rather than re-reading its whole tail on every call, so a fleet +node backed by a remote environment meets the same no-duplicate follow +guarantee a local node meets. It SHALL do so through the same follow cursor +`spinloop remote logs -f` uses — deduplicating by event id over a shared +overlap window — so the two follows cannot drift into different behavior. + +A read that finds nothing SHALL distinguish two states: a from-the-beginning +read that finds nothing, meaning the engine has never logged here, and a +later read that finds nothing new, meaning the log is quiet rather than +missing. Only the former SHALL be reported as a missing log. + +Opening a fresh follow of a node — for example, opening the fleet dashboard's +detail view on it — SHALL start the cursor over, so the fresh follow shows +its own tail rather than having it suppressed as already seen by a previous +follow of the same node. + +#### Scenario: A follow does not repeat events already shown + +- **WHEN** a remote node's log is polled repeatedly and the engine has + written no new output between two polls +- **THEN** the second poll returns no content, not the same events again + +#### Scenario: New output is shown once + +- **WHEN** the engine writes new output between two polls +- **THEN** only the new output is returned by the next poll, not the output + already returned by a previous one + +#### Scenario: A quiet poll is not reported as missing + +- **WHEN** a remote node's log has already shown output, and a later poll + finds nothing new +- **THEN** the log is not reported as missing + +#### Scenario: A log that has never shown output is reported as missing + +- **WHEN** a remote node's log is polled for the first time and the engine + has never logged anything +- **THEN** the log is reported as missing + +#### Scenario: Reopening a follow shows the tail again + +- **WHEN** a follow of a remote node's log is closed and reopened +- **THEN** the reopened follow shows the node's current tail, not an empty + result because those events were already shown by the previous follow diff --git a/openspec/changes/archive/2026-09-03-remote-node-log-follow/tasks.md b/openspec/changes/archive/2026-09-03-remote-node-log-follow/tasks.md new file mode 100644 index 00000000..acf87089 --- /dev/null +++ b/openspec/changes/archive/2026-09-03-remote-node-log-follow/tasks.md @@ -0,0 +1,37 @@ +## 1. Shared follow cursor + +- [x] 1.1 Add `internal/remote.FollowCursor` (dedup by event id over an + overlap window) and `internal/remote.FollowOverlap`, extracted from + `cmd/spinloop/remote_logs.go`'s inline follow state. +- [x] 1.2 Add unit tests for `FollowCursor`: start bound before/after an + event is seen, dedup of already-seen ids, pruning outside the overlap + window, and `Reset`. + +## 2. Standalone command uses the shared cursor + +- [x] 2.1 Rework `cmd/spinloop/remote_logs.go`'s `followLogsLoop` to use + `remote.NewFollowCursor(remote.FollowOverlap)` instead of its own + `printed`/`newest` maps, preserving existing behavior. +- [x] 2.2 Confirm the existing `TestFollow*` tests in `remote_logs_test.go` + still pass unmodified (they exercise `followLogsLoop` as a black box). + +## 3. Remote fleet node uses the shared cursor + +- [x] 3.1 Give `remoteNode` its own `*remote.FollowCursor`, created in + `NewRemoteNode`. +- [x] 3.2 Rework `remoteNode.Logs` to reset the cursor on `daemon.TailLog`, + bound its query with the cursor's `Start()`, and run the result + through `Advance()` before mapping it to a `daemon.LogsResponse`. +- [x] 3.3 Rework `logsFromRemote` to take the already-deduped fresh events + and a `missing` flag (true only for a from-the-beginning read that + found nothing), rather than a raw `LogResult` and an offset. +- [x] 3.4 Update `internal/fleet/remote_node_test.go`: `TestLogsFromRemote` + for the new signature and missing-vs-quiet distinction, and a test + that a follow-up poll bounds its CloudWatch query using + `remote.FollowOverlap` behind the last event shown. + +## 4. Verify + +- [x] 4.1 `go build ./...`, `go vet ./...`, `go test ./...` all pass. +- [x] 4.2 Confirm no other caller of `logsFromRemote` or `remoteNode.Logs` + needs updating for the new signatures. diff --git a/openspec/specs/remote-node/spec.md b/openspec/specs/remote-node/spec.md index 04e523ea..fba78f32 100644 --- a/openspec/specs/remote-node/spec.md +++ b/openspec/specs/remote-node/spec.md @@ -126,3 +126,52 @@ as a fleet of daemons alone. - **THEN** the fleet file is rejected, naming the node, because the name is the environment key +### Requirement: Reading a remote environment's logs resumes without duplicating events + +A remote environment's log read SHALL resume from the position it last +returned rather than re-reading its whole tail on every call, so a fleet +node backed by a remote environment meets the same no-duplicate follow +guarantee a local node meets. It SHALL do so through the same follow cursor +`spinloop remote logs -f` uses — deduplicating by event id over a shared +overlap window — so the two follows cannot drift into different behavior. + +A read that finds nothing SHALL distinguish two states: a from-the-beginning +read that finds nothing, meaning the engine has never logged here, and a +later read that finds nothing new, meaning the log is quiet rather than +missing. Only the former SHALL be reported as a missing log. + +Opening a fresh follow of a node — for example, opening the fleet dashboard's +detail view on it — SHALL start the cursor over, so the fresh follow shows +its own tail rather than having it suppressed as already seen by a previous +follow of the same node. + +#### Scenario: A follow does not repeat events already shown + +- **WHEN** a remote node's log is polled repeatedly and the engine has + written no new output between two polls +- **THEN** the second poll returns no content, not the same events again + +#### Scenario: New output is shown once + +- **WHEN** the engine writes new output between two polls +- **THEN** only the new output is returned by the next poll, not the output + already returned by a previous one + +#### Scenario: A quiet poll is not reported as missing + +- **WHEN** a remote node's log has already shown output, and a later poll + finds nothing new +- **THEN** the log is not reported as missing + +#### Scenario: A log that has never shown output is reported as missing + +- **WHEN** a remote node's log is polled for the first time and the engine + has never logged anything +- **THEN** the log is reported as missing + +#### Scenario: Reopening a follow shows the tail again + +- **WHEN** a follow of a remote node's log is closed and reopened +- **THEN** the reopened follow shows the node's current tail, not an empty + result because those events were already shown by the previous follow +