perf(health-check): retry quickly until a target first answers

internal/server/health_check.go

@@ -8,6 +8,7 @@ import (
 	"log/slog"
 	"net/http"
 	"net/url"
+	"sync/atomic"
 	"time"
 )
 
@@ -24,6 +25,11 @@ type HealthCheckConsumer interface {
 	HealthCheckCompleted(success bool)
 }
 
+// initialHealthCheckDelay is where the retry starts before doubling toward the
+// configured interval. Small enough that a container which is listening almost
+// immediately is noticed almost immediately.
+const initialHealthCheckDelay = 50 * time.Millisecond
+
 type HealthCheck struct {
 	consumer HealthCheckConsumer
 	endpoint *url.URL
@@ -33,6 +39,10 @@ type HealthCheck struct {
 
 	ctx    context.Context
 	cancel context.CancelFunc
+
+	// becameHealthy latches on the first successful probe. Until then the retry
+	// runs on a short backoff; afterwards the configured interval governs.
+	becameHealthy atomic.Bool
 }
 
 func NewHealthCheck(consumer HealthCheckConsumer, endpoint *url.URL, interval time.Duration, timeout time.Duration, host string) *HealthCheck {
@@ -59,22 +69,50 @@ func (hc *HealthCheck) Close() {
 
 // Private
 
+// run probes immediately, then retries on a short backoff until the target first
+// answers, and only then settles to the configured interval.
+//
+// The backoff exists because a target is routinely not listening yet at the
+// moment we first look: `docker start` returns when the container process is
+// created, not when the application is accepting connections. Measured on a real
+// daemon, the immediate probe was refused and the next one came a full interval
+// later -- 1009ms of pure waiting inside a 1154ms cold wake, for a container
+// whose app was ready almost at once. A deploy pays the same tax.
+//
+// Once a target is healthy the configured interval governs, so a running target
+// is not probed any harder than before.
 func (hc *HealthCheck) run() {
-	ticker := time.NewTicker(hc.interval)
-	defer ticker.Stop()
-
 	hc.check()
 
+	timer := time.NewTimer(hc.nextDelay(initialHealthCheckDelay))
+	defer timer.Stop()
+
+	delay := initialHealthCheckDelay
+
 	for {
 		select {
 		case <-hc.ctx.Done():
 			return
-		case <-ticker.C:
+		case <-timer.C:
 			hc.check()
+
+			if hc.becameHealthy.Load() {
+				delay = hc.interval
+			} else {
+				delay = min(delay*2, hc.interval)
+			}
+
+			timer.Reset(hc.nextDelay(delay))
 		}
 	}
 }
 
+// nextDelay never returns more than the configured interval, so a proxy
+// configured to probe quickly is not slowed down by the backoff.
+func (hc *HealthCheck) nextDelay(delay time.Duration) time.Duration {
+	return min(delay, hc.interval)
+}
+
 func (hc *HealthCheck) check() {
 	ctx, cancel := context.WithTimeout(hc.ctx, hc.timeout)
 	defer cancel()
@@ -117,6 +155,8 @@ func (hc *HealthCheck) check() {
 func (hc *HealthCheck) reportResult(success bool, err error) {
 	if !success {
 		slog.Info("Healthcheck failed", "url", hc.endpoint.String(), "error", err)
+	} else {
+		hc.becameHealthy.Store(true)
 	}
 
 	hc.consumer.HealthCheckCompleted(success)

internal/server/health_check_backoff_test.go

@@ -0,0 +1,144 @@
+package server
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"net/url"
+	"sync"
+	"sync/atomic"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+type recordingConsumer struct {
+	mu        sync.Mutex
+	successes int
+	failures  int
+	healthy   chan struct{}
+	once      sync.Once
+}
+
+func newRecordingConsumer() *recordingConsumer {
+	return &recordingConsumer{healthy: make(chan struct{})}
+}
+
+func (c *recordingConsumer) HealthCheckCompleted(success bool) {
+	c.mu.Lock()
+	if success {
+		c.successes++
+	} else {
+		c.failures++
+	}
+	c.mu.Unlock()
+
+	if success {
+		c.once.Do(func() { close(c.healthy) })
+	}
+}
+
+func (c *recordingConsumer) counts() (successes, failures int) {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	return c.successes, c.failures
+}
+
+// A target that is not listening the instant `docker start` returns is the normal
+// case, not the exception. Before this, the immediate probe failed and the next
+// one came a full interval later -- measured at 1009ms of pure waiting on a
+// container whose app was ready almost immediately, which was most of a 1154ms
+// cold wake.
+func TestHealthCheck_RetriesQuicklyUntilTheFirstSuccess(t *testing.T) {
+	var ready atomic.Bool
+
+	backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		if !ready.Load() {
+			// Stands in for a container whose process exists but is not listening.
+			w.WriteHeader(http.StatusServiceUnavailable)
+			return
+		}
+		w.WriteHeader(http.StatusOK)
+	}))
+	t.Cleanup(backend.Close)
+
+	endpoint, err := url.Parse(backend.URL)
+	require.NoError(t, err)
+
+	consumer := newRecordingConsumer()
+
+	// A one-second interval, the default. Without the backoff the first success
+	// could not arrive before the first tick.
+	hc := NewHealthCheck(consumer, endpoint, time.Second, time.Second, "")
+	t.Cleanup(hc.Close)
+
+	// Ready well inside one interval, but after the immediate probe has failed.
+	time.Sleep(120 * time.Millisecond)
+	ready.Store(true)
+
+	start := time.Now()
+	select {
+	case <-consumer.healthy:
+	case <-time.After(900 * time.Millisecond):
+		t.Fatal("readiness waited for the full check interval instead of retrying")
+	}
+
+	assert.Less(t, time.Since(start), 700*time.Millisecond,
+		"a target that became ready must be noticed without waiting out the interval")
+
+	_, failures := consumer.counts()
+	assert.Positive(t, failures, "the early probes should have failed and been retried")
+}
+
+// Once healthy, the configured interval is what governs -- the fast cadence is
+// for catching a boot, not for hammering a running target forever.
+func TestHealthCheck_SettlesToTheConfiguredIntervalAfterSuccess(t *testing.T) {
+	var probes atomic.Int64
+
+	backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		probes.Add(1)
+		w.WriteHeader(http.StatusOK)
+	}))
+	t.Cleanup(backend.Close)
+
+	endpoint, err := url.Parse(backend.URL)
+	require.NoError(t, err)
+
+	consumer := newRecordingConsumer()
+	hc := NewHealthCheck(consumer, endpoint, time.Second, time.Second, "")
+	t.Cleanup(hc.Close)
+
+	<-consumer.healthy
+	settled := probes.Load()
+
+	time.Sleep(400 * time.Millisecond)
+
+	assert.LessOrEqual(t, probes.Load()-settled, int64(1),
+		"a healthy target must be probed at its configured interval, not the wake cadence")
+}
+
+// A target that never comes up must not be probed in a tight loop for the whole
+// wake timeout.
+func TestHealthCheck_BackoffIsBoundedByTheConfiguredInterval(t *testing.T) {
+	var probes atomic.Int64
+
+	backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		probes.Add(1)
+		w.WriteHeader(http.StatusServiceUnavailable)
+	}))
+	t.Cleanup(backend.Close)
+
+	endpoint, err := url.Parse(backend.URL)
+	require.NoError(t, err)
+
+	hc := NewHealthCheck(newRecordingConsumer(), endpoint, 200*time.Millisecond, time.Second, "")
+	t.Cleanup(hc.Close)
+
+	time.Sleep(time.Second)
+
+	// Doubling from 50ms and capped at the 200ms interval: roughly
+	// 50+100+200+200+200 -- far fewer than a 50ms tight loop's 20.
+	assert.Less(t, probes.Load(), int64(12),
+		"the retry must back off rather than hammer a container that is not coming up")
+}

internal/server/router_idle_test.go

@@ -26,6 +26,12 @@ func testIdleRouter(t *testing.T, lifecycle ContainerLifecycle) *Router {
 		for _, service := range router.services.All() {
 			service.Dispose()
 		}
+
+		// Dispose stops the controllers but does not wait for a persist already in
+		// flight. SaveState takes the same saveLock, so this returns only once any
+		// in-progress write has finished -- otherwise it races t.TempDir cleanup
+		// and fails with "directory not empty", which -race makes far more likely.
+		_ = router.SaveState()
 	})
 
 	return router