"""Content-free phase timing for diagnosing slow Gateway operations.""" from __future__ import annotations import logging from collections.abc import Iterator from contextlib import contextmanager from time import perf_counter from starlette.exceptions import HTTPException from starlette.responses import Response class OperationTiming: """Measure handler work, not proxy/network or pre-handler/auth queue time. Phase names and context must be server-owned labels, never request content, database URLs or credentials. The response header also helps deployments where operators do not yet have application logs available. """ def __init__(self, response: Response | None, logger: logging.Logger, operation: str, **context: str) -> None: self.response = response if response is not None else Response() self.logger = logger self.operation = operation self.context = context self.started = perf_counter() self.phases: dict[str, float] = {} def __enter__(self) -> OperationTiming: return self def __exit__(self, exc_type, exc, traceback) -> None: total_ms = (perf_counter() - self.started) * 1000 metrics = {**self.phases, "handler_total": total_ms} self.response.headers["Server-Timing"] = ", ".join(f"{name};dur={duration:.2f}" for name, duration in metrics.items()) if isinstance(exc, HTTPException): # FastAPI discards the injected response on HTTPException. exc.headers = {**(exc.headers or {}), "Server-Timing": self.response.headers["Server-Timing"]} log = self.logger.warning if exc_type is not None or total_ms >= 1000 else self.logger.info try: log( "GATEWAY_OPERATION_TIMING operation=%s outcome=%s %s %s", self.operation, "error" if exc_type is not None else "ok", " ".join(f"{name}={value}" for name, value in self.context.items()), " ".join(f"{name}_ms={duration:.2f}" for name, duration in metrics.items()), ) except Exception: # Diagnostics must not hide the actual request error (or fail a # successful write) if a custom logging handler/disk is unavailable. pass @contextmanager def phase(self, name: str) -> Iterator[None]: started = perf_counter() try: yield finally: self.phases[name] = self.phases.get(name, 0.0) + (perf_counter() - started) * 1000