From 528bb1e483a7d4e50e00dbd935f105f2c1b64917 Mon Sep 17 00:00:00 2001 From: Josh Siviour Date: Thu, 23 Jul 2026 10:07:06 +1000 Subject: [PATCH] fix(lbagent): quiet expected startup heartbeat failures below ERROR (#579) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 | 28 ++++++++++ spinifex/lbagent/agent_test.go | 96 ++++++++++++++++++++++++++++++++++ 2 files changed, 124 insertions(+) diff --git a/spinifex/lbagent/agent.go b/spinifex/lbagent/agent.go index b8e151819..06ff07d31 100644 --- a/spinifex/lbagent/agent.go +++ b/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) diff --git a/spinifex/lbagent/agent_test.go b/spinifex/lbagent/agent_test.go index 214a78aef..d134c9429 100644 --- a/spinifex/lbagent/agent_test.go +++ b/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, `SenderLoadBalancerNotFoundOne or more load balancers not found.`) + })) +} + +// 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, `active`) + return + } + w.WriteHeader(http.StatusBadRequest) + fmt.Fprint(w, `LoadBalancerNotFound`) + })) + 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) + } +}