diff --git a/README.md b/README.md index c7981a0..a21d0f1 100644 --- a/README.md +++ b/README.md @@ -237,42 +237,60 @@ not answering. request* is evidence about the probe instead: the other `4xx` are the backend answering that our request is the problem (`404`/`410` the path is not there, `405` it does not take a `GET`, `401`/`403` we are not allowed to ask), and - `501` says it does not implement the - endpoint. A backend answering that way is **left in service** — still queried, - still contributing records — and reported as `probe_unsupported` rather than - `healthy`, so an operator can tell "verified healthy" from "not actually being - checked". A probe path that is wrong for one backend alone can therefore never - strand a working backend. The misconfiguration is logged once per transition, - naming the backend, the probe path and the status. + `501` says it does not implement the endpoint. +- **A backend is only gated on a probe that has worked for it.** Each backend + carries one latch: has its probe endpoint ever *answered* — replied with + something readable as healthy or unhealthy — since `pdbmux` started? A + rejection refused the request and a transport failure never reached the + endpoint, so neither one sets it; a `200`, a `503` or a degraded body does. + The latch decides which rule applies, and it never clears, so no repeating + pattern of failures can argue a backend back into service. + - **Never answered** — there is no health signal for this backend, so nothing + gates on one. It is **left in service** — still queried, still contributing + records — permanently, reported as `probe_unsupported` rather than + `healthy` so an operator can tell "verified healthy" from "not actually + being checked". Real failures do not take it out either: no conclusion about + a backend can be drawn from a probe that cannot run. This is the + misconfigured-path case, and it degrades that backend to the behaviour from + before health checks existed, which is the right floor. The + misconfiguration is logged once, naming the backend, the probe path and the + status. A backend that has been unreachable since `pdbmux` started has not + answered either, so it is not gated until it answers once — `reachable` on + `/healthz` is what reports it in the meantime. + - **Answered at least once** — the path works, so the probe is trusted and the + ordinary thresholds below apply. A later run of *rejections* counts as + failure, not `probe_unsupported`: a path that answered before and refuses + now has moved or changed its authorization, which is logged loudly when the + run starts. - **Thresholds** — a healthy backend leaves the pool after `health_probe_failures` (default 3) **consecutive** unsuccessful probes; a down one comes back after `health_probe_successes` (default 2) consecutive - successes, and the same thresholds gate `probe_unsupported` in and out. One - blip cannot flap a backend out, and one lucky reply cannot flap it back in. - The run counts every unsuccessful probe whatever its kind, so a backend that - fails every probe in mixed ways — a `503`, then a `404`, then a timeout — - still trips the threshold; only a success resets the run. A down backend keeps + successes, and the same failure threshold debounces the `probe_unsupported` + warning. One blip cannot flap a backend out, and one lucky reply cannot flap + it back in. The run counts every unsuccessful probe whatever its kind, so a + backend that fails every probe in mixed ways — a `503`, then a `404`, then a + timeout — still trips the threshold; only a success resets the run. Probes + from before the latch was set do not count toward it. A down backend keeps being probed, so recovery is automatic. -- **A window decides which state the run enters.** The run is a *failure* run — - `unhealthy`, backend skipped — whenever a real failure landed within the last - `health_probe_failures` probes, floored at 3 so the window always spans a - reject-heavy cycle. A run whose whole window holds nothing but refusals is - `probe_unsupported` and keeps serving queries. A backend flipping between kinds - — `404`, `503`, `404`, timeout — therefore keeps a failure inside every window - and stays out of the pool, while a backend whose probe path is merely wrong - returns to service one window after the single transient failure it suffered. - Bounding the evidence to a window is what makes that possible: a wrong probe - path can never answer a probe successfully, so a failure held against the whole - run would be held forever and would strand a backend that is answering queries - perfectly. A success clears the window along with the run. +- **Accepted trade-off: a probe path that is removed.** If a backend's probe + path works and later goes away — an upgrade, a proxy change — the latch is + already set, so the refusals count as failures and that backend is excluded + even though it is serving queries fine. Global fail-open still covers the case + where this happens to every backend, `/healthz` shows the state, and the log + line names the probe path: fix `health_probe_path`, or set + `health_probe_enabled: false`. There is no machinery to detect this + automatically — any rule that readmits a backend on "no real failure lately" + flaps a genuinely dead backend into service on a periodic failure pattern. - **Fails open** — if the prober has marked **every** backend down, `pdbmux` queries them all anyway. A wrong `health_probe_path`, a broken prober or a partition that only the prober sees can therefore never black-hole traffic; the worst case is today's behaviour. - **Serves immediately** — the listener never waits for a first probe round, and a backend nobody has probed yet counts as healthy, so a restart drops nothing. -- **Quiet** — only *transitions* (up→down, down→up, in and out of - `probe_unsupported`) are logged, never individual probes. +- **Quiet** — only *transitions* are logged, never individual probes: up→down, + down→up, a probe that has never answered reaching its failure threshold, the + first answer after that, and the start of a rejection run on a probe that used + to answer. - **Partial responses stay partial.** Health state changes which backends are asked, never what a merged answer means: a response built from a subset is still served, as before. Every merged response carries `X-Backends: diff --git a/health.go b/health.go index 7ff2822..b8e2815 100644 --- a/health.go +++ b/health.go @@ -19,11 +19,6 @@ const probeBodyLimit = 1 << 20 // runningState is the healthy state reported by PuppetDB's status service. const runningState = "running" -// minFailureWindow floors the failure window at the shortest reject-heavy cycle -// that must not flap — reject, reject, failure — since a shorter window would -// let its failure age out between two rejections. -const minFailureWindow = 3 - const ( stateHealthy = "healthy" stateUnhealthy = "unhealthy" @@ -44,16 +39,21 @@ const ( ) type probeState struct { - healthy bool - unsupported bool - probed bool - // failWindow counts the probes over which the last real failure still counts - // as evidence; while it is positive a not-OK run is a failure run. - failWindow int - failures int - successes int - lastProbe time.Time - lastErr string + healthy bool + probed bool + // usable latches the first time the probe endpoint answers with a verdict on + // this backend. It never clears: whether the probe works for a backend is a + // property of the deployment, not something to re-decide every round. + usable bool + // rejecting tracks whether the last probe refused the request, so a rejection + // run is logged when it starts rather than on every probe. + rejecting bool + // warned records that the unusable-probe misconfiguration has been logged. + warned bool + failures int + successes int + lastProbe time.Time + lastErr string } // backendHealth is a copy of one backend's probe state, safe to read outside the @@ -92,6 +92,20 @@ func (e *probeRejectedError) Error() string { return fmt.Sprintf("HTTP %d: probe path %q is not usable on this backend", e.status, e.path) } +// probeAnsweredError marks a failure the probe endpoint itself reported: the +// request reached it and came back with a verdict on the backend's services. +type probeAnsweredError struct{ msg string } + +func (e *probeAnsweredError) Error() string { return e.msg } + +// probeAnswered reports whether a probe reply is a verdict we can read as +// healthy or unhealthy, which is what makes the probe usable for a backend. A +// rejection refused the request and a transport failure never reached the +// endpoint, so neither one shows that the configured path works. +func probeAnswered(err error) bool { + return err == nil || errors.As(err, new(*probeAnsweredError)) +} + // probeRejects reports whether a status code refuses the probe request rather // than reporting the service unhealthy. A 4xx is the backend answering that our // request is the problem, and 501 says it does not implement the endpoint. @@ -126,7 +140,6 @@ type prober struct { interval time.Duration failures int successes int - window int client *http.Client log *log.Logger now func() time.Time @@ -149,7 +162,6 @@ func newProber(cfg Config, logger *log.Logger) *prober { interval: cfg.HealthProbeInterval, failures: cfg.HealthProbeFailures, successes: cfg.HealthProbeSuccesses, - window: max(cfg.HealthProbeFailures, minFailureWindow), client: &http.Client{Timeout: cfg.HealthProbeTimeout}, log: logger, now: time.Now, @@ -227,7 +239,7 @@ func (p *prober) snapshot() map[string]backendHealth { for name, st := range p.states { out[name] = backendHealth{ Healthy: st.healthy, - Unsupported: st.unsupported, + Unsupported: st.probed && !st.usable, Probed: st.probed, Failures: st.failures, Successes: st.successes, @@ -247,14 +259,14 @@ func (p *prober) probeOne(ctx context.Context, b Backend) { p.record(b.Name, err) } -// record applies one probe outcome, flipping state only once the matching -// threshold is reached so a single blip cannot flap a backend in either -// direction. One run of consecutive not-OK probes makes the down decision, no -// matter how the kinds are mixed; the kinds only pick which non-healthy state -// the run enters. A real failure outranks a rejection for the length of the -// failure window, not for the whole run: a backend whose probe path is -// permanently wrong would otherwise be stranded out of the pool for good by one -// old transient failure, since only a success it can never give clears it. +// record applies one probe outcome. Which rule applies is decided by a latch, +// not by anything that decays: until the probe endpoint has answered once, this +// backend has no health signal at all, so nothing may gate on one and it stays +// in service however its probes fail. Once the probe has answered, the path +// works and every unsuccessful probe counts toward the failure threshold — +// rejections included, since a path that answered before and refuses now has +// changed. The latch never clears, so a repeating pattern of failures cannot +// argue a backend back into service. func (p *prober) record(name string, err error) { p.mu.Lock() st, ok := p.states[name] @@ -266,53 +278,52 @@ func (p *prober) record(name string, err error) { st.probed = true st.lastProbe = p.now() - var transition string + var transitions []string + if !st.usable && probeAnswered(err) { + st.usable = true + // Only evidence from the working probe debounces the state. + st.failures, st.successes = 0, 0 + if st.warned { + st.warned = false + transitions = append(transitions, fmt.Sprintf("info: backend %q now answers the health probe %q; its health is being checked again", name, p.path)) + } + } + if outcome == outcomeOK { st.lastErr = "" - st.failures, st.failWindow = 0, 0 + st.failures = 0 st.successes++ - if st.successes >= p.successes { - switch { - case st.unsupported: - st.unsupported = false - transition = fmt.Sprintf("info: backend %q health probe %q is usable again", name, p.path) - case !st.healthy: - st.healthy = true - transition = fmt.Sprintf("info: backend %q is up after %d consecutive probe successes", name, st.successes) - } + if st.usable && !st.healthy && st.successes >= p.successes { + st.healthy = true + transitions = append(transitions, fmt.Sprintf("info: backend %q is up after %d consecutive probe successes", name, st.successes)) } } else { st.lastErr = err.Error() st.successes = 0 st.failures++ - if outcome == outcomeFailure { - st.failWindow = p.window - } else if st.failWindow > 0 { - st.failWindow-- - } - if st.failures >= p.failures { - switch { - case st.failWindow > 0: - // A probe inside the window was evidence about the backend itself, so the - // run is a failure run whatever else it also contains. - st.unsupported = false - if st.healthy { - st.healthy = false - transition = fmt.Sprintf("warning: backend %q is down after %d consecutive failed probes: %v", name, st.failures, err) - } - case !st.unsupported: - // Nothing but refusals of the probe request, which says nothing about the - // backend's health: it keeps serving queries, unverified. - st.unsupported, st.healthy = true, true - transition = fmt.Sprintf("warning: backend %q rejected the health probe %d times: %v; leaving it in service but unverified, fix health_probe_path or its authorization", name, st.failures, err) + if !st.usable { + // No probe has ever worked here, so this says nothing about the backend: it + // keeps serving queries, unverified. + if st.failures >= p.failures && !st.warned { + st.warned = true + transitions = append(transitions, fmt.Sprintf("warning: backend %q has never answered the health probe %q, last %v; leaving it in service but unverified, fix health_probe_path or its authorization", name, p.path, err)) + } + } else { + if outcome == outcomeRejected && !st.rejecting { + transitions = append(transitions, fmt.Sprintf("warning: backend %q now rejects the health probe %q, which worked before: %v; the endpoint moved or its authorization changed, so the refusals count as failures", name, p.path, err)) + } + if st.healthy && st.failures >= p.failures { + st.healthy = false + transitions = append(transitions, fmt.Sprintf("warning: backend %q is down after %d consecutive failed probes: %v", name, st.failures, err)) } } } + st.rejecting = outcome == outcomeRejected p.mu.Unlock() // Only transitions are logged: this loop runs for the life of the process. - if transition != "" { - p.log.Print(transition) + for _, t := range transitions { + p.log.Print(t) } } @@ -335,9 +346,12 @@ func (p *prober) probe(ctx context.Context, b Backend) error { return &probeRejectedError{status: resp.StatusCode, path: p.path} } if resp.StatusCode != http.StatusOK { - return fmt.Errorf("HTTP %d: %s", resp.StatusCode, strings.TrimSpace(string(body))) + return &probeAnsweredError{msg: fmt.Sprintf("HTTP %d: %s", resp.StatusCode, strings.TrimSpace(string(body)))} } - return statusBodyHealthy(body) + if err := statusBodyHealthy(body); err != nil { + return &probeAnsweredError{msg: err.Error()} + } + return nil } // statusBodyHealthy rejects a 200 whose body reports a service that is starting, diff --git a/health_test.go b/health_test.go index a030420..5c74a40 100644 --- a/health_test.go +++ b/health_test.go @@ -77,20 +77,39 @@ func healthConfig(aURL, bURL string) Config { return cfg } +// answeredProbe is a failure the probe endpoint itself reported — a 503, say — +// so it proves the probe works and counts against the backend. +func answeredProbe() error { + return &probeAnsweredError{msg: "HTTP 503: service is not running"} +} + +// deadProbe never reached the endpoint, so it says nothing about whether the +// probe works there. +func deadProbe() error { return errors.New("dial tcp: connection refused") } + +func rejectedProbe(p *prober) error { + return &probeRejectedError{status: http.StatusNotFound, path: p.path} +} + +// markUsable latches the probe as working without changing the backend's state. +func markUsable(t *testing.T, p *prober, name string) { + t.Helper() + p.record(name, nil) + if p.snapshot()[name].Unsupported { + t.Fatalf("backend %q still reports an unusable probe after a success", name) + } +} + func markDown(t *testing.T, p *prober, name string) { t.Helper() for i := 0; i < p.failures; i++ { - p.record(name, errors.New("probe failed")) + p.record(name, answeredProbe()) } if p.healthy(name) { t.Fatalf("backend %q still healthy after %d probe failures", name, p.failures) } } -func rejectedProbe(p *prober) error { - return &probeRejectedError{status: http.StatusNotFound, path: p.path} -} - func markUnsupported(t *testing.T, p *prober, name string) { t.Helper() for i := 0; i < p.failures; i++ { @@ -110,19 +129,19 @@ func TestProber_FailureThresholdDebouncesABlip(t *testing.T) { p := newTestProber(t, cfg) for i := 1; i < 3; i++ { - p.record("a", errors.New("boom")) + p.record("a", answeredProbe()) if !p.healthy("a") { t.Fatalf("backend went down after %d of 3 failures", i) } } - // A success inside the window resets the run, so the blip never flaps it out. + // A success resets the run, so the blip never flaps it out. p.record("a", nil) - p.record("a", errors.New("boom")) - p.record("a", errors.New("boom")) + p.record("a", answeredProbe()) + p.record("a", answeredProbe()) if !p.healthy("a") { t.Fatal("a failure run interrupted by a success should not mark the backend down") } - p.record("a", errors.New("boom")) + p.record("a", answeredProbe()) if p.healthy("a") { t.Fatal("backend should be down after 3 consecutive failures") } @@ -139,7 +158,7 @@ func TestProber_SuccessThresholdDebouncesRecovery(t *testing.T) { t.Fatal("one success should not bring a down backend back") } // A failure in between restarts the recovery run. - p.record("a", errors.New("boom")) + p.record("a", answeredProbe()) p.record("a", nil) if p.healthy("a") { t.Fatal("recovery run should restart after an interleaved failure") @@ -575,6 +594,9 @@ func TestProber_ServerErrorsAndTransportFailuresStillMarkDown(t *testing.T) { if classifyProbe(err) != outcomeFailure { t.Fatalf("a refused connection classified as %v, want a real failure (err %v)", classifyProbe(err), err) } + // A transport failure never reached the probe endpoint, so it is only evidence + // once the endpoint has answered before. + markUsable(t, p, "a") for i := 0; i < p.failures; i++ { p.record("a", err) } @@ -583,31 +605,83 @@ func TestProber_ServerErrorsAndTransportFailuresStillMarkDown(t *testing.T) { } } -// A real failure landing in a rejected run outranks the rejections: the run is -// one run of unsuccessful probes, and its worst evidence decides the state. -func TestProber_RealFailureInARejectedRunMarksDown(t *testing.T) { +// Only a reply from the probe endpoint shows that the probe works there: a +// transport failure never got one, and a rejection refused the request. +func TestProbeAnswered_OnlyRepliesFromTheEndpointCount(t *testing.T) { + sb := newStatusBackend(t) + p := newTestProber(t, healthConfig(sb.srv.URL, "http://b.invalid")) + probe := func() error { return p.probe(t.Context(), Backend{Name: "a", URL: sb.srv.URL}) } + + sb.reply(http.StatusOK, runningStatusBody) + if !probeAnswered(probe()) { + t.Error("a running status was not counted as an answer") + } + sb.reply(http.StatusServiceUnavailable, degradedStatusBody("error")) + if !probeAnswered(probe()) { + t.Error("a 503 from the probe endpoint was not counted as an answer") + } + sb.reply(http.StatusOK, degradedStatusBody("starting")) + if !probeAnswered(probe()) { + t.Error("a degraded body on a 200 was not counted as an answer") + } + sb.reply(http.StatusNotFound, "nope") + if probeAnswered(probe()) { + t.Error("a rejected probe was counted as an answer") + } + if probeAnswered(deadProbe()) { + t.Error("a transport failure was counted as an answer") + } +} + +// Once the probe endpoint answers, its verdict gates the backend even if every +// earlier probe was refused: the path works after all. +func TestProber_AnsweredFailureAfterRejectionsMarksDown(t *testing.T) { p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) markUnsupported(t, p, "a") for i := 0; i < 20; i++ { p.record("a", rejectedProbe(p)) } - p.record("a", errors.New("boom")) + for i := 0; i < p.failures; i++ { + p.record("a", answeredProbe()) + } if p.healthy("a") { - t.Fatal("a real failure inside a rejected run left the backend in service") + t.Fatal("the backend stayed in service after its probe endpoint answered with failures") } if got := p.snapshot()["a"].stateName(); got != stateUnhealthy { t.Errorf("state = %q, want %q", got, stateUnhealthy) } } +// The rejections before the endpoint answered are not evidence about the +// backend, so they do not count toward the threshold that takes it out. +func TestProber_RejectionsBeforeTheLatchDoNotCountAsFailures(t *testing.T) { + cfg := healthConfig("http://a.invalid", "http://b.invalid") + cfg.HealthProbeFailures = 3 + p := newTestProber(t, cfg) + for i := 0; i < 20; i++ { + p.record("a", rejectedProbe(p)) + } + + for i := 1; i < cfg.HealthProbeFailures; i++ { + p.record("a", answeredProbe()) + if !p.healthy("a") { + t.Fatalf("backend went down after %d of %d failures from a working probe", i, cfg.HealthProbeFailures) + } + } + p.record("a", answeredProbe()) + if p.healthy("a") { + t.Fatal("backend should be down after a full run of failures from a working probe") + } +} + // The regression this guards: a backend failing every probe but flipping the // kind of failure — a fronting proxy alternating 404 and 503, say — never // answers a probe successfully, so it must go down at the threshold like any // other permanently failing backend. func TestProber_AlternatingOutcomeKindsStillMarkDown(t *testing.T) { rejected := func(p *prober) error { return rejectedProbe(p) } - failed := func(*prober) error { return errors.New("boom") } + failed := func(*prober) error { return answeredProbe() } ok := func(*prober) error { return nil } cycles := map[string][]func(*prober) error{ @@ -668,12 +742,12 @@ func TestProber_SuccessResetsTheRunInEveryDirection(t *testing.T) { case "rejected": return rejectedProbe(p) case "failure": - return errors.New("boom") + return answeredProbe() default: if i%2 == 0 { return rejectedProbe(p) } - return errors.New("boom") + return answeredProbe() } } for i := 0; i < cfgFailures-1; i++ { @@ -713,134 +787,147 @@ func TestProber_RecoversFromProbeUnsupported(t *testing.T) { } } -// Rejections cannot talk a down backend back into the pool while a real failure -// is still inside the window — the failure is still the best evidence there is. -// Once it has aged out and nothing but refusals is left, the probe rather than -// the backend is what is broken. -func TestProber_RejectionsReadmitADownBackendOnlyAfterTheFailureAgesOut(t *testing.T) { - p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) - markDown(t, p, "a") - - for i := 1; i < p.window; i++ { - p.record("a", rejectedProbe(p)) - if p.healthy("a") { - t.Fatalf("rejection %d of a %d-probe window re-admitted a backend whose failure is still in view", i, p.window) - } - if got := p.snapshot()["a"].stateName(); got != stateUnhealthy { - t.Fatalf("state = %q after rejection %d, want %q", got, i, stateUnhealthy) - } - } - - p.record("a", rejectedProbe(p)) - if !p.healthy("a") { - t.Fatalf("backend stayed excluded after its last failure left the %d-probe window", p.window) - } - if got := p.snapshot()["a"].stateName(); got != stateProbeUnsupported { - t.Fatalf("state = %q, want %q", got, stateProbeUnsupported) - } - - p.record("a", nil) - markUnsupported(t, p, "a") -} - -// A success clears the failure window as well as the run, so what follows it is -// judged on its own evidence. -func TestProber_SuccessClearsTheFailureWindow(t *testing.T) { - p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) - markDown(t, p, "a") - - for i := 0; i < p.successes; i++ { - p.record("a", nil) - } - if !p.healthy("a") { - t.Fatal("backend did not recover after its success threshold") - } - markUnsupported(t, p, "a") -} - -// The stranding regression: a backend whose probe path is permanently wrong can -// never answer a probe successfully, so one transient failure in the middle of -// its 404s must not exclude it for the life of the process. -func TestProber_AgedOutFailureSettlesOnProbeUnsupported(t *testing.T) { - p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) - for i := 0; i < p.failures*3; i++ { - p.record("a", rejectedProbe(p)) - } - if got := p.snapshot()["a"].stateName(); got != stateProbeUnsupported { - t.Fatalf("state = %q before the failure, want %q", got, stateProbeUnsupported) - } - - p.record("a", errors.New("read: connection reset by peer")) - if p.healthy("a") { - t.Fatal("a real failure did not take the backend out of the pool") - } - - for i := 1; i < p.window; i++ { - p.record("a", rejectedProbe(p)) - if p.healthy("a") { - t.Fatalf("the failure aged out after %d of %d probes", i, p.window) - } - } - p.record("a", rejectedProbe(p)) - - for i := 0; i < 500; i++ { - p.record("a", rejectedProbe(p)) - if !p.healthy("a") { - t.Fatalf("backend was still excluded %d probes after its failure aged out", i+p.window) - } - if got := p.snapshot()["a"].stateName(); got != stateProbeUnsupported { - t.Fatalf("state = %q, want %q", got, stateProbeUnsupported) - } - } -} - -// The window is the failure threshold, floored so it always spans a -// reject-heavy cycle. -func TestProber_FailureWindowFollowsTheThreshold(t *testing.T) { - for _, tc := range []struct{ failures, window int }{ - {1, minFailureWindow}, {2, minFailureWindow}, {3, 3}, {5, 5}, {9, 9}, - } { +// The misconfigured-path case: nothing has ever answered the probe on this +// backend, so there is no health signal to gate on and it keeps serving queries +// however its probes fail — including real failures, since a probe that cannot +// run supports no conclusion about the backend behind it. +func TestProber_NeverAnsweredProbeStaysInServiceForever(t *testing.T) { + for _, failures := range []int{1, 2, 3, 5, 9} { cfg := healthConfig("http://a.invalid", "http://b.invalid") - cfg.HealthProbeFailures = tc.failures + cfg.HealthProbeFailures = failures p := newTestProber(t, cfg) - if p.window != tc.window { - t.Fatalf("health_probe_failures = %d gave a window of %d, want %d", tc.failures, p.window, tc.window) - } - markDown(t, p, "a") - for i := 1; i < tc.window; i++ { - p.record("a", rejectedProbe(p)) - if p.healthy("a") { - t.Fatalf("threshold %d: failure aged out after %d of %d probes", tc.failures, i, tc.window) + for i := 0; i < 500; i++ { + if i%3 == 2 { + p.record("a", deadProbe()) + } else { + p.record("a", rejectedProbe(p)) + } + if !p.healthy("a") { + t.Fatalf("threshold %d: backend left the pool at probe %d on a probe that never worked", failures, i+1) + } + if got := p.snapshot()["a"].stateName(); got != stateProbeUnsupported { + t.Fatalf("threshold %d: state = %q at probe %d, want %q", failures, got, i+1, stateProbeUnsupported) } } + } +} + +// Once the probe has answered, the latch is set for good: a later run of +// rejections means the endpoint moved or its authorization changed, so it +// counts as failure instead of putting the backend back into probe_unsupported. +func TestProber_RejectionRunAfterTheLatchIsAFailureRun(t *testing.T) { + p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) + markUsable(t, p, "a") + + for i := 0; i < 100; i++ { p.record("a", rejectedProbe(p)) + } + if p.healthy("a") { + t.Fatal("a rejection run after the probe had worked left the backend in service") + } + if got := p.snapshot()["a"].stateName(); got != stateUnhealthy { + t.Fatalf("state = %q, want %q", got, stateUnhealthy) + } +} + +// With the latch set the ordinary thresholds apply to every kind of +// unsuccessful probe, in both directions. +func TestProber_LatchedBackendExcludesAndReadmits(t *testing.T) { + for _, fail := range []func() error{answeredProbe, deadProbe} { + p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) + markUsable(t, p, "a") + + for i := 1; i < p.failures; i++ { + p.record("a", fail()) + if !p.healthy("a") { + t.Fatalf("backend left the pool after %d of %d failures", i, p.failures) + } + } + p.record("a", fail()) + if p.healthy("a") { + t.Fatal("backend stayed in service after a full failure run") + } + if got := p.snapshot()["a"].stateName(); got != stateUnhealthy { + t.Fatalf("state = %q, want %q", got, stateUnhealthy) + } + + for i := 1; i < p.successes; i++ { + p.record("a", nil) + if p.healthy("a") { + t.Fatalf("backend came back after %d of %d successes", i, p.successes) + } + } + p.record("a", nil) if !p.healthy("a") { - t.Fatalf("threshold %d: failure never aged out of the %d-probe window", tc.failures, tc.window) + t.Fatal("backend did not come back after a full success run") + } + if got := p.snapshot()["a"].stateName(); got != stateHealthy { + t.Fatalf("state = %q, want %q", got, stateHealthy) } } } -// Every cycle that keeps failing, whatever it mixes in, must settle down and stay -// down: once a backend has left the pool nothing but a success may bring it back. +// Every state the prober can hold recovers on nothing but successes. +func TestProber_RecoversFromEveryState(t *testing.T) { + setups := map[string]func(*testing.T, *prober){ + stateUnprobed: func(*testing.T, *prober) {}, + stateUnhealthy: func(t *testing.T, p *prober) { markDown(t, p, "a") }, + stateProbeUnsupported: func(t *testing.T, p *prober) { markUnsupported(t, p, "a") }, + } + for name, setup := range setups { + t.Run(name, func(t *testing.T) { + p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) + setup(t, p) + for i := 0; i < p.successes; i++ { + p.record("a", nil) + } + if !p.healthy("a") { + t.Fatal("backend did not recover on consecutive successes") + } + if got := p.snapshot()["a"].stateName(); got != stateHealthy { + t.Fatalf("state = %q, want %q", got, stateHealthy) + } + }) + } +} + +// The regression this guards: the decaying rule it replaced readmitted a dead +// backend on a repeating pattern of one failure followed by a run of +// rejections, once per cycle, forever. Once the probe has answered, no pattern +// of unsuccessful probes may put a backend back into service — only a success +// may, and these backends never give one. func TestProber_MixedFailureCyclesNeverFlapBackIntoService(t *testing.T) { rejected := func(p *prober) error { return rejectedProbe(p) } - failed := func(*prober) error { return errors.New("boom") } + failed := func(*prober) error { return answeredProbe() } + dead := func(*prober) error { return deadProbe() } cycles := map[string][]func(*prober) error{ "rejected/failure": {rejected, failed}, "failure/rejected": {failed, rejected}, - "reject-heavy 3-cycle": {rejected, rejected, failed}, "failure-heavy 3-cycle": {rejected, failed, failed}, - "failure-led 3-cycle": {failed, rejected, rejected}, "paired 4-cycle": {rejected, rejected, failed, failed}, + "transport/rejected": {dead, rejected}, + "all rejections": {rejected}, } + // The reviewer's exact counterexample, at every run length past any window the + // old rule used, in both failure flavours. + for n := 1; n <= 10; n++ { + run := make([]func(*prober) error, n) + for i := range run { + run[i] = rejected + } + cycles[fmt.Sprintf("failure then %d rejections", n)] = append([]func(*prober) error{failed}, run...) + cycles[fmt.Sprintf("transport failure then %d rejections", n)] = append([]func(*prober) error{dead}, run...) + } + for name, cycle := range cycles { - for _, failures := range []int{1, 2, 3, 5} { + for failures := 1; failures <= 9; failures++ { t.Run(fmt.Sprintf("%s/threshold %d", name, failures), func(t *testing.T) { cfg := healthConfig("http://a.invalid", "http://b.invalid") cfg.HealthProbeFailures = failures p := newTestProber(t, cfg) + markUsable(t, p, "a") down := false for i := 0; i < 600; i++ { @@ -871,10 +958,17 @@ func TestProber_LogsProbeRejectionOncePerTransition(t *testing.T) { } rejected := &probeRejectedError{status: http.StatusNotFound, path: p.path} + // The warning is debounced by the failure threshold like every other verdict. + for i := 0; i < p.failures-1; i++ { + p.record("a", rejected) + } + if buf.Len() != 0 { + t.Fatalf("a sub-threshold rejection run was already logged:\n%s", buf.String()) + } for i := 0; i < 50; i++ { p.record("a", rejected) } - if n := strings.Count(buf.String(), "rejected the health probe"); n != 1 { + if n := strings.Count(buf.String(), "never answered the health probe"); n != 1 { t.Fatalf("logged the misconfiguration %d times, want once:\n%s", n, buf.String()) } if !strings.Contains(buf.String(), `backend "a"`) || !strings.Contains(buf.String(), defaultHealthProbePath) { @@ -884,18 +978,49 @@ func TestProber_LogsProbeRejectionOncePerTransition(t *testing.T) { t.Errorf("log line does not name the status: %s", buf.String()) } - // Recovery logs its own single line, and a second rejected run logs again. + // The probe starting to answer logs its own single line. for i := 0; i < p.successes+5; i++ { p.record("a", nil) } - if n := strings.Count(buf.String(), "usable again"); n != 1 { - t.Fatalf("logged recovery %d times, want once:\n%s", n, buf.String()) + if n := strings.Count(buf.String(), "now answers the health probe"); n != 1 { + t.Fatalf("logged the probe becoming usable %d times, want once:\n%s", n, buf.String()) } + + // A rejection run once the probe has worked is a different event, logged loudly + // when it starts and never again while it lasts. + buf.Reset() for i := 0; i < 50; i++ { p.record("a", rejected) } - if n := strings.Count(buf.String(), "rejected the health probe"); n != 2 { - t.Fatalf("second rejected run logged %d times in total, want 2:\n%s", n, buf.String()) + if n := strings.Count(buf.String(), "now rejects the health probe"); n != 1 { + t.Fatalf("logged the rejection run %d times, want once:\n%s", n, buf.String()) + } + if n := strings.Count(buf.String(), "never answered the health probe"); n != 0 { + t.Errorf("a rejection run after the probe worked was reported as an unusable probe:\n%s", buf.String()) + } + if n := strings.Count(buf.String(), "is down after"); n != 1 { + t.Errorf("the backend going down was logged %d times, want once:\n%s", n, buf.String()) + } +} + +func TestProber_LogsEachDownAndUpTransitionOnce(t *testing.T) { + var buf strings.Builder + p := newProber(healthConfig("http://a.invalid", "http://b.invalid"), log.New(&buf, "", 0)) + if p == nil { + t.Fatal("newProber returned nil for an enabled config") + } + + for i := 0; i < p.failures+20; i++ { + p.record("a", answeredProbe()) + } + for i := 0; i < p.successes+20; i++ { + p.record("a", nil) + } + if n := strings.Count(buf.String(), "is down after"); n != 1 { + t.Errorf("logged the backend going down %d times, want once:\n%s", n, buf.String()) + } + if n := strings.Count(buf.String(), "is up after"); n != 1 { + t.Errorf("logged the backend coming back %d times, want once:\n%s", n, buf.String()) } }