fix(lbagent): quiet expected startup heartbeat failures below ERROR (#579)

A freshly launched LB agent begins heartbeating the instant the VM boots,
but the gateway node fielding that first heartbeat may not yet have the LB
record — it is still replicating from the node that created it — so the
gateway answers 400 LoadBalancerNotFound. The IMDS credential chain is
likewise not always warm on the first tick. Both self-heal within a few
ticks, yet every early failure was logged at ERROR, flooding the console
telemetry with startup noise (46 such lines across 8 agents in one run).

Bound these to a registration grace window: before any heartbeat has ever
succeeded, and only within the window, a failure logs at INFO. Past the
window with no success — the fingerprint of a genuinely blackholed agent —
or after any prior success, a failure logs at ERROR as before, so the
serial-console telemetry still surfaces a real blackhole. The only change
for a persistent failure is a bounded delay before it escalates.

spinifex/lbagent/agent.go

@@ -43,6 +43,15 @@ const (
 
 	// pollInterval is how often the agent sends a heartbeat.
 	pollInterval = 5 * time.Second
+
+	// registrationGrace bounds how long startup heartbeat failures are logged
+	// below ERROR. A freshly launched LB races its own record's replication to
+	// the gateway node that fields the first heartbeat, so early failures
+	// (LoadBalancerNotFound, IMDS credentials not yet warm) are expected and
+	// self-heal within a few ticks. Past this window with no success — the
+	// fingerprint of a genuinely network-blackholed agent — failures escalate
+	// to ERROR so the serial-console telemetry still surfaces them.
+	registrationGrace = 60 * time.Second
 )
 
 // Data-plane engine names (duplicated from handlers/elbv2 to avoid an import cycle).
@@ -69,6 +78,12 @@ type Agent struct {
 	healthTargets   []HealthTarget // active probe targets (nginx/NLB only)
 	stopCh          chan struct{}
 
+	// startedAt anchors the registration grace window; firstHeartbeatOK
+	// records whether any heartbeat has ever succeeded. Both are touched only
+	// from the single poll goroutine (Start -> tick), so they need no lock.
+	startedAt        time.Time
+	firstHeartbeatOK bool
+
 	// For testing: override the reload functions (HAProxy / nginx).
 	reloadFn      func(configPath, pidPath string) error
 	reloadNginxFn func(configPath, pidPath string) error
@@ -127,6 +142,7 @@ func New(lbID, gatewayURL, accessKey, secretKey, region string) (*Agent, error)
 		signer:        signer,
 		client:        client,
 		stopCh:        make(chan struct{}),
+		startedAt:     time.Now(),
 		reloadFn:      reloadHAProxy,
 		reloadNginxFn: reloadNginx,
 		statsFn:       queryHAProxyStats,
@@ -184,9 +200,21 @@ func (a *Agent) tick() {
 		// Include the dial target so the serial console disambiguates a
 		// transport failure (never reached AWSGW — "send request: dial ...")
 		// from an HTTP-level rejection ("gateway returned NNN: ...").
+		//
+		// Before the first successful heartbeat, and only within the grace
+		// window, a failure is an expected startup race (record not yet
+		// replicated, credentials not yet warm) and logs at INFO. Past the
+		// window, or once any heartbeat has succeeded, a failure is real and
+		// logs at ERROR so the console telemetry still catches a blackhole.
+		if !a.firstHeartbeatOK && time.Since(a.startedAt) < registrationGrace {
+			slog.Info("Heartbeat pending during startup", "err", err,
+				"gateway", a.gatewayURL, "elapsed", time.Since(a.startedAt).Round(time.Second))
+			return
+		}
 		slog.Error("Heartbeat failed", "err", err, "gateway", a.gatewayURL, "region", a.region)
 		return
 	}
+	a.firstHeartbeatOK = true
 
 	slog.Debug("Heartbeat OK", "status", resp.Status, "configHash", resp.ConfigHash)
 

spinifex/lbagent/agent_test.go

@@ -1,12 +1,15 @@
 package lbagent
 
 import (
+	"bytes"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
 	"os"
 	"path/filepath"
+	"strings"
 	"sync/atomic"
 	"testing"
 	"time"
@@ -647,3 +650,96 @@ func TestFetchConfig_WriteError(t *testing.T) {
 		t.Errorf("localConfigHash should be empty after write failure, got %q", agent.localConfigHash)
 	}
 }
+
+// notFoundGateway returns 400 LoadBalancerNotFound for every heartbeat, the
+// shape a freshly launched LB sees while its record replicates to the gateway
+// node fielding the first heartbeat.
+func notFoundGateway(t *testing.T) *httptest.Server {
+	t.Helper()
+	return httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		w.Header().Set("Content-Type", "text/xml")
+		w.WriteHeader(http.StatusBadRequest)
+		fmt.Fprint(w, `<ErrorResponse><Error><Type>Sender</Type><Code>LoadBalancerNotFound</Code><Message>One or more load balancers not found.</Message></Error></ErrorResponse>`)
+	}))
+}
+
+// captureSlog redirects the default logger to a buffer for the duration of the
+// test and returns an accessor for the accumulated output.
+func captureSlog(t *testing.T) func() string {
+	t.Helper()
+	var buf bytes.Buffer
+	prev := slog.Default()
+	slog.SetDefault(slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})))
+	t.Cleanup(func() { slog.SetDefault(prev) })
+	return buf.String
+}
+
+func TestHeartbeat_StartupFailureLogsBelowError(t *testing.T) {
+	gw := notFoundGateway(t)
+	defer gw.Close()
+
+	agent := newTestAgent(t, gw.URL)
+	logs := captureSlog(t)
+
+	// Fresh agent, inside the grace window and never yet successful: a
+	// LoadBalancerNotFound is a startup race, not an error.
+	agent.tick()
+
+	out := logs()
+	if strings.Contains(out, "level=ERROR") {
+		t.Errorf("startup heartbeat failure logged at ERROR within grace window:\n%s", out)
+	}
+	if !strings.Contains(out, "Heartbeat pending during startup") {
+		t.Errorf("expected startup-pending log line, got:\n%s", out)
+	}
+}
+
+func TestHeartbeat_FailureAfterGraceLogsError(t *testing.T) {
+	gw := notFoundGateway(t)
+	defer gw.Close()
+
+	agent := newTestAgent(t, gw.URL)
+	logs := captureSlog(t)
+
+	// Past the grace window with no prior success — the blackhole fingerprint —
+	// must escalate so the console telemetry catches it.
+	agent.startedAt = time.Now().Add(-2 * registrationGrace)
+	agent.tick()
+
+	out := logs()
+	if !strings.Contains(out, "level=ERROR") || !strings.Contains(out, "Heartbeat failed") {
+		t.Errorf("post-grace heartbeat failure did not escalate to ERROR:\n%s", out)
+	}
+}
+
+func TestHeartbeat_FailureAfterFirstSuccessLogsError(t *testing.T) {
+	// A gateway that answers healthily once, then only ever 400s.
+	var beats atomic.Int32
+	gw := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		w.Header().Set("Content-Type", "text/xml")
+		if beats.Add(1) == 1 {
+			fmt.Fprint(w, `<LBAgentHeartbeatResponse><LBAgentHeartbeatResult><Status>active</Status><ConfigHash></ConfigHash></LBAgentHeartbeatResult></LBAgentHeartbeatResponse>`)
+			return
+		}
+		w.WriteHeader(http.StatusBadRequest)
+		fmt.Fprint(w, `<ErrorResponse><Error><Code>LoadBalancerNotFound</Code></Error></ErrorResponse>`)
+	}))
+	defer gw.Close()
+
+	agent := newTestAgent(t, gw.URL)
+	logs := captureSlog(t)
+
+	// First tick succeeds (still inside grace); the next failure must be ERROR
+	// regardless of the window, because the agent has proven it can reach the
+	// gateway, so any later failure is real.
+	agent.tick()
+	agent.tick()
+
+	out := logs()
+	if !agent.firstHeartbeatOK {
+		t.Fatal("firstHeartbeatOK not set after a successful heartbeat")
+	}
+	if !strings.Contains(out, "level=ERROR") || !strings.Contains(out, "Heartbeat failed") {
+		t.Errorf("post-success heartbeat failure did not log ERROR:\n%s", out)
+	}
+}