fix: back off a guest port that cannot converge, and name its ENI (#828)

Two ports on env19 have no tap behind them anywhere in the cluster:
their NB Logical_Switch_Port reads up: false and the SB Port_Binding
has chassis: [], so nothing can ever claim them. ensureGuestPortDatapath
is already bounded, but the outer reconcile loop calls it again every
cycle, so each dead port pays the full 45s nudge sequence and files
another ERROR roughly twelve times an hour, which is 1500 of vpcd's 1691
daily WARN lines and all of its ERRORs.

A port that burns its convergence deadline now backs off, doubling from
a minute to a thirty-minute cap, and clears the moment it binds. The
failure and recovery lines also carry the ENI, the EIP and the guest IP:
they previously named only the VPC and the LSP, so the guest behind a
stuck port could not be identified from telemetry.

spinifex/network/reconcile/apply.go

@@ -43,6 +43,63 @@ var (
 // reset re-syncs that view. Package var so tests can shrink it.
 var sbResetEscalateAfter = 3
 
+// Backoff applied to a guest port that burned its convergence deadline. Doubles
+// per consecutive failure from the base and holds at the cap. Package vars so
+// tests shorten them.
+var (
+	guestPortBackoffBase = time.Minute
+	guestPortBackoffMax  = 30 * time.Minute
+)
+
+// portBackoffUntil reports whether lspName is inside its convergence backoff,
+// and when that expires.
+func (r *reconciler) portBackoffUntil(lspName string) (time.Time, bool) {
+	r.portBackoffMu.Lock()
+	defer r.portBackoffMu.Unlock()
+	state, ok := r.portBackoff[lspName]
+	if !ok || !time.Now().Before(state.until) {
+		return time.Time{}, false
+	}
+	return state.until, true
+}
+
+// recordPortFailure counts another failed convergence for lspName and returns
+// the new consecutive-failure count and the backoff now in force.
+func (r *reconciler) recordPortFailure(lspName string) (int, time.Duration) {
+	r.portBackoffMu.Lock()
+	defer r.portBackoffMu.Unlock()
+	if r.portBackoff == nil {
+		r.portBackoff = map[string]portBackoffState{}
+	}
+	state := r.portBackoff[lspName]
+	state.failures++
+	backoff := guestPortBackoffBase << min(state.failures-1, 16)
+	if backoff > guestPortBackoffMax || backoff <= 0 {
+		backoff = guestPortBackoffMax
+	}
+	state.until = time.Now().Add(backoff)
+	r.portBackoff[lspName] = state
+	return state.failures, backoff
+}
+
+// clearPortBackoff drops any backoff for lspName, reporting whether one was held
+// so the caller can log the recovery rather than a routine convergence.
+func (r *reconciler) clearPortBackoff(lspName string) bool {
+	r.portBackoffMu.Lock()
+	defer r.portBackoffMu.Unlock()
+	if _, ok := r.portBackoff[lspName]; !ok {
+		return false
+	}
+	delete(r.portBackoff, lspName)
+	return true
+}
+
+// eniIDFromPort recovers the ENI a guest port belongs to. Telemetry carried only
+// the LSP name, which no operator can map back to a guest.
+func eniIDFromPort(lspName string) string {
+	return strings.TrimPrefix(lspName, "port-")
+}
+
 // applyVPCs ensures every intent VPC has a LogicalRouter. Stray OVN-only
 // routers are left alone.
 func (r *reconciler) applyVPCs(ctx context.Context, intent IntentState, actual ActualState) {
@@ -498,7 +555,7 @@ func (r *reconciler) applyEIPs(ctx context.Context, intent IntentState, _ Actual
 		if err := r.nat.AddEIP(ctx, spec); err != nil {
 			slog.Error("reconcile/apply: AddEIP failed", "external_ip", spec.ExternalIP, "logical_ip", spec.LogicalIP, "err", err)
 		}
-		r.ensureGuestPortDatapath(ctx, spec.VPCID, spec.PortName)
+		r.ensureGuestPortDatapath(ctx, spec)
 	}
 }
 
@@ -643,10 +700,19 @@ func subnetIDForIP(subnets map[string]topology.SubnetSpec, ip string) string {
 // not once: post-reboot the guest tap is replumbed seconds after this runs, so a
 // single early nudge fires before the port exists and never binds it. No-op when no
 // verifier is wired or the EIP carries no guest port.
-func (r *reconciler) ensureGuestPortDatapath(ctx context.Context, vpcID, lspName string) {
+func (r *reconciler) ensureGuestPortDatapath(ctx context.Context, spec policy.EIPSpec) {
+	vpcID, lspName := spec.VPCID, spec.PortName
 	if r.gwClaim == nil || lspName == "" {
 		return
 	}
+	// A port with no tap behind it never binds, so without this every cycle pays
+	// the full nudge sequence and files another ERROR for a guest that is gone.
+	if until, held := r.portBackoffUntil(lspName); held {
+		slog.Debug("reconcile/apply: guest port still in convergence backoff; not re-probing",
+			"vpc_id", vpcID, "lsp", lspName, "eni_id", eniIDFromPort(lspName),
+			"retry_in_ms", otelsetup.Millis(time.Until(until)))
+		return
+	}
 	deadline := time.Now().Add(guestPortDatapathTimeout)
 	nudged := false
 	misses := 0
@@ -658,7 +724,11 @@ func (r *reconciler) ensureGuestPortDatapath(ctx context.Context, vpcID, lspName
 			return
 		}
 		if up {
-			if nudged {
+			if r.clearPortBackoff(lspName) {
+				slog.Info("reconcile/apply: guest port datapath recovered after repeated failures",
+					"vpc_id", vpcID, "lsp", lspName, "eni_id", eniIDFromPort(lspName),
+					"external_ip", spec.ExternalIP, "logical_ip", spec.LogicalIP)
+			} else if nudged {
 				slog.Info("reconcile/apply: guest port datapath converged after recompute", "vpc_id", vpcID, "lsp", lspName)
 			}
 			return
@@ -674,8 +744,13 @@ func (r *reconciler) ensureGuestPortDatapath(ctx context.Context, vpcID, lspName
 			resetEscalated = r.escalateSBReset(ctx, "vpc_id", vpcID, "lsp", lspName)
 		}
 		if time.Now().After(deadline) {
+			failures, backoff := r.recordPortFailure(lspName)
 			slog.Error("reconcile/apply: guest port datapath did not converge; EIP ingress may be unreachable",
-				"vpc_id", vpcID, "lsp", lspName, "timeout_ms", otelsetup.Millis(guestPortDatapathTimeout))
+				"vpc_id", vpcID, "lsp", lspName, "eni_id", eniIDFromPort(lspName),
+				"external_ip", spec.ExternalIP, "logical_ip", spec.LogicalIP,
+				"consecutive_failures", failures,
+				"timeout_ms", otelsetup.Millis(guestPortDatapathTimeout),
+				"retry_in_ms", otelsetup.Millis(backoff))
 			return
 		}
 		select {

spinifex/network/reconcile/apply_gateway_claim_test.go

@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"github.com/mulgadc/spinifex/spinifex/network/ovn/nbdb"
+	"github.com/mulgadc/spinifex/spinifex/network/policy"
 )
 
 // fakeClaimVerifier scripts a sequence of GatewayPortClaimed results and counts
@@ -386,7 +387,7 @@ func TestEnsureGatewayDatapath_EIPUnreachableRepairs(t *testing.T) {
 
 func TestEnsureGuestPortDatapath_NoVerifierIsNoop(t *testing.T) {
 	r := &reconciler{} // gwClaim nil
-	r.ensureGuestPortDatapath(context.Background(), "vpc-a", "port-eni-1")
+	r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
 	// Reaching here without panic is the assertion.
 }
 
@@ -394,7 +395,7 @@ func TestEnsureGuestPortDatapath_EmptyLSPIsNoop(t *testing.T) {
 	f := &fakeClaimVerifier{}
 	r := &reconciler{gwClaim: f}
 
-	r.ensureGuestPortDatapath(context.Background(), "vpc-a", "")
+	r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a"})
 
 	if f.guestChecks != 0 {
 		t.Errorf("guestChecks = %d, want 0 (empty lsp must skip the probe)", f.guestChecks)
@@ -406,7 +407,7 @@ func TestEnsureGuestPortDatapath_UpNoNudge(t *testing.T) {
 	f := &fakeClaimVerifier{guestUpAfter: 0}
 	r := &reconciler{gwClaim: f}
 
-	r.ensureGuestPortDatapath(context.Background(), "vpc-a", "port-eni-1")
+	r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
 
 	if f.nudges != 0 {
 		t.Errorf("up guest port nudged %d times, want 0", f.nudges)
@@ -425,7 +426,7 @@ func TestEnsureGuestPortDatapath_NudgeThenConverge(t *testing.T) {
 	f := &fakeClaimVerifier{guestUpAfter: 1}
 	r := &reconciler{gwClaim: f}
 
-	r.ensureGuestPortDatapath(context.Background(), "vpc-a", "port-eni-1")
+	r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
 
 	if f.nudges != 1 {
 		t.Errorf("nudges = %d, want exactly 1 (nudge once, then converge)", f.nudges)
@@ -439,7 +440,7 @@ func TestEnsureGuestPortDatapath_NeverConvergesRecomputesEachMiss(t *testing.T)
 
 	done := make(chan struct{})
 	go func() {
-		r.ensureGuestPortDatapath(context.Background(), "vpc-a", "port-eni-1")
+		r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
 		close(done)
 	}()
 	select {
@@ -463,7 +464,7 @@ func TestEnsureGuestPortDatapath_ProbeErrorBailsOut(t *testing.T) {
 	f := &fakeClaimVerifier{guestErr: errors.New("ovn-sbctl down")}
 	r := &reconciler{gwClaim: f}
 
-	r.ensureGuestPortDatapath(context.Background(), "vpc-a", "port-eni-1")
+	r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
 
 	if f.nudges != 0 {
 		t.Errorf("nudges = %d, want 0 (bail out on probe error, do not nudge blindly)", f.nudges)
@@ -482,7 +483,7 @@ func TestEnsureGuestPortDatapath_ContextCancelStops(t *testing.T) {
 
 	done := make(chan struct{})
 	go func() {
-		r.ensureGuestPortDatapath(ctx, "vpc-a", "port-eni-1")
+		r.ensureGuestPortDatapath(ctx, policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
 		close(done)
 	}()
 	time.Sleep(20 * time.Millisecond)
@@ -551,7 +552,9 @@ func TestEnsureGuestPortDatapath_WedgedSBEscalatesResetOnce(t *testing.T) {
 	f := &fakeClaimVerifier{guestUpAfter: -1, sbNotConnected: true}
 	r := &reconciler{gwClaim: f}
 
-	runToDeadline(t, func() { r.ensureGuestPortDatapath(context.Background(), "vpc-a", "port-eni-1") })
+	runToDeadline(t, func() {
+		r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
+	})
 
 	if f.sbResets != 1 {
 		t.Errorf("sbResets = %d, want exactly 1 (escalate once on a wedged SB)", f.sbResets)
@@ -564,7 +567,9 @@ func TestEnsureGuestPortDatapath_ConnectedSBNeverResets(t *testing.T) {
 	f := &fakeClaimVerifier{guestUpAfter: -1, sbNotConnected: false}
 	r := &reconciler{gwClaim: f}
 
-	runToDeadline(t, func() { r.ensureGuestPortDatapath(context.Background(), "vpc-a", "port-eni-1") })
+	runToDeadline(t, func() {
+		r.ensureGuestPortDatapath(context.Background(), policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"})
+	})
 
 	if f.sbResets != 0 {
 		t.Errorf("sbResets = %d, want 0 (connected SB must never be reset)", f.sbResets)

spinifex/network/reconcile/apply_guest_port_backoff_test.go

@@ -0,0 +1,98 @@
+package reconcile
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	"github.com/mulgadc/spinifex/spinifex/network/policy"
+)
+
+// withFastGuestPortBackoff shrinks the post-failure backoff so a test can cross
+// it without sleeping for a minute.
+func withFastGuestPortBackoff(t *testing.T, base, ceiling time.Duration) {
+	t.Helper()
+	b, m := guestPortBackoffBase, guestPortBackoffMax
+	guestPortBackoffBase, guestPortBackoffMax = base, ceiling
+	t.Cleanup(func() { guestPortBackoffBase, guestPortBackoffMax = b, m })
+}
+
+// TestEnsureGuestPortDatapath_BacksOffAfterFailure covers the zombie port: one
+// whose guest is gone can never bind, so the second pass must cost nothing
+// rather than paying the whole nudge sequence again.
+func TestEnsureGuestPortDatapath_BacksOffAfterFailure(t *testing.T) {
+	withFastGuestPortBounds(t)
+	withFastGuestPortBackoff(t, time.Minute, time.Hour)
+
+	f := &fakeClaimVerifier{guestUpAfter: -1} // never up
+	r := &reconciler{gwClaim: f}
+	spec := policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"}
+
+	r.ensureGuestPortDatapath(context.Background(), spec)
+	afterFirst := f.nudges
+	if afterFirst == 0 {
+		t.Fatal("first pass nudged 0 times, want the full sequence")
+	}
+
+	r.ensureGuestPortDatapath(context.Background(), spec)
+	if f.nudges != afterFirst {
+		t.Errorf("nudges = %d after the second pass, want %d: a port inside its backoff must not be re-probed",
+			f.nudges, afterFirst)
+	}
+}
+
+// TestEnsureGuestPortDatapath_BackoffGrowsAndCaps checks the interval doubles
+// per consecutive failure and then holds, so a permanently dead port settles at
+// a fixed low rate instead of one report per reconcile cycle.
+func TestEnsureGuestPortDatapath_BackoffGrowsAndCaps(t *testing.T) {
+	r := &reconciler{}
+	withFastGuestPortBackoff(t, time.Minute, 8*time.Minute)
+
+	want := []time.Duration{time.Minute, 2 * time.Minute, 4 * time.Minute, 8 * time.Minute, 8 * time.Minute}
+	for i, w := range want {
+		failures, backoff := r.recordPortFailure("port-eni-1")
+		if failures != i+1 {
+			t.Errorf("failure %d: count = %d, want %d", i+1, failures, i+1)
+		}
+		if backoff != w {
+			t.Errorf("failure %d: backoff = %s, want %s", i+1, backoff, w)
+		}
+	}
+}
+
+// TestEnsureGuestPortDatapath_BackoffClearsOnConverge covers the guest coming
+// back: the port must be probed again immediately once it binds, and the held
+// backoff must not survive to delay the next real failure.
+func TestEnsureGuestPortDatapath_BackoffClearsOnConverge(t *testing.T) {
+	withFastGuestPortBounds(t)
+	withFastGuestPortBackoff(t, time.Millisecond, time.Millisecond)
+
+	f := &fakeClaimVerifier{guestUpAfter: -1}
+	r := &reconciler{gwClaim: f}
+	spec := policy.EIPSpec{VPCID: "vpc-a", PortName: "port-eni-1"}
+
+	r.ensureGuestPortDatapath(context.Background(), spec)
+	if _, held := r.portBackoffUntil(spec.PortName); held {
+		time.Sleep(2 * time.Millisecond)
+	}
+
+	// The guest comes back.
+	f.guestUpAfter = 0
+	f.nudges = 0
+	r.ensureGuestPortDatapath(context.Background(), spec)
+
+	if _, held := r.portBackoffUntil(spec.PortName); held {
+		t.Error("backoff still held after the port converged")
+	}
+	if _, ok := r.portBackoff[spec.PortName]; ok {
+		t.Error("backoff entry not cleared after the port converged")
+	}
+}
+
+// TestEniIDFromPort pins the attribution added to the failure log: the LSP name
+// alone cannot be mapped back to a guest.
+func TestEniIDFromPort(t *testing.T) {
+	if got := eniIDFromPort("port-eni-6b9b6e142f20ed708"); got != "eni-6b9b6e142f20ed708" {
+		t.Errorf("eniIDFromPort = %q, want %q", got, "eni-6b9b6e142f20ed708")
+	}
+}

spinifex/network/reconcile/reconcile.go

@@ -8,6 +8,8 @@ import (
 	"errors"
 	"fmt"
 	"log/slog"
+	"sync"
+	"time"
 
 	"github.com/mulgadc/spinifex/spinifex/network/external"
 	"github.com/mulgadc/spinifex/spinifex/network/ovn"
@@ -127,6 +129,18 @@ type reconciler struct {
 	ipsecEnabled bool
 	underlayMTU  int
 	reloadIntent func(ctx context.Context) (IntentState, error)
+
+	// Guest ports that burned their convergence deadline, so a port whose guest
+	// is gone stops paying the full nudge sequence every cycle.
+	portBackoffMu sync.Mutex
+	portBackoff   map[string]portBackoffState
+}
+
+// portBackoffState is one guest port's consecutive failure count and the instant
+// its backoff expires.
+type portBackoffState struct {
+	failures int
+	until    time.Time
 }
 
 var _ Reconciler = (*reconciler)(nil)