diff --git a/internal/server/health_check.go b/internal/server/health_check.go index 59eeba3..6f333dc 100644 --- a/internal/server/health_check.go +++ b/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) diff --git a/internal/server/health_check_backoff_test.go b/internal/server/health_check_backoff_test.go new file mode 100644 index 0000000..0930720 --- /dev/null +++ b/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") +} diff --git a/internal/server/router_idle_test.go b/internal/server/router_idle_test.go index 9658996..9767660 100644 --- a/internal/server/router_idle_test.go +++ b/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