fix(httpapi): log dependency state on transition, not every probe

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,
                     },
                 )
 

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"
+    ]