From d610609c0fc9c1b0e5ad89aa75b02cfbdc1c6129 Mon Sep 17 00:00:00 2001 From: Pete Cornish Date: Thu, 3 Sep 2026 22:23:10 +0100 Subject: [PATCH] fix(fleet): retire a start's capacity wait once the next attempt goes out MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A remote start refused for capacity reports "instance no-capacity; retrying in 120s" — true until the next attempt is issued. The attempt that finds capacity then holds one request for the whole boot and reports nothing more, so the dashboard tile, which shows the latest line as the node's current situation, went on reporting a capacity wait for minutes, beside its own refreshes reporting the node running. remote.Start already has the fix: it calls onState with StateInFlight when a fresh attempt goes out, exactly so an observer can retire the previous attempt's verdict. The fleet node passed nil for it, so only the CLI got the benefit. Wire it through, and turn it into a line the tile can show. Guard a nil progress callback while here: remote.Start writes its lines unconditionally, so a caller passing nil was relying on which paths the start happened to take. Add the elapsed time beside the in-flight verb, recomputed on each repaint. A start's lines can legitimately stand unchanged for minutes, so a moving number is what separates a tile that is waiting from one that is wedged. --- cmd/spinloop/dashboard_model.go | 36 +++++++++-- cmd/spinloop/dashboard_render.go | 2 +- cmd/spinloop/fleet_dashboard_test.go | 30 +++++++++ internal/fleet/remote_node.go | 35 +++++++++- internal/fleet/remote_node_test.go | 96 +++++++++++++++++++++++++++- openspec/specs/fleet-client/spec.md | 27 ++++++++ 6 files changed, 217 insertions(+), 9 deletions(-) diff --git a/cmd/spinloop/dashboard_model.go b/cmd/spinloop/dashboard_model.go index 99e3323c..20c62348 100644 --- a/cmd/spinloop/dashboard_model.go +++ b/cmd/spinloop/dashboard_model.go @@ -41,12 +41,13 @@ type dashEntry struct { } // dashAction is the board's account of a start or stop in flight on one -// node: the verb, the last line the call has reported, and the call's own -// context — the abort's door. A node with nothing in flight carries the zero -// value. +// node: the verb, the last line the call has reported, when the action began, +// and the call's own context — the abort's door. A node with nothing in +// flight carries the zero value. type dashAction struct { verb string // "start" or "stop" line string // the call's latest status line; empty until it reports one + since time.Time // when the action was issued; zero where the board has no clock on it cancel context.CancelFunc // end the wait on the call; nil where the zero value sits aborted bool // the operator ended the wait, so the line says so } @@ -115,6 +116,33 @@ func dashVerbProgress(verb string) string { return verb + "ing" } +// dashNow is the board's clock. A variable so a test can pin what an in-flight +// tile draws for elapsed time. +var dashNow = time.Now + +// dashActionProgress is the tile's in-flight heading: the verb, with how long +// the action has been running once the board has a clock on it. +// +// The elapsed time is the tile's heartbeat. A start's own status lines can +// legitimately stand unchanged for minutes — the attempt that finds capacity +// holds one request for the whole boot and says nothing while it does — so +// without a moving number there is no way to tell a tile that is waiting from +// one that is wedged. It is computed on every repaint rather than baked into a +// line when that line arrives, which is the difference between a heartbeat and +// another thing that can go stale; the board's tick repaints a couple of times +// a second's worth of the way there, often enough for the number to move. +func dashActionProgress(a dashAction) string { + verb := dashVerbProgress(a.verb) + if a.since.IsZero() { + return verb + } + elapsed := dashNow().Sub(a.since) + if elapsed < 0 { + elapsed = 0 + } + return verb + " " + formatDuration(int(elapsed.Seconds())) +} + // dashActionProgressMsg is one intermediate line of a call behind an in- // flight action, sent to the program by the call's own goroutine as the work // proceeds. @@ -424,7 +452,7 @@ func (m *dashModel) beginAction(verb string) tea.Cmd { return nil } ctx, cancel := context.WithCancel(context.Background()) - m.actions[m.cursor] = dashAction{verb: verb, cancel: cancel} + m.actions[m.cursor] = dashAction{verb: verb, since: dashNow(), cancel: cancel} m.statusLine = dashVerbProgress(verb) + " " + e.name + "…" send := m.send progress := func(line string) { diff --git a/cmd/spinloop/dashboard_render.go b/cmd/spinloop/dashboard_render.go index a9565ef5..2ed13951 100644 --- a/cmd/spinloop/dashboard_render.go +++ b/cmd/spinloop/dashboard_render.go @@ -194,7 +194,7 @@ func dashNodeContentLines(name string, r fleet.NodeResult, a dashAction) []strin var b strings.Builder switch { case a.verb != "": - fmt.Fprintf(&b, "%s %s\n", name, dashVerbProgress(a.verb)) + fmt.Fprintf(&b, "%s %s\n", name, dashActionProgress(a)) if a.line != "" { fmt.Fprintln(&b, a.line) } diff --git a/cmd/spinloop/fleet_dashboard_test.go b/cmd/spinloop/fleet_dashboard_test.go index 871f85e7..46df9fe4 100644 --- a/cmd/spinloop/fleet_dashboard_test.go +++ b/cmd/spinloop/fleet_dashboard_test.go @@ -375,6 +375,36 @@ func TestDashTileActionInFlight(t *testing.T) { } } +// The elapsed time beside the verb is the tile's heartbeat. A start's own +// status lines can legitimately stand unchanged for minutes — the attempt that +// finds capacity holds one request for the whole boot and says nothing while +// it does — so the moving number is what tells the operator the tile is +// waiting rather than wedged. It is drawn from the board's clock on every +// repaint, not baked into a line when that line arrives. +func TestDashTileActionInFlightShowsElapsed(t *testing.T) { + lipgloss.SetColorProfile(termenv.Ascii) + now := time.Now() + dashNow = func() time.Time { return now } + t.Cleanup(func() { dashNow = time.Now }) + + a := dashAction{verb: "start", since: now.Add(-150 * time.Second), + line: "instance no-capacity; retrying in 120s"} + want := dashTileExpected([]string{ + dashHealthGlyph(dashAttention) + " dev-2 starting 2m 30s", + "instance no-capacity; retrying in 120s", + "", "", "", "", "", "", "", "", "", "", + }) + if got := dashTile("dev-2", fleet.NodeResult{Name: "dev-2"}, false, a); got != want { + t.Errorf("elapsed in-flight tile mismatch:\ngot:\n%q\nwant:\n%q", got, want) + } + // The same tile a minute later, with nothing else having changed: the + // number has moved, which is the whole point of it. + now = now.Add(time.Minute) + if got := dashTile("dev-2", fleet.NodeResult{Name: "dev-2"}, false, a); !strings.Contains(got, "starting 3m 30s") { + t.Errorf("the elapsed time did not move with the clock:\n%q", got) + } +} + // A report that lands while an action is in flight shows on the tile beside // the call's own lines: the call says what the operator asked for, the report // says what the node is doing — a boot half done already carries a state and diff --git a/internal/fleet/remote_node.go b/internal/fleet/remote_node.go index 088641ef..6eb3d512 100644 --- a/internal/fleet/remote_node.go +++ b/internal/fleet/remote_node.go @@ -68,15 +68,46 @@ func (n *remoteNode) Start(ctx context.Context) (daemon.StatusResponse, error) { // StartWithProgress is Start carrying the control plane's own status lines up // as the boot proceeds — the environment's state and the wait to the next -// poll, one line per retry. The caller shows or drops them. +// poll, one line per retry, plus a line of its own each time a fresh attempt +// goes out. The caller shows or drops them. func (n *remoteNode) StartWithProgress(ctx context.Context, progress func(string)) (daemon.StatusResponse, error) { - resp, err := remote.Start(ctx, n.cfg, progress, nil, nil) + if progress == nil { + // remote.Start writes its lines unconditionally; a caller that wants + // none says so by passing nil rather than by being lucky about which + // paths the start happens to take. + progress = func(string) {} + } + onState := func(state string) { + if line := startStateLine(state); line != "" { + progress(line) + } + } + resp, err := remote.Start(ctx, n.cfg, progress, onState, nil) if err != nil { return daemon.StatusResponse{}, err } return statusFromRemote(*resp), nil } +// startStateLine is the progress line a poll's state earns, or "" for the +// states that already have one. +// +// Only StateInFlight earns one, and it exists to retire a stale wait notice. +// remote.Start's own progress lines are written immediately before a wait +// ("instance no-capacity; retrying in 120s") and are true only until the next +// attempt goes out — but the attempt that finds capacity holds its single +// request for the whole boot, minutes, and writes nothing more. A caller that +// scrolls its lines is fine either way; a caller that shows the latest line as +// the node's current situation — the dashboard tile — would otherwise go on +// reporting a capacity wait long after the instance was up and serving. This +// is the client-side report StateInFlight was added for. +func startStateLine(state string) string { + if state == remote.StateInFlight { + return "waking the instance…" + } + return "" +} + // StartWith is how a router wakes a node to serve something. A remote environment // is not woken: what it serves is set by `spinloop remote deploy`, a heavier flow // (provisioning, weight seeding, ingress) that a node start must not conflate. diff --git a/internal/fleet/remote_node_test.go b/internal/fleet/remote_node_test.go index 2ed8c729..bdfbe4fc 100644 --- a/internal/fleet/remote_node_test.go +++ b/internal/fleet/remote_node_test.go @@ -8,6 +8,7 @@ import ( "net/http" "net/http/httptest" "path/filepath" + "slices" "strings" "sync" "testing" @@ -424,8 +425,99 @@ func TestRemoteNodeStartWithProgressReportsTheBoot(t *testing.T) { if attempts != 2 { t.Errorf("start attempts = %d (want 2)", attempts) } - if len(lines) < 1 || !strings.Contains(lines[0], "instance starting; retrying in 1s") { - t.Errorf("progress lines = %q (want the boot's retry line)", lines) + // Each attempt announces itself, and the retry between them carries the + // control plane's own wording. + want := []string{"waking the instance…", "instance starting; retrying in 1s", "waking the instance…"} + if !slices.Equal(lines, want) { + t.Errorf("progress lines = %q (want %q)", lines, want) + } +} + +// The bug this guards: a start refused for capacity, then granted. The refusal +// writes "instance no-capacity; retrying in 120s" — true until the next +// attempt goes out, and the attempt that finds capacity then holds its single +// request for the whole boot without writing anything more. A caller that +// shows the latest line as the node's current situation (the dashboard tile) +// would go on reporting a capacity wait for the rest of the start, beside its +// own refreshes reporting the instance running. The last line a start reports +// must never be the retired capacity notice. +func TestRemoteNodeStartWithProgressRetiresACapacityWait(t *testing.T) { + stubAWSCreds(t) + var ( + mu sync.Mutex + lines []string + attempts int + ) + mux := http.NewServeMux() + mux.HandleFunc("POST /start", func(w http.ResponseWriter, r *http.Request) { + mu.Lock() + attempts++ + first := attempts == 1 + mu.Unlock() + w.Header().Set("Content-Type", "application/json") + if first { // no GPU to be had in any zone yet + w.WriteHeader(http.StatusServiceUnavailable) + w.Write([]byte(`{"state":"no-capacity","retryAfterSeconds":1}`)) + return + } + w.Write([]byte(`{"state":"ready","healthy":true}`)) + }) + srv := httptest.NewServer(mux) + t.Cleanup(srv.Close) + cfg := remote.Config{StartURL: srv.URL + "/start", StopURL: srv.URL + "/start", Region: "us-east-1"} + node, err := NewRemoteNode("env", cfg) + if err != nil { + t.Fatal(err) + } + starter := node.(ProgressStarter) + if _, err := starter.StartWithProgress(context.Background(), func(line string) { + mu.Lock() + lines = append(lines, line) + mu.Unlock() + }); err != nil { + t.Fatalf("StartWithProgress: %v", err) + } + mu.Lock() + defer mu.Unlock() + if len(lines) == 0 { + t.Fatal("the start reported nothing at all") + } + // The wait was reported when it was true... + if !slices.ContainsFunc(lines, func(l string) bool { return strings.Contains(l, "no-capacity") }) { + t.Errorf("progress lines = %q (want the capacity refusal reported)", lines) + } + // ...and retired by the attempt that superseded it. + if last := lines[len(lines)-1]; strings.Contains(last, "no-capacity") { + t.Errorf("the start's last line is the retired capacity wait: %q (all: %q)", last, lines) + } +} + +// A start that wants no progress lines says so with a nil callback, and is not +// relying on which paths the start happens to take: remote.Start writes its +// lines unconditionally, so every one of them has to land somewhere safe. +func TestRemoteNodeStartWithProgressAcceptsNoReporter(t *testing.T) { + stubAWSCreds(t) + var attempts int + mux := http.NewServeMux() + mux.HandleFunc("POST /start", func(w http.ResponseWriter, r *http.Request) { + attempts++ + w.Header().Set("Content-Type", "application/json") + if attempts == 1 { + w.WriteHeader(http.StatusServiceUnavailable) + w.Write([]byte(`{"state":"no-capacity","retryAfterSeconds":1}`)) + return + } + w.Write([]byte(`{"state":"ready","healthy":true}`)) + }) + srv := httptest.NewServer(mux) + t.Cleanup(srv.Close) + cfg := remote.Config{StartURL: srv.URL + "/start", StopURL: srv.URL + "/start", Region: "us-east-1"} + node, err := NewRemoteNode("env", cfg) + if err != nil { + t.Fatal(err) + } + if _, err := node.(ProgressStarter).StartWithProgress(context.Background(), nil); err != nil { + t.Fatalf("StartWithProgress with no reporter: %v", err) } } diff --git a/openspec/specs/fleet-client/spec.md b/openspec/specs/fleet-client/spec.md index 0bacbc0a..5b6913c0 100644 --- a/openspec/specs/fleet-client/spec.md +++ b/openspec/specs/fleet-client/spec.md @@ -695,6 +695,19 @@ SHALL change nothing on the tile. Each finished action SHALL clear the action from its node's tile, which is then the node's report alone, and leave its outcome on the status line, the one-shot wording. +The tile SHALL show the verb with how long the action has been running, counted +from when the operator issued it and recomputed as the tile is repainted rather +than fixed when a status line arrives. A start's status lines can stand +unchanged for minutes — the attempt that succeeds holds one request for the +whole boot and reports nothing while it does — so the elapsed time is what +distinguishes a tile that is waiting from one that is wedged. + +A status line a node reports SHALL describe the node's situation now, not a +situation that has since been superseded. A line that is true only until the +node's next attempt — a wait before a retry, and the reason for it — SHALL be +replaced when that attempt is issued, so a tile never goes on reporting a +refused start beside its own refreshes reporting the node running. + The outcome of an action SHALL be shown inside the dashboard (a status line the operator can read before the next refresh replaces attention), and a refused or unreachable action SHALL NOT close the dashboard. What an action changes in state @@ -754,6 +767,20 @@ never invited to press a key that would do nothing there. - **AND** when the start finishes, the tile is the node's report alone and the outcome is on the status line +#### Scenario: A start's elapsed time keeps moving + +- **WHEN** a start is in flight and reports no new status line for some time +- **THEN** the elapsed time beside the verb keeps advancing on the tile, so the + operator can tell the start is still waiting rather than wedged + +#### Scenario: A refused start does not outlive its refusal + +- **WHEN** a node's start is refused for want of capacity, and a later attempt + is issued once capacity is free +- **THEN** the tile reports the capacity wait while it holds, and stops + reporting it once the next attempt is under way, rather than showing it + beside a refresh that reports the node running + #### Scenario: An in-flight start before any report - **WHEN** the operator starts a node before any refresh of it has answered