diff --git a/README.md b/README.md index 344f012..a3455a5 100644 --- a/README.md +++ b/README.md @@ -228,42 +228,69 @@ not answering. or `unknown` counts as a failure. A body that is not in that shape is judged on its status code alone, so pointing `health_probe_path` at some other endpoint still works. -- **A refused probe is not a sick backend.** Only evidence about the *backend* - takes it out of the pool: a transport failure (connection refused, DNS, TLS, +- **A refused probe is not a sick backend.** Probe replies split in two. Evidence + about the *backend* is a transport failure (connection refused, DNS, TLS, timeout), a `5xx` — `503` included, since trapperkeeper answers `503` exactly when its services are not nominal — or a `429`, which is the backend reporting its own capacity rather than judging the request, so an overloaded backend gets backed off instead of kept at full traffic. A reply that refuses the *probe - request* is evidence about the probe instead: the other `4xx` are the backend + request* is evidence about the probe: 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. The kinds decide - *which* state the run enters: a real failure anywhere in the run outranks a - refusal, so the backend goes `unhealthy` and is skipped, and only a run of - nothing but refusals enters `probe_unsupported` and stays in service. A down - backend keeps being probed, so recovery is automatic. + 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. +- **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 23d9b47..b8e2815 100644 --- a/health.go +++ b/health.go @@ -39,12 +39,17 @@ const ( ) type probeState struct { - healthy bool - unsupported bool - probed bool - // runFailed records whether the current run of not-OK probes contains at - // least one real failure, which decides which non-healthy state it enters. - runFailed bool + 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 @@ -87,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. @@ -220,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, @@ -240,11 +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, and a real failure anywhere in the run outranks a rejection. +// 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] @@ -256,49 +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.runFailed = 0, false + 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++ - st.runFailed = st.runFailed || outcome == outcomeFailure - if st.failures >= p.failures { - switch { - case st.runFailed: - // Some probe in this run 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) } } @@ -321,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 4a3e040..0fe6b0d 100644 --- a/health_test.go +++ b/health_test.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "errors" + "fmt" "io" "log" "net/http" @@ -76,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++ { @@ -109,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") } @@ -138,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") @@ -574,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) } @@ -582,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{ @@ -667,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++ { @@ -697,41 +772,167 @@ func TestProber_SuccessResetsTheRunInEveryDirection(t *testing.T) { } } -func TestProber_RecoversFromProbeUnsupported(t *testing.T) { - p := newTestProber(t, healthConfig("http://a.invalid", "http://b.invalid")) - markUnsupported(t, p, "a") +// 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 = failures + p := newTestProber(t, cfg) - for i := 0; i < p.successes; i++ { - p.record("a", nil) - } - if !p.healthy("a") { - t.Fatal("backend left the pool while recovering") - } - if got := p.snapshot()["a"].stateName(); got != stateHealthy { - t.Fatalf("state = %q, want %q", got, stateHealthy) + 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) + } + } } } -// Rejections cannot talk a down backend back into the pool while its failure run -// is unbroken — the failures are still the run's best evidence. A successful -// probe ends the run, and rejections after that mean the probe stopped working -// rather than the backend. -func TestProber_RejectedProbeReadmitsADownBackendOnlyAfterASuccess(t *testing.T) { +// 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")) - markDown(t, p, "a") + markUsable(t, p, "a") - for i := 0; i < p.failures*5; i++ { + for i := 0; i < 100; i++ { p.record("a", rejectedProbe(p)) - if p.healthy("a") { - t.Fatal("rejections re-admitted a backend whose failure run never ended") - } + } + 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) } +} - p.record("a", nil) - markUnsupported(t, p, "a") +// 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.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 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 answeredProbe() } + dead := func(*prober) error { return deadProbe() } + + cycles := map[string][]func(*prober) error{ + "rejected/failure": {rejected, failed}, + "failure/rejected": {failed, rejected}, + "failure-heavy 3-cycle": {rejected, failed, failed}, + "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 := 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++ { + p.record("a", cycle[i%len(cycle)](p)) + switch { + case !p.healthy("a"): + down = true + case down: + t.Fatalf("backend flapped back into service at probe %d", i+1) + } + } + if !down { + t.Fatal("a backend that failed 600 probes never left the pool") + } + if got := p.snapshot()["a"].stateName(); got != stateUnhealthy { + t.Errorf("state = %q, want %q", got, stateUnhealthy) + } + }) + } + } } func TestProber_LogsProbeRejectionOncePerTransition(t *testing.T) { @@ -742,10 +943,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) { @@ -755,18 +963,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()) } } diff --git a/server.go b/server.go index 7bc4447..a16b96a 100644 --- a/server.go +++ b/server.go @@ -682,7 +682,7 @@ type backendReport struct { // every configured backend regardless of probe state: "ok" or the error text. Reachable string `json:"reachable"` // State is the background prober's verdict. probe_unsupported means the probe - // path is unusable on this backend, so its health is unknown — read Reachable + // has never answered on this backend, so its health is unknown — read Reachable // to find out whether it is up. State string `json:"state"` // healthy | unhealthy | probe_unsupported | unprobed | unmonitored Failures int `json:"consecutive_failures"`