diff --git a/spinifex/handlers/imds/metadata.go b/spinifex/handlers/imds/metadata.go index 59e554b9a..907d4bbe6 100644 --- a/spinifex/handlers/imds/metadata.go +++ b/spinifex/handlers/imds/metadata.go @@ -237,7 +237,7 @@ func (s *IMDSServiceImpl) dispatch(w http.ResponseWriter, r *http.Request, eni * // A backend error counts as "no profile" so the iam/ subtree stays // self-consistent — 404 here rather than advertised with 404ing leaves, // which fails cloud-init's metadata crawl. - if profile, err := s.profileFor(ctx, eni); err != nil || profile == nil { + if profile, _, err := s.profileFor(ctx, eni); err != nil || profile == nil { w.WriteHeader(http.StatusNotFound) // no profile → no iam/ subtree, as on real EC2 return } @@ -373,12 +373,13 @@ func (s *IMDSServiceImpl) serveUserData(ctx context.Context, w http.ResponseWrit // serveIAMInfo writes the instance profile ARN and ID, or 404 if none is attached. func (s *IMDSServiceImpl) serveIAMInfo(ctx context.Context, w http.ResponseWriter, eni *eniFacts) { - profile, err := s.profileFor(ctx, eni) + profile, miss, err := s.profileFor(ctx, eni) if err != nil { w.WriteHeader(http.StatusInternalServerError) return } if profile == nil { + s.roleMiss.warn(ctx, eni, miss) w.WriteHeader(http.StatusNotFound) return } @@ -391,12 +392,15 @@ func (s *IMDSServiceImpl) serveIAMInfo(ctx context.Context, w http.ResponseWrite // serveSecurityCredentialsList writes the role name(s) under the profile. // No profile/role returns an empty 200; a backend failure returns 500. func (s *IMDSServiceImpl) serveSecurityCredentialsList(ctx context.Context, w http.ResponseWriter, eni *eniFacts) { - profile, err := s.profileFor(ctx, eni) + profile, miss, err := s.profileFor(ctx, eni) if err != nil { w.WriteHeader(http.StatusInternalServerError) return } if profile == nil || profile.RoleName == "" { + // The empty body is what an SDK reads as "no IMDS role"; it then keeps + // signing with credentials it can never refresh. Say why here or nowhere. + s.roleMiss.warn(ctx, eni, miss) writeText(w, "") return } @@ -406,12 +410,15 @@ func (s *IMDSServiceImpl) serveSecurityCredentialsList(ctx context.Context, w ht // serveRoleCredentials mints or returns cached credentials for the named role. // A name mismatch is 404; a backend failure resolving the profile is 500. func (s *IMDSServiceImpl) serveRoleCredentials(ctx context.Context, w http.ResponseWriter, eni *eniFacts, roleParam string) { - profile, err := s.profileFor(ctx, eni) + profile, miss, err := s.profileFor(ctx, eni) if err != nil { w.WriteHeader(http.StatusInternalServerError) return } if profile == nil || profile.RoleName == "" || roleParam != profile.RoleName { + // A name mismatch is the guest's own doing and carries roleMissNone, which + // warn ignores; only an unresolvable role is worth a line. + s.roleMiss.warn(ctx, eni, miss) w.WriteHeader(http.StatusNotFound) return } @@ -612,29 +619,37 @@ func (s *IMDSServiceImpl) instanceFor(ctx context.Context, w http.ResponseWriter return inst } -// profileFor resolves the IAM instance profile for an ENI. -// Returns (nil, nil) when absent, (nil, err) on backend failure — never collapses errors to absent. -func (s *IMDSServiceImpl) profileFor(ctx context.Context, eni *eniFacts) (*resolvedProfile, error) { +// profileFor resolves the IAM instance profile for an ENI. Returns (nil, why, +// nil) when absent and (nil, _, err) on backend failure — never collapses errors +// to absent. The reason exists because every absent case answers 200-empty or +// 404, which a guest cannot distinguish from having no role at all. +func (s *IMDSServiceImpl) profileFor(ctx context.Context, eni *eniFacts) (*resolvedProfile, roleMiss, error) { inst, err := s.resolver.resolveInstance(ctx, eni) if err != nil { slog.ErrorContext(ctx, "IMDS: instance resolution failed", "instance_id", eni.instanceID, "err", err) - return nil, err + return nil, roleMissNone, err } - if inst == nil || inst.iamInstanceProfileArn == "" { - return nil, nil + if inst == nil { + return nil, roleMissInstanceUnresolved, nil + } + if inst.iamInstanceProfileArn == "" { + return nil, roleMissNoProfile, nil } profile, err := s.iam.ResolveInstanceProfile(ctx, eni.iamAccountID(), inst.iamInstanceProfileArn) if err != nil { if err.Error() == awserrors.ErrorIAMNoSuchEntity { - return nil, nil // profile deleted; treat as no role + return nil, roleMissProfileDeleted, nil // profile deleted; treat as no role } slog.ErrorContext(ctx, "IMDS: resolve instance profile failed", "account_id", eni.iamAccountID(), "arn", inst.iamInstanceProfileArn, "err", err) - return nil, err + return nil, roleMissNone, err } if profile == nil { - return nil, nil + return nil, roleMissProfileDeleted, nil } - return &resolvedProfile{ARN: profile.ARN, InstanceProfileID: profile.InstanceProfileID, RoleName: profile.RoleName}, nil + if profile.RoleName == "" { + return nil, roleMissNoProfile, nil + } + return &resolvedProfile{ARN: profile.ARN, InstanceProfileID: profile.InstanceProfileID, RoleName: profile.RoleName}, roleMissNone, nil } // resolvedProfile is the slice of an IAM instance profile served by the metadata surface. diff --git a/spinifex/handlers/imds/metadata_test.go b/spinifex/handlers/imds/metadata_test.go index 7a61c4246..2bb39372f 100644 --- a/spinifex/handlers/imds/metadata_test.go +++ b/spinifex/handlers/imds/metadata_test.go @@ -135,6 +135,7 @@ func newTestService(res eniResolver, fIAM profileLookup, assumer stsAssumer) (*I v1Allow: newV1AllowCache(), creds: newCredCache(assumer), iam: fIAM, + roleMiss: newRoleMissLogger(func() time.Time { return now }), pubKeys: &fakePublicKeys{}, now: func() time.Time { return now }, baseDomain: "spx3.net", diff --git a/spinifex/handlers/imds/role_visibility.go b/spinifex/handlers/imds/role_visibility.go new file mode 100644 index 000000000..3069303f6 --- /dev/null +++ b/spinifex/handlers/imds/role_visibility.go @@ -0,0 +1,93 @@ +package handlers_imds + +import ( + "context" + "log/slog" + "sync" + "time" +) + +// roleMiss says why IMDS resolved no instance role. Every value ends in an +// empty role list or a 404, which an SDK reports as "no EC2 IMDS role found" +// and then keeps signing with whatever it already holds. +type roleMiss string + +const ( + // roleMissNone means a role was resolved. + roleMissNone roleMiss = "" + + // roleMissInstanceUnresolved: DescribeInstances returned nothing for the + // ENI's instance. Normal while an instance launches or terminates, a fault + // once the instance is running and its agents are calling the API. + roleMissInstanceUnresolved roleMiss = "instance_unresolved" + + // roleMissNoProfile: the instance record carries no instance profile ARN. + roleMissNoProfile roleMiss = "no_instance_profile" + + // roleMissProfileDeleted: the ARN is set but IAM no longer has the profile. + roleMissProfileDeleted roleMiss = "instance_profile_deleted" +) + +// roleMissLogInterval throttles the warning per instance and reason. An SDK +// that cannot refresh retries indefinitely — one stuck guest produced 42,517 +// role-list requests over five days — so logging every miss would bury the +// signal it is meant to raise. +const roleMissLogInterval = 5 * time.Minute + +// roleMissLogger warns the first time an instance cannot be given a role and +// then at most once per interval, so a stuck fleet stays legible. +type roleMissLogger struct { + interval time.Duration + now func() time.Time + + mu sync.Mutex + seen map[string]time.Time +} + +func newRoleMissLogger(now func() time.Time) *roleMissLogger { + return &roleMissLogger{interval: roleMissLogInterval, now: now, seen: make(map[string]time.Time)} +} + +// warn logs the miss unless the same instance and reason were logged inside the +// interval. Returns whether it logged, which the tests assert on. +func (l *roleMissLogger) warn(ctx context.Context, eni *eniFacts, reason roleMiss) bool { + if l == nil || reason == roleMissNone { + return false + } + + key := eni.instanceID + "\x00" + string(reason) + now := l.now() + + l.mu.Lock() + last, ok := l.seen[key] + if ok && now.Sub(last) < l.interval { + l.mu.Unlock() + return false + } + l.seen[key] = now + l.mu.Unlock() + + // Warn, not Error: on a launching or terminating instance this is expected. + // It is the persistence that matters, which is what the interval exposes. + slog.WarnContext(ctx, "IMDS: no instance role to serve; a guest holding expired credentials cannot refresh", + "reason", string(reason), + "instance_id", eni.instanceID, + "eni_id", eni.eniID, + "account_id", eni.iamAccountID()) + return true +} + +// sweep drops entries older than twice the interval so the map is bounded by +// the instances currently missing a role, not by every instance ever seen. +func (l *roleMissLogger) sweep(now time.Time) { + if l == nil { + return + } + l.mu.Lock() + defer l.mu.Unlock() + for key, last := range l.seen { + if now.Sub(last) > 2*l.interval { + delete(l.seen, key) + } + } +} diff --git a/spinifex/handlers/imds/role_visibility_test.go b/spinifex/handlers/imds/role_visibility_test.go new file mode 100644 index 000000000..abcdc3f9b --- /dev/null +++ b/spinifex/handlers/imds/role_visibility_test.go @@ -0,0 +1,140 @@ +package handlers_imds + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "log/slog" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/mulgadc/spinifex/spinifex/awserrors" + handlers_iam "github.com/mulgadc/spinifex/spinifex/handlers/iam" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// Each absent-role case must be distinguishable. Before this the three collapsed +// into one nil and the credential path failed with nothing in the logs. +func TestProfileForReportsWhyTheRoleIsMissing(t *testing.T) { + tests := []struct { + name string + res *fakeResolver + iam *fakeIAM + want roleMiss + }{ + { + name: "instance not visible", + res: &fakeResolver{eni: testENI()}, + iam: &fakeIAM{}, + want: roleMissInstanceUnresolved, + }, + { + name: "no profile attached", + res: &fakeResolver{eni: testENI(), inst: &instanceFacts{}}, + iam: &fakeIAM{}, + want: roleMissNoProfile, + }, + { + name: "profile deleted from IAM", + res: &fakeResolver{eni: testENI(), inst: &instanceFacts{iamInstanceProfileArn: "arn:aws:iam::111122223333:instance-profile/gone"}}, + iam: &fakeIAM{profileErr: errors.New(awserrors.ErrorIAMNoSuchEntity)}, + want: roleMissProfileDeleted, + }, + { + name: "role resolved", + res: &fakeResolver{eni: testENI(), inst: &instanceFacts{iamInstanceProfileArn: "arn:aws:iam::111122223333:instance-profile/app"}}, + iam: &fakeIAM{profile: &handlers_iam.InstanceProfile{ARN: "arn", InstanceProfileID: "AIPA", RoleName: "app"}}, + want: roleMissNone, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + svc, _ := newTestService(tc.res, tc.iam, &fakeAssumer{}) + + profile, miss, err := svc.profileFor(context.Background(), testENI()) + + require.NoError(t, err) + assert.Equal(t, tc.want, miss) + assert.Equal(t, tc.want == roleMissNone, profile != nil) + }) + } +} + +// A backend failure is an error, not a miss: it 500s rather than answering an +// empty role list, so attributing it to the guest would be wrong. +func TestProfileForKeepsBackendFailuresAsErrors(t *testing.T) { + svc, _ := newTestService(&fakeResolver{eni: testENI(), instErr: errors.New("nats timeout")}, &fakeIAM{}, &fakeAssumer{}) + + profile, miss, err := svc.profileFor(context.Background(), testENI()) + + require.Error(t, err) + assert.Nil(t, profile) + assert.Equal(t, roleMissNone, miss) +} + +// One stuck guest produced 42,517 role-list requests over five days, so the +// warning has to survive that volume without burying itself. +func TestRoleMissLoggerThrottlesPerInstanceAndReason(t *testing.T) { + now := time.Unix(1_700_000_000, 0).UTC() + l := newRoleMissLogger(func() time.Time { return now }) + eni := testENI() + + assert.True(t, l.warn(context.Background(), eni, roleMissInstanceUnresolved), "first miss must log") + assert.False(t, l.warn(context.Background(), eni, roleMissInstanceUnresolved), "repeat inside the interval must not") + assert.True(t, l.warn(context.Background(), eni, roleMissNoProfile), "a different reason is a different fault") + + other := testENI() + other.instanceID = "i-9999999999" + assert.True(t, l.warn(context.Background(), other, roleMissInstanceUnresolved), "a second instance must log on its own") + + now = now.Add(roleMissLogInterval + time.Second) + assert.True(t, l.warn(context.Background(), eni, roleMissInstanceUnresolved), "past the interval it must log again") +} + +// roleMissNone is the resolved case and must never produce a line. +func TestRoleMissLoggerIgnoresResolvedRoles(t *testing.T) { + l := newRoleMissLogger(time.Now) + assert.False(t, l.warn(context.Background(), testENI(), roleMissNone)) +} + +// The map is keyed by instance, so without a sweep a long-lived vpcd would +// accumulate an entry for every instance that ever missed. +func TestRoleMissLoggerSweepBoundsTheMap(t *testing.T) { + now := time.Unix(1_700_000_000, 0).UTC() + l := newRoleMissLogger(func() time.Time { return now }) + + require.True(t, l.warn(context.Background(), testENI(), roleMissInstanceUnresolved)) + l.sweep(now.Add(roleMissLogInterval)) + assert.Len(t, l.seen, 1, "an entry inside the window is still throttling") + + l.sweep(now.Add(3 * roleMissLogInterval)) + assert.Empty(t, l.seen) +} + +// The empty role list is what an SDK reads as "no IMDS role" before it goes on +// signing with credentials it cannot refresh. That answer must not be silent. +func TestSecurityCredentialsListLogsAnUnresolvableRole(t *testing.T) { + svc, _ := newTestService(&fakeResolver{eni: testENI()}, &fakeIAM{}, &fakeAssumer{}) + + var buf bytes.Buffer + restore := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelWarn}))) + t.Cleanup(func() { slog.SetDefault(restore) }) + + rec := httptest.NewRecorder() + svc.serveSecurityCredentialsList(context.Background(), rec, testENI()) + + require.Equal(t, http.StatusOK, rec.Code) + assert.Empty(t, rec.Body.String()) + + var line map[string]any + require.NoError(t, json.Unmarshal(bytes.TrimSpace(buf.Bytes()), &line)) + assert.Equal(t, string(roleMissInstanceUnresolved), line["reason"]) + assert.Equal(t, "i-0123456789", line["instance_id"]) + assert.Equal(t, "eni-aaa", line["eni_id"]) +} diff --git a/spinifex/handlers/imds/service.go b/spinifex/handlers/imds/service.go index c99710840..02667e4f0 100644 --- a/spinifex/handlers/imds/service.go +++ b/spinifex/handlers/imds/service.go @@ -65,6 +65,7 @@ type IMDSServiceImpl struct { v1Allow *v1AllowCache creds *credCache iam profileLookup + roleMiss *roleMissLogger pubKeys publicKeyLookup tapResp *tapResponderManager listTaps listTapsFunc @@ -142,6 +143,7 @@ func NewIMDSServiceImpl(ctx context.Context, natsConn *nats.Conn, sts stsAssumer v1Allow: newV1AllowCache(), creds: newCredCache(sts), iam: iamSvc, + roleMiss: newRoleMissLogger(time.Now), pubKeys: pubKeys, listTaps: listTaps, now: time.Now, @@ -232,6 +234,7 @@ func (s *IMDSServiceImpl) sweepExpired(ctx context.Context) { s.tokens.sweep(now) s.creds.sweep(now) s.v1Allow.sweep(now) + s.roleMiss.sweep(now) } } }