From 3789535fdeb2d4f7f605d449bdc9a6e5f0543506 Mon Sep 17 00:00:00 2001 From: scttfrdmn <3011922+scttfrdmn@users.noreply.github.com> Date: Tue, 18 Aug 2026 19:27:08 -0700 Subject: [PATCH] fix: status no longer presents an unread TTL as a resolved "none" Three related defects in `spawn status`/`spored status`: 1. When spored can't read its own tags (e.g. the #502 IAM gap), the config load failure was silently swallowed into zero-value defaults, and status rendered "TTL: none -- instance will not auto-terminate" -- a definite claim from data that was never actually read. Added Config.ConfigLoadError, threaded from the provider's tag-load failure, so status can render "TTL: UNKNOWN -- could not read config ()" instead. 2. That on-instance line could sit directly above spawn status's own "Termination deadline: " (read from tags with the CALLER's credentials) with nothing connecting the two -- an operator had to notice the contradiction by hand. spawn status now detects this exact combination and prints an explicit "Lifecycle mismatch" notice. 3. Started/Elapsed described the status-agent invocation's own age, not the instance's, falling back to time.Now() when the spawn:launch-time tag couldn't be read -- exactly the failure mode in (1) -- so a 7h39m-old instance reported "Elapsed: 0s". Added a second fallback tier: EC2's own PendingTime from the instance identity document via IMDS, which needs no IAM permission, so the instance's real age survives a tag-read failure. The fallback source is labelled inline when it isn't the authoritative tag. Fixes #508 --- CHANGELOG.md | 26 +++++++++++ cmd/spored/main.go | 65 ++++++++++++++++++++++---- cmd/spored/resolve_launch_time_test.go | 40 ++++++++++++++++ cmd/status.go | 38 +++++++++++++++ cmd/status_test.go | 59 +++++++++++++++++++++++ pkg/provider/ec2.go | 6 +++ pkg/provider/provider.go | 28 +++++++++-- 7 files changed, 249 insertions(+), 13 deletions(-) create mode 100644 cmd/spored/resolve_launch_time_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index cedae84..e01b8e5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -69,6 +69,32 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 the instance branch of `RemoveResource`, matching its volume/key-pair/ security-group siblings, so a real (non-dry-run) sweep of stale residue reports a satisfied request instead of a doomed `Terminate` failure. +- **`spawn status`/`spored status` could print mutually contradictory + lifecycle statements in one screen, and misreported an instance's actual + age** (#508). Three related defects: + 1. When `spored` couldn't read its own tags (e.g. the #502 IAM gap, or any + `ec2:DescribeTags` denial), the config load failure was silently + swallowed into zero-value defaults, and status rendered `TTL: none — + instance will not auto-terminate` — a definite claim asserted from data + that was never actually read. It now renders `TTL: UNKNOWN — could not + read config ()` in that case, via a new `Config.ConfigLoadError` + field threaded from the provider's tag-load failure. + 2. That on-instance "none"/"UNKNOWN" line could appear directly above + `spawn status`'s own `Termination deadline: ` (read from tags with + the *caller's*, not the instance's, credentials) with nothing + connecting the two. `spawn status` now detects this specific + combination and prints an explicit "Lifecycle mismatch" notice: the + deadline tag exists, but the instance cannot see it, so nothing on the + instance will enforce it. + 3. `Started`/`Elapsed` described the *status-agent invocation's* age, not + the instance's — falling back to `time.Now()` when the + `spawn:launch-time` tag couldn't be read, which is exactly the failure + mode above, so a 7h39m-old instance reported `Elapsed: 0s`. Added a + second fallback tier: EC2's own `PendingTime` from the instance identity + document (via IMDS, no IAM permission required), so the instance's real + age survives a tag-read failure and only falls back to the agent's own + start time when IMDS is also unavailable. The fallback source is now + labelled inline when it isn't the authoritative tag. ## [0.100.2] - 2026-08-18 diff --git a/cmd/spored/main.go b/cmd/spored/main.go index 5c565f8..3b3fcb6 100644 --- a/cmd/spored/main.go +++ b/cmd/spored/main.go @@ -345,6 +345,39 @@ func newCompleteCmd() *cobra.Command { return cmd } +// launchTimeSourceTag/IMDS/Estimated label which source resolveLaunchTime +// used, most to least authoritative. Exported as constants so callers can +// compare against them without restating the literal strings (and so a typo +// in one place can't silently desync the comparison from the label). +const ( + launchTimeSourceTag = "spawn:launch-time tag" + launchTimeSourceIMDS = "EC2 instance identity (IMDS)" + launchTimeSourceEstimated = "estimated (status agent start — actual instance age unavailable)" +) + +// resolveLaunchTime picks the most authoritative available source for the +// instance's actual launch time, most to least authoritative (spawn#508): +// 1. tagLaunchTime — the spawn:launch-time tag, read via ec2:DescribeTags. +// Authoritative when readable. +// 2. pendingTime — EC2's own record of when this instance's launch was +// requested, read from the instance identity document via IMDS. Needs NO +// IAM permission, so it survives exactly the failure mode (#502-style +// DescribeTags denial) that makes (1) unavailable — this is what turns +// "Elapsed: 0s" on a 7h-old instance into the instance's real age even +// when tags can't be read. +// 3. statusAgentStart — this status-agent invocation's own start time. Last +// resort; only reached when both the tag AND IMDS are unavailable. Using +// this as "Started"/"Elapsed" (unlabelled) was the spawn#508 bug. +func resolveLaunchTime(tagLaunchTime, pendingTime, statusAgentStart time.Time) (time.Time, string) { + if !tagLaunchTime.IsZero() { + return tagLaunchTime, launchTimeSourceTag + } + if !pendingTime.IsZero() { + return pendingTime, launchTimeSourceIMDS + } + return statusAgentStart, launchTimeSourceEstimated +} + func handleStatus(checkComplete bool) error { // Create agent to get configuration and metrics ctx := context.Background() @@ -409,7 +442,12 @@ func handleStatus(checkComplete bool) error { idleTime = time.Since(ag.GetLastActivityTime()) } - // Calculate start time + // Calculate start time — this is the STATUS AGENT INVOCATION's own start + // (this process, which runs fresh on every `spored status` call), not the + // instance's. It is only ever used as a last-resort fallback below: using + // it as "Started"/"Elapsed" is exactly the spawn#508 bug (a 7h39m-old + // instance reported "Elapsed: 0s" because this was the only source + // available when the tag-authoritative LaunchTime couldn't be read). startTime := time.Now().Add(-uptime) // ── Identity ────────────────────────────────────────────────────────────── @@ -417,11 +455,7 @@ func handleStatus(checkComplete bool) error { fmt.Printf(" %s\n\n", strings.Repeat("─", 46)) fmt.Printf(" spored: v%s\n", version()) - // Use original launch time from tag if available; fall back to startTime - launchTime := startTime - if !config.LaunchTime.IsZero() { - launchTime = config.LaunchTime - } + launchTime, launchTimeSource := resolveLaunchTime(config.LaunchTime, identity.PendingTime, startTime) elapsed := time.Since(launchTime) computeSecs := ag.TotalComputeSeconds() computeTime := time.Duration(computeSecs) * time.Second @@ -448,12 +482,27 @@ func handleStatus(checkComplete bool) error { if computeTime > 0 && stoppedTime > 0 { fmt.Printf(" (%s compute · %s stopped)", formatDuration(computeTime), formatDuration(stoppedTime)) } + if launchTimeSource != launchTimeSourceTag { + // Only annotate the fallback paths — the common case (the tag read + // cleanly) stays unadorned. Surfacing the source is exactly what #508 + // needed: "Elapsed: 0s" with no indication it was the status agent's + // own age, not the instance's. + fmt.Printf(" (source: %s)", launchTimeSource) + } fmt.Println() - if !terminateAt.IsZero() { + // config.ConfigLoadError is set only when the tag read itself failed + // (ec2:DescribeTags denied, etc, spawn#502/#508) — in that case every + // zero-value config field is UNKNOWN, not unset, and rendering "TTL: none" + // asserts a specific, possibly-false fact ("will not auto-terminate") + // from data that was never actually read. + switch { + case config.ConfigLoadError != "": + fmt.Printf(" TTL: UNKNOWN — could not read config (%s)\n", config.ConfigLoadError) + case !terminateAt.IsZero(): fmt.Printf(" TTL: %s remaining (terminates %s)\n", formatDuration(ttlRemaining), terminateAt.UTC().Format("2006-01-02 15:04 UTC")) - } else { + default: fmt.Println(" TTL: none — instance will not auto-terminate") } diff --git a/cmd/spored/resolve_launch_time_test.go b/cmd/spored/resolve_launch_time_test.go new file mode 100644 index 0000000..de7800e --- /dev/null +++ b/cmd/spored/resolve_launch_time_test.go @@ -0,0 +1,40 @@ +package main + +import ( + "testing" + "time" +) + +// TestResolveLaunchTime is the spawn#508 regression test: a status run must +// never present the status-agent's own start time as the instance's age +// (Elapsed) without at least degrading gracefully through IMDS's +// PendingTime — which needs no IAM permission — before falling all the way +// back to "estimated". Before this fix, a #502-affected instance (DescribeTags +// denied) fell straight from "no LaunchTime tag" to the agent's own start +// time, so a 7h39m-old instance reported Elapsed: 0s. +func TestResolveLaunchTime(t *testing.T) { + tag := time.Date(2026, 8, 17, 22, 26, 0, 0, time.UTC) + pending := time.Date(2026, 8, 17, 22, 25, 58, 0, time.UTC) + agentStart := time.Date(2026, 8, 18, 6, 5, 30, 0, time.UTC) // ~7h39m after pending + + t.Run("tag present => tag wins, regardless of the others", func(t *testing.T) { + got, source := resolveLaunchTime(tag, pending, agentStart) + if !got.Equal(tag) || source != launchTimeSourceTag { + t.Errorf("got (%v, %q), want (%v, %q)", got, source, tag, launchTimeSourceTag) + } + }) + + t.Run("tag absent, IMDS present => IMDS wins over the agent's own start (the core #508 fix)", func(t *testing.T) { + got, source := resolveLaunchTime(time.Time{}, pending, agentStart) + if !got.Equal(pending) || source != launchTimeSourceIMDS { + t.Errorf("got (%v, %q), want (%v, %q) — must not fall through to the agent's own start when IMDS PendingTime is available", got, source, pending, launchTimeSourceIMDS) + } + }) + + t.Run("both absent => falls back to the agent's own start, labelled as an estimate", func(t *testing.T) { + got, source := resolveLaunchTime(time.Time{}, time.Time{}, agentStart) + if !got.Equal(agentStart) || source != launchTimeSourceEstimated { + t.Errorf("got (%v, %q), want (%v, %q)", got, source, agentStart, launchTimeSourceEstimated) + } + }) +} diff --git a/cmd/status.go b/cmd/status.go index 78d2d0b..bac1251 100644 --- a/cmd/status.go +++ b/cmd/status.go @@ -127,6 +127,7 @@ func runStatus(cmd *cobra.Command, args []string) error { } fmt.Print(string(output)) + fmt.Print(ttlReconciliationNotice(instance, string(output))) fmt.Print(lifecycleProtectionBlock(instance)) fmt.Print(dnsStatusNotice(instance)) fmt.Print(sporedUpgradeNotice(instance.Tags["spawn:spored-version"], string(output), instance.InstanceID)) @@ -214,6 +215,42 @@ func lifecycleDeadline(instance *aws.InstanceInfo) (time.Time, bool) { return time.Time{}, false } +// ttlReconciliationNotice detects and calls out spawn#508's core symptom: the +// on-instance status output (statusOutput, from spored, sourced from EC2 +// tags read WITH THE INSTANCE'S OWN CREDENTIALS) says the instance has no TTL +// or couldn't determine one, while the CLI's OWN view of the same instance's +// tags (read with the caller's credentials, via instance.Tags — usually a +// broader IAM principal than the instance role) shows a live +// spawn:ttl-deadline. That combination is not two independent facts to +// present side by side and let the operator reconcile by hand — it IS the +// finding: the deadline exists, but nothing on the instance can see it, so +// nothing on the instance will enforce it. Returns "" when there's nothing to +// reconcile (the on-instance view agrees, or there's no deadline at all). +func ttlReconciliationNotice(instance *aws.InstanceInfo, statusOutput string) string { + onInstanceUnresolved := strings.Contains(statusOutput, "TTL: none — instance will not auto-terminate") || + strings.Contains(statusOutput, "TTL: UNKNOWN") + if !onInstanceUnresolved { + return "" // on-instance view already resolved a TTL; nothing to reconcile + } + + deadline, haveDeadline := lifecycleDeadline(instance) + if !haveDeadline { + return "" // no tag-based deadline either — the on-instance "none" is consistent + } + + remaining := time.Until(deadline) + if remaining <= 0 { + return fmt.Sprintf("\n%s Lifecycle mismatch: spored (on-instance) could not resolve a TTL, but the "+ + "spawn:ttl-deadline tag (%s) is already past due. Nothing on the instance is enforcing it — "+ + "terminate manually if this instance should be gone.\n", + i18n.Symbol("warning"), deadline.UTC().Format("2006-01-02 15:04 UTC")) + } + return fmt.Sprintf("\n%s Lifecycle mismatch: spored (on-instance) could not resolve a TTL, but "+ + "spawn:ttl-deadline (read from tags with YOUR credentials) says %s (in %s). The instance cannot "+ + "see its own deadline, so nothing on it will enforce this automatically — see the likely cause below.\n", + i18n.Symbol("warning"), deadline.UTC().Format("2006-01-02 15:04 UTC"), formatDuration(remaining)) +} + // elasticIPNotice returns a line describing any Elastic IP attached to the // instance, or "" if none. On a running instance it's informational; on a // stopped instance it's a billable-leak warning (an EIP keeps billing while the @@ -289,6 +326,7 @@ func runStatusOverSSM(ctx context.Context, client *aws.Client, instance *aws.Ins out += res.Stderr } fmt.Print(out) + fmt.Print(ttlReconciliationNotice(instance, out)) fmt.Print(lifecycleProtectionBlock(instance)) fmt.Print(dnsStatusNotice(instance)) fmt.Print(sporedUpgradeNotice(instance.Tags["spawn:spored-version"], out, instance.InstanceID)) diff --git a/cmd/status_test.go b/cmd/status_test.go index 86e7374..dfde2ea 100644 --- a/cmd/status_test.go +++ b/cmd/status_test.go @@ -231,3 +231,62 @@ func TestStatusOutputModes(t *testing.T) { }) } } + +// TestTTLReconciliationNotice is the spawn#508 regression test: `spawn +// status` used to print `TTL: none — instance will not auto-terminate` +// (from the on-instance spored output, sourced with the instance's own +// credentials) directly above `Termination deadline: ` (from +// lifecycleProtectionBlock, reading the same tags with the CALLER's +// credentials) with nothing connecting the two — an operator had to notice +// the contradiction and guess which was true. ttlReconciliationNotice must +// surface that combination explicitly instead of leaving it implicit. +func TestTTLReconciliationNotice(t *testing.T) { + future := time.Now().Add(3 * time.Hour).UTC().Format(time.RFC3339) + past := time.Now().Add(-1 * time.Hour).UTC().Format(time.RFC3339) + + t.Run("on-instance none + tag deadline exists => mismatch warning", func(t *testing.T) { + inst := &aws.InstanceInfo{Tags: map[string]string{"spawn:ttl-deadline": future}} + statusOutput := " TTL: none — instance will not auto-terminate\n" + got := ttlReconciliationNotice(inst, statusOutput) + if !strings.Contains(got, "Lifecycle mismatch") { + t.Errorf("expected a mismatch notice, got %q", got) + } + if !strings.Contains(got, "could not resolve a TTL") { + t.Errorf("notice should name the on-instance symptom, got %q", got) + } + }) + + t.Run("on-instance UNKNOWN (config load failed) + tag deadline exists => mismatch warning", func(t *testing.T) { + inst := &aws.InstanceInfo{Tags: map[string]string{"spawn:ttl-deadline": future}} + statusOutput := " TTL: UNKNOWN — could not read config (access denied)\n" + got := ttlReconciliationNotice(inst, statusOutput) + if !strings.Contains(got, "Lifecycle mismatch") { + t.Errorf("expected a mismatch notice for the UNKNOWN case too, got %q", got) + } + }) + + t.Run("on-instance none + PAST DUE tag deadline => past-due variant", func(t *testing.T) { + inst := &aws.InstanceInfo{Tags: map[string]string{"spawn:ttl-deadline": past}} + statusOutput := " TTL: none — instance will not auto-terminate\n" + got := ttlReconciliationNotice(inst, statusOutput) + if !strings.Contains(got, "past due") { + t.Errorf("expected the past-due variant, got %q", got) + } + }) + + t.Run("on-instance none + NO tag deadline => nothing to reconcile", func(t *testing.T) { + inst := &aws.InstanceInfo{Tags: map[string]string{}} + statusOutput := " TTL: none — instance will not auto-terminate\n" + if got := ttlReconciliationNotice(inst, statusOutput); got != "" { + t.Errorf("expected empty when there's no tag deadline to conflict with, got %q", got) + } + }) + + t.Run("on-instance RESOLVED a TTL => nothing to reconcile even if tag deadline present", func(t *testing.T) { + inst := &aws.InstanceInfo{Tags: map[string]string{"spawn:ttl-deadline": future}} + statusOutput := " TTL: 2h30m0s remaining (terminates 2026-08-18 15:00 UTC)\n" + if got := ttlReconciliationNotice(inst, statusOutput); got != "" { + t.Errorf("expected empty when the on-instance view already agrees, got %q", got) + } + }) +} diff --git a/pkg/provider/ec2.go b/pkg/provider/ec2.go index 5061676..d08aecc 100644 --- a/pkg/provider/ec2.go +++ b/pkg/provider/ec2.go @@ -85,6 +85,7 @@ func NewEC2Provider(ctx context.Context) (*EC2Provider, error) { PublicIP: publicIP, PrivateIP: privateIP, Provider: "ec2", + PendingTime: idDoc.PendingTime, } // Update config with region @@ -98,6 +99,11 @@ func NewEC2Provider(ctx context.Context) (*EC2Provider, error) { providerConfig = &Config{ IdleCPUPercent: 5.0, Observability: observability.DefaultConfig(), + // Every field above is a default, not a measurement — a caller + // (spawn status/spored status) must not present TTL=0/IdleTimeout=0 + // as "no TTL configured" when the real story is "couldn't read the + // config that says otherwise" (spawn#508). + ConfigLoadError: err.Error(), } instanceName = "" } diff --git a/pkg/provider/provider.go b/pkg/provider/provider.go index c0b9850..711f94f 100644 --- a/pkg/provider/provider.go +++ b/pkg/provider/provider.go @@ -18,6 +18,16 @@ type Identity struct { PublicIP string // Public IP address PrivateIP string // Private IP address Provider string // "ec2" or "local" + + // PendingTime is EC2's own record of when this instance's launch was + // requested, read from the instance identity document via IMDS — no + // ec2:DescribeTags/DescribeInstances permission required, unlike + // spawn:launch-time. It is the instance's actual age, not the invoking + // CLI/agent process's age: `spored status` used to fall back to + // time.Now() (its OWN start time) when spawn:launch-time couldn't be + // read, so a 7h-old instance reported "Elapsed: 0s" (spawn#508). Zero for + // the local provider. + PendingTime time.Time } // PluginDeclaration references a plugin to install at instance startup. @@ -28,11 +38,19 @@ type PluginDeclaration struct { // Config represents the agent configuration type Config struct { - TTL time.Duration - TTLDeadline time.Time // absolute deadline = launch_time + TTL; authoritative across stop/wake cycles - LaunchTime time.Time // original launch time; never resets on stop/wake - ComputeSeconds int64 // accumulated compute seconds since launch (updated by spored) - EBSHourlyCost float64 // actual EBS cost per hour (queried at first start, tagged for reuse) + TTL time.Duration + TTLDeadline time.Time // absolute deadline = launch_time + TTL; authoritative across stop/wake cycles + LaunchTime time.Time // original launch time; never resets on stop/wake + + // ConfigLoadError, when non-empty, means the config below is NOT what the + // instance's tags actually say — the load failed (e.g. ec2:DescribeTags + // denied, spawn#502/#508) and every zero-value field is "unknown", not + // "unset". A caller displaying TTL/IdleTimeout/etc. MUST check this before + // rendering an absent value as a resolved one (e.g. "TTL: none — instance + // will not auto-terminate" when the truth is "TTL: could not be read"). + ConfigLoadError string + ComputeSeconds int64 // accumulated compute seconds since launch (updated by spored) + EBSHourlyCost float64 // actual EBS cost per hour (queried at first start, tagged for reuse) IdleTimeout time.Duration HibernateOnIdle bool CostLimit float64