fix: log why IMDS cannot serve an instance role (#818)

An unresolvable instance role answers an empty 200 on the
security-credentials list and a 404 on the credential itself. An SDK reads
that as "no EC2 IMDS role found" and keeps signing with whatever it already
holds, so a guest whose credentials have expired retries forever and never
recovers. On wattle four guests did this for five days: 42,517 role-list
requests, no credential fetches, and not one line anywhere saying why.

The absence was invisible because three layers returned a silent nil -
DescribeInstances missing the instance, no instance profile ARN on the
record, and a profile IAM no longer has. profileFor now reports which of
those it hit, and the two credential paths warn on it, throttled to one line
per instance and reason every five minutes so a stuck fleet stays legible at
that request volume. A role-name mismatch is the guest's own doing and stays
silent.

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.

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",

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

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"])
+}

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