diff --git a/src/kit/httpapi/_probes.py b/src/kit/httpapi/_probes.py index 03b647a..eb760e7 100644 --- a/src/kit/httpapi/_probes.py +++ b/src/kit/httpapi/_probes.py @@ -50,6 +50,12 @@ def probe_router( moved with an API version would need the deployment updated in lockstep. """ log = logger or logging.getLogger("kit.httpapi") + # Last state logged per dependency, so /readyz reports transitions rather + # than repeating steady state on every kubelet poll. Per router, which means + # per app, which means per process: a replica that restarts re-establishes + # its own baseline and logs what it finds once. + logged: dict[str, tuple[State, str, str]] = {} + router = APIRouter(include_in_schema=False) @router.get("/healthz") @@ -83,28 +89,59 @@ async def readyz() -> Response: # pyright: ignore[reportUnusedFunction] if result.blocking: ready = False + # ON TRANSITION ONLY, never once per probe. A kubelet polls /readyz + # every few seconds forever, so logging steady state here emits the + # same warning thousands of times a day per replica. That is not a + # louder signal, it is a quieter one: the line that matters (a + # dependency that JUST broke) is buried in identical copies of a + # line that has been true since boot, and it is billed by the + # gigabyte in the log store. + # + # Keyed by dependency, holding the last state and reason we logged, + # so a flap from ready to error to ready logs both edges while a + # dependency sitting unconfigured since startup logs exactly once. + previous = logged.get(result.name) + current = (result.effective, result.reason, str(result.error)) + changed = previous != current + + if changed: + logged[result.name] = current + if result.effective is State.ERROR: - # The detail stays server-side. - log.warning( - "dependency check failed", - extra={ - "request_id": request_id(), - "dependency": result.name, - "required": result.required, - "error": str(result.error), - }, - ) + if changed: + # The detail stays server-side. + log.warning( + "dependency check failed", + extra={ + "request_id": request_id(), + "dependency": result.name, + "required": result.required, + "error": str(result.error), + }, + ) elif result.effective is State.UNCONFIGURED: - # Logged even when it is not blocking, because "this deployment - # has no object storage" is exactly the fact somebody needs when - # a feature is mysteriously absent. - log.warning( - "dependency is not configured", + if changed: + # Still logged, because "this deployment has no object + # storage" is exactly the fact somebody needs when a feature + # is mysteriously absent. Once is enough to establish it. + log.warning( + "dependency is not configured", + extra={ + "request_id": request_id(), + "dependency": result.name, + "required": result.required, + "reason": result.reason, + }, + ) + elif changed and previous is not None: + # Recovery is worth a line: it is the other half of any + # incident, and without it a log shows only the breakage. + log.info( + "dependency recovered", extra={ "request_id": request_id(), "dependency": result.name, "required": result.required, - "reason": result.reason, }, ) diff --git a/tests/test_probes.py b/tests/test_probes.py index ff7d88d..f32e69a 100644 --- a/tests/test_probes.py +++ b/tests/test_probes.py @@ -121,3 +121,77 @@ async def test_required_unconfigured_blocks_and_optional_does_not( assert response.status_code == expected_status assert response.json()["checks"] == {"auth": "unconfigured"} + + +async def test_steady_state_is_logged_once_not_once_per_probe( + caplog: pytest.LogCaptureFixture, +) -> None: + """THE reason this logging is keyed by state rather than emitted per call. + + A kubelet polls /readyz every few seconds for the life of the pod. Logging + steady state here would emit the same warning thousands of times a day per + replica, which does not make the signal louder: it buries the line that + matters (a dependency that JUST broke) under identical copies of a line + that has been true since boot, and bills for the privilege. + """ + registry = Registry() + # Optional, exactly as a real service declares its cache: an absent + # cache is a slower service, not a broken one, so readiness stays 200. + registry.add_optional_unconfigured("valkey", "CACHE_URL is empty") + app = build(registry) + + with caplog.at_level("WARNING", logger="kit.httpapi"): + for _ in range(5): + assert (await call(app, "/readyz")).status_code == 200 + + unconfigured = [r for r in caplog.records if r.msg == "dependency is not configured"] + assert len(unconfigured) == 1, ( + f"five probes produced {len(unconfigured)} warnings; steady state must log once" + ) + + +async def test_a_failing_dependency_logs_once_while_it_stays_failing( + caplog: pytest.LogCaptureFixture, +) -> None: + registry = Registry() + registry.add("postgres", failing_check(RuntimeError("down"))) + app = build(registry) + + with caplog.at_level("WARNING", logger="kit.httpapi"): + for _ in range(4): + assert (await call(app, "/readyz")).status_code == 503 + + failures = [r for r in caplog.records if r.msg == "dependency check failed"] + assert len(failures) == 1 + + +async def test_both_edges_of_a_flap_are_logged(caplog: pytest.LogCaptureFixture) -> None: + """Breaking and recovering are each worth exactly one line. + + Without the recovery line a log shows only half of every incident: the + moment it broke, and never the moment it came back. + """ + healthy = True + + async def flapping() -> None: + if not healthy: + raise RuntimeError("down") + + registry = Registry() + registry.add("postgres", flapping) + app = build(registry) + + with caplog.at_level("INFO", logger="kit.httpapi"): + assert (await call(app, "/readyz")).status_code == 200 + healthy = False + assert (await call(app, "/readyz")).status_code == 503 + assert (await call(app, "/readyz")).status_code == 503 + healthy = True + assert (await call(app, "/readyz")).status_code == 200 + + assert [r.msg for r in caplog.records if r.msg == "dependency check failed"] == [ + "dependency check failed" + ] + assert [r.msg for r in caplog.records if r.msg == "dependency recovered"] == [ + "dependency recovered" + ]