fix(fleet): retire a start's capacity wait on the next attempt

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) {

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)
 		}

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

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.

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)
 	}
 }
 

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