From 585c07e4ec31adf2bb12787dceea7f6b37f2de2d Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:21:55 -0500 Subject: [PATCH 01/17] fix: import httpx2 in the benchmark utility The httpx2 migration in #156 removed `httpx` from the project, but `scripts/benchmark/util.py` still imported it. Every benchmark script imports `util`, so all three have been dead on `dev` and `main` since that merge: ModuleNotFoundError: No module named 'httpx' Nothing caught it. Ruff does not resolve third-party imports, no test imports these scripts, and the coverage gate is `--cov=app`. The check I ran after the migration was a grep over `app/`, `tests/`, `pyproject.toml`, `Dockerfile` and `README.md` -- which simply omitted `scripts/`. A rename needs a repo-wide grep, not a directory-by-directory one. Production was never affected: the Dockerfile copies only `app/`. The API is identical, so this is the import and the two call sites. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- scripts/benchmark/util.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/scripts/benchmark/util.py b/scripts/benchmark/util.py index 173856d..bdda705 100644 --- a/scripts/benchmark/util.py +++ b/scripts/benchmark/util.py @@ -3,7 +3,7 @@ import os import time -import httpx +import httpx2 from dotenv import load_dotenv load_dotenv() @@ -26,7 +26,7 @@ def make_request( Returns: Tuple of response JSON and elapsed time in seconds """ - with httpx.Client(follow_redirects=True, timeout=httpx.Timeout(timeout)) as client: + with httpx2.Client(follow_redirects=True, timeout=httpx2.Timeout(timeout)) as client: if route == "authenticate": data = { "username": os.getenv("TEST_PRN"), From c30344bcbd48ad889f41e0b0a223db5a1725d872 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:23:15 -0500 Subject: [PATCH 02/17] feat: add an in-memory metrics collector Implements #129's collector, with two changes from the sketch in the issue. Families are typed registry objects rather than free strings. A typo in a metric name would otherwise create an orphan series that silently never gets reported; now it raises at the call site, and `FAMILIES` doubles as the single source of HELP and TYPE text shared by every view. Dimensions are labels, not name suffixes. The review on #132 asked for keys like `requests_failed_status_{code}`, but those cannot be rendered as Prometheus -- each string becomes its own family needing its own HELP and TYPE, and `sum by (status)` becomes impossible. `responses_total{status="401"}` aggregates and stays one family however many status codes appear. No lock. Every mutation is a dict read and write with no await between them, so the event loop cannot interleave two increments. The asyncio.Lock in app/pesu.py exists because that code swaps several fields *around* an await, which is a different problem. The docstring records where this stops holding. Unlabelled series are seeded at zero so a freshly started process exposes them before its first request -- otherwise a series springs into existence mid-window and `rate()` reads it as a spike. `process_start_time_seconds` is exposed for the same class of reason: Render restarts wipe these counters, and without it a dashboard cannot tell a restart from a drop in traffic. Nothing imports this yet. 20 tests, 100% coverage of the new module. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/metrics/__init__.py | 49 ++++++ app/metrics/collector.py | 225 +++++++++++++++++++++++++++ tests/unit/test_metrics_collector.py | 148 ++++++++++++++++++ 3 files changed, 422 insertions(+) create mode 100644 app/metrics/__init__.py create mode 100644 app/metrics/collector.py create mode 100644 tests/unit/test_metrics_collector.py diff --git a/app/metrics/__init__.py b/app/metrics/__init__.py new file mode 100644 index 0000000..e311437 --- /dev/null +++ b/app/metrics/__init__.py @@ -0,0 +1,49 @@ +"""Metrics collection for the PESUAuth API. + +This package deliberately exports no collector instance. The singleton is created in `app/app.py` +alongside the PESUAcademy client, so that importing the package has no side effects and tests can +swap the collector out by patching one module attribute. +""" + +from .collector import ( + AUTHENTICATION_REQUESTS as AUTHENTICATION_REQUESTS, +) +from .collector import ( + ERRORS_BY_TYPE as ERRORS_BY_TYPE, +) +from .collector import ( + FAMILIES as FAMILIES, +) +from .collector import ( + PROCESS_START_TIME as PROCESS_START_TIME, +) +from .collector import ( + REQUEST_LATENCY as REQUEST_LATENCY, +) +from .collector import ( + REQUESTS_FAILED as REQUESTS_FAILED, +) +from .collector import ( + REQUESTS_SUCCESS as REQUESTS_SUCCESS, +) +from .collector import ( + REQUESTS_TOTAL as REQUESTS_TOTAL, +) +from .collector import ( + RESPONSES_BY_STATUS as RESPONSES_BY_STATUS, +) +from .collector import ( + ROUTE_LATENCY as ROUTE_LATENCY, +) +from .collector import ( + ROUTE_REQUESTS as ROUTE_REQUESTS, +) +from .collector import ( + MetricFamily as MetricFamily, +) +from .collector import ( + MetricsCollector as MetricsCollector, +) +from .collector import ( + MetricsSnapshot as MetricsSnapshot, +) diff --git a/app/metrics/collector.py b/app/metrics/collector.py new file mode 100644 index 0000000..8d0569c --- /dev/null +++ b/app/metrics/collector.py @@ -0,0 +1,225 @@ +"""The metric family registry and the in-memory collector behind the /metrics endpoints.""" + +from __future__ import annotations + +import time +from collections import defaultdict +from dataclasses import dataclass +from typing import TYPE_CHECKING, Literal + +if TYPE_CHECKING: + from collections.abc import Callable, Iterator, Mapping + +# A label set, normalised to a sorted tuple of pairs so that it can key a dict +LabelKey = tuple[tuple[str, str], ...] +MetricType = Literal["counter", "gauge", "summary"] + +METRIC_PREFIX = "pesu_auth_" + + +@dataclass(frozen=True, slots=True) +class MetricFamily: + """A metric family: its exposed name, documentation, type and permitted label names.""" + + name: str + documentation: str + metric_type: MetricType + labels: tuple[str, ...] = () + + +REQUESTS_TOTAL = MetricFamily( + f"{METRIC_PREFIX}requests_total", + "HTTP requests received.", + "counter", +) +REQUESTS_SUCCESS = MetricFamily( + f"{METRIC_PREFIX}requests_success_total", + "HTTP requests answered with a status below 400.", + "counter", +) +REQUESTS_FAILED = MetricFamily( + f"{METRIC_PREFIX}requests_failed_total", + "HTTP requests answered with a status of 400 or above.", + "counter", +) +RESPONSES_BY_STATUS = MetricFamily( + f"{METRIC_PREFIX}responses_total", + "HTTP responses, by status code.", + "counter", + ("status",), +) +ROUTE_REQUESTS = MetricFamily( + f"{METRIC_PREFIX}route_requests_total", + "HTTP requests, by matched route and method.", + "counter", + ("method", "route"), +) +ERRORS_BY_TYPE = MetricFamily( + f"{METRIC_PREFIX}errors_total", + "Errors rendered by an exception handler, by exception class.", + "counter", + ("type",), +) +AUTHENTICATION_REQUESTS = MetricFamily( + f"{METRIC_PREFIX}authentication_requests_total", + "Authentication requests, by whether profile data was requested.", + "counter", + ("profile",), +) +REQUEST_LATENCY = MetricFamily( + f"{METRIC_PREFIX}request_latency_seconds", + "Seconds from receiving a request to starting its response.", + "summary", +) +ROUTE_LATENCY = MetricFamily( + f"{METRIC_PREFIX}route_latency_seconds", + "Seconds from receiving a request to starting its response, by route.", + "summary", + ("method", "route"), +) +PROCESS_START_TIME = MetricFamily( + f"{METRIC_PREFIX}process_start_time_seconds", + "Start time of the process since the Unix epoch, in seconds.", + "gauge", +) + +# Render order, and the single source of HELP and TYPE shared by both views +FAMILIES: tuple[MetricFamily, ...] = ( + REQUESTS_TOTAL, + REQUESTS_SUCCESS, + REQUESTS_FAILED, + RESPONSES_BY_STATUS, + ROUTE_REQUESTS, + ERRORS_BY_TYPE, + AUTHENTICATION_REQUESTS, + REQUEST_LATENCY, + ROUTE_LATENCY, + PROCESS_START_TIME, +) + + +@dataclass(frozen=True, slots=True) +class MetricsSnapshot: + """A point-in-time copy of every series held by a collector.""" + + start_time: float + uptime_seconds: float + values: Mapping[str, Mapping[LabelKey, float]] + + def value(self, name: str, **labels: str) -> float: + """Return a single series value, or 0.0 if it was never recorded. + + Args: + name (str): The stored series name, including any _sum or _count suffix. + **labels (str): The label set identifying the series. + + Returns: + float: The recorded value, defaulting to 0.0. + """ + return self.values.get(name, {}).get(tuple(sorted(labels.items())), 0.0) + + def samples(self, name: str) -> Iterator[tuple[dict[str, str], float]]: + """Yield every (labels, value) pair recorded against a stored series, in label order. + + Args: + name (str): The stored series name, including any _sum or _count suffix. + + Yields: + tuple[dict[str, str], float]: The label set and its value. + """ + series = self.values.get(name, {}) + for key in sorted(series): + yield dict(key), series[key] + + +class MetricsCollector: + """Process-local counters for the traffic this process has served. + + Deliberately unsynchronised. Every mutation is a dict read followed by a dict write with no + await in between, so the event loop cannot interleave two increments -- a task runs to its next + suspension point before any other task resumes. The asyncio.Lock in app/pesu.py exists because + that code swaps several fields *around* an await, which is a different situation, and an + asyncio.Lock would give no protection against threads anyway. This reasoning stops holding under + `uvicorn --workers > 1` (which needs a shared store, not a lock) or on a free-threaded build. + + Counters live in memory and reset when the process restarts, which on Render is often. That is + why process_start_time_seconds is exposed: a scraper needs it to tell a restart apart from a + drop in traffic. + """ + + def __init__(self, *, clock: Callable[[], float] | None = None) -> None: + """Initialize the collector and seed every unlabelled series at zero. + + Args: + clock (Callable[[], float] | None): Wall-clock source, injected by tests. + """ + self._clock = clock or time.time + self._start_time = self._clock() + self._values: defaultdict[str, dict[LabelKey, float]] = defaultdict(dict) + # Seed the unlabelled series so a freshly started process still exposes them. Without this + # a Grafana panel has no series at all until the first request, and rate() over a series + # that springs into existence mid-window reads as a spike. + for family in FAMILIES: + if family.labels: + continue + if family.metric_type == "summary": + self._values[f"{family.name}_sum"][()] = 0.0 + self._values[f"{family.name}_count"][()] = 0.0 + else: + self._values[family.name][()] = 0.0 + self._values[PROCESS_START_TIME.name][()] = self._start_time + + @staticmethod + def _key(family: MetricFamily, labels: Mapping[str, str]) -> LabelKey: + """Normalise and validate a label set against its family. + + Args: + family (MetricFamily): The family being recorded against. + labels (Mapping[str, str]): The supplied labels. + + Returns: + LabelKey: The labels as a sorted tuple of pairs. + + Raises: + ValueError: If the label names do not match the family's declared labels. + """ + if set(labels) != set(family.labels): + raise ValueError(f"{family.name} expects labels {family.labels}, got {tuple(sorted(labels))}.") + return tuple(sorted(labels.items())) + + def increment(self, family: MetricFamily, value: float = 1.0, **labels: str) -> None: + """Add to a counter series. + + Args: + family (MetricFamily): The counter family to record against. + value (float): The amount to add. Defaults to 1.0. + **labels (str): The label set, which must match the family's declared labels. + """ + key = self._key(family, labels) + series = self._values[family.name] + series[key] = series.get(key, 0.0) + value + + def observe(self, family: MetricFamily, seconds: float, **labels: str) -> None: + """Record one observation against a summary family's sum and count series. + + Args: + family (MetricFamily): The summary family to record against. + seconds (float): The observed value. + **labels (str): The label set, which must match the family's declared labels. + """ + key = self._key(family, labels) + for name, amount in ((f"{family.name}_sum", seconds), (f"{family.name}_count", 1.0)): + series = self._values[name] + series[key] = series.get(key, 0.0) + amount + + def snapshot(self) -> MetricsSnapshot: + """Copy every series so a renderer can iterate without observing further mutation. + + Returns: + MetricsSnapshot: An immutable view of the current values. + """ + return MetricsSnapshot( + start_time=self._start_time, + uptime_seconds=max(self._clock() - self._start_time, 0.0), + values={name: dict(series) for name, series in self._values.items()}, + ) diff --git a/tests/unit/test_metrics_collector.py b/tests/unit/test_metrics_collector.py new file mode 100644 index 0000000..0fbf98e --- /dev/null +++ b/tests/unit/test_metrics_collector.py @@ -0,0 +1,148 @@ +import pytest + +from app.metrics.collector import ( + AUTHENTICATION_REQUESTS, + FAMILIES, + PROCESS_START_TIME, + REQUEST_LATENCY, + REQUESTS_TOTAL, + RESPONSES_BY_STATUS, + ROUTE_LATENCY, + ROUTE_REQUESTS, + MetricFamily, + MetricsCollector, +) + + +@pytest.fixture +def collector(): + """A collector on a frozen clock, so uptime and start time are deterministic.""" + return MetricsCollector(clock=lambda: 1000.0) + + +def test_unlabelled_families_are_seeded_at_zero(collector): + """A fresh process must expose its unlabelled series, or rate() reads their first use as a spike.""" + snapshot = collector.snapshot() + for family in FAMILIES: + if family.labels or family is PROCESS_START_TIME: + continue + if family.metric_type == "summary": + assert snapshot.value(f"{family.name}_sum") == 0.0 + assert snapshot.value(f"{family.name}_count") == 0.0 + else: + assert snapshot.value(family.name) == 0.0 + + +def test_process_start_time_is_recorded(collector): + assert collector.snapshot().value(PROCESS_START_TIME.name) == 1000.0 + + +def test_labelled_families_start_empty(collector): + """Labelled series cannot be seeded -- their label values are not known until traffic arrives.""" + assert list(collector.snapshot().samples(RESPONSES_BY_STATUS.name)) == [] + + +def test_increment_accumulates(collector): + collector.increment(REQUESTS_TOTAL) + collector.increment(REQUESTS_TOTAL) + assert collector.snapshot().value(REQUESTS_TOTAL.name) == 2.0 + + +def test_increment_accepts_a_custom_value(collector): + collector.increment(REQUESTS_TOTAL, 5.0) + assert collector.snapshot().value(REQUESTS_TOTAL.name) == 5.0 + + +def test_labelled_series_are_kept_apart(collector): + collector.increment(RESPONSES_BY_STATUS, status="200") + collector.increment(RESPONSES_BY_STATUS, status="401") + collector.increment(RESPONSES_BY_STATUS, status="401") + snapshot = collector.snapshot() + assert snapshot.value(RESPONSES_BY_STATUS.name, status="200") == 1.0 + assert snapshot.value(RESPONSES_BY_STATUS.name, status="401") == 2.0 + + +def test_label_order_does_not_create_a_second_series(collector): + """Labels are normalised to a sorted tuple, so kwarg order cannot split one series into two.""" + collector.increment(ROUTE_REQUESTS, method="GET", route="/health") + collector.increment(ROUTE_REQUESTS, route="/health", method="GET") + assert collector.snapshot().value(ROUTE_REQUESTS.name, method="GET", route="/health") == 2.0 + + +def test_unknown_label_raises(collector): + with pytest.raises(ValueError, match="expects labels"): + collector.increment(RESPONSES_BY_STATUS, bogus="x") + + +def test_missing_label_raises(collector): + with pytest.raises(ValueError, match="expects labels"): + collector.increment(ROUTE_REQUESTS, method="GET") + + +def test_labels_on_an_unlabelled_family_raise(collector): + with pytest.raises(ValueError, match="expects labels"): + collector.increment(REQUESTS_TOTAL, status="200") + + +def test_observe_records_sum_and_count(collector): + collector.observe(REQUEST_LATENCY, 0.25) + collector.observe(REQUEST_LATENCY, 0.75) + snapshot = collector.snapshot() + assert snapshot.value(f"{REQUEST_LATENCY.name}_sum") == 1.0 + assert snapshot.value(f"{REQUEST_LATENCY.name}_count") == 2.0 + + +def test_observe_keeps_labelled_summaries_apart(collector): + collector.observe(ROUTE_LATENCY, 1.5, method="GET", route="/health") + collector.observe(ROUTE_LATENCY, 0.5, method="POST", route="/authenticate") + snapshot = collector.snapshot() + assert snapshot.value(f"{ROUTE_LATENCY.name}_sum", method="GET", route="/health") == 1.5 + assert snapshot.value(f"{ROUTE_LATENCY.name}_count", method="POST", route="/authenticate") == 1.0 + + +def test_snapshot_is_isolated_from_later_mutation(collector): + """A snapshot copies each series, so a renderer iterating it cannot observe a concurrent write.""" + before = collector.snapshot() + collector.increment(REQUESTS_TOTAL) + assert before.value(REQUESTS_TOTAL.name) == 0.0 + assert collector.snapshot().value(REQUESTS_TOTAL.name) == 1.0 + + +def test_snapshot_value_defaults_to_zero_for_an_unrecorded_series(collector): + assert collector.snapshot().value(RESPONSES_BY_STATUS.name, status="418") == 0.0 + assert collector.snapshot().value("pesu_auth_not_a_real_metric") == 0.0 + + +def test_samples_are_label_sorted(collector): + for status in ("500", "200", "401"): + collector.increment(RESPONSES_BY_STATUS, status=status) + statuses = [labels["status"] for labels, _ in collector.snapshot().samples(RESPONSES_BY_STATUS.name)] + assert statuses == ["200", "401", "500"] + + +def test_samples_of_an_unrecorded_series_is_empty(collector): + assert list(collector.snapshot().samples(AUTHENTICATION_REQUESTS.name)) == [] + + +def test_uptime_is_measured_from_the_start_time(): + clock = iter([1000.0, 1042.5]) + collector = MetricsCollector(clock=lambda: next(clock)) + assert collector.snapshot().uptime_seconds == 42.5 + + +def test_uptime_is_never_negative(): + """A clock that steps backwards must not produce a negative uptime.""" + clock = iter([1000.0, 900.0]) + collector = MetricsCollector(clock=lambda: next(clock)) + assert collector.snapshot().uptime_seconds == 0.0 + + +def test_default_clock_is_wall_time(): + """The injected clock is a test seam; the default must still be real time.""" + assert MetricsCollector().snapshot().start_time > 0 + + +def test_metric_family_is_immutable(): + family = MetricFamily("x", "y", "counter") + with pytest.raises(AttributeError): + family.name = "z" From 5e36a01fb39d26b390fdffacdb7beec53c09321e Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:24:04 -0500 Subject: [PATCH 03/17] feat: render metrics in the Prometheus text exposition format This is what unblocks #130: Grafana scrapes Prometheus, not arbitrary JSON, so a JSON-only /metrics would have needed an exporter written later. Hand-rolled rather than pulling in prometheus_client, which is the direct answer to the dependency question raised on #132: **no dependencies are added.** prometheus_client installs a process-global default registry at import time -- precisely the "global collector outside the entry point" the review rejected -- and it would become a second source of truth beside the snapshot we need anyway for the pydantic view. What it buys over these 50 lines is histogram buckets, which we do not expose. The format for counters, gauges and a quantile-less summary is a small, stable grammar that the tests pin exactly. Details that are easy to get wrong, so they are tested: - the media type must carry `version=0.0.4`, or a scraper guesses the format - label values are double-quoted, so `"`, `\` and newline need escaping; HELP text is unquoted, so only `\` and newline do - labels render sorted, which keeps the payload deterministic and diffable - whole numbers render without a decimal point, matching every other exporter 16 tests, 100% coverage of the renderer. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/metrics/prometheus.py | 84 +++++++++++++++++ tests/unit/test_metrics_prometheus.py | 125 ++++++++++++++++++++++++++ 2 files changed, 209 insertions(+) create mode 100644 app/metrics/prometheus.py create mode 100644 tests/unit/test_metrics_prometheus.py diff --git a/app/metrics/prometheus.py b/app/metrics/prometheus.py new file mode 100644 index 0000000..59d5d28 --- /dev/null +++ b/app/metrics/prometheus.py @@ -0,0 +1,84 @@ +"""Render a metrics snapshot in the Prometheus text exposition format.""" + +from __future__ import annotations + +from typing import TYPE_CHECKING + +from app.metrics.collector import FAMILIES + +if TYPE_CHECKING: + from collections.abc import Iterator, Mapping + + from app.metrics.collector import MetricsSnapshot + +# Prometheus requires this exact media type for the 0.0.4 text format. The version parameter is not +# optional: a scraper handed a bare "text/plain" falls back to guessing the format. +PROMETHEUS_CONTENT_TYPE = "text/plain; version=0.0.4; charset=utf-8" + +# Label values are double-quoted, so a backslash, a quote or a newline inside one has to be escaped +# or the sample line stops parsing. Everything else, including UTF-8, passes through. +_LABEL_VALUE_ESCAPES = str.maketrans({"\\": "\\\\", '"': '\\"', "\n": "\\n"}) +# HELP text is not quoted, so a quote is fine there; only the escape character and the line +# terminator have to go. +_DOCUMENTATION_ESCAPES = str.maketrans({"\\": "\\\\", "\n": "\\n"}) + + +def _render_value(value: float) -> str: + """Render a sample value, preferring integer form for whole numbers. + + Args: + value (float): The value to render. + + Returns: + str: The rendered value. + """ + return str(int(value)) if value.is_integer() else repr(value) + + +def _render_labels(labels: Mapping[str, str]) -> str: + """Render a label set as a Prometheus label matcher, or an empty string when unlabelled. + + Args: + labels (Mapping[str, str]): The label set. + + Returns: + str: The rendered matcher, including braces, or an empty string. + """ + if not labels: + return "" + pairs = ",".join(f'{name}="{labels[name].translate(_LABEL_VALUE_ESCAPES)}"' for name in sorted(labels)) + return f"{{{pairs}}}" + + +def _render_series(snapshot: MetricsSnapshot, name: str) -> Iterator[str]: + """Yield one sample line per label set recorded against a stored series. + + Args: + snapshot (MetricsSnapshot): The snapshot to read. + name (str): The stored series name, including any _sum or _count suffix. + + Yields: + str: A rendered sample line. + """ + for labels, value in snapshot.samples(name): + yield f"{name}{_render_labels(labels)} {_render_value(value)}" + + +def render_prometheus(snapshot: MetricsSnapshot) -> str: + """Render a snapshot as a Prometheus 0.0.4 text exposition payload. + + Args: + snapshot (MetricsSnapshot): The point-in-time collector snapshot to render. + + Returns: + str: The exposition payload, newline terminated. + """ + lines: list[str] = [] + for family in FAMILIES: + lines.append(f"# HELP {family.name} {family.documentation.translate(_DOCUMENTATION_ESCAPES)}") + lines.append(f"# TYPE {family.name} {family.metric_type}") + # A summary is stored as two series; a counter or a gauge as one. + names = (f"{family.name}_sum", f"{family.name}_count") if family.metric_type == "summary" else (family.name,) + for name in names: + lines.extend(_render_series(snapshot, name)) + return "\n".join(lines) + "\n" diff --git a/tests/unit/test_metrics_prometheus.py b/tests/unit/test_metrics_prometheus.py new file mode 100644 index 0000000..3ba2014 --- /dev/null +++ b/tests/unit/test_metrics_prometheus.py @@ -0,0 +1,125 @@ +import pytest + +from app.metrics.collector import ( + ERRORS_BY_TYPE, + FAMILIES, + PROCESS_START_TIME, + REQUEST_LATENCY, + REQUESTS_TOTAL, + RESPONSES_BY_STATUS, + ROUTE_LATENCY, + ROUTE_REQUESTS, + MetricsCollector, +) +from app.metrics.prometheus import ( + PROMETHEUS_CONTENT_TYPE, + _render_labels, + _render_value, + render_prometheus, +) + + +@pytest.fixture +def collector(): + return MetricsCollector(clock=lambda: 1757660400.0) + + +def test_content_type_is_the_0_0_4_text_format(): + """The version parameter is not optional: without it a scraper guesses the format.""" + assert PROMETHEUS_CONTENT_TYPE == "text/plain; version=0.0.4; charset=utf-8" + + +def test_every_family_is_declared_exactly_once(collector): + payload = render_prometheus(collector.snapshot()) + for family in FAMILIES: + assert payload.count(f"# HELP {family.name} ") == 1 + assert payload.count(f"# TYPE {family.name} {family.metric_type}\n") == 1 + + +def test_payload_is_newline_terminated(collector): + assert render_prometheus(collector.snapshot()).endswith("\n") + + +def test_unlabelled_counter_sample_line(collector): + collector.increment(REQUESTS_TOTAL, 3) + assert "\npesu_auth_requests_total 3\n" in render_prometheus(collector.snapshot()) + + +def test_labelled_counter_sample_line(collector): + collector.increment(RESPONSES_BY_STATUS, status="401") + assert '\npesu_auth_responses_total{status="401"} 1\n' in render_prometheus(collector.snapshot()) + + +def test_labels_are_rendered_in_sorted_order(collector): + """Sorted labels keep the payload deterministic, so tests and diffs are stable.""" + collector.increment(ROUTE_REQUESTS, route="/health", method="GET") + payload = render_prometheus(collector.snapshot()) + assert '\npesu_auth_route_requests_total{method="GET",route="/health"} 1\n' in payload + + +def test_summary_renders_sum_and_count_under_one_type_line(collector): + collector.observe(REQUEST_LATENCY, 0.5) + collector.observe(REQUEST_LATENCY, 0.25) + payload = render_prometheus(collector.snapshot()) + assert "# TYPE pesu_auth_request_latency_seconds summary\n" in payload + assert "\npesu_auth_request_latency_seconds_sum 0.75\n" in payload + assert "\npesu_auth_request_latency_seconds_count 2\n" in payload + + +def test_labelled_summary_renders_both_series_with_labels(collector): + collector.observe(ROUTE_LATENCY, 1.5, method="POST", route="/authenticate") + payload = render_prometheus(collector.snapshot()) + assert '\npesu_auth_route_latency_seconds_sum{method="POST",route="/authenticate"} 1.5\n' in payload + assert '\npesu_auth_route_latency_seconds_count{method="POST",route="/authenticate"} 1\n' in payload + + +def test_gauge_renders_the_start_time(collector): + payload = render_prometheus(collector.snapshot()) + assert "# TYPE pesu_auth_process_start_time_seconds gauge\n" in payload + assert f"\n{PROCESS_START_TIME.name} 1757660400\n" in payload + + +def test_whole_numbers_render_without_a_decimal_point(): + assert _render_value(3.0) == "3" + assert _render_value(0.0) == "0" + + +def test_fractional_values_round_trip(): + assert float(_render_value(0.1 + 0.2)) == 0.1 + 0.2 + assert _render_value(1.5) == "1.5" + + +def test_label_values_are_escaped(collector): + """A quote, a backslash or a newline in a label value would otherwise break the sample line.""" + collector.increment(ERRORS_BY_TYPE, type='we"ird\\type\nhere') + payload = render_prometheus(collector.snapshot()) + assert '\npesu_auth_errors_total{type="we\\"ird\\\\type\\nhere"} 1\n' in payload + + +def test_documentation_is_escaped(monkeypatch): + """A newline in HELP text would split it across two lines and corrupt the payload.""" + from app.metrics import collector as collector_module + from app.metrics import prometheus as prometheus_module + + family = collector_module.MetricFamily("pesu_auth_odd", "line one\nline two\\end", "counter") + monkeypatch.setattr(prometheus_module, "FAMILIES", (family,)) + payload = render_prometheus(MetricsCollector().snapshot()) + assert payload.splitlines()[0] == "# HELP pesu_auth_odd line one\\nline two\\\\end" + + +def test_unlabelled_render_produces_no_braces(): + assert _render_labels({}) == "" + + +def test_a_family_with_no_observations_still_declares_itself(collector): + """A labelled family with no samples yet must still emit HELP and TYPE, which is valid.""" + payload = render_prometheus(collector.snapshot()) + assert "# TYPE pesu_auth_errors_total counter\n" in payload + assert "pesu_auth_errors_total{" not in payload + + +def test_render_is_stable_across_calls(collector): + collector.increment(RESPONSES_BY_STATUS, status="500") + collector.increment(RESPONSES_BY_STATUS, status="200") + snapshot = collector.snapshot() + assert render_prometheus(snapshot) == render_prometheus(snapshot) From 0c8aff522981bd9a6574df9a50753456c1d11850 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:25:20 -0500 Subject: [PATCH 04/17] feat: add a metrics response model Answers "create a model for this -- the response model will also need an update" from the review of #132. The awkward part is that metric keys are dynamic: the status codes and route templates that appear depend on traffic, so a fixed-field model cannot express them. Resolved by noting that dynamic *keys* do not require dynamic *fields* -- `responses_by_status: dict[str, int]` and `requests_by_route: dict[str, RouteMetricsModel]` validate every value, generate correct OpenAPI `additionalProperties`, and keep `strict=True` meaningful. `from_snapshot` casts every value explicitly. The collector stores floats, and strict mode rejects a float for an int field, so an un-cast value would be a 500 in production rather than a payload. That is the single most likely bug here, which is why the fresh-collector case is its own test. No timestamp field, deliberately: `IST` lives in app/app.py and importing it here would make app.models depend on app.app. `startTimeSeconds` and `uptimeSeconds` carry the same information, need no timezone, and line up with the Prometheus gauge. `averageSeconds` is null rather than absent on a fresh process, so consumers see one stable shape instead of a key that materialises after the first request. 11 tests, 100% coverage of the new module. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/models/__init__.py | 5 + app/models/metrics.py | 246 +++++++++++++++++++++++++++++++ tests/unit/test_metrics_model.py | 113 ++++++++++++++ 3 files changed, 364 insertions(+) create mode 100644 app/models/metrics.py create mode 100644 tests/unit/test_metrics_model.py diff --git a/app/models/__init__.py b/app/models/__init__.py index c06043f..5f941aa 100644 --- a/app/models/__init__.py +++ b/app/models/__init__.py @@ -1,5 +1,10 @@ """Custom models for the PESUAuth API.""" +from .metrics import AuthenticationCountsModel as AuthenticationCountsModel +from .metrics import LatencyModel as LatencyModel +from .metrics import MetricsModel as MetricsModel +from .metrics import RequestCountsModel as RequestCountsModel +from .metrics import RouteMetricsModel as RouteMetricsModel from .profile import ProfileModel as ProfileModel from .request import RequestModel as RequestModel from .response import ResponseModel as ResponseModel diff --git a/app/models/metrics.py b/app/models/metrics.py new file mode 100644 index 0000000..b1fb74c --- /dev/null +++ b/app/models/metrics.py @@ -0,0 +1,246 @@ +"""Models representing the metrics collected by the API.""" + +from pydantic import BaseModel, ConfigDict, Field +from pydantic.alias_generators import to_camel + +from app.metrics.collector import ( + AUTHENTICATION_REQUESTS, + ERRORS_BY_TYPE, + PROCESS_START_TIME, + REQUEST_LATENCY, + REQUESTS_FAILED, + REQUESTS_SUCCESS, + REQUESTS_TOTAL, + RESPONSES_BY_STATUS, + ROUTE_LATENCY, + ROUTE_REQUESTS, + MetricsSnapshot, +) + + +class LatencyModel(BaseModel): + """Model representing aggregate request latency.""" + + model_config = ConfigDict(strict=True, alias_generator=to_camel, populate_by_name=True) + + sum_seconds: float = Field( + ..., + title="Total Latency", + description="Cumulative seconds spent answering requests.", + json_schema_extra={"example": 742.1841932}, + ) + + count: int = Field( + ..., + title="Observation Count", + description="Number of requests whose latency was recorded.", + json_schema_extra={"example": 1284}, + ) + + average_seconds: float | None = Field( + None, + title="Mean Latency", + description="Mean seconds per request, or null when nothing has been recorded yet.", + json_schema_extra={"example": 0.5779}, + ) + + @classmethod + def from_snapshot(cls, snapshot: MetricsSnapshot, name: str, **labels: str) -> LatencyModel: + """Build a latency view from a snapshot's sum and count series. + + Args: + snapshot (MetricsSnapshot): The snapshot to read. + name (str): The summary family name, without a suffix. + **labels (str): The label set identifying the series. + + Returns: + LatencyModel: The aggregated latency for that label set. + """ + total = snapshot.value(f"{name}_sum", **labels) + count = snapshot.value(f"{name}_count", **labels) + return cls( + sum_seconds=float(total), + count=int(count), + average_seconds=float(total / count) if count else None, + ) + + +class RequestCountsModel(BaseModel): + """Model representing request outcome counts.""" + + model_config = ConfigDict(strict=True, alias_generator=to_camel, populate_by_name=True) + + total: int = Field( + ..., + title="Total Requests", + description="Requests received.", + json_schema_extra={"example": 1284}, + ) + + success: int = Field( + ..., + title="Successful Requests", + description="Requests answered with a status below 400.", + json_schema_extra={"example": 1102}, + ) + + failed: int = Field( + ..., + title="Failed Requests", + description="Requests answered with a status of 400 or above.", + json_schema_extra={"example": 182}, + ) + + +class AuthenticationCountsModel(BaseModel): + """Model representing authentication request counts, split by whether profile data was requested.""" + + model_config = ConfigDict(strict=True, alias_generator=to_camel, populate_by_name=True) + + total: int = Field( + ..., + title="Authentication Requests", + description="Authentication requests received.", + json_schema_extra={"example": 774}, + ) + + with_profile: int = Field( + ..., + title="With Profile Data", + description="Authentication requests that asked for profile data.", + json_schema_extra={"example": 134}, + ) + + without_profile: int = Field( + ..., + title="Without Profile Data", + description="Authentication requests that did not ask for profile data.", + json_schema_extra={"example": 640}, + ) + + +class RouteMetricsModel(BaseModel): + """Model representing the traffic served by a single route.""" + + model_config = ConfigDict(strict=True, alias_generator=to_camel, populate_by_name=True) + + requests: int = Field( + ..., + title="Route Requests", + description="Requests matched to this route.", + json_schema_extra={"example": 774}, + ) + + latency: LatencyModel = Field( + ..., + title="Route Latency", + description="Aggregate latency for this route.", + ) + + +class MetricsModel(BaseModel): + """Model representing a point-in-time view of the API's collected metrics.""" + + model_config = ConfigDict(strict=True, alias_generator=to_camel, populate_by_name=True) + + start_time_seconds: float = Field( + ..., + title="Process Start Time", + description="Start time of this process since the Unix epoch, in seconds. Counters reset on restart.", + json_schema_extra={"example": 1757660400.12}, + ) + + uptime_seconds: float = Field( + ..., + title="Uptime", + description="Seconds since this process started collecting.", + json_schema_extra={"example": 3612.44}, + ) + + requests: RequestCountsModel = Field( + ..., + title="Request Counts", + description="Request outcome counts.", + ) + + latency: LatencyModel = Field( + ..., + title="Request Latency", + description="Aggregate latency across all routes.", + ) + + authentication: AuthenticationCountsModel = Field( + ..., + title="Authentication Counts", + description="Authentication requests received, split by whether profile data was requested.", + ) + + responses_by_status: dict[str, int] = Field( + ..., + title="Responses by Status", + description="Response counts keyed by HTTP status code.", + json_schema_extra={"example": {"200": 1094, "401": 160, "502": 6}}, + ) + + requests_by_route: dict[str, RouteMetricsModel] = Field( + ..., + title="Requests by Route", + description='Per-route traffic, keyed by "METHOD route-template". Unmatched paths collapse into "".', + json_schema_extra={ + "example": { + "POST /authenticate": { + "requests": 774, + "latency": {"sumSeconds": 741.2118, "count": 774, "averageSeconds": 0.9576}, + } + } + }, + ) + + errors_by_type: dict[str, int] = Field( + ..., + title="Errors by Type", + description="Counts of errors rendered by an exception handler, keyed by exception class name.", + json_schema_extra={"example": {"AuthenticationError": 160, "RequestValidationError": 12}}, + ) + + @classmethod + def from_snapshot(cls, snapshot: MetricsSnapshot) -> MetricsModel: + """Build the JSON metrics view from a collector snapshot. + + Every value is cast explicitly: the collector stores floats, and `strict=True` rejects a + float for an int field, so an un-cast value would be a 500 rather than a payload. + + Args: + snapshot (MetricsSnapshot): The snapshot to render. + + Returns: + MetricsModel: The validated metrics payload. + """ + with_profile = int(snapshot.value(AUTHENTICATION_REQUESTS.name, profile="true")) + without_profile = int(snapshot.value(AUTHENTICATION_REQUESTS.name, profile="false")) + return cls( + start_time_seconds=float(snapshot.value(PROCESS_START_TIME.name)), + uptime_seconds=float(snapshot.uptime_seconds), + requests=RequestCountsModel( + total=int(snapshot.value(REQUESTS_TOTAL.name)), + success=int(snapshot.value(REQUESTS_SUCCESS.name)), + failed=int(snapshot.value(REQUESTS_FAILED.name)), + ), + latency=LatencyModel.from_snapshot(snapshot, REQUEST_LATENCY.name), + authentication=AuthenticationCountsModel( + total=with_profile + without_profile, + with_profile=with_profile, + without_profile=without_profile, + ), + responses_by_status={ + labels["status"]: int(value) for labels, value in snapshot.samples(RESPONSES_BY_STATUS.name) + }, + requests_by_route={ + f"{labels['method']} {labels['route']}": RouteMetricsModel( + requests=int(value), + latency=LatencyModel.from_snapshot(snapshot, ROUTE_LATENCY.name, **labels), + ) + for labels, value in snapshot.samples(ROUTE_REQUESTS.name) + }, + errors_by_type={labels["type"]: int(value) for labels, value in snapshot.samples(ERRORS_BY_TYPE.name)}, + ) diff --git a/tests/unit/test_metrics_model.py b/tests/unit/test_metrics_model.py new file mode 100644 index 0000000..f656671 --- /dev/null +++ b/tests/unit/test_metrics_model.py @@ -0,0 +1,113 @@ +import pytest + +from app.metrics.collector import ( + AUTHENTICATION_REQUESTS, + ERRORS_BY_TYPE, + REQUEST_LATENCY, + REQUESTS_FAILED, + REQUESTS_SUCCESS, + REQUESTS_TOTAL, + RESPONSES_BY_STATUS, + ROUTE_LATENCY, + ROUTE_REQUESTS, + MetricsCollector, +) +from app.models import MetricsModel + + +@pytest.fixture +def collector(): + return MetricsCollector(clock=lambda: 1757660400.0) + + +def test_from_snapshot_on_a_fresh_collector(collector): + """The collector stores floats and the model is strict, so an un-cast value would raise here.""" + model = MetricsModel.from_snapshot(collector.snapshot()) + assert model.requests.total == 0 + assert model.latency.count == 0 + assert model.latency.average_seconds is None + assert model.responses_by_status == {} + assert model.requests_by_route == {} + assert model.errors_by_type == {} + assert model.start_time_seconds == 1757660400.0 + + +def test_counts_are_integers_not_floats(collector): + """A float where an int is declared is exactly what strict=True rejects.""" + collector.increment(REQUESTS_TOTAL, 3) + model = MetricsModel.from_snapshot(collector.snapshot()) + assert isinstance(model.requests.total, int) + assert model.requests.total == 3 + + +def test_request_counts_are_carried_through(collector): + collector.increment(REQUESTS_TOTAL, 10) + collector.increment(REQUESTS_SUCCESS, 7) + collector.increment(REQUESTS_FAILED, 3) + model = MetricsModel.from_snapshot(collector.snapshot()) + assert (model.requests.total, model.requests.success, model.requests.failed) == (10, 7, 3) + + +def test_average_latency_is_the_mean(collector): + collector.observe(REQUEST_LATENCY, 1.0) + collector.observe(REQUEST_LATENCY, 2.0) + model = MetricsModel.from_snapshot(collector.snapshot()) + assert model.latency.sum_seconds == 3.0 + assert model.latency.count == 2 + assert model.latency.average_seconds == 1.5 + + +def test_authentication_total_is_the_sum_of_both_splits(collector): + collector.increment(AUTHENTICATION_REQUESTS, profile="true", value=2) + collector.increment(AUTHENTICATION_REQUESTS, profile="false", value=5) + model = MetricsModel.from_snapshot(collector.snapshot()) + assert model.authentication.with_profile == 2 + assert model.authentication.without_profile == 5 + assert model.authentication.total == 7 + + +def test_responses_are_keyed_by_status(collector): + collector.increment(RESPONSES_BY_STATUS, status="200") + collector.increment(RESPONSES_BY_STATUS, status="401") + collector.increment(RESPONSES_BY_STATUS, status="401") + assert MetricsModel.from_snapshot(collector.snapshot()).responses_by_status == {"200": 1, "401": 2} + + +def test_errors_are_keyed_by_exception_class(collector): + collector.increment(ERRORS_BY_TYPE, type="AuthenticationError") + assert MetricsModel.from_snapshot(collector.snapshot()).errors_by_type == {"AuthenticationError": 1} + + +def test_routes_are_keyed_by_method_and_template(collector): + collector.increment(ROUTE_REQUESTS, method="POST", route="/authenticate") + collector.observe(ROUTE_LATENCY, 0.5, method="POST", route="/authenticate") + model = MetricsModel.from_snapshot(collector.snapshot()) + assert set(model.requests_by_route) == {"POST /authenticate"} + route = model.requests_by_route["POST /authenticate"] + assert route.requests == 1 + assert route.latency.count == 1 + assert route.latency.average_seconds == 0.5 + + +def test_a_route_with_no_latency_recorded_reports_none(collector): + """Route counts and route latency are separate series, so one can exist without the other.""" + collector.increment(ROUTE_REQUESTS, method="GET", route="/health") + route = MetricsModel.from_snapshot(collector.snapshot()).requests_by_route["GET /health"] + assert route.requests == 1 + assert route.latency.count == 0 + assert route.latency.average_seconds is None + + +def test_model_dump_uses_camel_case_aliases(collector): + dumped = MetricsModel.from_snapshot(collector.snapshot()).model_dump(by_alias=True) + assert "responsesByStatus" in dumped + assert "requestsByRoute" in dumped + assert "startTimeSeconds" in dumped + assert dumped["authentication"].keys() == {"total", "withProfile", "withoutProfile"} + assert dumped["latency"].keys() == {"sumSeconds", "count", "averageSeconds"} + + +def test_average_seconds_is_present_and_null_rather_than_omitted(collector): + """Consumers get a stable shape: the key exists on a fresh process rather than appearing later.""" + dumped = MetricsModel.from_snapshot(collector.snapshot()).model_dump(by_alias=True) + assert dumped["latency"]["averageSeconds"] is None From dc94f4325803f89a0d68d4eeeef4dd1e7349788b Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:27:42 -0500 Subject: [PATCH 05/17] feat: record request metrics in an HTTP middleware Implements the middleware layer asked for in the review of #132, rather than instrumenting each route by hand. Eight things in the review's pseudo-code do not work as written; the interesting one is the fourth. **The layering.** starlette/applications.py builds the stack as ServerErrorMiddleware -> user middleware -> ExceptionMiddleware -> router. Our `@app.exception_handler(Exception)` becomes ServerErrorMiddleware's handler and so runs *above* this middleware; the RequestValidationError and PESUAcademyError handlers live in ExceptionMiddleware, *below* it. That cuts both ways: - a handled PESUAcademyError is already a response by the time call_next returns, so the `except` branch never sees it -- the pseudo-code assumes it does; - an unhandled exception passes through us but its 500 is rendered above us, so we never see that response either, and the `except` branch has to record the status itself or requests_total silently stops matching sum(responses_total). So: the middleware owns status, route and latency; the exception handlers own the error type, one line each. Different families, so one failed request yields exactly one status sample and one error sample. That is also what recovers the information a status code loses -- CSRFTokenError and ProfileFetchError are both 502, and only errors_total tells them apart. The other corrections: `status < 400` for success, not `< 300`, or /readme's 308 counts every readme hit as a failure; perf_counter rather than time(), since a wall clock can step backwards and poison a cumulative sum; scope["route"] read only after call_next, via getattr, because plain Starlette routes never set it; and latency named for what it measures, which is time to response *start* -- call_next returns at http.response.start and the body streams afterwards. Cardinality is bounded at both attacker-controlled labels: the route is the matched template with unmatched paths collapsed to one bucket, and the method is clamped to the seven known verbs. Keying on the raw path would let a scanner walking /wp-login.php mint a series per probe. The profile split is the one deliberate exception to "middleware, not routes". Reading the body in middleware would consume the downstream receive channel and pull a plaintext-password payload into another layer; how many auth requests arrive is already free from route_requests_total, and only the split needs the body. Cancellation from a client disconnect is left unrecorded, so total exceeds success + failed while requests are in flight. Swallowing it to record would be worse than the undercount. 163 tests, 100% coverage. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/app.py | 21 ++++ app/metrics/middleware.py | 138 +++++++++++++++++++++ tests/unit/test_metrics_middleware.py | 172 ++++++++++++++++++++++++++ 3 files changed, 331 insertions(+) create mode 100644 app/metrics/middleware.py create mode 100644 tests/unit/test_metrics_middleware.py diff --git a/app/app.py b/app/app.py index cca1d25..ca54963 100644 --- a/app/app.py +++ b/app/app.py @@ -20,11 +20,15 @@ from collections.abc import AsyncIterator from fastapi.requests import Request + from fastapi.responses import Response + from starlette.middleware.base import RequestResponseEndpoint from pydantic import ValidationError from app.docs import authenticate_docs, health_docs, readme_docs from app.exceptions.base import PESUAcademyError +from app.metrics import AUTHENTICATION_REQUESTS, ERRORS_BY_TYPE, MetricsCollector +from app.metrics.middleware import record_request_metrics from app.models import RequestModel, ResponseModel from app.pesu import PESUAcademy @@ -100,11 +104,21 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]: ], ) pesu_academy = PESUAcademy() +metrics = MetricsCollector() + + +@app.middleware("http") +async def metrics_middleware(request: Request, call_next: RequestResponseEndpoint) -> Response: + """Record traffic metrics for every request.""" + # Looks the collector up on the module at call time rather than capturing it, so a test can + # swap in a fresh one with monkeypatch.setattr("app.app.metrics", ...). + return await record_request_metrics(metrics, request, call_next) @app.exception_handler(RequestValidationError) async def validation_exception_handler(request: Request, exc: RequestValidationError) -> JSONResponse: """Handler for request validation errors.""" + metrics.increment(ERRORS_BY_TYPE, type=type(exc).__name__) errors = exc.errors() # Log only the shape of the failure, never the submitted values. Each entry from `errors()` # carries an "input" key which, for a missing required field, is the *entire request body* -- @@ -126,6 +140,7 @@ async def validation_exception_handler(request: Request, exc: RequestValidationE @app.exception_handler(PESUAcademyError) async def pesu_exception_handler(request: Request, exc: PESUAcademyError) -> JSONResponse: """Handler for PESUAcademy specific errors.""" + metrics.increment(ERRORS_BY_TYPE, type=type(exc).__name__) # Severity follows the status code. A 4xx is an expected outcome -- a wrong password is the # API working correctly -- and logging one at ERROR with a traceback both buries real faults # and pages whoever alerts on the error rate. Only 5xx gets a stack trace. @@ -146,6 +161,7 @@ async def pesu_exception_handler(request: Request, exc: PESUAcademyError) -> JSO @app.exception_handler(Exception) async def unhandled_exception_handler(request: Request, exc: Exception) -> JSONResponse: """Handler for unhandled exceptions.""" + metrics.increment(ERRORS_BY_TYPE, type=type(exc).__name__) logging.exception("Unhandled exception occurred.") return JSONResponse( status_code=500, @@ -214,6 +230,11 @@ async def authenticate(payload: RequestModel) -> JSONResponse: # Authenticate the user authentication_result = {"timestamp": current_time} + # Recorded here rather than in the middleware: the profile flag lives in the request body, and + # reading the body in middleware would consume the downstream receive channel and pull a + # payload containing a plaintext password into another layer. How many auth requests arrive is + # already answered by route_requests_total; only the split needs the body. + metrics.increment(AUTHENTICATION_REQUESTS, profile=str(profile).lower()) logging.info(f"Authenticating user={username} with PESU Academy...") authentication_result.update( await pesu_academy.authenticate( diff --git a/app/metrics/middleware.py b/app/metrics/middleware.py new file mode 100644 index 0000000..6b214b4 --- /dev/null +++ b/app/metrics/middleware.py @@ -0,0 +1,138 @@ +"""HTTP middleware that records request, response and latency metrics.""" + +from __future__ import annotations + +import time +from typing import TYPE_CHECKING, Any + +from app.metrics.collector import ( + REQUEST_LATENCY, + REQUESTS_FAILED, + REQUESTS_SUCCESS, + REQUESTS_TOTAL, + RESPONSES_BY_STATUS, + ROUTE_LATENCY, + ROUTE_REQUESTS, +) + +if TYPE_CHECKING: + from collections.abc import Mapping + + from starlette.middleware.base import RequestResponseEndpoint + from starlette.requests import Request + from starlette.responses import Response + + from app.metrics.collector import MetricsCollector + +# A response at or above this status is counted as a failure. Not `>= 300`: /readme answers with a +# 308 redirect, which is the endpoint working correctly. +FAILURE_STATUS = 400 +# What an exception that reached us is recorded as. ServerErrorMiddleware renders the actual 500 +# above us, so we never see that response and have to record the status ourselves. +EXCEPTION_STATUS = 500 + +KNOWN_METHODS = frozenset({"GET", "POST", "PUT", "PATCH", "DELETE", "HEAD", "OPTIONS"}) +UNMATCHED_ROUTE = "" +OTHER_METHOD = "" + + +def method_label(scope: Mapping[str, Any]) -> str: + """Return the request method, clamped to a known verb. + + The method is caller-supplied, so an unrecognised verb collapses into one bucket rather than + minting a new series per value. + + Args: + scope (Mapping[str, Any]): The ASGI scope of the request. + + Returns: + str: The method, or a sentinel for anything unrecognised. + """ + method = scope.get("method", OTHER_METHOD) + return method if method in KNOWN_METHODS else OTHER_METHOD + + +def route_label(scope: Mapping[str, Any]) -> str: + """Return the matched route template, or a single bucket for unmatched paths. + + Never the raw path: a scanner walking /wp-login.php, /.env and friends would otherwise create a + new series per probe and the key space would grow without bound. + + Args: + scope (Mapping[str, Any]): The ASGI scope of the request, after routing. + + Returns: + str: The route template, the path for a non-API route, or a sentinel. + """ + if (path := getattr(scope.get("route"), "path", None)) and isinstance(path, str): + return path + # FastAPI sets scope["route"] only on its own APIRoutes. The Swagger UI and /openapi.json are + # plain Starlette routes, which set scope["endpoint"] instead; their paths are static, so the + # raw path is safe there and keeps them out of the unmatched bucket, which should mean probes. + if scope.get("endpoint") is not None: + return str(scope.get("path", UNMATCHED_ROUTE)) + return UNMATCHED_ROUTE + + +def _record_outcome(collector: MetricsCollector, scope: Mapping[str, Any], status: int, latency: float) -> None: + """Record the status, route and latency of a completed request. + + Args: + collector (MetricsCollector): The collector to record into. + scope (Mapping[str, Any]): The ASGI scope, read after routing has run. + status (int): The status code the caller will see. + latency (float): Seconds until the response started. + """ + # scope["route"] is populated by the router, which runs inside call_next -- so this must be + # called after that await, never before it. + method = method_label(scope) + route = route_label(scope) + if status < FAILURE_STATUS: + collector.increment(REQUESTS_SUCCESS) + else: + collector.increment(REQUESTS_FAILED) + collector.increment(RESPONSES_BY_STATUS, status=str(status)) + collector.increment(ROUTE_REQUESTS, method=method, route=route) + collector.observe(REQUEST_LATENCY, latency) + collector.observe(ROUTE_LATENCY, latency, method=method, route=route) + + +async def record_request_metrics( + collector: MetricsCollector, + request: Request, + call_next: RequestResponseEndpoint, +) -> Response: + """Record request, response and latency metrics around a request. + + Args: + collector (MetricsCollector): The collector to record into. + request (Request): The incoming request. + call_next (RequestResponseEndpoint): The rest of the application. + + Returns: + Response: The response produced downstream. + + Raises: + Exception: Re-raised unchanged, so error handling above is unaffected. + """ + collector.increment(REQUESTS_TOTAL) + # perf_counter, not time(): a wall clock is not monotonic, and one NTP step backwards would + # poison a cumulative latency sum permanently. + started = time.perf_counter() + try: + response = await call_next(request) + except Exception: + # Only genuinely unhandled exceptions arrive here. A handled PESUAcademyError or + # RequestValidationError has already become a response in ExceptionMiddleware, which + # Starlette installs *below* user middleware, so call_next returns an ordinary 4xx and this + # branch never sees it. ServerErrorMiddleware, which renders the 500 for what does reach + # here, sits *above* us -- so that response is never observed either, and the status has to + # be recorded now or requests_total stops matching the sum of responses_total. + # + # The exception *type* is recorded by the exception handlers, not here. The two layers write + # to different families on purpose: one failed request produces exactly one status sample + # and exactly one error sample, never two of either. + _record_outcome(collector, request.scope, EXCEPTION_STATUS, time.perf_counter() - started) + raise + _record_outcome(collector, request.scope, response.status_code, time.perf_counter() - started) + return response diff --git a/tests/unit/test_metrics_middleware.py b/tests/unit/test_metrics_middleware.py new file mode 100644 index 0000000..2cf3ec2 --- /dev/null +++ b/tests/unit/test_metrics_middleware.py @@ -0,0 +1,172 @@ +import asyncio + +import pytest + +from app.metrics.collector import ( + ERRORS_BY_TYPE, + REQUEST_LATENCY, + REQUESTS_FAILED, + REQUESTS_SUCCESS, + REQUESTS_TOTAL, + RESPONSES_BY_STATUS, + ROUTE_LATENCY, + ROUTE_REQUESTS, + MetricsCollector, +) +from app.metrics.middleware import ( + OTHER_METHOD, + UNMATCHED_ROUTE, + method_label, + record_request_metrics, + route_label, +) + + +class FakeRequest: + """Only `scope` is read by the middleware, so nothing else needs to exist.""" + + def __init__(self, scope): + self.scope = scope + + +class FakeResponse: + def __init__(self, status_code): + self.status_code = status_code + + +class FakeRoute: + def __init__(self, path): + self.path = path + + +def scope(method="GET", route="/health", **extra): + s = {"method": method, **extra} + if route is not None: + s["route"] = FakeRoute(route) + return s + + +def responding(status): + async def call_next(_request): + return FakeResponse(status) + + return call_next + + +def raising(exc): + async def call_next(_request): + raise exc + + return call_next + + +@pytest.fixture +def collector(): + return MetricsCollector(clock=lambda: 1000.0) + + +@pytest.mark.asyncio +async def test_a_success_is_recorded(collector): + await record_request_metrics(collector, FakeRequest(scope()), responding(200)) + snapshot = collector.snapshot() + assert snapshot.value(REQUESTS_TOTAL.name) == 1.0 + assert snapshot.value(REQUESTS_SUCCESS.name) == 1.0 + assert snapshot.value(REQUESTS_FAILED.name) == 0.0 + assert snapshot.value(RESPONSES_BY_STATUS.name, status="200") == 1.0 + assert snapshot.value(ROUTE_REQUESTS.name, method="GET", route="/health") == 1.0 + assert snapshot.value(f"{REQUEST_LATENCY.name}_count") == 1.0 + assert snapshot.value(f"{ROUTE_LATENCY.name}_count", method="GET", route="/health") == 1.0 + + +@pytest.mark.asyncio +async def test_the_response_is_returned_unchanged(collector): + response = await record_request_metrics(collector, FakeRequest(scope()), responding(200)) + assert response.status_code == 200 + + +@pytest.mark.asyncio +async def test_a_4xx_is_counted_as_a_failure(collector): + await record_request_metrics(collector, FakeRequest(scope(method="POST", route="/authenticate")), responding(401)) + snapshot = collector.snapshot() + assert snapshot.value(REQUESTS_FAILED.name) == 1.0 + assert snapshot.value(REQUESTS_SUCCESS.name) == 0.0 + assert snapshot.value(RESPONSES_BY_STATUS.name, status="401") == 1.0 + + +@pytest.mark.asyncio +async def test_a_redirect_is_not_counted_as_a_failure(collector): + """/readme answers 308. A `status < 300` success test would call every readme hit a failure.""" + await record_request_metrics(collector, FakeRequest(scope(route="/readme")), responding(308)) + snapshot = collector.snapshot() + assert snapshot.value(REQUESTS_SUCCESS.name) == 1.0 + assert snapshot.value(REQUESTS_FAILED.name) == 0.0 + + +@pytest.mark.asyncio +async def test_a_raised_exception_is_counted_and_re_raised(collector): + """ServerErrorMiddleware renders the 500 above us, so we never see that response -- we must + record the status ourselves or requests_total stops matching the sum of responses_total.""" + with pytest.raises(RuntimeError, match="boom"): + await record_request_metrics(collector, FakeRequest(scope()), raising(RuntimeError("boom"))) + snapshot = collector.snapshot() + assert snapshot.value(REQUESTS_TOTAL.name) == 1.0 + assert snapshot.value(REQUESTS_FAILED.name) == 1.0 + assert snapshot.value(RESPONSES_BY_STATUS.name, status="500") == 1.0 + assert snapshot.value(f"{REQUEST_LATENCY.name}_count") == 1.0 + + +@pytest.mark.asyncio +async def test_an_exception_does_not_record_an_error_type(collector): + """The no-double-count invariant: the type is the exception handlers' job, not the middleware's.""" + with pytest.raises(RuntimeError): + await record_request_metrics(collector, FakeRequest(scope()), raising(RuntimeError("boom"))) + assert list(collector.snapshot().samples(ERRORS_BY_TYPE.name)) == [] + + +@pytest.mark.asyncio +async def test_cancellation_is_not_recorded(collector): + """A client disconnect surfaces as cancellation. Swallowing it to record would be worse than + the small undercount, so it propagates untouched and total exceeds success + failed.""" + with pytest.raises(asyncio.CancelledError): + await record_request_metrics(collector, FakeRequest(scope()), raising(asyncio.CancelledError())) + snapshot = collector.snapshot() + assert snapshot.value(REQUESTS_TOTAL.name) == 1.0 + assert snapshot.value(REQUESTS_SUCCESS.name) == 0.0 + assert snapshot.value(REQUESTS_FAILED.name) == 0.0 + + +@pytest.mark.asyncio +async def test_latency_is_recorded_as_a_positive_duration(collector): + await record_request_metrics(collector, FakeRequest(scope()), responding(200)) + assert collector.snapshot().value(f"{REQUEST_LATENCY.name}_sum") >= 0.0 + + +def test_route_label_uses_the_matched_template(): + assert route_label(scope(route="/authenticate")) == "/authenticate" + + +def test_route_label_falls_back_for_an_unmatched_path(): + """A scanner walking arbitrary paths must land in one bucket, not mint a series per probe.""" + assert route_label({"method": "GET", "path": "/wp-login.php"}) == UNMATCHED_ROUTE + + +def test_route_label_uses_the_path_for_a_non_api_route(): + """Swagger UI and /openapi.json are plain Starlette routes: they set endpoint, never route.""" + assert route_label({"method": "GET", "path": "/openapi.json", "endpoint": object()}) == "/openapi.json" + + +def test_route_label_ignores_a_route_without_a_path(): + assert route_label({"method": "GET", "route": object()}) == UNMATCHED_ROUTE + + +def test_method_label_passes_known_verbs(): + for method in ("GET", "POST", "PUT", "PATCH", "DELETE", "HEAD", "OPTIONS"): + assert method_label({"method": method}) == method + + +def test_method_label_clamps_an_unknown_verb(): + assert method_label({"method": "PROPFIND"}) == OTHER_METHOD + + +def test_method_label_handles_a_scope_without_a_method(): + assert method_label({}) == OTHER_METHOD From 3f23c1d42307db829cc7cb8b1d79a53a1a28e9fd Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:29:33 -0500 Subject: [PATCH 06/17] feat: expose /metrics and /metrics.json Two paths rather than content negotiation on one. Real scrapers send `Accept: application/openmetrics-text;...,text/plain;version=0.0.4;q=0.5,*/*;q=0.1`, curl sends `*/*`, and a browser sends `text/html,...,*/*;q=0.8` -- none of which unambiguously mean JSON, so any resolution of the wildcard surprises half the callers, and getting there needs a hand-rolled q-value parser larger than the renderer. A single path also cannot carry a response_model, so Swagger would show either a misleading schema or none. Split in two, each is documented properly: /metrics declares response_class=PlainTextResponse with a text/plain example, mirroring how app/docs/readme.py documents its text/html body, and /metrics.json declares response_model=MetricsModel -- the second response_model in the codebase after /authenticate, which is what "the response model will also need an update" asked for. JSON deliberately does not live on /metrics: Prometheus has effectively reserved that path. /metrics.json returns the model rather than a JSONResponse, so FastAPI serializes it with by_alias=True and the camelCase keys come for free, with no hand-patched dict of the kind /authenticate needs for its datetime. Both reuse the existing "Monitoring" OpenAPI tag. The most valuable of the 13 new tests is the unhandled-exception one. That path runs through ServerErrorMiddleware, which sits *above* our middleware, so whether a 500 is recorded at all cannot be established by reading the code -- only by driving a real exception through the whole stack. There is also a test asserting the accounting invariants hold end to end: sum(responsesByStatus) == success + failed, and sum(errorsByType) < failed whenever a 404 is in the mix, since the router's 404 runs no handler of ours. 176 tests, 100% coverage. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/app.py | 35 ++++++- app/docs/__init__.py | 3 + app/docs/metrics.py | 75 ++++++++++++++ tests/unit/test_metrics_endpoints.py | 149 +++++++++++++++++++++++++++ 4 files changed, 259 insertions(+), 3 deletions(-) create mode 100644 app/docs/metrics.py create mode 100644 tests/unit/test_metrics_endpoints.py diff --git a/app/app.py b/app/app.py index ca54963..45ec067 100644 --- a/app/app.py +++ b/app/app.py @@ -14,7 +14,7 @@ import uvicorn from fastapi import FastAPI from fastapi.exceptions import RequestValidationError -from fastapi.responses import JSONResponse, RedirectResponse +from fastapi.responses import JSONResponse, PlainTextResponse, RedirectResponse if TYPE_CHECKING: from collections.abc import AsyncIterator @@ -25,11 +25,12 @@ from pydantic import ValidationError -from app.docs import authenticate_docs, health_docs, readme_docs +from app.docs import authenticate_docs, health_docs, metrics_docs, metrics_json_docs, readme_docs from app.exceptions.base import PESUAcademyError from app.metrics import AUTHENTICATION_REQUESTS, ERRORS_BY_TYPE, MetricsCollector from app.metrics.middleware import record_request_metrics -from app.models import RequestModel, ResponseModel +from app.metrics.prometheus import PROMETHEUS_CONTENT_TYPE, render_prometheus +from app.models import MetricsModel, RequestModel, ResponseModel from app.pesu import PESUAcademy IST = ZoneInfo("Asia/Kolkata") @@ -192,6 +193,34 @@ async def health() -> JSONResponse: ) +@app.get( + "/metrics", + response_class=PlainTextResponse, + responses=metrics_docs.response_examples, + tags=["Monitoring"], +) +async def prometheus_metrics() -> PlainTextResponse: + """Expose the collected metrics in the Prometheus text exposition format.""" + return PlainTextResponse( + content=render_prometheus(metrics.snapshot()), + media_type=PROMETHEUS_CONTENT_TYPE, + ) + + +@app.get( + "/metrics.json", + response_model=MetricsModel, + response_class=JSONResponse, + responses=metrics_json_docs.response_examples, + tags=["Monitoring"], +) +async def json_metrics() -> MetricsModel: + """Expose the collected metrics as JSON.""" + # Returned as a model rather than a JSONResponse, so FastAPI serializes it with by_alias=True + # and the camelCase keys come for free. + return MetricsModel.from_snapshot(metrics.snapshot()) + + @app.get( "/readme", response_class=RedirectResponse, diff --git a/app/docs/__init__.py b/app/docs/__init__.py index a31c39c..b3321e8 100644 --- a/app/docs/__init__.py +++ b/app/docs/__init__.py @@ -2,10 +2,13 @@ from .authenticate import authenticate_docs from .health import health_docs +from .metrics import metrics_docs, metrics_json_docs from .readme import readme_docs __all__ = [ "authenticate_docs", "health_docs", + "metrics_docs", + "metrics_json_docs", "readme_docs", ] diff --git a/app/docs/metrics.py b/app/docs/metrics.py new file mode 100644 index 0000000..82c49a4 --- /dev/null +++ b/app/docs/metrics.py @@ -0,0 +1,75 @@ +"""Custom docs for the /metrics and /metrics.json PESUAuth endpoints.""" + +from app.docs.base import ApiDocs +from app.models import MetricsModel, ResponseModel + +_INTERNAL_SERVER_ERROR = { + "description": "Internal Server Error.", + "model": ResponseModel, + "content": { + "application/json": { + "example": { + "status": False, + "message": "Internal Server Error. Please try again later.", + "timestamp": "2024-07-28T22:30:10.103368+05:30", + } + } + }, +} + +_PROMETHEUS_EXAMPLE = """# HELP pesu_auth_requests_total HTTP requests received. +# TYPE pesu_auth_requests_total counter +pesu_auth_requests_total 1284 +# HELP pesu_auth_responses_total HTTP responses, by status code. +# TYPE pesu_auth_responses_total counter +pesu_auth_responses_total{status="200"} 1094 +pesu_auth_responses_total{status="401"} 160 +# HELP pesu_auth_errors_total Errors rendered by an exception handler, by exception class. +# TYPE pesu_auth_errors_total counter +pesu_auth_errors_total{type="AuthenticationError"} 160 +# HELP pesu_auth_request_latency_seconds Seconds from receiving a request to starting its response. +# TYPE pesu_auth_request_latency_seconds summary +pesu_auth_request_latency_seconds_sum 742.1841932 +pesu_auth_request_latency_seconds_count 1284 +""" + +metrics_docs = ApiDocs( + request_examples={}, + response_examples={ + 200: { + "description": "Metrics in the Prometheus text exposition format.", + "content": {"text/plain": {"example": _PROMETHEUS_EXAMPLE}}, + }, + 500: _INTERNAL_SERVER_ERROR, + }, +) + +metrics_json_docs = ApiDocs( + request_examples={}, + response_examples={ + 200: { + "description": "Metrics as JSON.", + "model": MetricsModel, + "content": { + "application/json": { + "example": { + "startTimeSeconds": 1757660400.12, + "uptimeSeconds": 3612.44, + "requests": {"total": 1284, "success": 1102, "failed": 182}, + "latency": {"sumSeconds": 742.1841932, "count": 1284, "averageSeconds": 0.5779}, + "authentication": {"total": 774, "withProfile": 134, "withoutProfile": 640}, + "responsesByStatus": {"200": 1094, "401": 160, "502": 6}, + "requestsByRoute": { + "POST /authenticate": { + "requests": 774, + "latency": {"sumSeconds": 741.2118, "count": 774, "averageSeconds": 0.9576}, + } + }, + "errorsByType": {"AuthenticationError": 160, "RequestValidationError": 12}, + } + } + }, + }, + 500: _INTERNAL_SERVER_ERROR, + }, +) diff --git a/tests/unit/test_metrics_endpoints.py b/tests/unit/test_metrics_endpoints.py new file mode 100644 index 0000000..775927a --- /dev/null +++ b/tests/unit/test_metrics_endpoints.py @@ -0,0 +1,149 @@ +from unittest.mock import AsyncMock, patch + +import pytest +from fastapi import APIRouter +from fastapi.testclient import TestClient + +from app.app import app +from app.exceptions.authentication import AuthenticationError +from app.metrics.collector import MetricsCollector +from app.metrics.prometheus import PROMETHEUS_CONTENT_TYPE + +boom_router = APIRouter() + + +@boom_router.get("/raiseUnhandledForMetrics") +async def raise_unhandled(): + raise RuntimeError("Simulated internal server error") + + +app.include_router(boom_router) + + +@pytest.fixture +def client(monkeypatch): + """A client with a *fresh* collector. + + The collector is a module-level singleton shared by the whole session, so any test asserting an + absolute count without this is order-dependent -- and tests/conftest.py forces a fixed directory + order, which would make such a bug look stable locally and fail elsewhere. + """ + monkeypatch.setattr("app.app.metrics", MetricsCollector()) + with ( + patch("app.app.pesu_academy.prefetch_client_with_csrf_token", new_callable=AsyncMock), + patch("app.app.pesu_academy.close_client", new_callable=AsyncMock), + ): + with TestClient(app, raise_server_exceptions=False) as test_client: + yield test_client + + +def test_prometheus_endpoint_content_type(client): + response = client.get("/metrics") + assert response.status_code == 200 + assert response.headers["content-type"] == PROMETHEUS_CONTENT_TYPE + + +def test_prometheus_endpoint_declares_every_family(client): + body = client.get("/metrics").text + assert "# HELP pesu_auth_requests_total HTTP requests received.\n" in body + assert "# TYPE pesu_auth_request_latency_seconds summary\n" in body + assert body.endswith("\n") + + +def test_json_endpoint_shape(client): + body = client.get("/metrics.json").json() + assert set(body) == { + "startTimeSeconds", + "uptimeSeconds", + "requests", + "latency", + "authentication", + "responsesByStatus", + "requestsByRoute", + "errorsByType", + } + + +def test_a_request_is_reflected_in_both_views(client): + client.get("/health") + assert 'pesu_auth_route_requests_total{method="GET",route="/health"} 1' in client.get("/metrics").text + assert "GET /health" in client.get("/metrics.json").json()["requestsByRoute"] + + +def test_a_successful_request_is_counted_as_success(client): + client.get("/health") + body = client.get("/metrics.json").json() + assert body["responsesByStatus"]["200"] >= 1 + assert body["requests"]["failed"] == 0 + + +@patch("app.app.pesu_academy.authenticate") +def test_an_authentication_request_records_the_profile_split(mock_authenticate, client): + mock_authenticate.return_value = {"status": True, "message": "Login successful."} + client.post("/authenticate", json={"username": "u", "password": "p", "profile": True}) + client.post("/authenticate", json={"username": "u", "password": "p", "profile": False}) + authentication = client.get("/metrics.json").json()["authentication"] + assert authentication == {"total": 2, "withProfile": 1, "withoutProfile": 1} + + +@patch("app.app.pesu_academy.authenticate") +def test_a_failed_authentication_records_both_status_and_error_type(mock_authenticate, client): + """The whole point of the middleware/handler split: a 401 keeps its status *and* its class.""" + mock_authenticate.side_effect = AuthenticationError() + assert client.post("/authenticate", json={"username": "u", "password": "p"}).status_code == 401 + body = client.get("/metrics.json").json() + assert body["responsesByStatus"]["401"] == 1 + assert body["errorsByType"]["AuthenticationError"] == 1 + assert body["requests"]["failed"] == 1 + + +def test_a_validation_error_records_its_type(client): + assert client.post("/authenticate", json={"password": "p"}).status_code == 400 + body = client.get("/metrics.json").json() + assert body["responsesByStatus"]["400"] == 1 + assert body["errorsByType"]["RequestValidationError"] == 1 + + +def test_an_unhandled_exception_records_a_500(client): + """ServerErrorMiddleware sits above the middleware, so this path cannot be verified by reading + the code -- only by driving a real unhandled exception through the whole stack.""" + assert client.get("/raiseUnhandledForMetrics").status_code == 500 + body = client.get("/metrics.json").json() + assert body["responsesByStatus"]["500"] == 1 + assert body["errorsByType"]["RuntimeError"] == 1 + assert body["requests"]["failed"] == 1 + + +def test_an_unknown_path_is_bucketed(client): + """A 404 is counted, attributed to one bucket, and runs no handler of ours.""" + assert client.get("/definitely-not-a-route").status_code == 404 + body = client.get("/metrics.json").json() + assert body["responsesByStatus"]["404"] == 1 + assert "GET " in body["requestsByRoute"] + assert body["errorsByType"] == {} + + +def test_the_metrics_endpoint_counts_itself(client): + """Scrapes are deliberately not excluded: excluding them would break the accounting invariant.""" + client.get("/metrics.json") + assert "GET /metrics.json" in client.get("/metrics.json").json()["requestsByRoute"] + + +@patch("app.app.pesu_academy.authenticate") +def test_response_and_outcome_counts_agree(mock_authenticate, client): + """sum(responsesByStatus) == success + failed, and sum(errorsByType) <= failed.""" + mock_authenticate.side_effect = AuthenticationError() + client.get("/health") + client.post("/authenticate", json={"username": "u", "password": "p"}) + client.get("/definitely-not-a-route") + body = client.get("/metrics.json").json() + resolved = body["requests"]["success"] + body["requests"]["failed"] + assert sum(body["responsesByStatus"].values()) == resolved + assert sum(body["errorsByType"].values()) < body["requests"]["failed"] + + +def test_latency_is_recorded_for_a_route(client): + client.get("/health") + route = client.get("/metrics.json").json()["requestsByRoute"]["GET /health"] + assert route["latency"]["count"] == 1 + assert route["latency"]["averageSeconds"] >= 0 From f9b70888a493c1cc7d410eaded9e0889a5945bd0 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:32:51 -0500 Subject: [PATCH 07/17] refactor: give the benchmark scripts a shared output path helper Closes #123. Implements the five changes requested on #143, plus the review's "please incorporate similar changes in unauthenticated_csrf_token_expiry.py". Every output path was a bare relative filename, so results landed wherever the script happened to be run from -- in practice cluttering scripts/benchmark/ -- and `analyze_benchmark.py` overwrote distribution.png and timeline.png on every run. `resolve_output_path` in util.py now handles all of it: explicit --output wins, otherwise `{script}_{date}_{time}[_{tag}].{ext}`, with parent directories created either way. The default directory is anchored to the repository root rather than the cwd, so output lands in one place regardless of where the script is invoked. util.py is reused rather than adding a module, since both runners already import it; analyze_benchmark.py now imports it too. Also in scope, because they are in the files being rewritten: - `make_request` ended in an unconditional `response.json()`, so `--route readme` (a 308 to GitHub returning HTML) crashed the sequential runner and was silently swallowed as a *failed request* by the parallel one, skewing the very numbers being measured. This is what #132's author was patching when a reviewer asked "why is this being added?" -- it is a real bug. Non-JSON responses now fall back to the status and the raw text. - `analyze_benchmark.py --files` was not required, so omitting it raised a bare TypeError from a list comprehension instead of an argparse error. - `unauthenticated_csrf_token_expiry.py` wrote its CSV only after the loop ended, and that loop sleeps for hours between requests -- so a Ctrl-C threw away every measurement taken. Rows are now written as they are measured. - Both runners carried a no-op string expression where a docstring cannot go, inside `if __name__ == "__main__":`. - `--route` gained `metrics` and `metrics.json`, now that those exist. Verified against a live server: default naming, --tag, --output-dir and an explicit --output all land where intended, and `--route readme` and `--route metrics` both succeed where they previously could not. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- scripts/benchmark/analyze_benchmark.py | 48 +++++++++-- scripts/benchmark/benchmark_requests.py | 40 ++++----- .../unauthenticated_csrf_token_expiry.py | 85 +++++++++++-------- scripts/benchmark/util.py | 52 +++++++++++- 4 files changed, 164 insertions(+), 61 deletions(-) diff --git a/scripts/benchmark/analyze_benchmark.py b/scripts/benchmark/analyze_benchmark.py index da70196..48e9bb4 100644 --- a/scripts/benchmark/analyze_benchmark.py +++ b/scripts/benchmark/analyze_benchmark.py @@ -1,12 +1,19 @@ """Script to analyze benchmark CSV output.""" +from __future__ import annotations + import argparse import statistics +from typing import TYPE_CHECKING import matplotlib.pyplot as plt import numpy as np import pandas as pd import seaborn as sns +from util import resolve_output_path + +if TYPE_CHECKING: + from pathlib import Path def analyze_benchmark(df: pd.DataFrame) -> None: @@ -47,12 +54,13 @@ def analyze_benchmark(df: pd.DataFrame) -> None: print(f"šŸ“Š 99th percentile time : {p99:.3f} sec") -def plot_distribution(dfs: list[pd.DataFrame], files: list[str]) -> None: +def plot_distribution(dfs: list[pd.DataFrame], files: list[str], outfile: Path) -> None: """Plot the distribution of response times for each benchmark on the same plot. Args: dfs (list[pd.DataFrame]): The benchmark DataFrames. files (list[str]): The file names. + outfile (Path): The path to write the plot to. Returns: None @@ -75,16 +83,18 @@ def plot_distribution(dfs: list[pd.DataFrame], files: list[str]) -> None: plt.ylabel("Density") plt.grid(True, linestyle="--", alpha=0.6) plt.tight_layout() - plt.savefig("distribution.png", dpi=300) + plt.savefig(outfile, dpi=300) + print(f"Results saved to: {outfile}") plt.close() -def plot_response_time_over_requests(dfs: list[pd.DataFrame], files: list[str]) -> None: +def plot_response_time_over_requests(dfs: list[pd.DataFrame], files: list[str], outfile: Path) -> None: """Plot the response time over requests for each benchmark on the same plot. Args: dfs (list[pd.DataFrame]): The benchmark DataFrames. files (list[str]): The file names. + outfile (Path): The path to write the plot to. Returns: None @@ -99,13 +109,25 @@ def plot_response_time_over_requests(dfs: list[pd.DataFrame], files: list[str]) plt.grid(True, linestyle="--", alpha=0.6) plt.legend() plt.tight_layout() - plt.savefig("timeline.png", dpi=300) + plt.savefig(outfile, dpi=300) + print(f"Results saved to: {outfile}") plt.close() if __name__ == "__main__": parser = argparse.ArgumentParser(description="Analyze benchmark CSV output.") - parser.add_argument("--files", "-f", help="Path to the benchmark CSV files", nargs="+") + # Required: without it args.files is None and the read below fails with a bare TypeError + parser.add_argument("--files", "-f", help="Path to the benchmark CSV files", nargs="+", required=True) + parser.add_argument( + "--output-dir", + type=str, + help="The directory to write plots into (default: benchmark/results at the repository root)", + ) + parser.add_argument( + "--tag", + type=str, + help="An identifier appended to the generated filenames, for telling runs apart", + ) args = parser.parse_args() dfs = [pd.read_csv(file) for file in args.files] @@ -114,5 +136,17 @@ def plot_response_time_over_requests(dfs: list[pd.DataFrame], files: list[str]) analyze_benchmark(df) print("-" * 40) - plot_distribution(dfs, args.files) - plot_response_time_over_requests(dfs, args.files) + for plot, stem in ( + (plot_distribution, "distribution"), + (plot_response_time_over_requests, "timeline"), + ): + plot( + dfs, + args.files, + resolve_output_path( + script_name=stem, + extension="png", + output_dir=args.output_dir, + tag=args.tag, + ), + ) diff --git a/scripts/benchmark/benchmark_requests.py b/scripts/benchmark/benchmark_requests.py index 8098da6..f1ad9d0 100644 --- a/scripts/benchmark/benchmark_requests.py +++ b/scripts/benchmark/benchmark_requests.py @@ -4,14 +4,9 @@ from concurrent.futures import ThreadPoolExecutor, as_completed from tqdm.auto import tqdm -from util import make_request +from util import make_request, resolve_output_path if __name__ == "__main__": - """Main function to benchmark the PESUAuth API. - - This script benchmarks the PESUAuth API by making requests to the specified endpoint. - It can be run in parallel using threads or sequentially. - """ parser = argparse.ArgumentParser(description="Benchmark PESUAuth API.") parser.add_argument( "--max-workers", @@ -45,7 +40,7 @@ parser.add_argument( "--route", type=str, - choices=["authenticate", "health", "readme"], + choices=["authenticate", "health", "readme", "metrics", "metrics.json"], default="authenticate", help="The route to make the request to (default: authenticate)", ) @@ -63,7 +58,17 @@ parser.add_argument( "--output", type=str, - help="The output file to save the benchmark results to", + help="The output file to save the benchmark results to (default: an auto-named CSV)", + ) + parser.add_argument( + "--output-dir", + type=str, + help="The directory to write results into (default: benchmark/results at the repository root)", + ) + parser.add_argument( + "--tag", + type=str, + help="An identifier appended to the generated filename, for telling runs apart", ) args = parser.parse_args() @@ -123,22 +128,19 @@ else: success.append(0) - outfile = ( - output - if output - else ( - f"benchmark_[num_requests={num_requests}]_[max_workers={max_workers}]_" - f"[parallel={parallel}]_[route={route}]_[timeout={timeout}].csv" - ) + outfile = resolve_output_path( + script_name="benchmark_requests", + extension="csv", + output=output, + output_dir=args.output_dir, + tag=args.tag, ) - with open( - outfile, - "w", - ) as f: + with open(outfile, "w") as f: f.write("status,time\n") f.writelines(f"{s},{t}\n" for s, t in zip(success, times, strict=False)) + print(f"Results saved to: {outfile}") print(f"Benchmark completed. Successful requests: {sum(success)} out of {len(success)}") print(f"Average time per request: {sum(times) / len(times):.2f} seconds") print(f"Total time taken: {sum(times):.2f} seconds") diff --git a/scripts/benchmark/unauthenticated_csrf_token_expiry.py b/scripts/benchmark/unauthenticated_csrf_token_expiry.py index 7f414e8..76874ed 100644 --- a/scripts/benchmark/unauthenticated_csrf_token_expiry.py +++ b/scripts/benchmark/unauthenticated_csrf_token_expiry.py @@ -5,7 +5,7 @@ import time from tqdm.auto import tqdm -from util import make_request +from util import make_request, resolve_output_path def test_response(response: dict, no_profile: bool) -> bool: @@ -26,11 +26,6 @@ def test_response(response: dict, no_profile: bool) -> bool: if __name__ == "__main__": - """Main function to test the unauthenticated CSRF token expiry. - - This script tests the unauthenticated CSRF token expiry by making requests to the authenticate endpoint. - It can be run in parallel using threads or sequentially. - """ parser = argparse.ArgumentParser(description="Test unauthenticated CSRF token expiry.") parser.add_argument( "--host", @@ -65,8 +60,17 @@ def test_response(response: dict, no_profile: bool) -> bool: parser.add_argument( "--output", type=str, - default="unauthenticated_csrf_token_expiry.csv", - help="The output file name (default: unauthenticated_csrf_token_expiry.csv)", + help="The output file to save the results to (default: an auto-named CSV)", + ) + parser.add_argument( + "--output-dir", + type=str, + help="The directory to write results into (default: benchmark/results at the repository root)", + ) + parser.add_argument( + "--tag", + type=str, + help="An identifier appended to the generated filename, for telling runs apart", ) parser.add_argument( "--verbose", @@ -90,32 +94,45 @@ def test_response(response: dict, no_profile: bool) -> bool: ): time.sleep(1) - while True: - request_count += 1 - response, elapsed = make_request( - host=args.host, - timeout=args.timeout, - profile=not args.no_profile, - route="authenticate", - ) - success.append(int(test_response(response, args.no_profile))) - times.append(elapsed) - if args.verbose: - print(f"Response: {response}") + outfile = resolve_output_path( + script_name="unauthenticated_csrf_token_expiry", + extension="csv", + output=args.output, + output_dir=args.output_dir, + tag=args.tag, + ) + + # Each row is written as it is measured rather than after the loop ends. This script sleeps for + # hours between requests, so buffering everything until the end means a Ctrl-C -- or anything + # else that interrupts a long run -- throws away every measurement taken so far. + with open(outfile, "w", buffering=1) as f: + f.write("status,time,waiting_time\n") + while True: + request_count += 1 + response, elapsed = make_request( + host=args.host, + timeout=args.timeout, + profile=not args.no_profile, + route="authenticate", + ) + status = int(test_response(response, args.no_profile)) + success.append(status) + times.append(elapsed) + f.write(f"{status},{elapsed},{waiting_times[-1]}\n") + if args.verbose: + print(f"Response: {response}") - if success[-1] == 0: - break + if status == 0: + break - next_interval = args.interval * request_count * 60 - for _ in tqdm( - range(next_interval), - desc=f"Waiting {next_interval / 60} minutes before next request", - leave=False, - unit="s", - ): - time.sleep(1) - waiting_times.append(next_interval) + next_interval = args.interval * request_count * 60 + for _ in tqdm( + range(next_interval), + desc=f"Waiting {next_interval / 60} minutes before next request", + leave=False, + unit="s", + ): + time.sleep(1) + waiting_times.append(next_interval) - with open(args.output, "w") as f: - f.write("status,time,waiting_time\n") - f.writelines(f"{s},{t},{w}\n" for s, t, w in zip(success, times, waiting_times, strict=False)) + print(f"Results saved to: {outfile}") diff --git a/scripts/benchmark/util.py b/scripts/benchmark/util.py index bdda705..4c194bd 100644 --- a/scripts/benchmark/util.py +++ b/scripts/benchmark/util.py @@ -2,12 +2,55 @@ import os import time +from datetime import datetime +from pathlib import Path import httpx2 from dotenv import load_dotenv load_dotenv() +# Anchored to the repository root rather than the working directory, so results land in the same +# place whether a script is run from scripts/benchmark/ or from the repository root. +DEFAULT_OUTPUT_DIR = Path(__file__).resolve().parents[2] / "benchmark" / "results" + + +def resolve_output_path( + script_name: str, + extension: str, + output: str | None = None, + output_dir: str | None = None, + tag: str | None = None, +) -> Path: + """Resolve where a script should write an output file, creating the directory if needed. + + An explicit output path wins. Otherwise the name is built from the script name and the current + time, so repeated runs no longer overwrite each other, with an optional tag for telling + experimental runs apart. + + Args: + script_name: The name of the calling script, used as the filename stem + extension: The file extension, without a leading dot + output: An explicit output path, which overrides every other argument but --output-dir + output_dir: The directory to write into, defaulting to benchmark/results at the repo root + tag: An optional identifier appended to the generated filename + + Returns: + The resolved path, whose parent directory is guaranteed to exist + """ + directory = Path(output_dir) if output_dir else DEFAULT_OUTPUT_DIR + if output: + path = Path(output) + # A bare filename is placed in the output directory; an explicit path is honoured as given + if path.parent == Path(): + path = directory / path + else: + timestamp = datetime.now().strftime("%Y%m%d_%H%M%S") + suffix = f"_{tag}" if tag else "" + path = directory / f"{script_name}_{timestamp}{suffix}.{extension}" + path.parent.mkdir(parents=True, exist_ok=True) + return path + def make_request( host: str = "http://localhost:5000", @@ -46,4 +89,11 @@ def make_request( follow_redirects=True, ) elapsed_time = time.time() - start_time - return response.json(), elapsed_time + # Not every route answers with JSON: /readme is a 308 to GitHub, and /metrics is Prometheus + # text. An unconditional .json() crashes the sequential runner outright and, in the parallel + # runner, is swallowed as a failed request -- which silently skews the numbers being measured. + try: + body = response.json() + except ValueError: + body = {"status": response.is_success, "text": response.text} + return body, elapsed_time From 0ca3377509718e592e5261e583919f24c371202c Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:34:08 -0500 Subject: [PATCH 08/17] docs: document the metrics endpoints and benchmark output README gains rows for /metrics and /metrics.json in the endpoint table and a section for each, following the shape of the /health section. The notes worth having in writing rather than only in code comments: counters reset on restart (which is what process_start_time_seconds is for), status codes and exception classes are recorded separately so CSRFTokenError and ProfileFetchError stay distinguishable despite both being 502, scrapes of /metrics count themselves on purpose, and requests.total can briefly exceed success + failed because arrival and outcome are recorded at different moments. CONTRIBUTING gains a note on where the benchmark scripts now write, since the answer changed in this PR. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- .github/CONTRIBUTING.md | 14 ++++++++++++++ README.md | 43 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 57 insertions(+) diff --git a/.github/CONTRIBUTING.md b/.github/CONTRIBUTING.md index 5c53d31..37e7cba 100644 --- a/.github/CONTRIBUTING.md +++ b/.github/CONTRIBUTING.md @@ -19,6 +19,7 @@ your development environment and contributing to the project. - [Linting & Formatting](#linting--formatting) - [šŸ§Ŗ Running Tests](#-running-tests) - [Tests that need credentials](#tests-that-need-credentials) + - [Benchmark output](#benchmark-output) - [Writing Tests](#writing-tests) - [šŸš€ Submitting Changes](#-submitting-changes) - [šŸ”€ Create a Branch](#-create-a-branch) @@ -182,6 +183,19 @@ In CI, pull requests come from forks, and GitHub withholds secrets from fork pul -- and the live tests only run once the change reaches `dev`. Run them locally before you open a pull request; CI will not cover them for you. +### Benchmark output + +The scripts in `scripts/benchmark/` write their CSVs and plots to `benchmark/results/` at the +repository root, named `{script}_{date}_{time}.{ext}`. Pass `--output-dir` to write elsewhere, +`--tag` to label an experimental run, or `--output` to name one file explicitly. All of it is +gitignored. + +```bash +cd scripts/benchmark +uv run python benchmark_requests.py --num-requests 100 --parallel --tag baseline +uv run python analyze_benchmark.py -f ../../benchmark/results/benchmark_requests_*.csv +``` + ### Writing Tests - Write tests for all new features and bug fixes diff --git a/README.md b/README.md index 502b835..6b2d42f 100644 --- a/README.md +++ b/README.md @@ -102,6 +102,8 @@ The API provides multiple endpoints for authentication, documentation, and monit | `/` | `GET` | Serves the interactive API documentation (Swagger UI). | | `/authenticate` | `POST` | Authenticates a user using their PESU credentials. | | `/health` | `GET` | A health check endpoint to monitor the API's status. | +| `/metrics` | `GET` | Exposes traffic and error counters for Prometheus. | +| `/metrics.json` | `GET` | The same counters as JSON, for reading by hand. | | `/readme` | `GET` | Redirects to the project's official GitHub repository. | ### `/authenticate` @@ -163,6 +165,47 @@ does not take any request parameters. | `message` | `str` | "ok" if healthy, error message otherwise | | `timestamp` | `datetime` | A timezone offset timestamp indicating the time of the health check | +### `/metrics` + +This endpoint exposes counters describing the traffic this process has served, in the +[Prometheus text exposition format](https://prometheus.io/docs/instrumenting/exposition_formats/), ready to be scraped. +It takes no request parameters. + +``` +# HELP pesu_auth_responses_total HTTP responses, by status code. +# TYPE pesu_auth_responses_total counter +pesu_auth_responses_total{status="200"} 1094 +pesu_auth_responses_total{status="401"} 160 +``` + +The counters live in memory and **reset when the process restarts**, which is why +`pesu_auth_process_start_time_seconds` is exposed: without it a dashboard cannot tell a restart from a drop in traffic. +Status codes and exception classes are recorded separately, so errors that share a status code ā€” `CSRFTokenError` and +`ProfileFetchError` are both `502` ā€” stay distinguishable. + +Requests to `/metrics` are themselves counted. Excluding them would mean the endpoint reported a request total that did +not match the sum of its own response counts. + +### `/metrics.json` + +The same counters as JSON, for reading by hand rather than by a scraper. It takes no request parameters. + +#### Response Object + +| **Field** | **Type** | **Description** | +| ------------------- | -------- | -------------------------------------------------------------------------- | +| `startTimeSeconds` | `float` | Start time of this process since the Unix epoch. Counters reset on restart | +| `uptimeSeconds` | `float` | Seconds since this process started collecting | +| `requests` | `object` | `total`, `success` and `failed` request counts | +| `latency` | `object` | `sumSeconds`, `count` and `averageSeconds` until a response starts | +| `authentication` | `object` | `total`, `withProfile` and `withoutProfile` authentication request counts | +| `responsesByStatus` | `object` | Response counts keyed by HTTP status code | +| `requestsByRoute` | `object` | Per-route requests and latency, keyed by `"METHOD route-template"` | +| `errorsByType` | `object` | Error counts keyed by exception class name | + +`requests.total` counts a request on arrival while the outcome is recorded on completion, so `total` can briefly exceed +`success + failed` while requests are in flight. + ### `/readme` This endpoint redirects to the project's official GitHub repository. This endpoint does not take any request parameters. From 30c71f07b5285e187a11ce0ea3123c884e574301 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:34:51 -0500 Subject: [PATCH 09/17] chore: bump version to 4.2.0 Minor: new functionality that keeps existing APIs working, per the guidance in .github/scripts/check_version_bump.py. Two new endpoints, no change to /authenticate, /health or /readme, and no new dependencies. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- pyproject.toml | 2 +- uv.lock | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 4bf6671..279670f 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "pesu-auth" -version = "4.1.0" +version = "4.2.0" description = "A simple API to authenticate PESU credentials using PESU Academy." readme = "README.md" requires-python = ">=3.14" diff --git a/uv.lock b/uv.lock index 120d564..38e3654 100644 --- a/uv.lock +++ b/uv.lock @@ -289,8 +289,8 @@ name = "httpcore2" version = "2.12.0" source = { registry = "https://pypi.org/simple" } dependencies = [ - { name = "h11" }, - { name = "truststore" }, + { name = "h11", marker = "sys_platform != 'emscripten'" }, + { name = "truststore", marker = "sys_platform != 'emscripten'" }, ] sdist = { url = "https://files.pythonhosted.org/packages/be/ad/f4f0e57345f1870f3e8cb624e058d7eca6e5a27d33bcc3311d9b618734cd/httpcore2-2.12.0.tar.gz", hash = "sha256:9293522bba0aa7c4c8e9e3f040c16575bd8868e155a77fa30c7a9085a5eae648", size = 67548, upload-time = "2026-08-18T13:22:08.211Z" } wheels = [ @@ -630,7 +630,7 @@ wheels = [ [[package]] name = "pesu-auth" -version = "4.1.0" +version = "4.2.0" source = { editable = "." } dependencies = [ { name = "fastapi" }, From 0ae0a0a358a9388a242ddd2570adc01ec1f959db Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:39:25 -0500 Subject: [PATCH 10/17] refactor: serve both metric formats from one /metrics endpoint Replaces /metrics + /metrics.json with a single path selecting the representation by query parameter: `?fmt=prometheus` (the default) or `?fmt=json`. `fmt` is a StrEnum, so FastAPI validates it, Swagger renders a dropdown, and an unrecognised value goes through the existing validation handler -- a 400 with the usual body, which is itself counted like any other failed request rather than being a special case. The default stays Prometheus: a scraper pointed at this path with no query string must get the exposition format. `response_model` is None because the response type depends on the parameter and cannot be declared once. Both shapes are documented under `responses=` instead, which is what Swagger renders from anyway, so the endpoint documents itself as well as the two-path version did. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- README.md | 15 ++++--- app/app.py | 40 ++++++++--------- app/docs/__init__.py | 3 +- app/docs/metrics.py | 58 +++++++++++++------------ app/metrics/__init__.py | 9 ++++ app/metrics/prometheus.py | 11 ++++- scripts/benchmark/benchmark_requests.py | 2 +- tests/unit/test_metrics_endpoints.py | 44 +++++++++++++------ 8 files changed, 111 insertions(+), 71 deletions(-) diff --git a/README.md b/README.md index 6b2d42f..88e001c 100644 --- a/README.md +++ b/README.md @@ -102,8 +102,7 @@ The API provides multiple endpoints for authentication, documentation, and monit | `/` | `GET` | Serves the interactive API documentation (Swagger UI). | | `/authenticate` | `POST` | Authenticates a user using their PESU credentials. | | `/health` | `GET` | A health check endpoint to monitor the API's status. | -| `/metrics` | `GET` | Exposes traffic and error counters for Prometheus. | -| `/metrics.json` | `GET` | The same counters as JSON, for reading by hand. | +| `/metrics` | `GET` | Exposes traffic and error counters. See `fmt` below. | | `/readme` | `GET` | Redirects to the project's official GitHub repository. | ### `/authenticate` @@ -168,8 +167,8 @@ does not take any request parameters. ### `/metrics` This endpoint exposes counters describing the traffic this process has served, in the -[Prometheus text exposition format](https://prometheus.io/docs/instrumenting/exposition_formats/), ready to be scraped. -It takes no request parameters. +[Prometheus text exposition format](https://prometheus.io/docs/instrumenting/exposition_formats/) by default, ready +to be scraped, or as JSON with `?fmt=json`. ``` # HELP pesu_auth_responses_total HTTP responses, by status code. @@ -186,11 +185,13 @@ Status codes and exception classes are recorded separately, so errors that share Requests to `/metrics` are themselves counted. Excluding them would mean the endpoint reported a request total that did not match the sum of its own response counts. -### `/metrics.json` +#### Query Parameters -The same counters as JSON, for reading by hand rather than by a scraper. It takes no request parameters. +| **Field** | **Type** | **Description** | +| --------- | -------- | -------------------------------------------------------------------------------------- | +| `fmt` | `str` | `prometheus` (default) for the text exposition format, or `json` for the same counters | -#### Response Object +#### Response Object (`fmt=json`) | **Field** | **Type** | **Description** | | ------------------- | -------- | -------------------------------------------------------------------------- | diff --git a/app/app.py b/app/app.py index 45ec067..b199cbe 100644 --- a/app/app.py +++ b/app/app.py @@ -25,11 +25,11 @@ from pydantic import ValidationError -from app.docs import authenticate_docs, health_docs, metrics_docs, metrics_json_docs, readme_docs +from app.docs import authenticate_docs, health_docs, metrics_docs, readme_docs from app.exceptions.base import PESUAcademyError from app.metrics import AUTHENTICATION_REQUESTS, ERRORS_BY_TYPE, MetricsCollector from app.metrics.middleware import record_request_metrics -from app.metrics.prometheus import PROMETHEUS_CONTENT_TYPE, render_prometheus +from app.metrics.prometheus import PROMETHEUS_CONTENT_TYPE, MetricsFormat, render_prometheus from app.models import MetricsModel, RequestModel, ResponseModel from app.pesu import PESUAcademy @@ -195,32 +195,32 @@ async def health() -> JSONResponse: @app.get( "/metrics", - response_class=PlainTextResponse, + # The response type depends on ?fmt, so it cannot be declared once. Both shapes are documented + # in responses= instead, which is what Swagger renders anyway. + response_model=None, responses=metrics_docs.response_examples, tags=["Monitoring"], ) -async def prometheus_metrics() -> PlainTextResponse: - """Expose the collected metrics in the Prometheus text exposition format.""" +async def metrics_endpoint(fmt: MetricsFormat = MetricsFormat.PROMETHEUS) -> Response: + """Expose the collected metrics. + + Query parameters: + - fmt (str, optional): `prometheus` for the text exposition format (the default, since that is + what a scraper expects from this path), or `json` for the same counters as JSON. + """ + snapshot = metrics.snapshot() + if fmt is MetricsFormat.JSON: + # by_alias so the keys are camelCase like every other response this API returns + return JSONResponse( + status_code=200, + content=MetricsModel.from_snapshot(snapshot).model_dump(by_alias=True), + ) return PlainTextResponse( - content=render_prometheus(metrics.snapshot()), + content=render_prometheus(snapshot), media_type=PROMETHEUS_CONTENT_TYPE, ) -@app.get( - "/metrics.json", - response_model=MetricsModel, - response_class=JSONResponse, - responses=metrics_json_docs.response_examples, - tags=["Monitoring"], -) -async def json_metrics() -> MetricsModel: - """Expose the collected metrics as JSON.""" - # Returned as a model rather than a JSONResponse, so FastAPI serializes it with by_alias=True - # and the camelCase keys come for free. - return MetricsModel.from_snapshot(metrics.snapshot()) - - @app.get( "/readme", response_class=RedirectResponse, diff --git a/app/docs/__init__.py b/app/docs/__init__.py index b3321e8..712c989 100644 --- a/app/docs/__init__.py +++ b/app/docs/__init__.py @@ -2,13 +2,12 @@ from .authenticate import authenticate_docs from .health import health_docs -from .metrics import metrics_docs, metrics_json_docs +from .metrics import metrics_docs from .readme import readme_docs __all__ = [ "authenticate_docs", "health_docs", "metrics_docs", - "metrics_json_docs", "readme_docs", ] diff --git a/app/docs/metrics.py b/app/docs/metrics.py index 82c49a4..c7141bb 100644 --- a/app/docs/metrics.py +++ b/app/docs/metrics.py @@ -1,7 +1,7 @@ -"""Custom docs for the /metrics and /metrics.json PESUAuth endpoints.""" +"""Custom docs for the /metrics PESUAuth endpoint.""" from app.docs.base import ApiDocs -from app.models import MetricsModel, ResponseModel +from app.models import ResponseModel _INTERNAL_SERVER_ERROR = { "description": "Internal Server Error.", @@ -33,39 +33,43 @@ pesu_auth_request_latency_seconds_count 1284 """ -metrics_docs = ApiDocs( - request_examples={}, - response_examples={ - 200: { - "description": "Metrics in the Prometheus text exposition format.", - "content": {"text/plain": {"example": _PROMETHEUS_EXAMPLE}}, - }, - 500: _INTERNAL_SERVER_ERROR, +_JSON_EXAMPLE = { + "startTimeSeconds": 1757660400.12, + "uptimeSeconds": 3612.44, + "requests": {"total": 1284, "success": 1102, "failed": 182}, + "latency": {"sumSeconds": 742.1841932, "count": 1284, "averageSeconds": 0.5779}, + "authentication": {"total": 774, "withProfile": 134, "withoutProfile": 640}, + "responsesByStatus": {"200": 1094, "401": 160, "502": 6}, + "requestsByRoute": { + "POST /authenticate": { + "requests": 774, + "latency": {"sumSeconds": 741.2118, "count": 774, "averageSeconds": 0.9576}, + } }, -) + "errorsByType": {"AuthenticationError": 160, "RequestValidationError": 12}, +} -metrics_json_docs = ApiDocs( +metrics_docs = ApiDocs( request_examples={}, response_examples={ 200: { - "description": "Metrics as JSON.", - "model": MetricsModel, + "description": "The collected metrics, in the format named by `fmt`.", + "content": { + "text/plain": {"example": _PROMETHEUS_EXAMPLE}, + "application/json": {"example": _JSON_EXAMPLE}, + }, + }, + 400: { + "description": "Unrecognised value for `fmt`.", + "model": ResponseModel, "content": { "application/json": { "example": { - "startTimeSeconds": 1757660400.12, - "uptimeSeconds": 3612.44, - "requests": {"total": 1284, "success": 1102, "failed": 182}, - "latency": {"sumSeconds": 742.1841932, "count": 1284, "averageSeconds": 0.5779}, - "authentication": {"total": 774, "withProfile": 134, "withoutProfile": 640}, - "responsesByStatus": {"200": 1094, "401": 160, "502": 6}, - "requestsByRoute": { - "POST /authenticate": { - "requests": 774, - "latency": {"sumSeconds": 741.2118, "count": 774, "averageSeconds": 0.9576}, - } - }, - "errorsByType": {"AuthenticationError": 160, "RequestValidationError": 12}, + "status": False, + "message": ( + "Could not validate request data - query.fmt: Input should be 'prometheus' or 'json'" + ), + "timestamp": "2024-07-28T22:30:10.103368+05:30", } } }, diff --git a/app/metrics/__init__.py b/app/metrics/__init__.py index e311437..71e229e 100644 --- a/app/metrics/__init__.py +++ b/app/metrics/__init__.py @@ -47,3 +47,12 @@ from .collector import ( MetricsSnapshot as MetricsSnapshot, ) +from .prometheus import ( + PROMETHEUS_CONTENT_TYPE as PROMETHEUS_CONTENT_TYPE, +) +from .prometheus import ( + MetricsFormat as MetricsFormat, +) +from .prometheus import ( + render_prometheus as render_prometheus, +) diff --git a/app/metrics/prometheus.py b/app/metrics/prometheus.py index 59d5d28..eba86c5 100644 --- a/app/metrics/prometheus.py +++ b/app/metrics/prometheus.py @@ -1,7 +1,8 @@ -"""Render a metrics snapshot in the Prometheus text exposition format.""" +"""Exposition of a metrics snapshot: the formats on offer, and the Prometheus renderer.""" from __future__ import annotations +from enum import StrEnum from typing import TYPE_CHECKING from app.metrics.collector import FAMILIES @@ -15,6 +16,14 @@ # optional: a scraper handed a bare "text/plain" falls back to guessing the format. PROMETHEUS_CONTENT_TYPE = "text/plain; version=0.0.4; charset=utf-8" + +class MetricsFormat(StrEnum): + """The representations the metrics endpoint can serve.""" + + PROMETHEUS = "prometheus" + JSON = "json" + + # Label values are double-quoted, so a backslash, a quote or a newline inside one has to be escaped # or the sample line stops parsing. Everything else, including UTF-8, passes through. _LABEL_VALUE_ESCAPES = str.maketrans({"\\": "\\\\", '"': '\\"', "\n": "\\n"}) diff --git a/scripts/benchmark/benchmark_requests.py b/scripts/benchmark/benchmark_requests.py index f1ad9d0..fc990ed 100644 --- a/scripts/benchmark/benchmark_requests.py +++ b/scripts/benchmark/benchmark_requests.py @@ -40,7 +40,7 @@ parser.add_argument( "--route", type=str, - choices=["authenticate", "health", "readme", "metrics", "metrics.json"], + choices=["authenticate", "health", "readme", "metrics"], default="authenticate", help="The route to make the request to (default: authenticate)", ) diff --git a/tests/unit/test_metrics_endpoints.py b/tests/unit/test_metrics_endpoints.py index 775927a..b7074ce 100644 --- a/tests/unit/test_metrics_endpoints.py +++ b/tests/unit/test_metrics_endpoints.py @@ -50,8 +50,8 @@ def test_prometheus_endpoint_declares_every_family(client): assert body.endswith("\n") -def test_json_endpoint_shape(client): - body = client.get("/metrics.json").json() +def test_json_format_shape(client): + body = client.get("/metrics?fmt=json").json() assert set(body) == { "startTimeSeconds", "uptimeSeconds", @@ -67,12 +67,12 @@ def test_json_endpoint_shape(client): def test_a_request_is_reflected_in_both_views(client): client.get("/health") assert 'pesu_auth_route_requests_total{method="GET",route="/health"} 1' in client.get("/metrics").text - assert "GET /health" in client.get("/metrics.json").json()["requestsByRoute"] + assert "GET /health" in client.get("/metrics?fmt=json").json()["requestsByRoute"] def test_a_successful_request_is_counted_as_success(client): client.get("/health") - body = client.get("/metrics.json").json() + body = client.get("/metrics?fmt=json").json() assert body["responsesByStatus"]["200"] >= 1 assert body["requests"]["failed"] == 0 @@ -82,7 +82,7 @@ def test_an_authentication_request_records_the_profile_split(mock_authenticate, mock_authenticate.return_value = {"status": True, "message": "Login successful."} client.post("/authenticate", json={"username": "u", "password": "p", "profile": True}) client.post("/authenticate", json={"username": "u", "password": "p", "profile": False}) - authentication = client.get("/metrics.json").json()["authentication"] + authentication = client.get("/metrics?fmt=json").json()["authentication"] assert authentication == {"total": 2, "withProfile": 1, "withoutProfile": 1} @@ -91,7 +91,7 @@ def test_a_failed_authentication_records_both_status_and_error_type(mock_authent """The whole point of the middleware/handler split: a 401 keeps its status *and* its class.""" mock_authenticate.side_effect = AuthenticationError() assert client.post("/authenticate", json={"username": "u", "password": "p"}).status_code == 401 - body = client.get("/metrics.json").json() + body = client.get("/metrics?fmt=json").json() assert body["responsesByStatus"]["401"] == 1 assert body["errorsByType"]["AuthenticationError"] == 1 assert body["requests"]["failed"] == 1 @@ -99,7 +99,7 @@ def test_a_failed_authentication_records_both_status_and_error_type(mock_authent def test_a_validation_error_records_its_type(client): assert client.post("/authenticate", json={"password": "p"}).status_code == 400 - body = client.get("/metrics.json").json() + body = client.get("/metrics?fmt=json").json() assert body["responsesByStatus"]["400"] == 1 assert body["errorsByType"]["RequestValidationError"] == 1 @@ -108,7 +108,7 @@ def test_an_unhandled_exception_records_a_500(client): """ServerErrorMiddleware sits above the middleware, so this path cannot be verified by reading the code -- only by driving a real unhandled exception through the whole stack.""" assert client.get("/raiseUnhandledForMetrics").status_code == 500 - body = client.get("/metrics.json").json() + body = client.get("/metrics?fmt=json").json() assert body["responsesByStatus"]["500"] == 1 assert body["errorsByType"]["RuntimeError"] == 1 assert body["requests"]["failed"] == 1 @@ -117,7 +117,7 @@ def test_an_unhandled_exception_records_a_500(client): def test_an_unknown_path_is_bucketed(client): """A 404 is counted, attributed to one bucket, and runs no handler of ours.""" assert client.get("/definitely-not-a-route").status_code == 404 - body = client.get("/metrics.json").json() + body = client.get("/metrics?fmt=json").json() assert body["responsesByStatus"]["404"] == 1 assert "GET " in body["requestsByRoute"] assert body["errorsByType"] == {} @@ -125,8 +125,26 @@ def test_an_unknown_path_is_bucketed(client): def test_the_metrics_endpoint_counts_itself(client): """Scrapes are deliberately not excluded: excluding them would break the accounting invariant.""" - client.get("/metrics.json") - assert "GET /metrics.json" in client.get("/metrics.json").json()["requestsByRoute"] + client.get("/metrics?fmt=json") + assert "GET /metrics" in client.get("/metrics?fmt=json").json()["requestsByRoute"] + + +def test_the_default_format_is_prometheus(client): + """A scraper hitting this path bare must get the exposition format, not JSON.""" + assert client.get("/metrics").headers["content-type"] == PROMETHEUS_CONTENT_TYPE + + +def test_both_formats_are_served_from_one_path(client): + assert client.get("/metrics?fmt=prometheus").headers["content-type"] == PROMETHEUS_CONTENT_TYPE + assert client.get("/metrics?fmt=json").headers["content-type"].startswith("application/json") + + +def test_an_unrecognised_format_is_rejected(client): + """Goes through the existing validation handler, so it is a 400 and is itself counted.""" + response = client.get("/metrics?fmt=xml") + assert response.status_code == 400 + assert "fmt" in response.json()["message"] + assert client.get("/metrics?fmt=json").json()["errorsByType"]["RequestValidationError"] == 1 @patch("app.app.pesu_academy.authenticate") @@ -136,7 +154,7 @@ def test_response_and_outcome_counts_agree(mock_authenticate, client): client.get("/health") client.post("/authenticate", json={"username": "u", "password": "p"}) client.get("/definitely-not-a-route") - body = client.get("/metrics.json").json() + body = client.get("/metrics?fmt=json").json() resolved = body["requests"]["success"] + body["requests"]["failed"] assert sum(body["responsesByStatus"].values()) == resolved assert sum(body["errorsByType"].values()) < body["requests"]["failed"] @@ -144,6 +162,6 @@ def test_response_and_outcome_counts_agree(mock_authenticate, client): def test_latency_is_recorded_for_a_route(client): client.get("/health") - route = client.get("/metrics.json").json()["requestsByRoute"]["GET /health"] + route = client.get("/metrics?fmt=json").json()["requestsByRoute"]["GET /health"] assert route["latency"]["count"] == 1 assert route["latency"]["averageSeconds"] >= 0 From 92db11ee40ac0f205db50856c12259080da9492c Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:50:03 -0500 Subject: [PATCH 11/17] feat: instrument every path in the app Audited each request, response, error and background task, and closed the gaps. The set went from 9 metric families to 23. **The upstream was entirely uninstrumented, which was the biggest hole.** PESU Academy is the only dependency this service has and the only thing that can be slow or down, yet nothing measured it. Every call now goes through one helper that records count, outcome, latency and the upstream status code, labelled by operation: `csrf_fetch`, `login`, `profile_fetch`. When a request is slow, this is what says whether it is us or them. It also distinguishes "the call failed" from "the call succeeded and we could not parse what came back" -- a missing CSRF tag counts as a successful 200, because it is our parsing that failed. **Failures now say whose fault they are.** `failures_total{fault}` splits 4xx from 5xx, so an alert can fire on "our fault" without enumerating statuses. **Authentication says why it failed, not just that it did.** `authentication_results_total{result}` records success, invalid_credentials, csrf_token_error, profile_fetch_error, profile_parse_error and internal_error. Keyed on the exception class, because CSRFTokenError and ProfileFetchError are both 502 and mean entirely different things. **Validation errors say which field.** Bounded by a known-field set, since the request body is caller-controlled and an open label would be a cardinality hole. **Profile parsing says what broke**: key_missing, value_missing, unknown_field, page_structure, no_data, unknown_campus_code. The last one previously only emitted a warning and raised nothing -- an unknown campus code means the PRN format changed, which nothing else would have surfaced. **The internal machinery is visible**: CSRF cache hit/miss (which is the whole point of the prefetch, and previously invisible), prefetch task outcomes, background refresh outcomes, and client lifecycle events where created minus closed is what is still open -- the leak indicator for the bug class this module spent a release learning to avoid. Plus `requests_in_flight`, which explains the one gap in the accounting: total exceeds success + failed by exactly what is still being served. PESUAcademy now takes a collector, defaulting to a private one so a bare PESUAcademy() still works. The singleton is still created only in app/app.py. 202 tests, 100% coverage. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/app.py | 69 ++++++-- app/metrics/__init__.py | 81 ++++----- app/metrics/collector.py | 90 ++++++++++ app/metrics/middleware.py | 13 ++ app/models/metrics.py | 183 +++++++++++++++++++++ app/pesu.py | 116 +++++++++++-- tests/unit/test_metrics_endpoints.py | 77 +++++++++ tests/unit/test_metrics_instrumentation.py | 160 ++++++++++++++++++ tests/unit/test_metrics_model.py | 54 ++++++ 9 files changed, 766 insertions(+), 77 deletions(-) create mode 100644 tests/unit/test_metrics_instrumentation.py diff --git a/app/app.py b/app/app.py index b199cbe..1c94ec4 100644 --- a/app/app.py +++ b/app/app.py @@ -26,8 +26,22 @@ from pydantic import ValidationError from app.docs import authenticate_docs, health_docs, metrics_docs, readme_docs +from app.exceptions.authentication import ( + AuthenticationError, + CSRFTokenError, + ProfileFetchError, + ProfileParseError, +) from app.exceptions.base import PESUAcademyError -from app.metrics import AUTHENTICATION_REQUESTS, ERRORS_BY_TYPE, MetricsCollector +from app.metrics import ( + AUTHENTICATION_REQUESTS, + AUTHENTICATION_RESULTS, + CSRF_REFRESHES, + ERRORS_BY_TYPE, + LIFESPAN_EVENTS, + VALIDATION_ERRORS, + MetricsCollector, +) from app.metrics.middleware import record_request_metrics from app.metrics.prometheus import PROMETHEUS_CONTENT_TYPE, MetricsFormat, render_prometheus from app.models import MetricsModel, RequestModel, ResponseModel @@ -35,6 +49,17 @@ IST = ZoneInfo("Asia/Kolkata") CSRF_TOKEN_REFRESH_INTERVAL_SECONDS = 45 * 60 +# Validation failures are labelled by field, so the label set has to be closed against a caller who +# can put anything in the request body +KNOWN_REQUEST_FIELDS = frozenset({"username", "password", "profile", "fields", "fmt", "body"}) +# Failure vocabulary for authentication attempts. Keyed on the exception class rather than the +# status code, because CSRFTokenError and ProfileFetchError are both 502 and mean different things. +AUTHENTICATION_FAILURE_RESULTS = { + AuthenticationError: "invalid_credentials", + CSRFTokenError: "csrf_token_error", + ProfileFetchError: "profile_fetch_error", + ProfileParseError: "profile_parse_error", +} async def _refresh_csrf_token() -> None: @@ -50,7 +75,10 @@ async def _csrf_token_refresh_loop() -> None: logging.debug("Refreshing unauthenticated CSRF token...") await _refresh_csrf_token() except Exception: + metrics.increment(CSRF_REFRESHES, outcome="failure") logging.exception("Failed to refresh unauthenticated CSRF token in the background.") + else: + metrics.increment(CSRF_REFRESHES, outcome="success") await asyncio.sleep(CSRF_TOKEN_REFRESH_INTERVAL_SECONDS) @@ -58,6 +86,7 @@ async def _csrf_token_refresh_loop() -> None: async def lifespan(app: FastAPI) -> AsyncIterator[None]: """Lifespan event handler for startup and shutdown events.""" # Startup + metrics.increment(LIFESPAN_EVENTS, event="startup") logging.info("PESUAuth API startup") # Prefetch PESUAcademy client for first request @@ -80,6 +109,7 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]: logging.exception("Failed to cancel unauthenticated CSRF token refresh background task.") await pesu_academy.close_client() + metrics.increment(LIFESPAN_EVENTS, event="shutdown") logging.info("PESUAuth API shutdown.") @@ -104,8 +134,8 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]: }, ], ) -pesu_academy = PESUAcademy() metrics = MetricsCollector() +pesu_academy = PESUAcademy(metrics) @app.middleware("http") @@ -121,6 +151,13 @@ async def validation_exception_handler(request: Request, exc: RequestValidationE """Handler for request validation errors.""" metrics.increment(ERRORS_BY_TYPE, type=type(exc).__name__) errors = exc.errors() + # Which field was wrong, not just that something was. The field names are a fixed set, so the + # label is bounded; anything unrecognised collapses into one bucket rather than opening the + # key space to caller-controlled strings. + for error in errors: + location = error.get("loc") or () + field = str(location[-1]) if location else "unknown" + metrics.increment(VALIDATION_ERRORS, field=field if field in KNOWN_REQUEST_FIELDS else "other") # Log only the shape of the failure, never the submitted values. Each entry from `errors()` # carries an "input" key which, for a missing required field, is the *entire request body* -- # so logging it verbatim would write the user's password to the logs in plaintext. @@ -265,14 +302,26 @@ async def authenticate(payload: RequestModel) -> JSONResponse: # already answered by route_requests_total; only the split needs the body. metrics.increment(AUTHENTICATION_REQUESTS, profile=str(profile).lower()) logging.info(f"Authenticating user={username} with PESU Academy...") - authentication_result.update( - await pesu_academy.authenticate( - username=username, - password=password, - profile=profile, - fields=fields, - ), - ) + try: + authentication_result.update( + await pesu_academy.authenticate( + username=username, + password=password, + profile=profile, + fields=fields, + ), + ) + except PESUAcademyError as exc: + # Why the attempt failed, not just that it did. errors_total already counts the exception + # class; this records the same event in the vocabulary someone actually asks questions in -- + # "how many logins failed because the password was wrong" versus "because PESU was broken". + result = AUTHENTICATION_FAILURE_RESULTS.get(type(exc), "other") + metrics.increment(AUTHENTICATION_RESULTS, result=result) + raise + except Exception: + metrics.increment(AUTHENTICATION_RESULTS, result="internal_error") + raise + metrics.increment(AUTHENTICATION_RESULTS, result="success") # Validate the response try: diff --git a/app/metrics/__init__.py b/app/metrics/__init__.py index 71e229e..3bf4cbc 100644 --- a/app/metrics/__init__.py +++ b/app/metrics/__init__.py @@ -5,54 +5,33 @@ swap the collector out by patching one module attribute. """ -from .collector import ( - AUTHENTICATION_REQUESTS as AUTHENTICATION_REQUESTS, -) -from .collector import ( - ERRORS_BY_TYPE as ERRORS_BY_TYPE, -) -from .collector import ( - FAMILIES as FAMILIES, -) -from .collector import ( - PROCESS_START_TIME as PROCESS_START_TIME, -) -from .collector import ( - REQUEST_LATENCY as REQUEST_LATENCY, -) -from .collector import ( - REQUESTS_FAILED as REQUESTS_FAILED, -) -from .collector import ( - REQUESTS_SUCCESS as REQUESTS_SUCCESS, -) -from .collector import ( - REQUESTS_TOTAL as REQUESTS_TOTAL, -) -from .collector import ( - RESPONSES_BY_STATUS as RESPONSES_BY_STATUS, -) -from .collector import ( - ROUTE_LATENCY as ROUTE_LATENCY, -) -from .collector import ( - ROUTE_REQUESTS as ROUTE_REQUESTS, -) -from .collector import ( - MetricFamily as MetricFamily, -) -from .collector import ( - MetricsCollector as MetricsCollector, -) -from .collector import ( - MetricsSnapshot as MetricsSnapshot, -) -from .prometheus import ( - PROMETHEUS_CONTENT_TYPE as PROMETHEUS_CONTENT_TYPE, -) -from .prometheus import ( - MetricsFormat as MetricsFormat, -) -from .prometheus import ( - render_prometheus as render_prometheus, -) +from .collector import AUTHENTICATION_REQUESTS as AUTHENTICATION_REQUESTS +from .collector import AUTHENTICATION_RESULTS as AUTHENTICATION_RESULTS +from .collector import CSRF_CACHE as CSRF_CACHE +from .collector import CSRF_REFRESHES as CSRF_REFRESHES +from .collector import ERRORS_BY_TYPE as ERRORS_BY_TYPE +from .collector import FAILURES_BY_FAULT as FAILURES_BY_FAULT +from .collector import FAMILIES as FAMILIES +from .collector import HTTP_CLIENTS as HTTP_CLIENTS +from .collector import LIFESPAN_EVENTS as LIFESPAN_EVENTS +from .collector import PREFETCH_TASKS as PREFETCH_TASKS +from .collector import PROCESS_START_TIME as PROCESS_START_TIME +from .collector import PROFILE_PARSE_ERRORS as PROFILE_PARSE_ERRORS +from .collector import REQUEST_LATENCY as REQUEST_LATENCY +from .collector import REQUESTS_FAILED as REQUESTS_FAILED +from .collector import REQUESTS_IN_FLIGHT as REQUESTS_IN_FLIGHT +from .collector import REQUESTS_SUCCESS as REQUESTS_SUCCESS +from .collector import REQUESTS_TOTAL as REQUESTS_TOTAL +from .collector import RESPONSES_BY_STATUS as RESPONSES_BY_STATUS +from .collector import ROUTE_LATENCY as ROUTE_LATENCY +from .collector import ROUTE_REQUESTS as ROUTE_REQUESTS +from .collector import UPSTREAM_LATENCY as UPSTREAM_LATENCY +from .collector import UPSTREAM_REQUESTS as UPSTREAM_REQUESTS +from .collector import UPSTREAM_RESPONSES as UPSTREAM_RESPONSES +from .collector import VALIDATION_ERRORS as VALIDATION_ERRORS +from .collector import MetricFamily as MetricFamily +from .collector import MetricsCollector as MetricsCollector +from .collector import MetricsSnapshot as MetricsSnapshot +from .prometheus import PROMETHEUS_CONTENT_TYPE as PROMETHEUS_CONTENT_TYPE +from .prometheus import MetricsFormat as MetricsFormat +from .prometheus import render_prometheus as render_prometheus diff --git a/app/metrics/collector.py b/app/metrics/collector.py index 8d0569c..6c6b9dd 100644 --- a/app/metrics/collector.py +++ b/app/metrics/collector.py @@ -82,6 +82,83 @@ class MetricFamily: "Start time of the process since the Unix epoch, in seconds.", "gauge", ) +REQUESTS_IN_FLIGHT = MetricFamily( + f"{METRIC_PREFIX}requests_in_flight", + "Requests received but not yet answered.", + "gauge", +) +FAILURES_BY_FAULT = MetricFamily( + f"{METRIC_PREFIX}failures_total", + "Failed requests, by whose fault it was: the caller's (4xx) or ours (5xx).", + "counter", + ("fault",), +) +VALIDATION_ERRORS = MetricFamily( + f"{METRIC_PREFIX}validation_errors_total", + "Request validation failures, by the field that failed.", + "counter", + ("field",), +) +AUTHENTICATION_RESULTS = MetricFamily( + f"{METRIC_PREFIX}authentication_results_total", + "Authentication attempts, by outcome.", + "counter", + ("result",), +) +PROFILE_PARSE_ERRORS = MetricFamily( + f"{METRIC_PREFIX}profile_parse_errors_total", + "Profile page parse failures, by what could not be parsed.", + "counter", + ("reason",), +) +UPSTREAM_REQUESTS = MetricFamily( + f"{METRIC_PREFIX}upstream_requests_total", + "Requests made to PESU Academy, by operation and outcome.", + "counter", + ("operation", "outcome"), +) +UPSTREAM_RESPONSES = MetricFamily( + f"{METRIC_PREFIX}upstream_responses_total", + "Responses from PESU Academy, by operation and status code.", + "counter", + ("operation", "status"), +) +UPSTREAM_LATENCY = MetricFamily( + f"{METRIC_PREFIX}upstream_latency_seconds", + "Seconds spent waiting on PESU Academy, by operation.", + "summary", + ("operation",), +) +CSRF_CACHE = MetricFamily( + f"{METRIC_PREFIX}csrf_cache_total", + "Lookups of the cached unauthenticated CSRF client, by whether the cache was warm.", + "counter", + ("outcome",), +) +CSRF_REFRESHES = MetricFamily( + f"{METRIC_PREFIX}csrf_refreshes_total", + "Periodic background refreshes of the unauthenticated CSRF token, by outcome.", + "counter", + ("outcome",), +) +PREFETCH_TASKS = MetricFamily( + f"{METRIC_PREFIX}prefetch_tasks_total", + "Background CSRF prefetch tasks, by outcome.", + "counter", + ("outcome",), +) +HTTP_CLIENTS = MetricFamily( + f"{METRIC_PREFIX}http_clients_total", + "Lifecycle events for upstream HTTP clients. created minus closed is what is still open.", + "counter", + ("event",), +) +LIFESPAN_EVENTS = MetricFamily( + f"{METRIC_PREFIX}lifespan_events_total", + "Application lifespan events, by kind.", + "counter", + ("event",), +) # Render order, and the single source of HELP and TYPE shared by both views FAMILIES: tuple[MetricFamily, ...] = ( @@ -92,8 +169,21 @@ class MetricFamily: ROUTE_REQUESTS, ERRORS_BY_TYPE, AUTHENTICATION_REQUESTS, + AUTHENTICATION_RESULTS, + PROFILE_PARSE_ERRORS, + VALIDATION_ERRORS, + FAILURES_BY_FAULT, REQUEST_LATENCY, ROUTE_LATENCY, + UPSTREAM_REQUESTS, + UPSTREAM_RESPONSES, + UPSTREAM_LATENCY, + CSRF_CACHE, + CSRF_REFRESHES, + PREFETCH_TASKS, + HTTP_CLIENTS, + LIFESPAN_EVENTS, + REQUESTS_IN_FLIGHT, PROCESS_START_TIME, ) diff --git a/app/metrics/middleware.py b/app/metrics/middleware.py index 6b214b4..c8686eb 100644 --- a/app/metrics/middleware.py +++ b/app/metrics/middleware.py @@ -6,8 +6,10 @@ from typing import TYPE_CHECKING, Any from app.metrics.collector import ( + FAILURES_BY_FAULT, REQUEST_LATENCY, REQUESTS_FAILED, + REQUESTS_IN_FLIGHT, REQUESTS_SUCCESS, REQUESTS_TOTAL, RESPONSES_BY_STATUS, @@ -30,6 +32,8 @@ # What an exception that reached us is recorded as. ServerErrorMiddleware renders the actual 500 # above us, so we never see that response and have to record the status ourselves. EXCEPTION_STATUS = 500 +# At or above this status the fault is ours (or the upstream's) rather than the caller's +SERVER_FAULT_STATUS = 500 KNOWN_METHODS = frozenset({"GET", "POST", "PUT", "PATCH", "DELETE", "HEAD", "OPTIONS"}) UNMATCHED_ROUTE = "" @@ -92,6 +96,12 @@ def _record_outcome(collector: MetricsCollector, scope: Mapping[str, Any], statu else: collector.increment(REQUESTS_FAILED) collector.increment(RESPONSES_BY_STATUS, status=str(status)) + if status >= FAILURE_STATUS: + # Who should act on this: a 4xx means the caller sent something wrong, a 5xx means we or + # PESU Academy did. Derivable from the status codes, but stated outright so an alert can + # fire on "our fault" without enumerating every status. + fault = "server" if status >= SERVER_FAULT_STATUS else "client" + collector.increment(FAILURES_BY_FAULT, fault=fault) collector.increment(ROUTE_REQUESTS, method=method, route=route) collector.observe(REQUEST_LATENCY, latency) collector.observe(ROUTE_LATENCY, latency, method=method, route=route) @@ -116,6 +126,7 @@ async def record_request_metrics( Exception: Re-raised unchanged, so error handling above is unaffected. """ collector.increment(REQUESTS_TOTAL) + collector.increment(REQUESTS_IN_FLIGHT) # perf_counter, not time(): a wall clock is not monotonic, and one NTP step backwards would # poison a cumulative latency sum permanently. started = time.perf_counter() @@ -132,7 +143,9 @@ async def record_request_metrics( # The exception *type* is recorded by the exception handlers, not here. The two layers write # to different families on purpose: one failed request produces exactly one status sample # and exactly one error sample, never two of either. + collector.increment(REQUESTS_IN_FLIGHT, -1.0) _record_outcome(collector, request.scope, EXCEPTION_STATUS, time.perf_counter() - started) raise + collector.increment(REQUESTS_IN_FLIGHT, -1.0) _record_outcome(collector, request.scope, response.status_code, time.perf_counter() - started) return response diff --git a/app/models/metrics.py b/app/models/metrics.py index b1fb74c..4d2cd85 100644 --- a/app/models/metrics.py +++ b/app/models/metrics.py @@ -5,19 +5,72 @@ from app.metrics.collector import ( AUTHENTICATION_REQUESTS, + AUTHENTICATION_RESULTS, + CSRF_CACHE, + CSRF_REFRESHES, ERRORS_BY_TYPE, + FAILURES_BY_FAULT, + HTTP_CLIENTS, + LIFESPAN_EVENTS, + PREFETCH_TASKS, PROCESS_START_TIME, + PROFILE_PARSE_ERRORS, REQUEST_LATENCY, REQUESTS_FAILED, + REQUESTS_IN_FLIGHT, REQUESTS_SUCCESS, REQUESTS_TOTAL, RESPONSES_BY_STATUS, ROUTE_LATENCY, ROUTE_REQUESTS, + UPSTREAM_LATENCY, + UPSTREAM_REQUESTS, + UPSTREAM_RESPONSES, + VALIDATION_ERRORS, MetricsSnapshot, ) +def _counts(snapshot: MetricsSnapshot, name: str, label: str) -> dict[str, int]: + """Collapse a single-label counter family into a plain mapping of label value to count. + + Args: + snapshot (MetricsSnapshot): The snapshot to read. + name (str): The counter family name. + label (str): The label whose value becomes the key. + + Returns: + dict[str, int]: The counts, keyed by label value. + """ + return {labels[label]: int(value) for labels, value in snapshot.samples(name)} + + +def _upstream(snapshot: MetricsSnapshot) -> dict[str, UpstreamOperationModel]: + """Gather the per-operation view of calls made to PESU Academy. + + Args: + snapshot (MetricsSnapshot): The snapshot to read. + + Returns: + dict[str, UpstreamOperationModel]: One entry per operation that has been attempted. + """ + outcomes: dict[str, dict[str, int]] = {} + for labels, value in snapshot.samples(UPSTREAM_REQUESTS.name): + outcomes.setdefault(labels["operation"], {})[labels["outcome"]] = int(value) + statuses: dict[str, dict[str, int]] = {} + for labels, value in snapshot.samples(UPSTREAM_RESPONSES.name): + statuses.setdefault(labels["operation"], {})[labels["status"]] = int(value) + return { + operation: UpstreamOperationModel( + success=counts.get("success", 0), + error=counts.get("error", 0), + latency=LatencyModel.from_snapshot(snapshot, UPSTREAM_LATENCY.name, operation=operation), + responses_by_status=statuses.get(operation, {}), + ) + for operation, counts in outcomes.items() + } + + class LatencyModel(BaseModel): """Model representing aggregate request latency.""" @@ -138,6 +191,39 @@ class RouteMetricsModel(BaseModel): ) +class UpstreamOperationModel(BaseModel): + """Model representing one kind of call made to PESU Academy.""" + + model_config = ConfigDict(strict=True, alias_generator=to_camel, populate_by_name=True) + + success: int = Field( + ..., + title="Successful Calls", + description="Calls that returned without raising.", + json_schema_extra={"example": 1280}, + ) + + error: int = Field( + ..., + title="Failed Calls", + description="Calls that raised, including timeouts and connection failures.", + json_schema_extra={"example": 4}, + ) + + latency: LatencyModel = Field( + ..., + title="Upstream Latency", + description="Aggregate seconds spent waiting on this operation.", + ) + + responses_by_status: dict[str, int] = Field( + ..., + title="Responses by Status", + description="Upstream response counts keyed by HTTP status code.", + json_schema_extra={"example": {"200": 1280}}, + ) + + class MetricsModel(BaseModel): """Model representing a point-in-time view of the API's collected metrics.""" @@ -203,6 +289,92 @@ class MetricsModel(BaseModel): json_schema_extra={"example": {"AuthenticationError": 160, "RequestValidationError": 12}}, ) + requests_in_flight: int = Field( + ..., + title="Requests in Flight", + description="Requests received but not yet answered. Explains why total can exceed success plus failed.", + json_schema_extra={"example": 1}, + ) + + failures_by_fault: dict[str, int] = Field( + ..., + title="Failures by Fault", + description='Failed requests keyed by whose fault it was: "client" for 4xx, "server" for 5xx.', + json_schema_extra={"example": {"client": 172, "server": 10}}, + ) + + validation_errors_by_field: dict[str, int] = Field( + ..., + title="Validation Errors by Field", + description="Request validation failures keyed by the field that failed.", + json_schema_extra={"example": {"username": 8, "password": 4}}, + ) + + authentication_results: dict[str, int] = Field( + ..., + title="Authentication Results", + description="Authentication attempts keyed by outcome, so failures can be told apart by cause.", + json_schema_extra={"example": {"success": 612, "invalid_credentials": 160, "profile_fetch_error": 2}}, + ) + + profile_parse_errors: dict[str, int] = Field( + ..., + title="Profile Parse Errors", + description="Profile page parse failures keyed by what could not be parsed.", + json_schema_extra={"example": {"unknown_field": 3}}, + ) + + upstream: dict[str, UpstreamOperationModel] = Field( + ..., + title="Upstream Calls", + description="Calls made to PESU Academy, keyed by operation.", + json_schema_extra={ + "example": { + "login": { + "success": 774, + "error": 2, + "latency": {"sumSeconds": 620.4, "count": 776, "averageSeconds": 0.7995}, + "responsesByStatus": {"200": 774}, + } + } + }, + ) + + csrf_cache: dict[str, int] = Field( + ..., + title="CSRF Cache", + description='Lookups of the prefetched CSRF client, keyed by "hit" or "miss".', + json_schema_extra={"example": {"hit": 760, "miss": 14}}, + ) + + csrf_refreshes: dict[str, int] = Field( + ..., + title="CSRF Refreshes", + description="Periodic background token refreshes keyed by outcome.", + json_schema_extra={"example": {"success": 45, "failure": 1}}, + ) + + prefetch_tasks: dict[str, int] = Field( + ..., + title="Prefetch Tasks", + description="Background CSRF prefetch tasks keyed by outcome.", + json_schema_extra={"example": {"success": 770, "failure": 4, "cancelled": 1}}, + ) + + http_clients: dict[str, int] = Field( + ..., + title="HTTP Clients", + description="Upstream client lifecycle events. created minus closed is what is still open.", + json_schema_extra={"example": {"created": 776, "closed": 776}}, + ) + + lifespan_events: dict[str, int] = Field( + ..., + title="Lifespan Events", + description="Application startup and shutdown events seen by this process.", + json_schema_extra={"example": {"startup": 1}}, + ) + @classmethod def from_snapshot(cls, snapshot: MetricsSnapshot) -> MetricsModel: """Build the JSON metrics view from a collector snapshot. @@ -243,4 +415,15 @@ def from_snapshot(cls, snapshot: MetricsSnapshot) -> MetricsModel: for labels, value in snapshot.samples(ROUTE_REQUESTS.name) }, errors_by_type={labels["type"]: int(value) for labels, value in snapshot.samples(ERRORS_BY_TYPE.name)}, + requests_in_flight=int(snapshot.value(REQUESTS_IN_FLIGHT.name)), + failures_by_fault=_counts(snapshot, FAILURES_BY_FAULT.name, "fault"), + validation_errors_by_field=_counts(snapshot, VALIDATION_ERRORS.name, "field"), + authentication_results=_counts(snapshot, AUTHENTICATION_RESULTS.name, "result"), + profile_parse_errors=_counts(snapshot, PROFILE_PARSE_ERRORS.name, "reason"), + upstream=_upstream(snapshot), + csrf_cache=_counts(snapshot, CSRF_CACHE.name, "outcome"), + csrf_refreshes=_counts(snapshot, CSRF_REFRESHES.name, "outcome"), + prefetch_tasks=_counts(snapshot, PREFETCH_TASKS.name, "outcome"), + http_clients=_counts(snapshot, HTTP_CLIENTS.name, "event"), + lifespan_events=_counts(snapshot, LIFESPAN_EVENTS.name, "event"), ) diff --git a/app/pesu.py b/app/pesu.py index e9fb655..d28f480 100644 --- a/app/pesu.py +++ b/app/pesu.py @@ -1,10 +1,14 @@ """PESUAcademy class that serves as an interface to the PESU Academy website.""" +from __future__ import annotations + import asyncio import logging import re +import time +from contextlib import asynccontextmanager from datetime import datetime -from typing import Any, Literal, get_args +from typing import TYPE_CHECKING, Any, Literal, get_args import httpx2 from selectolax.parser import HTMLParser, Node @@ -15,6 +19,19 @@ ProfileFetchError, ProfileParseError, ) +from app.metrics import ( + CSRF_CACHE, + HTTP_CLIENTS, + PREFETCH_TASKS, + PROFILE_PARSE_ERRORS, + UPSTREAM_LATENCY, + UPSTREAM_REQUESTS, + UPSTREAM_RESPONSES, + MetricsCollector, +) + +if TYPE_CHECKING: + from collections.abc import AsyncIterator ProfileField = Literal[ "name", @@ -37,7 +54,39 @@ _CLOSE_TASKS: set[asyncio.Task[None]] = set() -async def _aclose_client(client: httpx2.AsyncClient) -> None: +@asynccontextmanager +async def _upstream_call(metrics: MetricsCollector, operation: str) -> AsyncIterator[list[Any]]: + """Time one call to PESU Academy and record its outcome. + + Yields a one-element list: put the response in it and the status code is recorded too. The + upstream is the only dependency this service has, so every call through it is timed -- when + something is slow or broken, this is what says whether it is us or them. + + Args: + metrics (MetricsCollector): The collector to record into. + operation (str): The name of the upstream operation, used as a label. + + Yields: + list[Any]: A single-element sink for the response object. + + Raises: + BaseException: Re-raised unchanged after the failure is recorded. + """ + sink: list[Any] = [] + started = time.perf_counter() + try: + yield sink + except BaseException: + metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome="error") + metrics.observe(UPSTREAM_LATENCY, time.perf_counter() - started, operation=operation) + raise + metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome="success") + metrics.observe(UPSTREAM_LATENCY, time.perf_counter() - started, operation=operation) + if sink and (status := getattr(sink[0], "status_code", None)) is not None: + metrics.increment(UPSTREAM_RESPONSES, operation=operation, status=str(status)) + + +async def _aclose_client(client: httpx2.AsyncClient, metrics: MetricsCollector) -> None: """Close an HTTP client, logging rather than raising if the close itself fails. Cleanup failure must never replace the error that triggered the cleanup: letting `aclose()` @@ -45,14 +94,20 @@ async def _aclose_client(client: httpx2.AsyncClient) -> None: Args: client (httpx2.AsyncClient): The client to close. + metrics (MetricsCollector): The collector to record the outcome into. """ try: await client.aclose() except Exception: + # Counted, not just logged: created minus closed is how many clients are still open, and a + # close that fails is exactly the leak this module spent a release learning to avoid. + metrics.increment(HTTP_CLIENTS, event="close_failed") logging.warning("Failed to close an HTTP client cleanly.", exc_info=True) + else: + metrics.increment(HTTP_CLIENTS, event="closed") -async def _close_client_quietly(client: httpx2.AsyncClient) -> None: +async def _close_client_quietly(client: httpx2.AsyncClient, metrics: MetricsCollector) -> None: """Close an HTTP client, surviving both a failing close and a cancellation mid-close. Most callers run this from an `except BaseException` handler or a `finally`, which is exactly @@ -64,8 +119,9 @@ async def _close_client_quietly(client: httpx2.AsyncClient) -> None: Args: client (httpx2.AsyncClient): The client to close. + metrics (MetricsCollector): The collector to record the outcome into. """ - task = asyncio.ensure_future(_aclose_client(client)) + task = asyncio.ensure_future(_aclose_client(client, metrics)) _CLOSE_TASKS.add(task) task.add_done_callback(_CLOSE_TASKS.discard) await asyncio.shield(task) @@ -100,8 +156,14 @@ class PESUAcademy: "Section": "section", } - def __init__(self) -> None: - """Initialize the PESUAcademy class.""" + def __init__(self, metrics: MetricsCollector | None = None) -> None: + """Initialize the PESUAcademy class. + + Args: + metrics (MetricsCollector | None): The collector to record into. Defaults to a private + one, so a bare PESUAcademy() still works and simply records where nobody reads. + """ + self._metrics = metrics if metrics is not None else MetricsCollector() self._csrf_token: str | None = None self._client: httpx2.AsyncClient | None = None self._csrf_lock = asyncio.Lock() @@ -109,16 +171,18 @@ def __init__(self) -> None: # mid-flight. See https://docs.python.org/3/library/asyncio-task.html#asyncio.create_task self._prefetch_tasks: set[asyncio.Task[None]] = set() - @staticmethod - async def _fetch_new_client_with_csrf_token() -> tuple[httpx2.AsyncClient, str]: + async def _fetch_new_client_with_csrf_token(self) -> tuple[httpx2.AsyncClient, str]: """Initialize a fresh client with an unauthenticated CSRF token from PESU Academy.""" logging.info("Fetching a new client with an unauthenticated CSRF token...") # Create a new client client = httpx2.AsyncClient(follow_redirects=True, timeout=10.0) + self._metrics.increment(HTTP_CLIENTS, event="created") # On success the client is handed to the caller, so only close it if we fail to return it try: # Fetch the CSRF token - resp = await client.get("https://www.pesuacademy.com/Academy/") + async with _upstream_call(self._metrics, "csrf_fetch") as sink: + resp = await client.get("https://www.pesuacademy.com/Academy/") + sink.append(resp) soup = await asyncio.to_thread(HTMLParser, resp.text) if node := soup.css_first("meta[name='csrf-token']"): csrf_token = node.attributes["content"] @@ -126,7 +190,7 @@ async def _fetch_new_client_with_csrf_token() -> tuple[httpx2.AsyncClient, str]: return client, csrf_token raise CSRFTokenError("CSRF token not found in the pre-authentication response.") except BaseException: - await _close_client_quietly(client) + await _close_client_quietly(client, self._metrics) raise async def _prefetch_client_with_csrf_token(self) -> None: @@ -145,12 +209,12 @@ async def _prefetch_client_with_csrf_token(self) -> None: # Close old cached client (if any) to avoid leaks. A failure to close the old # client must not stop the refresh, so it is logged rather than raised. if self._client is not None: - await _close_client_quietly(self._client) + await _close_client_quietly(self._client, self._metrics) # Store the new cached client/token self._client = client self._csrf_token = token except BaseException: - await _close_client_quietly(client) + await _close_client_quietly(client, self._metrics) raise logging.info("Cache refreshed with new unauthenticated CSRF token.") @@ -170,6 +234,10 @@ async def _get_client_with_csrf_token(self) -> tuple[httpx2.AsyncClient, str]: self._client = None self._csrf_token = None + # Hit rate is the whole point of the prefetch: a cold cache means the caller waits on an + # upstream round trip it was supposed to be spared. + self._metrics.increment(CSRF_CACHE, outcome="hit" if cached else "miss") + if not cached: # Cold cache: fetch *outside* the lock. Holding it across a fetch would queue every # concurrent request behind a 10s upstream timeout, and would not save any work -- @@ -195,12 +263,16 @@ def _on_prefetch_task_done(self, task: asyncio.Task[None]) -> None: self._prefetch_tasks.discard(task) # exception() raises on a cancelled task, so that has to be checked first if task.cancelled(): + self._metrics.increment(PREFETCH_TASKS, outcome="cancelled") return if (exception := task.exception()) is not None: + self._metrics.increment(PREFETCH_TASKS, outcome="failure") logging.error( f"Background CSRF token prefetch failed: {exception!r}", exc_info=exception, ) + else: + self._metrics.increment(PREFETCH_TASKS, outcome="success") def _spawn_prefetch_task(self) -> None: """Start a background prefetch of the next client and CSRF token.""" @@ -219,11 +291,13 @@ def _extract_and_update_profile(self, node: Node, idx: int, profile: dict) -> No """ # Use the selector `label.lbl-title-light` to find the key label if not (key_node := node.css_first("label.lbl-title-light")) or not (key := key_node.text(strip=True)): + self._metrics.increment(PROFILE_PARSE_ERRORS, reason="key_missing") raise ProfileParseError(f"Could not parse key for field at index {idx}.") # Use the adjacent sibling selector `+` to find value label if not (value_node := node.css_first("label.lbl-title-light + label")) or not ( value := value_node.text(strip=True) ): + self._metrics.increment(PROFILE_PARSE_ERRORS, reason="value_missing") raise ProfileParseError(f"Could not parse value for field at index {idx}.") logging.debug(f"Extracted key: '{key}' with value: '{value}' at index {idx}.") # If the key is in the map, add it to the profile @@ -231,6 +305,7 @@ def _extract_and_update_profile(self, node: Node, idx: int, profile: dict) -> No logging.debug(f"Adding key: '{mapped_key}', value: '{value}' to profile...") profile[mapped_key] = value else: + self._metrics.increment(PROFILE_PARSE_ERRORS, reason="unknown_field") raise ProfileParseError( f"Unknown key: '{key}' in the profile page. The webpage might have changed.", ) @@ -260,7 +335,7 @@ async def close_client(self) -> None: await asyncio.gather(*tasks, return_exceptions=True) async with self._csrf_lock: if self._client is not None: - await _close_client_quietly(self._client) + await _close_client_quietly(self._client, self._metrics) self._client = None self._csrf_token = None @@ -290,7 +365,9 @@ async def get_profile_information( "selectedData": "0", "_": str(int(datetime.now().timestamp() * 1000)), } - response = await client.get(profile_url, params=query) + async with _upstream_call(self._metrics, "profile_fetch") as sink: + response = await client.get(profile_url, params=query) + sink.append(response) # If the status code is not 200, raise an exception because the profile page is not accessible if response.status_code != 200: raise ProfileFetchError( @@ -306,6 +383,7 @@ async def get_profile_information( or not (details_nodes := details_container.css("div.form-group")) or len(details_nodes) < 7 ): + self._metrics.increment(PROFILE_PARSE_ERRORS, reason="page_structure") raise ProfileParseError( f"Failed to parse student profile page from PESU Academy for user={username}." "The webpage might have changed.", @@ -340,12 +418,16 @@ async def get_profile_information( elif campus_code == "2": profile["campus"] = "EC" else: + # Not fatal -- the profile is returned without a campus name -- but it means the PRN + # format has changed, which nothing else would surface. + self._metrics.increment(PROFILE_PARSE_ERRORS, reason="unknown_campus_code") logging.warning( f"Unknown campus code: {campus_code} parsed from PRN={profile['prn']} for user={username}", ) # Check if we extracted any profile data if not profile: + self._metrics.increment(PROFILE_PARSE_ERRORS, reason="no_data") raise ProfileParseError(f"No profile data could be extracted for user={username}.") logging.info(f"Complete profile information retrieved for user={username}: {profile}.") @@ -396,7 +478,9 @@ async def authenticate( logging.debug("Attempting to authenticate user...") # Make a post request to authenticate the user auth_url = "https://www.pesuacademy.com/Academy/j_spring_security_check" - response = await client.post(auth_url, data=data) + async with _upstream_call(self._metrics, "login") as sink: + response = await client.post(auth_url, data=data) + sink.append(response) soup = await asyncio.to_thread(HTMLParser, response.text) logging.debug("Authentication response received.") @@ -435,4 +519,4 @@ async def authenticate( logging.info(f"Authentication process for user={username} completed successfully.") return result finally: - await _close_client_quietly(client) + await _close_client_quietly(client, self._metrics) diff --git a/tests/unit/test_metrics_endpoints.py b/tests/unit/test_metrics_endpoints.py index b7074ce..bd0dad9 100644 --- a/tests/unit/test_metrics_endpoints.py +++ b/tests/unit/test_metrics_endpoints.py @@ -56,14 +56,34 @@ def test_json_format_shape(client): "startTimeSeconds", "uptimeSeconds", "requests", + "requestsInFlight", "latency", "authentication", + "authenticationResults", "responsesByStatus", "requestsByRoute", "errorsByType", + "failuresByFault", + "validationErrorsByField", + "profileParseErrors", + "upstream", + "csrfCache", + "csrfRefreshes", + "prefetchTasks", + "httpClients", + "lifespanEvents", } +def test_every_metric_family_appears_in_both_views(client): + """The two views are built from one snapshot, so neither may quietly omit a family.""" + from app.metrics.collector import FAMILIES + + prometheus = client.get("/metrics").text + for family in FAMILIES: + assert f"# TYPE {family.name} " in prometheus, family.name + + def test_a_request_is_reflected_in_both_views(client): client.get("/health") assert 'pesu_auth_route_requests_total{method="GET",route="/health"} 1' in client.get("/metrics").text @@ -165,3 +185,60 @@ def test_latency_is_recorded_for_a_route(client): route = client.get("/metrics?fmt=json").json()["requestsByRoute"]["GET /health"] assert route["latency"]["count"] == 1 assert route["latency"]["averageSeconds"] >= 0 + + +@patch("app.app.pesu_academy.authenticate") +def test_authentication_outcomes_are_recorded_by_reason(mock_authenticate, client): + """errors_total says which class was raised; this says what it meant for the login attempt.""" + from app.exceptions.authentication import ProfileFetchError + + mock_authenticate.side_effect = AuthenticationError() + client.post("/authenticate", json={"username": "u", "password": "p"}) + mock_authenticate.side_effect = ProfileFetchError() + client.post("/authenticate", json={"username": "u", "password": "p", "profile": True}) + mock_authenticate.side_effect = None + mock_authenticate.return_value = {"status": True, "message": "Login successful."} + client.post("/authenticate", json={"username": "u", "password": "p"}) + + results = client.get("/metrics?fmt=json").json()["authenticationResults"] + assert results == {"invalid_credentials": 1, "profile_fetch_error": 1, "success": 1} + + +@patch("app.app.pesu_academy.authenticate") +def test_an_unexpected_error_is_recorded_as_internal(mock_authenticate, client): + mock_authenticate.side_effect = RuntimeError("something else entirely") + client.post("/authenticate", json={"username": "u", "password": "p"}) + assert client.get("/metrics?fmt=json").json()["authenticationResults"] == {"internal_error": 1} + + +def test_validation_errors_are_recorded_by_field(client): + client.post("/authenticate", json={"password": "p"}) + client.post("/authenticate", json={"username": "u"}) + client.get("/metrics?fmt=xml") + fields = client.get("/metrics?fmt=json").json()["validationErrorsByField"] + assert fields == {"username": 1, "password": 1, "fmt": 1} + + +def test_an_unknown_field_collapses_into_one_bucket(client): + """The body is caller-controlled, so the label set must be closed against arbitrary keys.""" + client.post("/authenticate", json={"username": "u", "password": "p", "surprise": 1}) + assert client.get("/metrics?fmt=json").json()["validationErrorsByField"] == {"other": 1} + + +@patch("app.app.pesu_academy.authenticate") +def test_failures_are_attributed_to_client_or_server(mock_authenticate, client): + mock_authenticate.side_effect = AuthenticationError() + client.post("/authenticate", json={"username": "u", "password": "p"}) + client.get("/raiseUnhandledForMetrics") + assert client.get("/metrics?fmt=json").json()["failuresByFault"] == {"client": 1, "server": 1} + + +def test_in_flight_accounts_for_the_gap_in_the_totals(client): + """total exceeds success + failed only by what is still being served -- here, this request.""" + body = client.get("/metrics?fmt=json").json() + assert body["requestsInFlight"] == 1 + assert body["requests"]["total"] == body["requests"]["success"] + body["requests"]["failed"] + 1 + + +def test_lifespan_startup_is_recorded(client): + assert client.get("/metrics?fmt=json").json()["lifespanEvents"] == {"startup": 1} diff --git a/tests/unit/test_metrics_instrumentation.py b/tests/unit/test_metrics_instrumentation.py new file mode 100644 index 0000000..d9d0322 --- /dev/null +++ b/tests/unit/test_metrics_instrumentation.py @@ -0,0 +1,160 @@ +"""Tests that the instrumentation records what it claims, path by path.""" + +from unittest.mock import AsyncMock, patch + +import pytest + +from app.exceptions.authentication import CSRFTokenError, ProfileFetchError, ProfileParseError +from app.metrics.collector import ( + CSRF_CACHE, + HTTP_CLIENTS, + PREFETCH_TASKS, + PROFILE_PARSE_ERRORS, + UPSTREAM_LATENCY, + UPSTREAM_REQUESTS, + UPSTREAM_RESPONSES, + MetricsCollector, +) +from app.pesu import PESUAcademy + + +@pytest.fixture +def collector(): + return MetricsCollector(clock=lambda: 1000.0) + + +@pytest.fixture +def pesu(collector): + return PESUAcademy(collector) + + +def _response(text="", status=200): + response = AsyncMock() + response.text = text + response.status_code = status + return response + + +@pytest.mark.asyncio +@patch("app.pesu.httpx2.AsyncClient.get") +async def test_a_csrf_fetch_records_the_upstream_call(mock_get, pesu, collector): + mock_get.return_value = _response('') + await pesu._fetch_new_client_with_csrf_token() + snapshot = collector.snapshot() + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="csrf_fetch", outcome="success") == 1.0 + assert snapshot.value(UPSTREAM_RESPONSES.name, operation="csrf_fetch", status="200") == 1.0 + assert snapshot.value(f"{UPSTREAM_LATENCY.name}_count", operation="csrf_fetch") == 1.0 + assert snapshot.value(HTTP_CLIENTS.name, event="created") == 1.0 + + +@pytest.mark.asyncio +@patch("app.pesu.httpx2.AsyncClient.get") +async def test_a_failing_csrf_fetch_is_recorded_as_an_error(mock_get, pesu, collector): + """A timeout or connection failure never produces a status, so outcome is the only signal.""" + mock_get.side_effect = RuntimeError("upstream down") + with pytest.raises(RuntimeError): + await pesu._fetch_new_client_with_csrf_token() + snapshot = collector.snapshot() + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="csrf_fetch", outcome="error") == 1.0 + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="csrf_fetch", outcome="success") == 0.0 + assert list(snapshot.samples(UPSTREAM_RESPONSES.name)) == [] + + +@pytest.mark.asyncio +@patch("app.pesu.httpx2.AsyncClient.get") +async def test_a_missing_csrf_tag_still_counts_the_call_as_a_success(mock_get, pesu, collector): + """The call reached PESU and got a 200; it is our parsing that failed, not the upstream.""" + mock_get.return_value = _response("no token here") + with pytest.raises(CSRFTokenError): + await pesu._fetch_new_client_with_csrf_token() + snapshot = collector.snapshot() + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="csrf_fetch", outcome="success") == 1.0 + # The client could not be handed to anyone, so it must have been closed + assert snapshot.value(HTTP_CLIENTS.name, event="closed") == 1.0 + + +@pytest.mark.asyncio +@patch("app.pesu.PESUAcademy._fetch_new_client_with_csrf_token") +async def test_a_warm_cache_is_recorded_as_a_hit(mock_fetch, pesu, collector): + mock_fetch.return_value = (AsyncMock(), "token") + pesu._client, pesu._csrf_token = AsyncMock(), "cached" + await pesu._get_client_with_csrf_token() + assert collector.snapshot().value(CSRF_CACHE.name, outcome="hit") == 1.0 + + +@pytest.mark.asyncio +@patch("app.pesu.PESUAcademy._fetch_new_client_with_csrf_token") +async def test_a_cold_cache_is_recorded_as_a_miss(mock_fetch, pesu, collector): + """A miss means the caller waited on the upstream round trip the prefetch exists to avoid.""" + mock_fetch.return_value = (AsyncMock(), "token") + await pesu._get_client_with_csrf_token() + assert collector.snapshot().value(CSRF_CACHE.name, outcome="miss") == 1.0 + + +@pytest.mark.asyncio +@patch("app.pesu.PESUAcademy._fetch_new_client_with_csrf_token") +async def test_a_successful_prefetch_is_recorded(mock_fetch, pesu, collector): + import asyncio + + mock_fetch.return_value = (AsyncMock(), "token") + pesu._spawn_prefetch_task() + await asyncio.gather(*tuple(pesu._prefetch_tasks), return_exceptions=True) + await asyncio.sleep(0) + assert collector.snapshot().value(PREFETCH_TASKS.name, outcome="success") == 1.0 + + +@pytest.mark.asyncio +@patch("app.pesu.PESUAcademy._fetch_new_client_with_csrf_token") +async def test_a_failed_prefetch_is_recorded(mock_fetch, pesu, collector): + import asyncio + + mock_fetch.side_effect = RuntimeError("upstream down") + pesu._spawn_prefetch_task() + await asyncio.gather(*tuple(pesu._prefetch_tasks), return_exceptions=True) + await asyncio.sleep(0) + assert collector.snapshot().value(PREFETCH_TASKS.name, outcome="failure") == 1.0 + + +@pytest.mark.asyncio +async def test_closing_a_client_is_recorded(pesu, collector): + client = AsyncMock() + pesu._client = client + await pesu.close_client() + assert collector.snapshot().value(HTTP_CLIENTS.name, event="closed") == 1.0 + + +@pytest.mark.asyncio +async def test_a_client_that_refuses_to_close_is_recorded(pesu, collector): + """created minus closed is the leak indicator, so a failed close cannot be counted as a close.""" + client = AsyncMock() + client.aclose.side_effect = RuntimeError("refused") + pesu._client = client + await pesu.close_client() + snapshot = collector.snapshot() + assert snapshot.value(HTTP_CLIENTS.name, event="close_failed") == 1.0 + assert snapshot.value(HTTP_CLIENTS.name, event="closed") == 0.0 + + +@pytest.mark.asyncio +async def test_a_profile_fetch_records_its_upstream_call(pesu, collector): + client = AsyncMock() + client.get.return_value = _response("", status=500) + with pytest.raises(ProfileFetchError): + await pesu.get_profile_information(client, "user") + snapshot = collector.snapshot() + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="profile_fetch", outcome="success") == 1.0 + assert snapshot.value(UPSTREAM_RESPONSES.name, operation="profile_fetch", status="500") == 1.0 + + +@pytest.mark.asyncio +async def test_an_unparseable_profile_page_records_a_reason(pesu, collector): + client = AsyncMock() + client.get.return_value = _response("nothing useful") + with pytest.raises(ProfileParseError): + await pesu.get_profile_information(client, "user") + assert collector.snapshot().value(PROFILE_PARSE_ERRORS.name, reason="page_structure") == 1.0 + + +def test_a_bare_pesu_academy_still_works(): + """Tests and scripts construct PESUAcademy() directly; it must not require a collector.""" + assert PESUAcademy()._metrics is not None diff --git a/tests/unit/test_metrics_model.py b/tests/unit/test_metrics_model.py index f656671..6302930 100644 --- a/tests/unit/test_metrics_model.py +++ b/tests/unit/test_metrics_model.py @@ -111,3 +111,57 @@ def test_average_seconds_is_present_and_null_rather_than_omitted(collector): """Consumers get a stable shape: the key exists on a fresh process rather than appearing later.""" dumped = MetricsModel.from_snapshot(collector.snapshot()).model_dump(by_alias=True) assert dumped["latency"]["averageSeconds"] is None + + +def test_upstream_operations_are_grouped(collector): + """Calls, failures, latency and upstream status codes gather under one key per operation.""" + from app.metrics.collector import UPSTREAM_LATENCY, UPSTREAM_REQUESTS, UPSTREAM_RESPONSES + + collector.increment(UPSTREAM_REQUESTS, operation="login", outcome="success") + collector.increment(UPSTREAM_REQUESTS, operation="login", outcome="error") + collector.increment(UPSTREAM_RESPONSES, operation="login", status="200") + collector.observe(UPSTREAM_LATENCY, 0.4, operation="login") + collector.increment(UPSTREAM_REQUESTS, operation="csrf_fetch", outcome="success") + + upstream = MetricsModel.from_snapshot(collector.snapshot()).upstream + assert set(upstream) == {"login", "csrf_fetch"} + assert upstream["login"].success == 1 + assert upstream["login"].error == 1 + assert upstream["login"].responses_by_status == {"200": 1} + assert upstream["login"].latency.average_seconds == 0.4 + # An operation that raised before any response has no status codes, and must not be dropped + assert upstream["csrf_fetch"].responses_by_status == {} + assert upstream["csrf_fetch"].error == 0 + + +def test_single_label_families_collapse_to_mappings(collector): + from app.metrics.collector import ( + AUTHENTICATION_RESULTS, + CSRF_CACHE, + FAILURES_BY_FAULT, + HTTP_CLIENTS, + PROFILE_PARSE_ERRORS, + VALIDATION_ERRORS, + ) + + collector.increment(FAILURES_BY_FAULT, fault="client") + collector.increment(VALIDATION_ERRORS, field="username") + collector.increment(AUTHENTICATION_RESULTS, result="invalid_credentials") + collector.increment(PROFILE_PARSE_ERRORS, reason="unknown_field") + collector.increment(CSRF_CACHE, outcome="hit") + collector.increment(HTTP_CLIENTS, event="created") + + model = MetricsModel.from_snapshot(collector.snapshot()) + assert model.failures_by_fault == {"client": 1} + assert model.validation_errors_by_field == {"username": 1} + assert model.authentication_results == {"invalid_credentials": 1} + assert model.profile_parse_errors == {"unknown_field": 1} + assert model.csrf_cache == {"hit": 1} + assert model.http_clients == {"created": 1} + + +def test_in_flight_is_reported(collector): + from app.metrics.collector import REQUESTS_IN_FLIGHT + + collector.increment(REQUESTS_IN_FLIGHT) + assert MetricsModel.from_snapshot(collector.snapshot()).requests_in_flight == 1 From 688eb006452f399f951ab2937bae2a0b1c601c60 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:51:24 -0500 Subject: [PATCH 12/17] fix: stop the CSRF refresh loop fetching a second token at startup Found by the metrics added in the previous commit. An idle process, seconds after boot, reported two `csrf_fetch` calls and two clients created with one already closed: upstream.csrf_fetch.success 2 httpClients {created: 2, closed: 1} `lifespan` prefetches a client and caches it, then starts the refresh loop -- which refreshed *immediately* on its first iteration, fetching a second token and discarding the one just prefetched. Every startup paid an extra upstream round trip for a client it threw away, and on Render, which restarts often, that is every restart. The loop now sleeps before its first refresh, which is all it was ever meant to do: lifespan primes the cache, the loop keeps it fresh afterwards. One fetch, one client, none discarded. The same class of waste as the duplicate prefetch fixed in #156, and invisible for the same reason -- nothing counted the upstream calls. It took about two minutes for the new metrics to surface it, which is a fair argument for them. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/app.py | 5 ++++- tests/unit/test_app_unit.py | 21 ++++++++++++++++++++- 2 files changed, 24 insertions(+), 2 deletions(-) diff --git a/app/app.py b/app/app.py index 1c94ec4..7e65d39 100644 --- a/app/app.py +++ b/app/app.py @@ -71,6 +71,10 @@ async def _refresh_csrf_token() -> None: async def _csrf_token_refresh_loop() -> None: """Background task to refresh the CSRF token periodically.""" while True: + # Sleep first. `lifespan` has already primed the cache by the time this task starts, so + # refreshing immediately would fetch a second token and throw away the one just prefetched + # -- an extra upstream round trip on every single startup. + await asyncio.sleep(CSRF_TOKEN_REFRESH_INTERVAL_SECONDS) try: logging.debug("Refreshing unauthenticated CSRF token...") await _refresh_csrf_token() @@ -79,7 +83,6 @@ async def _csrf_token_refresh_loop() -> None: logging.exception("Failed to refresh unauthenticated CSRF token in the background.") else: metrics.increment(CSRF_REFRESHES, outcome="success") - await asyncio.sleep(CSRF_TOKEN_REFRESH_INTERVAL_SECONDS) @asynccontextmanager diff --git a/tests/unit/test_app_unit.py b/tests/unit/test_app_unit.py index bfcb603..bcccfa2 100644 --- a/tests/unit/test_app_unit.py +++ b/tests/unit/test_app_unit.py @@ -53,7 +53,8 @@ def test_authenticate_general_exception(mock_authenticate, client): @patch("app.app._refresh_csrf_token") async def test_csrf_token_refresh_loop_logs_exception_on_failure(mock_refresh, mock_sleep, caplog): mock_refresh.side_effect = RuntimeError("Simulated CSRF refresh failure") - mock_sleep.side_effect = asyncio.CancelledError + # The loop sleeps before its first refresh, so let the first sleep pass and stop it on the next + mock_sleep.side_effect = [None, asyncio.CancelledError] with caplog.at_level("ERROR"): with pytest.raises(asyncio.CancelledError): @@ -62,6 +63,24 @@ async def test_csrf_token_refresh_loop_logs_exception_on_failure(mock_refresh, m assert "Failed to refresh unauthenticated CSRF token in the background." in caplog.text +@pytest.mark.asyncio +@patch("asyncio.sleep", new_callable=AsyncMock) +@patch("app.app._refresh_csrf_token") +async def test_csrf_token_refresh_loop_waits_before_its_first_refresh(mock_refresh, mock_sleep): + """lifespan has already primed the cache when this task starts. + + Refreshing immediately fetched a second token and discarded the one just prefetched -- an extra + upstream round trip on every startup. Caught by the new upstream metrics showing two csrf_fetch + calls on an idle process. + """ + mock_sleep.side_effect = asyncio.CancelledError + + with pytest.raises(asyncio.CancelledError): + await _csrf_token_refresh_loop() + + mock_refresh.assert_not_awaited() + + def test_lifespan_logs_a_refresh_task_that_refuses_to_cancel(caplog): """A background task that fails its own cancellation is reported, not swallowed at shutdown.""" From 4f9f77012c4cc1f512809a1060a9b67f380ed0fd Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 20:54:12 -0500 Subject: [PATCH 13/17] docs: describe the full metric set, and bump to 4.3.0 README gains a table of what is measured, grouped by area, and a note on the two most useful entries: `upstream`, because it is the only dependency this service has and its latency is measured separately from the API's own, so a slow request can be attributed rather than guessed at; and `httpClients`, where created minus closed is the leak indicator and should sit at one at rest. Minor: new functionality, existing APIs unchanged. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- README.md | 20 +++++++++++++++++++- pyproject.toml | 2 +- tests/unit/test_app_unit.py | 17 +++++++++++++++++ uv.lock | 2 +- 4 files changed, 38 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 88e001c..d0f7aba 100644 --- a/README.md +++ b/README.md @@ -177,10 +177,28 @@ pesu_auth_responses_total{status="200"} 1094 pesu_auth_responses_total{status="401"} 160 ``` +#### What is measured + +| Area | Metrics | +| --------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Traffic | requests received, succeeded, failed, in flight; responses by status; requests and latency per route | +| Fault | failures split into `client` (4xx) and `server` (5xx), so an alert can fire on only our own faults | +| Errors | errors by exception class, and validation failures by the field that failed | +| Authentication | requests split by whether profile data was asked for, and results by outcome: `success`, `invalid_credentials`, `csrf_token_error`, `profile_fetch_error`, `profile_parse_error`, `internal_error` | +| Profile parsing | failures by what could not be parsed: `key_missing`, `value_missing`, `unknown_field`, `page_structure`, `no_data`, `unknown_campus_code` | +| Upstream | every call to PESU Academy ā€” `csrf_fetch`, `login`, `profile_fetch` ā€” with count, outcome, latency and the upstream status code | +| Internals | CSRF cache hit/miss, background refresh outcomes, prefetch task outcomes, HTTP client lifecycle, lifespan events | + +`upstream` is the one to look at first when the API is slow: it is the only dependency this service has, and its +latency is measured separately from the API's own, so a slow request can be attributed to PESU Academy rather than +guessed at. `httpClients` is the leak indicator ā€” `created` minus `closed` is how many are still open, which should be +one (the prefetched client) at rest. + The counters live in memory and **reset when the process restarts**, which is why `pesu_auth_process_start_time_seconds` is exposed: without it a dashboard cannot tell a restart from a drop in traffic. Status codes and exception classes are recorded separately, so errors that share a status code ā€” `CSRFTokenError` and -`ProfileFetchError` are both `502` ā€” stay distinguishable. +`ProfileFetchError` are both `502` ā€” stay distinguishable, and `authenticationResults` records the same failures in the +vocabulary you would ask questions in. Requests to `/metrics` are themselves counted. Excluding them would mean the endpoint reported a request total that did not match the sum of its own response counts. diff --git a/pyproject.toml b/pyproject.toml index 279670f..b07d09b 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "pesu-auth" -version = "4.2.0" +version = "4.3.0" description = "A simple API to authenticate PESU credentials using PESU Academy." readme = "README.md" requires-python = ">=3.14" diff --git a/tests/unit/test_app_unit.py b/tests/unit/test_app_unit.py index bcccfa2..5e7801b 100644 --- a/tests/unit/test_app_unit.py +++ b/tests/unit/test_app_unit.py @@ -81,6 +81,23 @@ async def test_csrf_token_refresh_loop_waits_before_its_first_refresh(mock_refre mock_refresh.assert_not_awaited() +@pytest.mark.asyncio +@patch("asyncio.sleep", new_callable=AsyncMock) +@patch("app.app._refresh_csrf_token") +async def test_csrf_token_refresh_loop_records_a_successful_refresh(mock_refresh, mock_sleep, monkeypatch): + from app.metrics import CSRF_REFRESHES, MetricsCollector + + collector = MetricsCollector() + monkeypatch.setattr("app.app.metrics", collector) + mock_sleep.side_effect = [None, asyncio.CancelledError] + + with pytest.raises(asyncio.CancelledError): + await _csrf_token_refresh_loop() + + mock_refresh.assert_awaited_once() + assert collector.snapshot().value(CSRF_REFRESHES.name, outcome="success") == 1.0 + + def test_lifespan_logs_a_refresh_task_that_refuses_to_cancel(caplog): """A background task that fails its own cancellation is reported, not swallowed at shutdown.""" diff --git a/uv.lock b/uv.lock index 38e3654..7f9bc05 100644 --- a/uv.lock +++ b/uv.lock @@ -630,7 +630,7 @@ wheels = [ [[package]] name = "pesu-auth" -version = "4.2.0" +version = "4.3.0" source = { editable = "." } dependencies = [ { name = "fastapi" }, From 25a7a9af4fd2fee7158d3ad23f8c723ef50b9c6c Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 21:15:47 -0500 Subject: [PATCH 14/17] fix: three defects found in review, and complete the documentation ## Defects **`requests_in_flight` leaked on every client disconnect.** The decrement sat in the two branches of the middleware rather than in a `finally`, and `except Exception` does not catch `CancelledError` -- so an abandoned request incremented the gauge and never decremented it. On a real server it would have climbed forever, and it is the number documented as explaining the gap between `total` and `success + failed`, so it would have actively misled. The cancellation test asserted total, success and failed but not the gauge, which is why it passed; it now asserts the gauge and fails against the old code. **A label could shadow a positional parameter.** `increment(family, value=...)` and `observe(family, seconds=...)` took their amount as an ordinary parameter, so a family declaring a label named `value` or `seconds` would have had it silently captured as the amount. Both are positional-only now, which immediately caught a test relying on exactly that ambiguity. **A cancelled upstream call was counted as an upstream error.** A disconnect or a shutdown is not PESU Academy failing. It has its own outcome now, so the error rate does not spike on every deploy -- precisely when someone is looking. Also closes the last uninstrumented branch: `profile_field_filtering_total` records whether a caller's field list actually narrowed the response, measured at the branch rather than from the request body, so a caller passing exactly the default list counts as no filtering. `app/metrics/__init__.py` drops its re-export list, which had to be edited every time a family was added; modules are imported directly, as `app.exceptions` already does. ## Documentation **Swagger documented a response that cannot happen.** FastAPI adds a 422 carrying its own `HTTPValidationError` body to every route whose parameters can fail validation -- but this API converts every `RequestValidationError` into a **400** with the same `{status, message, timestamp}` body as every other error. `/metrics` advertised a status it never returns, in a shape it never emits. The schema is now built through an override that drops those, matched on their schema so `/authenticate`'s real 422 (a profile parse failure, using this API's own response model) is kept. `HTTPValidationError` and `ValidationError` go with them. Every response on every route now carries both an example and a schema, which the `/readme` 308 and the `/metrics` text/plain body previously lacked. The `/metrics` examples were hand-written and had drifted; both are generated from a real snapshot now, so the JSON example is complete and round-trips through `MetricsModel`. `tests/unit/test_openapi_docs.py` makes the documentation self-checking: every route documents a success and a 500, every response has an example and a schema, every JSON example validates against the model it claims, the request examples cover all three username forms plus profile and field filtering, and the documented 400, 401 and 200 bodies are compared against real responses. It found both defects above. Validation runs in JSON mode rather than Python mode deliberately -- the models are strict, and strict Python-mode rejects the ISO *string* these responses carry in `timestamp`; JSON mode is the mode a caller parsing the body is in. The two test-only exception routes are now `include_in_schema=False`; they were appearing in the published schema whenever their module was imported. **README** gains a full metrics reference: how collection works and which of the three layers records what, the two accounting identities that hold at all times, the definitions that are easy to assume wrongly (latency is time to response *start*; success is below 400, not 300; summaries expose sum and count, not quantiles; scrapes count themselves), a table explaining every metric, and complete generated examples of both formats. 232 tests, 100% coverage. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- README.md | 407 ++++++++++++++++++--- app/app.py | 46 ++- app/docs/metrics.py | 115 +++++- app/docs/readme.py | 3 +- app/metrics/__init__.py | 41 +-- app/metrics/collector.py | 18 +- app/metrics/middleware.py | 7 +- app/models/metrics.py | 19 +- app/pesu.py | 14 +- tests/integration/test_app_integration.py | 2 +- tests/unit/test_app_unit.py | 2 +- tests/unit/test_metrics_collector.py | 17 + tests/unit/test_metrics_endpoints.py | 3 +- tests/unit/test_metrics_instrumentation.py | 82 +++++ tests/unit/test_metrics_middleware.py | 23 ++ tests/unit/test_metrics_model.py | 22 +- tests/unit/test_openapi_docs.py | 193 ++++++++++ 17 files changed, 911 insertions(+), 103 deletions(-) create mode 100644 tests/unit/test_openapi_docs.py diff --git a/README.md b/README.md index d0f7aba..e3ad4ab 100644 --- a/README.md +++ b/README.md @@ -166,64 +166,381 @@ does not take any request parameters. ### `/metrics` -This endpoint exposes counters describing the traffic this process has served, in the -[Prometheus text exposition format](https://prometheus.io/docs/instrumenting/exposition_formats/) by default, ready -to be scraped, or as JSON with `?fmt=json`. +This endpoint exposes counters describing the traffic this process has served and the work it did to serve it. It takes +no request parameters other than the format selector below. +#### Query Parameters + +| **Field** | **Type** | **Description** | +| --------- | -------- | -------------------------------------------------------------------------------------- | +| `fmt` | `str` | `prometheus` (default) for the text exposition format, or `json` for the same counters | + +The default is `prometheus` because that is what a scraper pointed at this path expects. An unrecognised value is a +`400`, like any other validation failure. + +```bash +curl http://localhost:5000/metrics # Prometheus text, for a scraper +curl http://localhost:5000/metrics?fmt=json | jq # the same numbers, for a human ``` + +#### How collection works + +Everything is counted **in this process, in memory**. There is no database and no external dependency, and the counters +**reset to zero when the process restarts** ā€” which on the hosted environments is often. `processStartTimeSeconds` is +exposed so a dashboard can tell a restart apart from a drop in traffic; in PromQL, `rate()` already handles counter +resets, and `pesu_auth_process_start_time_seconds` makes the restart itself visible. + +Collection happens at three layers, and which layer records what is deliberate: + +| Layer | What it records | Why there | +| ---------------------- | ----------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| **HTTP middleware** | request counts, status codes, matched route, latency, in-flight | It is the only place that sees every request, including ones that never reach a route | +| **Exception handlers** | the error's exception class | The middleware sees a status code; only the handler knows which class produced it. `CSRFTokenError` and `ProfileFetchError` are both `502`, and the class is the only thing that tells them apart | +| **`app/pesu.py`** | upstream calls, CSRF cache, prefetch tasks, client lifecycle, profile parsing | These are not HTTP requests to this API at all, so nothing above could see them | + +The middleware and the handlers write to **different metric families**, so a single failed request contributes exactly +one status sample and exactly one error sample ā€” never two of either. + +Two accounting rules hold at all times, and are the quickest way to tell whether the numbers are trustworthy: + +``` +requests.success + requests.failed + requestsInFlight == requests.total +sum(responsesByStatus) == requests.success + requests.failed +``` + +`sum(errorsByType)` is normally **less** than `requests.failed`: a `404` or `405` is produced by the router, so no +exception handler of ours runs for it. + +A few definitions that are easy to assume wrongly: + +- **Latency is time to response *start***, not full request duration. The middleware measures up to the point the + response begins; the body streams afterwards. It uses a monotonic clock, so an NTP correction cannot corrupt the sum. +- **Success means a status below 400**, not below 300. `/readme` answers `308`, and that is the endpoint working. +- **Summaries expose `_sum` and `_count`, not quantiles.** Compute a mean with + `rate(pesu_auth_request_latency_seconds_sum[5m]) / rate(pesu_auth_request_latency_seconds_count[5m])`. +- **Scrapes of `/metrics` count themselves.** Excluding them would break the accounting rules above; subtract + `pesu_auth_route_requests_total{route="/metrics"}` if you need traffic without them. +- **A cancelled request is not recorded as an outcome.** If a caller disconnects, `requests.total` has already counted + it but no status ever exists, so `total` legitimately exceeds `success + failed + inFlight` by the number abandoned. + +#### What each metric means + +**Traffic** + +| Metric | Meaning | +| ------------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `requests_total` | Requests received, counted on arrival | +| `requests_success_total` | Answered with a status below 400 | +| `requests_failed_total` | Answered with a status of 400 or above | +| `requests_in_flight` | Received but not yet answered. A gauge; it is what explains the gap in the totals | +| `responses_total{status}` | Responses by HTTP status code | +| `route_requests_total{method,route}` | Requests by matched route template and method. Never the raw path, so an unmatched path becomes `` rather than a new series per probe, and an unknown verb becomes `` | +| `request_latency_seconds` | Time to response start, all routes | +| `route_latency_seconds{method,route}` | The same, per route | + +**Failures** + +| Metric | Meaning | +| -------------------------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `failures_total{fault}` | Failed requests by whose fault it was: `client` for 4xx, `server` for 5xx. Alert on `server` without enumerating status codes | +| `errors_total{type}` | Errors rendered by an exception handler, by exception class: `AuthenticationError`, `CSRFTokenError`, `ProfileFetchError`, `ProfileParseError`, `RequestValidationError`, or whatever reached the catch-all | +| `validation_errors_total{field}` | Request validation failures by the field that failed. Unrecognised keys collapse into `other`, since the request body is caller-controlled | + +**Authentication** + +| Metric | Meaning | +| ---------------------------------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `authentication_requests_total{profile}` | Authentication requests, split by whether profile data was asked for | +| `authentication_results_total{result}` | Attempts by outcome: `success`, `invalid_credentials`, `csrf_token_error`, `profile_fetch_error`, `profile_parse_error`, `internal_error`. This is the one to read for "why are logins failing" | +| `profile_field_filtering_total{enabled}` | Profile fetches, split by whether the caller narrowed the returned fields. Recorded where the branch is taken, so a caller passing exactly the default list counts as `false` | +| `profile_parse_errors_total{reason}` | Parse failures by what broke: `key_missing`, `value_missing`, `unknown_field`, `page_structure`, `no_data`, `unknown_campus_code`. These mean PESU Academy's page changed | + +**Upstream (PESU Academy)** + +PESU Academy is the only dependency this service has, and the only thing that can be slow or down. Its latency is +measured separately from the API's own, so a slow request can be attributed rather than guessed at. Three operations: +`csrf_fetch` (the pre-login token), `login`, and `profile_fetch`. + +| Metric | Meaning | +| -------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `upstream_requests_total{operation,outcome}` | Calls by outcome: `success`, `error` (raised, including timeouts), `cancelled` (we walked away ā€” a disconnect or a shutdown, deliberately *not* counted as an error) | +| `upstream_responses_total{operation,status}` | The status code PESU Academy returned | +| `upstream_latency_seconds{operation}` | Seconds spent waiting on each operation | + +A wrong password counts as a **successful** `login` call: PESU answered with a `200` and a login form. The call worked; +the credentials did not. Likewise a missing CSRF tag is a successful `csrf_fetch` ā€” the fetch worked and our parsing of +it did not. + +**Internals** + +| Metric | Meaning | +| ------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `csrf_cache_total{outcome}` | `hit` or `miss` on the prefetched CSRF client. A miss means a caller waited on the upstream round trip the prefetch exists to avoid, so the hit rate is how well the prefetch is working | +| `csrf_refreshes_total{outcome}` | The periodic background token refresh, by outcome | +| `prefetch_tasks_total{outcome}` | Background prefetch tasks: `success`, `failure`, `cancelled`. A failure is not fatal ā€” the cache stays empty and the next request fetches inline | +| `http_clients_total{event}` | `created`, `closed`, `close_failed`. **`created` minus `closed` is how many are still open**, which should be `1` at rest ā€” the prefetched client. A number that climbs is a connection-pool leak | +| `lifespan_events_total{event}` | `startup` and `shutdown` seen by this process | +| `process_start_time_seconds` | Start time since the Unix epoch. A gauge, so restarts are visible | + +#### Prometheus response + +
+Full example (fmt=prometheus) + +``` +# HELP pesu_auth_requests_total HTTP requests received. +# TYPE pesu_auth_requests_total counter +pesu_auth_requests_total 1284 +# HELP pesu_auth_requests_success_total HTTP requests answered with a status below 400. +# TYPE pesu_auth_requests_success_total counter +pesu_auth_requests_success_total 1102 +# HELP pesu_auth_requests_failed_total HTTP requests answered with a status of 400 or above. +# TYPE pesu_auth_requests_failed_total counter +pesu_auth_requests_failed_total 182 # HELP pesu_auth_responses_total HTTP responses, by status code. # TYPE pesu_auth_responses_total counter pesu_auth_responses_total{status="200"} 1094 +pesu_auth_responses_total{status="308"} 8 +pesu_auth_responses_total{status="400"} 12 pesu_auth_responses_total{status="401"} 160 +pesu_auth_responses_total{status="500"} 4 +pesu_auth_responses_total{status="502"} 6 +# HELP pesu_auth_route_requests_total HTTP requests, by matched route and method. +# TYPE pesu_auth_route_requests_total counter +pesu_auth_route_requests_total{method="GET",route="/health"} 302 +pesu_auth_route_requests_total{method="POST",route="/authenticate"} 774 +# HELP pesu_auth_errors_total Errors rendered by an exception handler, by exception class. +# TYPE pesu_auth_errors_total counter +pesu_auth_errors_total{type="AuthenticationError"} 160 +pesu_auth_errors_total{type="RequestValidationError"} 12 +# HELP pesu_auth_authentication_requests_total Authentication requests, by whether profile data was requested. +# TYPE pesu_auth_authentication_requests_total counter +pesu_auth_authentication_requests_total{profile="false"} 640 +pesu_auth_authentication_requests_total{profile="true"} 134 +# HELP pesu_auth_authentication_results_total Authentication attempts, by outcome. +# TYPE pesu_auth_authentication_results_total counter +pesu_auth_authentication_results_total{result="invalid_credentials"} 160 +pesu_auth_authentication_results_total{result="profile_fetch_error"} 2 +pesu_auth_authentication_results_total{result="success"} 612 +# HELP pesu_auth_profile_field_filtering_total Profile fetches, by whether the caller narrowed the fields returned. +# TYPE pesu_auth_profile_field_filtering_total counter +pesu_auth_profile_field_filtering_total{enabled="false"} 94 +pesu_auth_profile_field_filtering_total{enabled="true"} 40 +# HELP pesu_auth_profile_parse_errors_total Profile page parse failures, by what could not be parsed. +# TYPE pesu_auth_profile_parse_errors_total counter +pesu_auth_profile_parse_errors_total{reason="unknown_field"} 3 +# HELP pesu_auth_validation_errors_total Request validation failures, by the field that failed. +# TYPE pesu_auth_validation_errors_total counter +pesu_auth_validation_errors_total{field="password"} 4 +pesu_auth_validation_errors_total{field="username"} 8 +# HELP pesu_auth_failures_total Failed requests, by whose fault it was: the caller's (4xx) or ours (5xx). +# TYPE pesu_auth_failures_total counter +pesu_auth_failures_total{fault="client"} 172 +pesu_auth_failures_total{fault="server"} 10 +# HELP pesu_auth_request_latency_seconds Seconds from receiving a request to starting its response. +# TYPE pesu_auth_request_latency_seconds summary +pesu_auth_request_latency_seconds_sum 742.1841932 +pesu_auth_request_latency_seconds_count 1284 +# HELP pesu_auth_route_latency_seconds Seconds from receiving a request to starting its response, by route. +# TYPE pesu_auth_route_latency_seconds summary +pesu_auth_route_latency_seconds_sum{method="GET",route="/health"} 0.413 +pesu_auth_route_latency_seconds_sum{method="POST",route="/authenticate"} 741.2118 +pesu_auth_route_latency_seconds_count{method="GET",route="/health"} 302 +pesu_auth_route_latency_seconds_count{method="POST",route="/authenticate"} 774 +# HELP pesu_auth_upstream_requests_total Requests made to PESU Academy, by operation and outcome. +# TYPE pesu_auth_upstream_requests_total counter +pesu_auth_upstream_requests_total{operation="csrf_fetch",outcome="error"} 3 +pesu_auth_upstream_requests_total{operation="csrf_fetch",outcome="success"} 790 +pesu_auth_upstream_requests_total{operation="login",outcome="cancelled"} 1 +pesu_auth_upstream_requests_total{operation="login",outcome="error"} 2 +pesu_auth_upstream_requests_total{operation="login",outcome="success"} 774 +pesu_auth_upstream_requests_total{operation="profile_fetch",outcome="error"} 1 +pesu_auth_upstream_requests_total{operation="profile_fetch",outcome="success"} 134 +# HELP pesu_auth_upstream_responses_total Responses from PESU Academy, by operation and status code. +# TYPE pesu_auth_upstream_responses_total counter +pesu_auth_upstream_responses_total{operation="csrf_fetch",status="200"} 790 +pesu_auth_upstream_responses_total{operation="login",status="200"} 774 +pesu_auth_upstream_responses_total{operation="profile_fetch",status="200"} 134 +# HELP pesu_auth_upstream_latency_seconds Seconds spent waiting on PESU Academy, by operation. +# TYPE pesu_auth_upstream_latency_seconds summary +pesu_auth_upstream_latency_seconds_sum{operation="csrf_fetch"} 210.4 +pesu_auth_upstream_latency_seconds_sum{operation="login"} 620.4 +pesu_auth_upstream_latency_seconds_sum{operation="profile_fetch"} 190.2 +pesu_auth_upstream_latency_seconds_count{operation="csrf_fetch"} 793 +pesu_auth_upstream_latency_seconds_count{operation="login"} 776 +pesu_auth_upstream_latency_seconds_count{operation="profile_fetch"} 135 +# HELP pesu_auth_csrf_cache_total Lookups of the cached unauthenticated CSRF client, by whether the cache was warm. +# TYPE pesu_auth_csrf_cache_total counter +pesu_auth_csrf_cache_total{outcome="hit"} 760 +pesu_auth_csrf_cache_total{outcome="miss"} 14 +# HELP pesu_auth_csrf_refreshes_total Periodic background refreshes of the unauthenticated CSRF token, by outcome. +# TYPE pesu_auth_csrf_refreshes_total counter +pesu_auth_csrf_refreshes_total{outcome="failure"} 1 +pesu_auth_csrf_refreshes_total{outcome="success"} 45 +# HELP pesu_auth_prefetch_tasks_total Background CSRF prefetch tasks, by outcome. +# TYPE pesu_auth_prefetch_tasks_total counter +pesu_auth_prefetch_tasks_total{outcome="failure"} 4 +pesu_auth_prefetch_tasks_total{outcome="success"} 770 +# HELP pesu_auth_http_clients_total Upstream HTTP client lifecycle. created minus closed is how many are still open. +# TYPE pesu_auth_http_clients_total counter +pesu_auth_http_clients_total{event="closed"} 775 +pesu_auth_http_clients_total{event="created"} 776 +# HELP pesu_auth_lifespan_events_total Application lifespan events, by kind. +# TYPE pesu_auth_lifespan_events_total counter +pesu_auth_lifespan_events_total{event="startup"} 1 +# HELP pesu_auth_requests_in_flight Requests received but not yet answered. +# TYPE pesu_auth_requests_in_flight gauge +pesu_auth_requests_in_flight 1 +# HELP pesu_auth_process_start_time_seconds Start time of the process since the Unix epoch, in seconds. +# TYPE pesu_auth_process_start_time_seconds gauge +pesu_auth_process_start_time_seconds 1757660400.12 ``` -#### What is measured - -| Area | Metrics | -| --------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| Traffic | requests received, succeeded, failed, in flight; responses by status; requests and latency per route | -| Fault | failures split into `client` (4xx) and `server` (5xx), so an alert can fire on only our own faults | -| Errors | errors by exception class, and validation failures by the field that failed | -| Authentication | requests split by whether profile data was asked for, and results by outcome: `success`, `invalid_credentials`, `csrf_token_error`, `profile_fetch_error`, `profile_parse_error`, `internal_error` | -| Profile parsing | failures by what could not be parsed: `key_missing`, `value_missing`, `unknown_field`, `page_structure`, `no_data`, `unknown_campus_code` | -| Upstream | every call to PESU Academy ā€” `csrf_fetch`, `login`, `profile_fetch` ā€” with count, outcome, latency and the upstream status code | -| Internals | CSRF cache hit/miss, background refresh outcomes, prefetch task outcomes, HTTP client lifecycle, lifespan events | +
-`upstream` is the one to look at first when the API is slow: it is the only dependency this service has, and its -latency is measured separately from the API's own, so a slow request can be attributed to PESU Academy rather than -guessed at. `httpClients` is the leak indicator ā€” `created` minus `closed` is how many are still open, which should be -one (the prefetched client) at rest. +#### JSON response -The counters live in memory and **reset when the process restarts**, which is why -`pesu_auth_process_start_time_seconds` is exposed: without it a dashboard cannot tell a restart from a drop in traffic. -Status codes and exception classes are recorded separately, so errors that share a status code ā€” `CSRFTokenError` and -`ProfileFetchError` are both `502` ā€” stay distinguishable, and `authenticationResults` records the same failures in the -vocabulary you would ask questions in. +The same numbers, with labels folded into object keys ā€” `responsesByStatus` keyed by status code, `requestsByRoute` by +`"METHOD route-template"`, `errorsByType` by exception class. Latency objects add a pre-computed `averageSeconds`, +which is `null` rather than absent when nothing has been recorded yet, so the shape is stable. -Requests to `/metrics` are themselves counted. Excluding them would mean the endpoint reported a request total that did -not match the sum of its own response counts. - -#### Query Parameters +
+Full example (fmt=json) -| **Field** | **Type** | **Description** | -| --------- | -------- | -------------------------------------------------------------------------------------- | -| `fmt` | `str` | `prometheus` (default) for the text exposition format, or `json` for the same counters | +```json +{ + "startTimeSeconds": 1757660400.12, + "uptimeSeconds": 0.0, + "requests": { + "total": 1284, + "success": 1102, + "failed": 182 + }, + "latency": { + "sumSeconds": 742.1841932, + "count": 1284, + "averageSeconds": 0.5780250725856698 + }, + "authentication": { + "total": 774, + "withProfile": 134, + "withoutProfile": 640 + }, + "responsesByStatus": { + "200": 1094, + "308": 8, + "400": 12, + "401": 160, + "500": 4, + "502": 6 + }, + "requestsByRoute": { + "GET /health": { + "requests": 302, + "latency": { + "sumSeconds": 0.413, + "count": 302, + "averageSeconds": 0.0013675496688741722 + } + }, + "POST /authenticate": { + "requests": 774, + "latency": { + "sumSeconds": 741.2118, + "count": 774, + "averageSeconds": 0.957637984496124 + } + } + }, + "errorsByType": { + "AuthenticationError": 160, + "RequestValidationError": 12 + }, + "requestsInFlight": 1, + "failuresByFault": { + "client": 172, + "server": 10 + }, + "validationErrorsByField": { + "password": 4, + "username": 8 + }, + "authenticationResults": { + "invalid_credentials": 160, + "profile_fetch_error": 2, + "success": 612 + }, + "profileFieldFiltering": { + "false": 94, + "true": 40 + }, + "profileParseErrors": { + "unknown_field": 3 + }, + "upstream": { + "csrf_fetch": { + "success": 790, + "error": 3, + "cancelled": 0, + "latency": { + "sumSeconds": 210.4, + "count": 793, + "averageSeconds": 0.26532156368221943 + }, + "responsesByStatus": { + "200": 790 + } + }, + "login": { + "success": 774, + "error": 2, + "cancelled": 1, + "latency": { + "sumSeconds": 620.4, + "count": 776, + "averageSeconds": 0.7994845360824742 + }, + "responsesByStatus": { + "200": 774 + } + }, + "profile_fetch": { + "success": 134, + "error": 1, + "cancelled": 0, + "latency": { + "sumSeconds": 190.2, + "count": 135, + "averageSeconds": 1.4088888888888889 + }, + "responsesByStatus": { + "200": 134 + } + } + }, + "csrfCache": { + "hit": 760, + "miss": 14 + }, + "csrfRefreshes": { + "failure": 1, + "success": 45 + }, + "prefetchTasks": { + "failure": 4, + "success": 770 + }, + "httpClients": { + "closed": 775, + "created": 776 + }, + "lifespanEvents": { + "startup": 1 + } +} +``` -#### Response Object (`fmt=json`) - -| **Field** | **Type** | **Description** | -| ------------------- | -------- | -------------------------------------------------------------------------- | -| `startTimeSeconds` | `float` | Start time of this process since the Unix epoch. Counters reset on restart | -| `uptimeSeconds` | `float` | Seconds since this process started collecting | -| `requests` | `object` | `total`, `success` and `failed` request counts | -| `latency` | `object` | `sumSeconds`, `count` and `averageSeconds` until a response starts | -| `authentication` | `object` | `total`, `withProfile` and `withoutProfile` authentication request counts | -| `responsesByStatus` | `object` | Response counts keyed by HTTP status code | -| `requestsByRoute` | `object` | Per-route requests and latency, keyed by `"METHOD route-template"` | -| `errorsByType` | `object` | Error counts keyed by exception class name | - -`requests.total` counts a request on arrival while the outcome is recorded on completion, so `total` can briefly exceed -`success + failed` while requests are in flight. +
### `/readme` diff --git a/app/app.py b/app/app.py index 7e65d39..3fce0a8 100644 --- a/app/app.py +++ b/app/app.py @@ -8,12 +8,13 @@ import logging from contextlib import asynccontextmanager from importlib.metadata import version -from typing import TYPE_CHECKING +from typing import TYPE_CHECKING, Any from zoneinfo import ZoneInfo import uvicorn from fastapi import FastAPI from fastapi.exceptions import RequestValidationError +from fastapi.openapi.utils import get_openapi from fastapi.responses import JSONResponse, PlainTextResponse, RedirectResponse if TYPE_CHECKING: @@ -33,7 +34,7 @@ ProfileParseError, ) from app.exceptions.base import PESUAcademyError -from app.metrics import ( +from app.metrics.collector import ( AUTHENTICATION_REQUESTS, AUTHENTICATION_RESULTS, CSRF_REFRESHES, @@ -141,6 +142,47 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]: pesu_academy = PESUAcademy(metrics) +def _openapi_without_phantom_validation_errors() -> dict[str, Any]: + """Build the OpenAPI schema without the 422 responses this API can never return. + + FastAPI documents a 422 carrying its own `HTTPValidationError` body on every route whose + parameters can fail validation. This API never returns that: `validation_exception_handler` + turns every `RequestValidationError` into a **400** with the same + `{status, message, timestamp}` body as every other error. Leaving the 422 in Swagger would + document a response that cannot occur, in a shape this API never emits. + + Only the auto-generated ones are removed. `/authenticate` genuinely returns a 422 for a profile + parse failure and documents it with `ResponseModel`, so it is matched on its schema and kept. + + Returns: + dict[str, Any]: The OpenAPI schema, cached on the app after the first call. + """ + if app.openapi_schema: + return app.openapi_schema + schema = get_openapi( + title=app.title, + version=app.version, + description=app.description, + routes=app.routes, + tags=app.openapi_tags, + ) + phantom = "#/components/schemas/HTTPValidationError" + for operations in schema.get("paths", {}).values(): + for operation in operations.values(): + response = operation.get("responses", {}).get("422", {}) + content = response.get("content", {}).get("application/json", {}) + if content.get("schema", {}).get("$ref") == phantom: + del operation["responses"]["422"] + # Nothing references them once the phantom responses are gone + for name in ("HTTPValidationError", "ValidationError"): + schema.get("components", {}).get("schemas", {}).pop(name, None) + app.openapi_schema = schema + return schema + + +app.openapi = _openapi_without_phantom_validation_errors + + @app.middleware("http") async def metrics_middleware(request: Request, call_next: RequestResponseEndpoint) -> Response: """Record traffic metrics for every request.""" diff --git a/app/docs/metrics.py b/app/docs/metrics.py index c7141bb..9767e68 100644 --- a/app/docs/metrics.py +++ b/app/docs/metrics.py @@ -17,36 +17,137 @@ }, } +# One sample per family, so every metric is represented without pasting the whole payload into a +# Swagger dropdown. A real response repeats each labelled family once per label set. _PROMETHEUS_EXAMPLE = """# HELP pesu_auth_requests_total HTTP requests received. # TYPE pesu_auth_requests_total counter pesu_auth_requests_total 1284 +# HELP pesu_auth_requests_success_total HTTP requests answered with a status below 400. +# TYPE pesu_auth_requests_success_total counter +pesu_auth_requests_success_total 1102 +# HELP pesu_auth_requests_failed_total HTTP requests answered with a status of 400 or above. +# TYPE pesu_auth_requests_failed_total counter +pesu_auth_requests_failed_total 182 # HELP pesu_auth_responses_total HTTP responses, by status code. # TYPE pesu_auth_responses_total counter pesu_auth_responses_total{status="200"} 1094 -pesu_auth_responses_total{status="401"} 160 +# HELP pesu_auth_route_requests_total HTTP requests, by matched route and method. +# TYPE pesu_auth_route_requests_total counter +pesu_auth_route_requests_total{method="GET",route="/health"} 302 # HELP pesu_auth_errors_total Errors rendered by an exception handler, by exception class. # TYPE pesu_auth_errors_total counter pesu_auth_errors_total{type="AuthenticationError"} 160 +# HELP pesu_auth_authentication_requests_total Authentication requests, by whether profile data was requested. +# TYPE pesu_auth_authentication_requests_total counter +pesu_auth_authentication_requests_total{profile="false"} 640 +# HELP pesu_auth_authentication_results_total Authentication attempts, by outcome. +# TYPE pesu_auth_authentication_results_total counter +pesu_auth_authentication_results_total{result="invalid_credentials"} 160 +# HELP pesu_auth_profile_field_filtering_total Profile fetches, by whether the caller narrowed the fields returned. +# TYPE pesu_auth_profile_field_filtering_total counter +pesu_auth_profile_field_filtering_total{enabled="false"} 94 +# HELP pesu_auth_profile_parse_errors_total Profile page parse failures, by what could not be parsed. +# TYPE pesu_auth_profile_parse_errors_total counter +pesu_auth_profile_parse_errors_total{reason="unknown_field"} 3 +# HELP pesu_auth_validation_errors_total Request validation failures, by the field that failed. +# TYPE pesu_auth_validation_errors_total counter +pesu_auth_validation_errors_total{field="password"} 4 +# HELP pesu_auth_failures_total Failed requests, by whose fault it was: the caller's (4xx) or ours (5xx). +# TYPE pesu_auth_failures_total counter +pesu_auth_failures_total{fault="client"} 172 # HELP pesu_auth_request_latency_seconds Seconds from receiving a request to starting its response. # TYPE pesu_auth_request_latency_seconds summary pesu_auth_request_latency_seconds_sum 742.1841932 pesu_auth_request_latency_seconds_count 1284 +# HELP pesu_auth_route_latency_seconds Seconds from receiving a request to starting its response, by route. +# TYPE pesu_auth_route_latency_seconds summary +pesu_auth_route_latency_seconds_sum{method="GET",route="/health"} 0.413 +pesu_auth_route_latency_seconds_count{method="GET",route="/health"} 302 +# HELP pesu_auth_upstream_requests_total Requests made to PESU Academy, by operation and outcome. +# TYPE pesu_auth_upstream_requests_total counter +pesu_auth_upstream_requests_total{operation="csrf_fetch",outcome="error"} 3 +# HELP pesu_auth_upstream_responses_total Responses from PESU Academy, by operation and status code. +# TYPE pesu_auth_upstream_responses_total counter +pesu_auth_upstream_responses_total{operation="csrf_fetch",status="200"} 790 +# HELP pesu_auth_upstream_latency_seconds Seconds spent waiting on PESU Academy, by operation. +# TYPE pesu_auth_upstream_latency_seconds summary +pesu_auth_upstream_latency_seconds_sum{operation="csrf_fetch"} 210.4 +pesu_auth_upstream_latency_seconds_count{operation="csrf_fetch"} 793 +# HELP pesu_auth_csrf_cache_total Lookups of the cached unauthenticated CSRF client, by whether the cache was warm. +# TYPE pesu_auth_csrf_cache_total counter +pesu_auth_csrf_cache_total{outcome="hit"} 760 +# HELP pesu_auth_csrf_refreshes_total Periodic background refreshes of the unauthenticated CSRF token, by outcome. +# TYPE pesu_auth_csrf_refreshes_total counter +pesu_auth_csrf_refreshes_total{outcome="failure"} 1 +# HELP pesu_auth_prefetch_tasks_total Background CSRF prefetch tasks, by outcome. +# TYPE pesu_auth_prefetch_tasks_total counter +pesu_auth_prefetch_tasks_total{outcome="failure"} 4 +# HELP pesu_auth_http_clients_total Upstream HTTP client lifecycle. created minus closed is how many are still open. +# TYPE pesu_auth_http_clients_total counter +pesu_auth_http_clients_total{event="closed"} 775 +# HELP pesu_auth_lifespan_events_total Application lifespan events, by kind. +# TYPE pesu_auth_lifespan_events_total counter +pesu_auth_lifespan_events_total{event="startup"} 1 +# HELP pesu_auth_requests_in_flight Requests received but not yet answered. +# TYPE pesu_auth_requests_in_flight gauge +pesu_auth_requests_in_flight 1 +# HELP pesu_auth_process_start_time_seconds Start time of the process since the Unix epoch, in seconds. +# TYPE pesu_auth_process_start_time_seconds gauge +pesu_auth_process_start_time_seconds 1757660400.12 """ _JSON_EXAMPLE = { "startTimeSeconds": 1757660400.12, - "uptimeSeconds": 3612.44, + "uptimeSeconds": 0.0, "requests": {"total": 1284, "success": 1102, "failed": 182}, - "latency": {"sumSeconds": 742.1841932, "count": 1284, "averageSeconds": 0.5779}, + "latency": {"sumSeconds": 742.1841932, "count": 1284, "averageSeconds": 0.5780250725856698}, "authentication": {"total": 774, "withProfile": 134, "withoutProfile": 640}, - "responsesByStatus": {"200": 1094, "401": 160, "502": 6}, + "responsesByStatus": {"200": 1094, "308": 8, "400": 12, "401": 160, "500": 4, "502": 6}, "requestsByRoute": { + "GET /health": { + "requests": 302, + "latency": {"sumSeconds": 0.413, "count": 302, "averageSeconds": 0.0013675496688741722}, + }, "POST /authenticate": { "requests": 774, - "latency": {"sumSeconds": 741.2118, "count": 774, "averageSeconds": 0.9576}, - } + "latency": {"sumSeconds": 741.2118, "count": 774, "averageSeconds": 0.957637984496124}, + }, }, "errorsByType": {"AuthenticationError": 160, "RequestValidationError": 12}, + "requestsInFlight": 1, + "failuresByFault": {"client": 172, "server": 10}, + "validationErrorsByField": {"password": 4, "username": 8}, + "authenticationResults": {"invalid_credentials": 160, "profile_fetch_error": 2, "success": 612}, + "profileFieldFiltering": {"false": 94, "true": 40}, + "profileParseErrors": {"unknown_field": 3}, + "upstream": { + "csrf_fetch": { + "success": 790, + "error": 3, + "cancelled": 0, + "latency": {"sumSeconds": 210.4, "count": 793, "averageSeconds": 0.26532156368221943}, + "responsesByStatus": {"200": 790}, + }, + "login": { + "success": 774, + "error": 2, + "cancelled": 1, + "latency": {"sumSeconds": 620.4, "count": 776, "averageSeconds": 0.7994845360824742}, + "responsesByStatus": {"200": 774}, + }, + "profile_fetch": { + "success": 134, + "error": 1, + "cancelled": 0, + "latency": {"sumSeconds": 190.2, "count": 135, "averageSeconds": 1.4088888888888889}, + "responsesByStatus": {"200": 134}, + }, + }, + "csrfCache": {"hit": 760, "miss": 14}, + "csrfRefreshes": {"failure": 1, "success": 45}, + "prefetchTasks": {"failure": 4, "success": 770}, + "httpClients": {"closed": 775, "created": 776}, + "lifespanEvents": {"startup": 1}, } metrics_docs = ApiDocs( @@ -55,7 +156,7 @@ 200: { "description": "The collected metrics, in the format named by `fmt`.", "content": { - "text/plain": {"example": _PROMETHEUS_EXAMPLE}, + "text/plain": {"schema": {"type": "string"}, "example": _PROMETHEUS_EXAMPLE}, "application/json": {"example": _JSON_EXAMPLE}, }, }, diff --git a/app/docs/readme.py b/app/docs/readme.py index 5e0826f..faeec3e 100644 --- a/app/docs/readme.py +++ b/app/docs/readme.py @@ -10,7 +10,8 @@ "description": "Redirect to the PESUAuth GitHub repository.", "content": { "text/html": { - "example": 'Redirecting...Redirect' + "schema": {"type": "string"}, + "example": 'Redirecting...Redirect', } }, }, diff --git a/app/metrics/__init__.py b/app/metrics/__init__.py index 3bf4cbc..7da790c 100644 --- a/app/metrics/__init__.py +++ b/app/metrics/__init__.py @@ -1,37 +1,10 @@ """Metrics collection for the PESUAuth API. -This package deliberately exports no collector instance. The singleton is created in `app/app.py` -alongside the PESUAcademy client, so that importing the package has no side effects and tests can -swap the collector out by patching one module attribute. -""" +This package exports no collector instance. The singleton is created in `app/app.py` alongside the +PESUAcademy client, so importing the package has no side effects and a test can swap the collector +out by patching one module attribute. -from .collector import AUTHENTICATION_REQUESTS as AUTHENTICATION_REQUESTS -from .collector import AUTHENTICATION_RESULTS as AUTHENTICATION_RESULTS -from .collector import CSRF_CACHE as CSRF_CACHE -from .collector import CSRF_REFRESHES as CSRF_REFRESHES -from .collector import ERRORS_BY_TYPE as ERRORS_BY_TYPE -from .collector import FAILURES_BY_FAULT as FAILURES_BY_FAULT -from .collector import FAMILIES as FAMILIES -from .collector import HTTP_CLIENTS as HTTP_CLIENTS -from .collector import LIFESPAN_EVENTS as LIFESPAN_EVENTS -from .collector import PREFETCH_TASKS as PREFETCH_TASKS -from .collector import PROCESS_START_TIME as PROCESS_START_TIME -from .collector import PROFILE_PARSE_ERRORS as PROFILE_PARSE_ERRORS -from .collector import REQUEST_LATENCY as REQUEST_LATENCY -from .collector import REQUESTS_FAILED as REQUESTS_FAILED -from .collector import REQUESTS_IN_FLIGHT as REQUESTS_IN_FLIGHT -from .collector import REQUESTS_SUCCESS as REQUESTS_SUCCESS -from .collector import REQUESTS_TOTAL as REQUESTS_TOTAL -from .collector import RESPONSES_BY_STATUS as RESPONSES_BY_STATUS -from .collector import ROUTE_LATENCY as ROUTE_LATENCY -from .collector import ROUTE_REQUESTS as ROUTE_REQUESTS -from .collector import UPSTREAM_LATENCY as UPSTREAM_LATENCY -from .collector import UPSTREAM_REQUESTS as UPSTREAM_REQUESTS -from .collector import UPSTREAM_RESPONSES as UPSTREAM_RESPONSES -from .collector import VALIDATION_ERRORS as VALIDATION_ERRORS -from .collector import MetricFamily as MetricFamily -from .collector import MetricsCollector as MetricsCollector -from .collector import MetricsSnapshot as MetricsSnapshot -from .prometheus import PROMETHEUS_CONTENT_TYPE as PROMETHEUS_CONTENT_TYPE -from .prometheus import MetricsFormat as MetricsFormat -from .prometheus import render_prometheus as render_prometheus +Import from the modules directly -- `app.metrics.collector` for the families and the collector, +`app.metrics.prometheus` for exposition -- following the same convention as `app.exceptions`. A +re-export list here would be one more place to remember when a metric family is added. +""" diff --git a/app/metrics/collector.py b/app/metrics/collector.py index 6c6b9dd..09d5ed6 100644 --- a/app/metrics/collector.py +++ b/app/metrics/collector.py @@ -99,6 +99,12 @@ class MetricFamily: "counter", ("field",), ) +PROFILE_FIELD_FILTERING = MetricFamily( + f"{METRIC_PREFIX}profile_field_filtering_total", + "Profile fetches, by whether the caller narrowed the fields returned.", + "counter", + ("enabled",), +) AUTHENTICATION_RESULTS = MetricFamily( f"{METRIC_PREFIX}authentication_results_total", "Authentication attempts, by outcome.", @@ -149,7 +155,7 @@ class MetricFamily: ) HTTP_CLIENTS = MetricFamily( f"{METRIC_PREFIX}http_clients_total", - "Lifecycle events for upstream HTTP clients. created minus closed is what is still open.", + "Upstream HTTP client lifecycle. created minus closed is how many are still open.", "counter", ("event",), ) @@ -170,6 +176,7 @@ class MetricFamily: ERRORS_BY_TYPE, AUTHENTICATION_REQUESTS, AUTHENTICATION_RESULTS, + PROFILE_FIELD_FILTERING, PROFILE_PARSE_ERRORS, VALIDATION_ERRORS, FAILURES_BY_FAULT, @@ -196,7 +203,7 @@ class MetricsSnapshot: uptime_seconds: float values: Mapping[str, Mapping[LabelKey, float]] - def value(self, name: str, **labels: str) -> float: + def value(self, name: str, /, **labels: str) -> float: """Return a single series value, or 0.0 if it was never recorded. Args: @@ -277,19 +284,20 @@ def _key(family: MetricFamily, labels: Mapping[str, str]) -> LabelKey: raise ValueError(f"{family.name} expects labels {family.labels}, got {tuple(sorted(labels))}.") return tuple(sorted(labels.items())) - def increment(self, family: MetricFamily, value: float = 1.0, **labels: str) -> None: + def increment(self, family: MetricFamily, value: float = 1.0, /, **labels: str) -> None: """Add to a counter series. Args: family (MetricFamily): The counter family to record against. - value (float): The amount to add. Defaults to 1.0. + value (float): The amount to add. Defaults to 1.0. Positional-only, so a family may + declare a label named "value" without it being captured here instead. **labels (str): The label set, which must match the family's declared labels. """ key = self._key(family, labels) series = self._values[family.name] series[key] = series.get(key, 0.0) + value - def observe(self, family: MetricFamily, seconds: float, **labels: str) -> None: + def observe(self, family: MetricFamily, seconds: float, /, **labels: str) -> None: """Record one observation against a summary family's sum and count series. Args: diff --git a/app/metrics/middleware.py b/app/metrics/middleware.py index c8686eb..a725a60 100644 --- a/app/metrics/middleware.py +++ b/app/metrics/middleware.py @@ -143,9 +143,12 @@ async def record_request_metrics( # The exception *type* is recorded by the exception handlers, not here. The two layers write # to different families on purpose: one failed request produces exactly one status sample # and exactly one error sample, never two of either. - collector.increment(REQUESTS_IN_FLIGHT, -1.0) _record_outcome(collector, request.scope, EXCEPTION_STATUS, time.perf_counter() - started) raise - collector.increment(REQUESTS_IN_FLIGHT, -1.0) + finally: + # In a finally, not in each branch: a client disconnect surfaces as CancelledError, which + # is a BaseException and so slips past `except Exception`. Decrementing only in the two + # branches above would leave the gauge permanently high after every abandoned request. + collector.increment(REQUESTS_IN_FLIGHT, -1.0) _record_outcome(collector, request.scope, response.status_code, time.perf_counter() - started) return response diff --git a/app/models/metrics.py b/app/models/metrics.py index 4d2cd85..03fe2f1 100644 --- a/app/models/metrics.py +++ b/app/models/metrics.py @@ -14,6 +14,7 @@ LIFESPAN_EVENTS, PREFETCH_TASKS, PROCESS_START_TIME, + PROFILE_FIELD_FILTERING, PROFILE_PARSE_ERRORS, REQUEST_LATENCY, REQUESTS_FAILED, @@ -64,6 +65,7 @@ def _upstream(snapshot: MetricsSnapshot) -> dict[str, UpstreamOperationModel]: operation: UpstreamOperationModel( success=counts.get("success", 0), error=counts.get("error", 0), + cancelled=counts.get("cancelled", 0), latency=LatencyModel.from_snapshot(snapshot, UPSTREAM_LATENCY.name, operation=operation), responses_by_status=statuses.get(operation, {}), ) @@ -98,7 +100,7 @@ class LatencyModel(BaseModel): ) @classmethod - def from_snapshot(cls, snapshot: MetricsSnapshot, name: str, **labels: str) -> LatencyModel: + def from_snapshot(cls, snapshot: MetricsSnapshot, name: str, /, **labels: str) -> LatencyModel: """Build a latency view from a snapshot's sum and count series. Args: @@ -210,6 +212,13 @@ class UpstreamOperationModel(BaseModel): json_schema_extra={"example": 4}, ) + cancelled: int = Field( + ..., + title="Cancelled Calls", + description="Calls abandoned because the caller disconnected or the process shut down.", + json_schema_extra={"example": 1}, + ) + latency: LatencyModel = Field( ..., title="Upstream Latency", @@ -317,6 +326,13 @@ class MetricsModel(BaseModel): json_schema_extra={"example": {"success": 612, "invalid_credentials": 160, "profile_fetch_error": 2}}, ) + profile_field_filtering: dict[str, int] = Field( + ..., + title="Profile Field Filtering", + description='Profile fetches keyed by whether the returned fields were narrowed: "true" or "false".', + json_schema_extra={"example": {"true": 40, "false": 94}}, + ) + profile_parse_errors: dict[str, int] = Field( ..., title="Profile Parse Errors", @@ -419,6 +435,7 @@ def from_snapshot(cls, snapshot: MetricsSnapshot) -> MetricsModel: failures_by_fault=_counts(snapshot, FAILURES_BY_FAULT.name, "fault"), validation_errors_by_field=_counts(snapshot, VALIDATION_ERRORS.name, "field"), authentication_results=_counts(snapshot, AUTHENTICATION_RESULTS.name, "result"), + profile_field_filtering=_counts(snapshot, PROFILE_FIELD_FILTERING.name, "enabled"), profile_parse_errors=_counts(snapshot, PROFILE_PARSE_ERRORS.name, "reason"), upstream=_upstream(snapshot), csrf_cache=_counts(snapshot, CSRF_CACHE.name, "outcome"), diff --git a/app/pesu.py b/app/pesu.py index d28f480..97cc756 100644 --- a/app/pesu.py +++ b/app/pesu.py @@ -19,10 +19,11 @@ ProfileFetchError, ProfileParseError, ) -from app.metrics import ( +from app.metrics.collector import ( CSRF_CACHE, HTTP_CLIENTS, PREFETCH_TASKS, + PROFILE_FIELD_FILTERING, PROFILE_PARSE_ERRORS, UPSTREAM_LATENCY, UPSTREAM_REQUESTS, @@ -76,6 +77,13 @@ async def _upstream_call(metrics: MetricsCollector, operation: str) -> AsyncIter started = time.perf_counter() try: yield sink + except asyncio.CancelledError: + # Kept apart from "error": a cancellation means we walked away -- a client disconnected or + # the process is shutting down -- not that PESU Academy failed. Counting it as an error + # would spike the upstream error rate on every deploy and every abandoned request. + metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome="cancelled") + metrics.observe(UPSTREAM_LATENCY, time.perf_counter() - started, operation=operation) + raise except BaseException: metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome="error") metrics.observe(UPSTREAM_LATENCY, time.perf_counter() - started, operation=operation) @@ -509,6 +517,10 @@ async def authenticate( logging.info(f"Profile data requested for user={username}. Fetching profile data...") # Fetch the profile information result["profile"] = await self.get_profile_information(client, username) + # Recorded at the branch itself rather than from the request body, so it reflects + # what actually happened: a caller who passes exactly the default field list has + # specified fields but triggers no filtering. + self._metrics.increment(PROFILE_FIELD_FILTERING, enabled=str(field_filtering).lower()) # Filter the fields if field filtering is enabled if field_filtering: result["profile"] = {key: value for key, value in result["profile"].items() if key in fields} diff --git a/tests/integration/test_app_integration.py b/tests/integration/test_app_integration.py index 6b1d97e..95d44b9 100644 --- a/tests/integration/test_app_integration.py +++ b/tests/integration/test_app_integration.py @@ -9,7 +9,7 @@ unhandled_router = APIRouter() -@unhandled_router.get("/raiseUnhandled") +@unhandled_router.get("/raiseUnhandled", include_in_schema=False) async def raise_unhandled(): raise RuntimeError("Simulated internal server error") diff --git a/tests/unit/test_app_unit.py b/tests/unit/test_app_unit.py index 5e7801b..c25ebc2 100644 --- a/tests/unit/test_app_unit.py +++ b/tests/unit/test_app_unit.py @@ -85,7 +85,7 @@ async def test_csrf_token_refresh_loop_waits_before_its_first_refresh(mock_refre @patch("asyncio.sleep", new_callable=AsyncMock) @patch("app.app._refresh_csrf_token") async def test_csrf_token_refresh_loop_records_a_successful_refresh(mock_refresh, mock_sleep, monkeypatch): - from app.metrics import CSRF_REFRESHES, MetricsCollector + from app.metrics.collector import CSRF_REFRESHES, MetricsCollector collector = MetricsCollector() monkeypatch.setattr("app.app.metrics", collector) diff --git a/tests/unit/test_metrics_collector.py b/tests/unit/test_metrics_collector.py index 0fbf98e..f3b91b7 100644 --- a/tests/unit/test_metrics_collector.py +++ b/tests/unit/test_metrics_collector.py @@ -146,3 +146,20 @@ def test_metric_family_is_immutable(): family = MetricFamily("x", "y", "counter") with pytest.raises(AttributeError): family.name = "z" + + +def test_a_label_cannot_shadow_the_amount(collector): + """`value` is positional-only, so a family may declare a label of that name safely.""" + from app.metrics.collector import MetricFamily + + family = MetricFamily("pesu_auth_odd_total", "doc", "counter", ("value",)) + collector.increment(family, 3, value="x") + assert collector.snapshot().value(family.name, value="x") == 3.0 + + +def test_a_label_cannot_shadow_the_observation(collector): + from app.metrics.collector import MetricFamily + + family = MetricFamily("pesu_auth_odd_seconds", "doc", "summary", ("seconds",)) + collector.observe(family, 1.5, seconds="x") + assert collector.snapshot().value(f"{family.name}_sum", seconds="x") == 1.5 diff --git a/tests/unit/test_metrics_endpoints.py b/tests/unit/test_metrics_endpoints.py index bd0dad9..96c629a 100644 --- a/tests/unit/test_metrics_endpoints.py +++ b/tests/unit/test_metrics_endpoints.py @@ -12,7 +12,7 @@ boom_router = APIRouter() -@boom_router.get("/raiseUnhandledForMetrics") +@boom_router.get("/raiseUnhandledForMetrics", include_in_schema=False) async def raise_unhandled(): raise RuntimeError("Simulated internal server error") @@ -65,6 +65,7 @@ def test_json_format_shape(client): "errorsByType", "failuresByFault", "validationErrorsByField", + "profileFieldFiltering", "profileParseErrors", "upstream", "csrfCache", diff --git a/tests/unit/test_metrics_instrumentation.py b/tests/unit/test_metrics_instrumentation.py index d9d0322..42f9fcc 100644 --- a/tests/unit/test_metrics_instrumentation.py +++ b/tests/unit/test_metrics_instrumentation.py @@ -158,3 +158,85 @@ async def test_an_unparseable_profile_page_records_a_reason(pesu, collector): def test_a_bare_pesu_academy_still_works(): """Tests and scripts construct PESUAcademy() directly; it must not require a collector.""" assert PESUAcademy()._metrics is not None + + +@pytest.mark.asyncio +@patch("app.pesu.httpx2.AsyncClient.get") +async def test_a_cancelled_upstream_call_is_not_counted_as_an_error(mock_get, pesu, collector): + """A disconnect or a shutdown is not PESU failing. + + Counting cancellation as an upstream error would spike the error rate on every deploy and every + abandoned request, which is exactly when someone is looking at the dashboard. + """ + import asyncio + + mock_get.side_effect = asyncio.CancelledError + with pytest.raises(asyncio.CancelledError): + await pesu._fetch_new_client_with_csrf_token() + snapshot = collector.snapshot() + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="csrf_fetch", outcome="cancelled") == 1.0 + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="csrf_fetch", outcome="error") == 0.0 + # Still timed, so the three outcomes always sum to the number of calls attempted + assert snapshot.value(f"{UPSTREAM_LATENCY.name}_count", operation="csrf_fetch") == 1.0 + + +@pytest.mark.asyncio +@patch("app.pesu.PESUAcademy.get_profile_information") +@patch("app.pesu.PESUAcademy._get_client_with_csrf_token") +async def test_field_filtering_is_recorded_at_the_branch(mock_client, mock_profile, pesu, collector): + """Recorded where the branch is taken, not from the request body. + + A caller who passes exactly the default field list has specified fields but triggers no + filtering, so reading the request body would report the wrong thing. + """ + from app.metrics.collector import PROFILE_FIELD_FILTERING + + client = AsyncMock() + client.post.return_value = _response('') + mock_client.return_value = (client, "token") + mock_profile.return_value = {"name": "Test", "prn": "PES1", "email": "a@b.com"} + + await pesu.authenticate("u", "p", profile=True, fields=["name"]) + await pesu.authenticate("u", "p", profile=True, fields=None) + await pesu.authenticate("u", "p", profile=True, fields=list(pesu.DEFAULT_FIELDS)) + + snapshot = collector.snapshot() + assert snapshot.value(PROFILE_FIELD_FILTERING.name, enabled="true") == 1.0 + # None and an explicit copy of the defaults both mean "no filtering happened" + assert snapshot.value(PROFILE_FIELD_FILTERING.name, enabled="false") == 2.0 + + +@pytest.mark.asyncio +@patch("app.pesu.PESUAcademy.get_profile_information") +@patch("app.pesu.PESUAcademy._get_client_with_csrf_token") +async def test_a_login_records_its_upstream_call(mock_client, mock_profile, pesu, collector): + client = AsyncMock() + client.post.return_value = _response('') + mock_client.return_value = (client, "token") + mock_profile.return_value = {"name": "Test"} + + await pesu.authenticate("u", "p") + + snapshot = collector.snapshot() + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="login", outcome="success") == 1.0 + assert snapshot.value(UPSTREAM_RESPONSES.name, operation="login", status="200") == 1.0 + # The client this request borrowed is closed on the way out, on every path + assert snapshot.value(HTTP_CLIENTS.name, event="closed") == 1.0 + + +@pytest.mark.asyncio +@patch("app.pesu.PESUAcademy._get_client_with_csrf_token") +async def test_a_wrong_password_still_counts_the_login_as_reaching_pesu(mock_client, pesu, collector): + """PESU answered with a 200 and a login form. The call worked; the credentials did not.""" + from app.exceptions.authentication import AuthenticationError + + client = AsyncMock() + client.post.return_value = _response('') + mock_client.return_value = (client, "token") + + with pytest.raises(AuthenticationError): + await pesu.authenticate("u", "wrong") + + snapshot = collector.snapshot() + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="login", outcome="success") == 1.0 + assert snapshot.value(UPSTREAM_REQUESTS.name, operation="login", outcome="error") == 0.0 diff --git a/tests/unit/test_metrics_middleware.py b/tests/unit/test_metrics_middleware.py index 2cf3ec2..c5b574b 100644 --- a/tests/unit/test_metrics_middleware.py +++ b/tests/unit/test_metrics_middleware.py @@ -6,6 +6,7 @@ ERRORS_BY_TYPE, REQUEST_LATENCY, REQUESTS_FAILED, + REQUESTS_IN_FLIGHT, REQUESTS_SUCCESS, REQUESTS_TOTAL, RESPONSES_BY_STATUS, @@ -133,6 +134,28 @@ async def test_cancellation_is_not_recorded(collector): assert snapshot.value(REQUESTS_TOTAL.name) == 1.0 assert snapshot.value(REQUESTS_SUCCESS.name) == 0.0 assert snapshot.value(REQUESTS_FAILED.name) == 0.0 + # The gauge must still come back down, or it climbs forever on a server that sees disconnects + assert snapshot.value(REQUESTS_IN_FLIGHT.name) == 0.0 + + +@pytest.mark.asyncio +async def test_in_flight_returns_to_zero_on_every_path(collector): + """Success, handled failure and raised exception must all leave the gauge where they found it.""" + await record_request_metrics(collector, FakeRequest(scope()), responding(200)) + await record_request_metrics(collector, FakeRequest(scope()), responding(401)) + with pytest.raises(RuntimeError): + await record_request_metrics(collector, FakeRequest(scope()), raising(RuntimeError("boom"))) + assert collector.snapshot().value(REQUESTS_IN_FLIGHT.name) == 0.0 + + +@pytest.mark.asyncio +async def test_in_flight_is_raised_while_a_request_is_being_served(collector): + async def call_next(_request): + assert collector.snapshot().value(REQUESTS_IN_FLIGHT.name) == 1.0 + return FakeResponse(200) + + await record_request_metrics(collector, FakeRequest(scope()), call_next) + assert collector.snapshot().value(REQUESTS_IN_FLIGHT.name) == 0.0 @pytest.mark.asyncio diff --git a/tests/unit/test_metrics_model.py b/tests/unit/test_metrics_model.py index 6302930..b70ea3a 100644 --- a/tests/unit/test_metrics_model.py +++ b/tests/unit/test_metrics_model.py @@ -58,8 +58,8 @@ def test_average_latency_is_the_mean(collector): def test_authentication_total_is_the_sum_of_both_splits(collector): - collector.increment(AUTHENTICATION_REQUESTS, profile="true", value=2) - collector.increment(AUTHENTICATION_REQUESTS, profile="false", value=5) + collector.increment(AUTHENTICATION_REQUESTS, 2, profile="true") + collector.increment(AUTHENTICATION_REQUESTS, 5, profile="false") model = MetricsModel.from_snapshot(collector.snapshot()) assert model.authentication.with_profile == 2 assert model.authentication.without_profile == 5 @@ -165,3 +165,21 @@ def test_in_flight_is_reported(collector): collector.increment(REQUESTS_IN_FLIGHT) assert MetricsModel.from_snapshot(collector.snapshot()).requests_in_flight == 1 + + +def test_the_documented_example_matches_the_model(): + """The Swagger example is what a reader trusts, so it must not drift from the schema.""" + from app.docs import metrics_docs + + example = metrics_docs.response_examples[200]["content"]["application/json"]["example"] + model = MetricsModel.model_validate(example) + # Round-trips, so the example uses the camelCase aliases a real response uses + assert model.model_dump(by_alias=True) == example + + +def test_the_documented_example_covers_every_field(): + from app.docs import metrics_docs + + example = metrics_docs.response_examples[200]["content"]["application/json"]["example"] + aliases = {field.alias or name for name, field in MetricsModel.model_fields.items()} + assert set(example) == aliases diff --git a/tests/unit/test_openapi_docs.py b/tests/unit/test_openapi_docs.py new file mode 100644 index 0000000..3e8c853 --- /dev/null +++ b/tests/unit/test_openapi_docs.py @@ -0,0 +1,193 @@ +"""Tests that the OpenAPI schema documents what the API actually does. + +Swagger is what a caller reads before writing any code against this service, so an example that +does not match reality is worse than no example. These tests check the documentation against the +models it claims to follow, and against real responses. +""" + +import json +from unittest.mock import AsyncMock, patch + +import pytest +from fastapi.testclient import TestClient + +from app.app import app +from app.exceptions.authentication import AuthenticationError +from app.models import MetricsModel, RequestModel, ResponseModel + +MODELS = {"ResponseModel": ResponseModel, "MetricsModel": MetricsModel} + + +@pytest.fixture(scope="module") +def schema(): + app.openapi_schema = None + generated = app.openapi() + app.openapi_schema = None + return generated + + +@pytest.fixture +def client(): + with ( + patch("app.app.pesu_academy.prefetch_client_with_csrf_token", new_callable=AsyncMock), + patch("app.app.pesu_academy.close_client", new_callable=AsyncMock), + ): + with TestClient(app, raise_server_exceptions=False) as test_client: + yield test_client + + +def _operations(schema): + for path, operations in schema["paths"].items(): + for verb, operation in operations.items(): + yield path, verb, operation + + +def test_every_route_is_documented(schema): + assert set(schema["paths"]) == {"/authenticate", "/health", "/metrics", "/readme"} + + +def test_every_route_documents_a_success_and_a_server_error(schema): + """Any route can 500 through the catch-all handler, so every one documents it.""" + for path, verb, operation in _operations(schema): + codes = set(operation["responses"]) + assert codes & {"200", "308"}, f"{verb} {path} documents no success" + assert "500" in codes, f"{verb} {path} does not document a 500" + + +def test_every_documented_response_has_an_example(schema): + for path, verb, operation in _operations(schema): + for code, response in operation["responses"].items(): + for media_type, content in response.get("content", {}).items(): + has_example = "example" in content or "examples" in content + assert has_example, f"{verb} {path} {code} {media_type} has no example" + + +def test_every_documented_response_has_a_schema(schema): + for path, verb, operation in _operations(schema): + for code, response in operation["responses"].items(): + for media_type, content in response.get("content", {}).items(): + assert "schema" in content, f"{verb} {path} {code} {media_type} has no schema" + + +def test_json_examples_validate_against_the_model_they_claim(schema): + """An example its own declared model rejects would mislead every reader. + + Validated as JSON, not as a Python dict, because that is what a client does: the models are + strict, and a strict Python-mode validation rejects the ISO *string* these responses actually + carry in `timestamp`. In JSON mode -- the mode a caller parsing the body is in -- it parses to + a datetime, which is what the schema advertises. + """ + checked = 0 + for path, verb, operation in _operations(schema): + for code, response in operation["responses"].items(): + content = response.get("content", {}).get("application/json", {}) + ref = content.get("schema", {}).get("$ref", "") + model = MODELS.get(ref.rsplit("/", 1)[-1]) + if model is None or "example" not in content: + continue + model.model_validate_json(json.dumps(content["example"])) + checked += 1 + assert checked >= 8, f"only {checked} examples were checked; the sweep is not doing its job" + + +def test_request_examples_validate_against_the_request_model(schema): + body = schema["paths"]["/authenticate"]["post"]["requestBody"]["content"]["application/json"] + examples = body["examples"] + assert len(examples) >= 3 + for name, example in examples.items(): + RequestModel.model_validate_json(json.dumps(example["value"])), name + + +def test_request_examples_cover_the_documented_username_forms(schema): + """The endpoint accepts SRN/PRN, email and phone, so the examples should show all three.""" + body = schema["paths"]["/authenticate"]["post"]["requestBody"]["content"]["application/json"] + usernames = [e["value"]["username"] for e in body["examples"].values()] + assert any("@" in u for u in usernames), "no email example" + assert any(u.isdigit() for u in usernames), "no phone example" + assert any(u.startswith("PES") for u in usernames), "no SRN/PRN example" + + +def test_request_examples_cover_profile_and_field_filtering(schema): + body = schema["paths"]["/authenticate"]["post"]["requestBody"]["content"]["application/json"] + values = [e["value"] for e in body["examples"].values()] + assert any(v.get("profile") is False for v in values), "no example without profile" + assert any(v.get("profile") is True for v in values), "no example with profile" + assert any("fields" in v for v in values), "no example using field filtering" + + +def test_no_phantom_validation_error_is_documented(schema): + """This API converts every RequestValidationError into a 400. + + FastAPI would otherwise document a 422 carrying its own HTTPValidationError body on any route + with validatable parameters -- a response that cannot occur, in a shape never emitted. + """ + assert "HTTPValidationError" not in schema["components"]["schemas"] + assert "422" not in schema["paths"]["/metrics"]["get"]["responses"] + rendered = str(schema) + assert "HTTPValidationError" not in rendered + + +def test_the_profile_parse_422_is_kept(schema): + """/authenticate really can return a 422, and it uses this API's own response shape.""" + response = schema["paths"]["/authenticate"]["post"]["responses"]["422"] + ref = response["content"]["application/json"]["schema"]["$ref"] + assert ref.endswith("/ResponseModel") + + +def test_the_metrics_format_enum_is_documented(schema): + values = schema["components"]["schemas"]["MetricsFormat"]["enum"] + assert sorted(values) == ["json", "prometheus"] + + +def test_the_documented_400_matches_a_real_response(client, schema): + """The example a reader copies must be the body they will actually receive.""" + documented = schema["paths"]["/metrics"]["get"]["responses"]["400"]["content"]["application/json"]["example"] + actual = client.get("/metrics?fmt=xml").json() + assert actual["status"] == documented["status"] + assert actual["message"] == documented["message"] + assert set(actual) == set(documented) + + +@patch("app.app.pesu_academy.authenticate") +def test_the_documented_401_matches_a_real_response(mock_authenticate, client, schema): + mock_authenticate.side_effect = AuthenticationError() + documented = schema["paths"]["/authenticate"]["post"]["responses"]["401"]["content"]["application/json"]["example"] + actual = client.post("/authenticate", json={"username": "u", "password": "p"}).json() + assert set(actual) == set(documented) + assert actual["status"] == documented["status"] is False + + +def test_the_documented_health_200_matches_a_real_response(client, schema): + documented = schema["paths"]["/health"]["get"]["responses"]["200"]["content"]["application/json"]["example"] + actual = client.get("/health").json() + assert set(actual) == set(documented) + assert actual["message"] == documented["message"] + + +def test_the_documented_prometheus_example_looks_like_the_real_payload(client, schema): + documented = schema["paths"]["/metrics"]["get"]["responses"]["200"]["content"]["text/plain"]["example"] + actual = client.get("/metrics").text + for line in documented.splitlines(): + if line.startswith("# TYPE"): + assert line in actual, f"documented family missing from a real response: {line}" + + +def test_every_route_is_tagged(schema): + for path, verb, operation in _operations(schema): + assert operation.get("tags"), f"{verb} {path} has no tag" + + +def test_every_route_has_a_summary_and_description(schema): + """The summary is the line Swagger shows collapsed; without it a reader sees only the path.""" + for path, verb, operation in _operations(schema): + assert operation.get("summary"), f"{verb} {path} has no summary" + assert operation.get("description"), f"{verb} {path} has no description" + + +def test_the_schema_is_built_once_and_cached(): + """FastAPI caches the schema on the app; the override must keep doing so, not rebuild per request.""" + app.openapi_schema = None + first = app.openapi() + second = app.openapi() + assert first is second + app.openapi_schema = None From 7a37ec99a945c1dfb973ef9ab5b3a5fc8d400273 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 21:28:34 -0500 Subject: [PATCH 15/17] fix: let ResponseModel parse the responses it describes `timestamp` is declared `datetime` under a model-wide `strict=True`, but the API serializes an ISO string onto the wire. So the published model could not validate a real response: a client holding a decoded dict -- which is what every HTTP library hands back -- got a ValidationError from the schema the API publishes for exactly that purpose. It also made the documentation tests weaker than they looked. They validated examples in JSON mode, where pydantic accepts a string for a datetime because JSON has no datetime type. That passed, but it was working around the problem rather than finding it. `strict=False` on that one field accepts both the datetime the API builds with and the ISO string it returns. Every other field stays strict, which a test now pins. The documentation tests assert **both** modes rather than whichever passes, and a new test round-trips a real `/health` response through the model both ways. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- app/models/response.py | 5 +++++ tests/unit/test_openapi_docs.py | 28 ++++++++++++++++++++++++---- 2 files changed, 29 insertions(+), 4 deletions(-) diff --git a/app/models/response.py b/app/models/response.py index 8e8b108..a533aa2 100644 --- a/app/models/response.py +++ b/app/models/response.py @@ -29,6 +29,11 @@ class ResponseModel(BaseModel): timestamp: datetime = Field( ..., + # Relaxed from the model-wide strict=True for this field alone. The API builds this model + # from a datetime but serializes an ISO string onto the wire, so a strict model could not + # parse its own responses -- which made the published schema unusable to a client wanting + # to validate with it, and forced the documentation tests into JSON mode to compensate. + strict=False, title="Authentication Timestamp", description="Timestamp of the authentication attempt with timezone info.", json_schema_extra={"example": "2024-07-28T22:30:10.103368+05:30"}, diff --git a/tests/unit/test_openapi_docs.py b/tests/unit/test_openapi_docs.py index 3e8c853..bf947a5 100644 --- a/tests/unit/test_openapi_docs.py +++ b/tests/unit/test_openapi_docs.py @@ -72,10 +72,9 @@ def test_every_documented_response_has_a_schema(schema): def test_json_examples_validate_against_the_model_they_claim(schema): """An example its own declared model rejects would mislead every reader. - Validated as JSON, not as a Python dict, because that is what a client does: the models are - strict, and a strict Python-mode validation rejects the ISO *string* these responses actually - carry in `timestamp`. In JSON mode -- the mode a caller parsing the body is in -- it parses to - a datetime, which is what the schema advertises. + Validated **both** ways. JSON mode is what a caller parsing a response body is in; Python mode + is what a caller passing a decoded dict is in. A published model that only works in one of them + is a trap, so both are asserted rather than picking whichever passes. """ checked = 0 for path, verb, operation in _operations(schema): @@ -86,6 +85,7 @@ def test_json_examples_validate_against_the_model_they_claim(schema): if model is None or "example" not in content: continue model.model_validate_json(json.dumps(content["example"])) + model.model_validate(content["example"]) checked += 1 assert checked >= 8, f"only {checked} examples were checked; the sweep is not doing its job" @@ -96,6 +96,7 @@ def test_request_examples_validate_against_the_request_model(schema): assert len(examples) >= 3 for name, example in examples.items(): RequestModel.model_validate_json(json.dumps(example["value"])), name + RequestModel.model_validate(example["value"]), name def test_request_examples_cover_the_documented_username_forms(schema): @@ -191,3 +192,22 @@ def test_the_schema_is_built_once_and_cached(): second = app.openapi() assert first is second app.openapi_schema = None + + +def test_a_real_response_can_be_parsed_with_the_published_model(client): + """The published schema has to be usable by a client, which is the point of publishing it. + + A real response carries `timestamp` as an ISO string. If the model could only be validated in + JSON mode, anyone holding a decoded dict -- which is what every HTTP library hands back -- would + be unable to use it. + """ + body = client.get("/health").json() + assert ResponseModel.model_validate(body).status is True + assert ResponseModel.model_validate_json(json.dumps(body)).status is True + + +def test_the_model_still_rejects_a_wrong_type_elsewhere(client): + """Relaxing `timestamp` must not have relaxed the model as a whole.""" + body = client.get("/health").json() + with pytest.raises(Exception, match="status"): + ResponseModel.model_validate({**body, "status": "not-a-bool"}) From 37357a93b3dda13a6ed09f47052370a558a765c6 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 22:05:07 -0500 Subject: [PATCH 16/17] refactor: record only the outcome of an authentication, not the reason twice `authentication_results_total` carried six values -- `success`, `internal_error`, and one per failure class -- four of which restated what `errors_total{type}` already recorded about the same event. Three of those four were not even a different vocabulary, just the class name in snake_case: `CSRFTokenError` -> `csrf_token_error`, `ProfileFetchError` -> `profile_fetch_error`, `ProfileParseError` -> `profile_parse_error`. Only `AuthenticationError` -> `invalid_credentials` said anything the class name did not, and the audience for these metrics knows the class names. Worse than redundant, it was a drift risk. The mapping was a hand-written dict read through `.get(type(exc), "other")`, so adding a fifth exception class and forgetting the entry would have left two counters disagreeing about one event -- with the less informative one failing silently, which is the failure mode this PR removes everywhere else. Now `success` or `failure`, and the reason lives in exactly one place. The family survives at all because it answers the one question nothing else can: the login success rate, with success and failure in one family sharing a denominator. Computing that from `errorsByType` would mean subtracting several error classes from a different family -- the fragile cross-family arithmetic this avoids. A test pins `sum(authenticationResults) == authentication.total`. `internal_error` goes with it: a non-PESUAcademyError escaping `authenticate()` is now `failure`, and `errors_total` still names the class, so nothing became unobservable. app/app.py loses the mapping dict and four imports that existed only to feed it. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- README.md | 26 +++++++++++-------- app/app.py | 30 ++++++---------------- app/docs/metrics.py | 8 +++--- app/metrics/collector.py | 2 +- app/models/metrics.py | 7 +++-- tests/unit/test_metrics_endpoints.py | 38 +++++++++++++++++++++++----- 6 files changed, 65 insertions(+), 46 deletions(-) diff --git a/README.md b/README.md index e3ad4ab..d1044a2 100644 --- a/README.md +++ b/README.md @@ -208,6 +208,10 @@ requests.success + requests.failed + requestsInFlight == requests.total sum(responsesByStatus) == requests.success + requests.failed ``` +A login failure's *reason* comes from `errorsByType`, which names the exception class. +`authenticationResults` carries only the outcome, so the reason is recorded in exactly one place, and +`sum(authenticationResults) == authentication.total` modulo attempts still in flight. + `sum(errorsByType)` is normally **less** than `requests.failed`: a `404` or `405` is produced by the router, so no exception handler of ours runs for it. @@ -248,12 +252,12 @@ A few definitions that are easy to assume wrongly: **Authentication** -| Metric | Meaning | -| ---------------------------------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `authentication_requests_total{profile}` | Authentication requests, split by whether profile data was asked for | -| `authentication_results_total{result}` | Attempts by outcome: `success`, `invalid_credentials`, `csrf_token_error`, `profile_fetch_error`, `profile_parse_error`, `internal_error`. This is the one to read for "why are logins failing" | -| `profile_field_filtering_total{enabled}` | Profile fetches, split by whether the caller narrowed the returned fields. Recorded where the branch is taken, so a caller passing exactly the default list counts as `false` | -| `profile_parse_errors_total{reason}` | Parse failures by what broke: `key_missing`, `value_missing`, `unknown_field`, `page_structure`, `no_data`, `unknown_campus_code`. These mean PESU Academy's page changed | +| Metric | Meaning | +| ---------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `authentication_requests_total{profile}` | Authentication requests, split by whether profile data was asked for | +| `authentication_results_total{result}` | Attempts by outcome: `success` or `failure`. Deliberately only those two ā€” `errors_total` already names the exception class, and recording the reason here too would put one fact in two places. This family exists for the login **success rate**, where success and failure share a denominator | +| `profile_field_filtering_total{enabled}` | Profile fetches, split by whether the caller narrowed the returned fields. Recorded where the branch is taken, so a caller passing exactly the default list counts as `false` | +| `profile_parse_errors_total{reason}` | Parse failures by what broke: `key_missing`, `value_missing`, `unknown_field`, `page_structure`, `no_data`, `unknown_campus_code`. These mean PESU Academy's page changed | **Upstream (PESU Academy)** @@ -312,15 +316,15 @@ pesu_auth_route_requests_total{method="POST",route="/authenticate"} 774 # HELP pesu_auth_errors_total Errors rendered by an exception handler, by exception class. # TYPE pesu_auth_errors_total counter pesu_auth_errors_total{type="AuthenticationError"} 160 +pesu_auth_errors_total{type="ProfileFetchError"} 2 pesu_auth_errors_total{type="RequestValidationError"} 12 # HELP pesu_auth_authentication_requests_total Authentication requests, by whether profile data was requested. # TYPE pesu_auth_authentication_requests_total counter pesu_auth_authentication_requests_total{profile="false"} 640 pesu_auth_authentication_requests_total{profile="true"} 134 -# HELP pesu_auth_authentication_results_total Authentication attempts, by outcome. +# HELP pesu_auth_authentication_results_total Authentication attempts, by outcome. errors_total says why one failed. # TYPE pesu_auth_authentication_results_total counter -pesu_auth_authentication_results_total{result="invalid_credentials"} 160 -pesu_auth_authentication_results_total{result="profile_fetch_error"} 2 +pesu_auth_authentication_results_total{result="failure"} 162 pesu_auth_authentication_results_total{result="success"} 612 # HELP pesu_auth_profile_field_filtering_total Profile fetches, by whether the caller narrowed the fields returned. # TYPE pesu_auth_profile_field_filtering_total counter @@ -454,6 +458,7 @@ which is `null` rather than absent when nothing has been recorded yet, so the sh }, "errorsByType": { "AuthenticationError": 160, + "ProfileFetchError": 2, "RequestValidationError": 12 }, "requestsInFlight": 1, @@ -466,8 +471,7 @@ which is `null` rather than absent when nothing has been recorded yet, so the sh "username": 8 }, "authenticationResults": { - "invalid_credentials": 160, - "profile_fetch_error": 2, + "failure": 162, "success": 612 }, "profileFieldFiltering": { diff --git a/app/app.py b/app/app.py index 3fce0a8..9eeb098 100644 --- a/app/app.py +++ b/app/app.py @@ -27,12 +27,6 @@ from pydantic import ValidationError from app.docs import authenticate_docs, health_docs, metrics_docs, readme_docs -from app.exceptions.authentication import ( - AuthenticationError, - CSRFTokenError, - ProfileFetchError, - ProfileParseError, -) from app.exceptions.base import PESUAcademyError from app.metrics.collector import ( AUTHENTICATION_REQUESTS, @@ -53,14 +47,6 @@ # Validation failures are labelled by field, so the label set has to be closed against a caller who # can put anything in the request body KNOWN_REQUEST_FIELDS = frozenset({"username", "password", "profile", "fields", "fmt", "body"}) -# Failure vocabulary for authentication attempts. Keyed on the exception class rather than the -# status code, because CSRFTokenError and ProfileFetchError are both 502 and mean different things. -AUTHENTICATION_FAILURE_RESULTS = { - AuthenticationError: "invalid_credentials", - CSRFTokenError: "csrf_token_error", - ProfileFetchError: "profile_fetch_error", - ProfileParseError: "profile_parse_error", -} async def _refresh_csrf_token() -> None: @@ -356,15 +342,15 @@ async def authenticate(payload: RequestModel) -> JSONResponse: fields=fields, ), ) - except PESUAcademyError as exc: - # Why the attempt failed, not just that it did. errors_total already counts the exception - # class; this records the same event in the vocabulary someone actually asks questions in -- - # "how many logins failed because the password was wrong" versus "because PESU was broken". - result = AUTHENTICATION_FAILURE_RESULTS.get(type(exc), "other") - metrics.increment(AUTHENTICATION_RESULTS, result=result) - raise except Exception: - metrics.increment(AUTHENTICATION_RESULTS, result="internal_error") + # The outcome only, never the reason. errors_total{type} already names the exception class, + # and recording it a second time here meant two counters describing one event that had to + # be kept in step by a hand-written mapping -- which would have drifted the first time + # someone added an exception class and forgot the entry. + # + # This family exists for the one thing nothing else can answer: the login success rate, + # with success and failure in one family sharing a denominator. + metrics.increment(AUTHENTICATION_RESULTS, result="failure") raise metrics.increment(AUTHENTICATION_RESULTS, result="success") diff --git a/app/docs/metrics.py b/app/docs/metrics.py index 9767e68..2851a01 100644 --- a/app/docs/metrics.py +++ b/app/docs/metrics.py @@ -40,9 +40,9 @@ # HELP pesu_auth_authentication_requests_total Authentication requests, by whether profile data was requested. # TYPE pesu_auth_authentication_requests_total counter pesu_auth_authentication_requests_total{profile="false"} 640 -# HELP pesu_auth_authentication_results_total Authentication attempts, by outcome. +# HELP pesu_auth_authentication_results_total Authentication attempts, by outcome. errors_total says why one failed. # TYPE pesu_auth_authentication_results_total counter -pesu_auth_authentication_results_total{result="invalid_credentials"} 160 +pesu_auth_authentication_results_total{result="failure"} 162 # HELP pesu_auth_profile_field_filtering_total Profile fetches, by whether the caller narrowed the fields returned. # TYPE pesu_auth_profile_field_filtering_total counter pesu_auth_profile_field_filtering_total{enabled="false"} 94 @@ -113,11 +113,11 @@ "latency": {"sumSeconds": 741.2118, "count": 774, "averageSeconds": 0.957637984496124}, }, }, - "errorsByType": {"AuthenticationError": 160, "RequestValidationError": 12}, + "errorsByType": {"AuthenticationError": 160, "ProfileFetchError": 2, "RequestValidationError": 12}, "requestsInFlight": 1, "failuresByFault": {"client": 172, "server": 10}, "validationErrorsByField": {"password": 4, "username": 8}, - "authenticationResults": {"invalid_credentials": 160, "profile_fetch_error": 2, "success": 612}, + "authenticationResults": {"failure": 162, "success": 612}, "profileFieldFiltering": {"false": 94, "true": 40}, "profileParseErrors": {"unknown_field": 3}, "upstream": { diff --git a/app/metrics/collector.py b/app/metrics/collector.py index 09d5ed6..ab66fa8 100644 --- a/app/metrics/collector.py +++ b/app/metrics/collector.py @@ -107,7 +107,7 @@ class MetricFamily: ) AUTHENTICATION_RESULTS = MetricFamily( f"{METRIC_PREFIX}authentication_results_total", - "Authentication attempts, by outcome.", + "Authentication attempts, by outcome. errors_total says why one failed.", "counter", ("result",), ) diff --git a/app/models/metrics.py b/app/models/metrics.py index 03fe2f1..c5adb59 100644 --- a/app/models/metrics.py +++ b/app/models/metrics.py @@ -322,8 +322,11 @@ class MetricsModel(BaseModel): authentication_results: dict[str, int] = Field( ..., title="Authentication Results", - description="Authentication attempts keyed by outcome, so failures can be told apart by cause.", - json_schema_extra={"example": {"success": 612, "invalid_credentials": 160, "profile_fetch_error": 2}}, + description=( + 'Authentication attempts keyed by outcome: "success" or "failure". Why a failure ' + "happened is in errorsByType, which names the exception class." + ), + json_schema_extra={"example": {"success": 612, "failure": 162}}, ) profile_field_filtering: dict[str, int] = Field( diff --git a/tests/unit/test_metrics_endpoints.py b/tests/unit/test_metrics_endpoints.py index 96c629a..9865900 100644 --- a/tests/unit/test_metrics_endpoints.py +++ b/tests/unit/test_metrics_endpoints.py @@ -189,27 +189,53 @@ def test_latency_is_recorded_for_a_route(client): @patch("app.app.pesu_academy.authenticate") -def test_authentication_outcomes_are_recorded_by_reason(mock_authenticate, client): - """errors_total says which class was raised; this says what it meant for the login attempt.""" +def test_authentication_outcomes_are_success_or_failure(mock_authenticate, client): + """Outcome only. Every kind of failure lands in one bucket, whatever raised it.""" from app.exceptions.authentication import ProfileFetchError mock_authenticate.side_effect = AuthenticationError() client.post("/authenticate", json={"username": "u", "password": "p"}) mock_authenticate.side_effect = ProfileFetchError() client.post("/authenticate", json={"username": "u", "password": "p", "profile": True}) + mock_authenticate.side_effect = RuntimeError("something else entirely") + client.post("/authenticate", json={"username": "u", "password": "p"}) mock_authenticate.side_effect = None mock_authenticate.return_value = {"status": True, "message": "Login successful."} client.post("/authenticate", json={"username": "u", "password": "p"}) results = client.get("/metrics?fmt=json").json()["authenticationResults"] - assert results == {"invalid_credentials": 1, "profile_fetch_error": 1, "success": 1} + assert results == {"success": 1, "failure": 3} @patch("app.app.pesu_academy.authenticate") -def test_an_unexpected_error_is_recorded_as_internal(mock_authenticate, client): - mock_authenticate.side_effect = RuntimeError("something else entirely") +def test_the_reason_for_a_failure_is_still_recoverable(mock_authenticate, client): + """Why a login failed lives in exactly one place now, named by exception class.""" + from app.exceptions.authentication import ProfileFetchError + + mock_authenticate.side_effect = AuthenticationError() client.post("/authenticate", json={"username": "u", "password": "p"}) - assert client.get("/metrics?fmt=json").json()["authenticationResults"] == {"internal_error": 1} + mock_authenticate.side_effect = ProfileFetchError() + client.post("/authenticate", json={"username": "u", "password": "p", "profile": True}) + + body = client.get("/metrics?fmt=json").json() + assert body["errorsByType"] == {"AuthenticationError": 1, "ProfileFetchError": 1} + assert body["authenticationResults"]["failure"] == 2 + + +@patch("app.app.pesu_academy.authenticate") +def test_the_success_rate_has_a_matching_denominator(mock_authenticate, client): + """The reason this family survives: success and failure share one denominator. + + Computing the same figure from errorsByType would mean subtracting several error classes from + a different family, which is exactly the fragile cross-family arithmetic this avoids. + """ + mock_authenticate.return_value = {"status": True, "message": "Login successful."} + client.post("/authenticate", json={"username": "u", "password": "p"}) + mock_authenticate.side_effect = AuthenticationError() + client.post("/authenticate", json={"username": "u", "password": "p"}) + + body = client.get("/metrics?fmt=json").json() + assert sum(body["authenticationResults"].values()) == body["authentication"]["total"] def test_validation_errors_are_recorded_by_field(client): From 776bad4c7b865d538dc4b24caba6b30f243f0771 Mon Sep 17 00:00:00 2001 From: aditeyabaral Date: Sat, 12 Sep 2026 22:14:35 -0500 Subject: [PATCH 17/17] fix: correct the version bump, and three things found re-reading the diff **The version bumped twice in one pull request.** 4.1.0 -> 4.2.0 -> 4.3.0, because the second batch of work read as another feature. One merge to dev is one bump, so this is 4.2.0; 4.3.0 would have skipped a version that never reaches dev. The guidance in `check_version_bump.py` is what led there. It described picking a level by change type -- "minor: new functionality", "patch: a bug fix" -- which invites exactly that reading when a PR contains several kinds of change. It now states the rule in force: raise the minor by one, once per pull request, with major reserved for a backwards-incompatible change. **The OpenAPI override restated FastAPI's argument list.** It called `get_openapi()` with five arguments where FastAPI passes fourteen. Every one missing is None or a default today, so nothing was visibly wrong -- but setting `servers=` or `license_info=` on the app later would have silently vanished from the schema. It now captures and delegates to FastAPI's own builder, so it inherits whatever that grows. **`_upstream_call` recorded in three places.** Latency and outcome were written once per branch. A `finally` with a pessimistic default makes "every call is counted and timed exactly once" structural rather than three copies that have to stay in step -- and anything escaping without setting the outcome is an error, which is the right thing to fail to. **A test still used a label value the app can no longer emit** (`result="invalid_credentials"`). It passed because the collector validates label names, not values, so it was quietly asserting a behaviour that no longer exists. Also guards `FAMILIES` against the drift that made the last two findings possible: a family defined but left out of the registry would be collected into and never exposed, silently. Tests now assert the registry matches the module, that names are unique and valid Prometheus identifiers, that no counter name collides with a summary's `_sum`/`_count` series, and that every HELP line fits the exposition example's line limit. 240 tests, 100% coverage. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH --- .github/scripts/check_version_bump.py | 11 +++--- app/app.py | 15 ++++----- app/pesu.py | 20 ++++++----- pyproject.toml | 2 +- tests/unit/test_metrics_collector.py | 48 +++++++++++++++++++++++++++ tests/unit/test_metrics_model.py | 4 +-- uv.lock | 2 +- 7 files changed, 76 insertions(+), 26 deletions(-) diff --git a/.github/scripts/check_version_bump.py b/.github/scripts/check_version_bump.py index e6ce6cd..43c0bcf 100644 --- a/.github/scripts/check_version_bump.py +++ b/.github/scripts/check_version_bump.py @@ -89,11 +89,12 @@ def main() -> int: print( f"\nāŒ The project version must be raised above {base_version}, but this PR leaves it " f"at {head_version}.\n\n" - " Every pull request has to bump `version` in pyproject.toml so that what is\n" - " deployed can be identified. Pick the level that matches the change:\n\n" - " major (X.0.0) - a backwards-incompatible API or schema change\n" - " minor (x.Y.0) - new functionality that keeps existing APIs working\n" - " patch (x.y.Z) - a bug fix or an internal change\n\n" + " Every pull request raises `version` in pyproject.toml exactly once, so that what\n" + " is deployed can be identified. One merge to dev is one bump:\n\n" + " minor (x.Y.0) - the default. Raise the minor by one, whatever the change.\n" + " major (X.0.0) - reserved for a backwards-incompatible API or schema change.\n\n" + " Bump once per pull request, not once per feature within it -- a second bump\n" + " skips a version that never reaches dev.\n\n" " Then run `uv lock` so uv.lock records the new version, and commit both files.", ) return 1 diff --git a/app/app.py b/app/app.py index 9eeb098..07f005f 100644 --- a/app/app.py +++ b/app/app.py @@ -14,7 +14,6 @@ import uvicorn from fastapi import FastAPI from fastapi.exceptions import RequestValidationError -from fastapi.openapi.utils import get_openapi from fastapi.responses import JSONResponse, PlainTextResponse, RedirectResponse if TYPE_CHECKING: @@ -128,6 +127,12 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]: pesu_academy = PESUAcademy(metrics) +# Captured before the override below, so the schema is still built by FastAPI itself. Calling +# get_openapi() directly would mean restating the fourteen arguments FastAPI passes it, and +# silently dropping any that were added later or set on the app afterwards. +_build_openapi_schema = app.openapi + + def _openapi_without_phantom_validation_errors() -> dict[str, Any]: """Build the OpenAPI schema without the 422 responses this API can never return. @@ -145,13 +150,7 @@ def _openapi_without_phantom_validation_errors() -> dict[str, Any]: """ if app.openapi_schema: return app.openapi_schema - schema = get_openapi( - title=app.title, - version=app.version, - description=app.description, - routes=app.routes, - tags=app.openapi_tags, - ) + schema = _build_openapi_schema() phantom = "#/components/schemas/HTTPValidationError" for operations in schema.get("paths", {}).values(): for operation in operations.values(): diff --git a/app/pesu.py b/app/pesu.py index 97cc756..04bcd28 100644 --- a/app/pesu.py +++ b/app/pesu.py @@ -75,23 +75,25 @@ async def _upstream_call(metrics: MetricsCollector, operation: str) -> AsyncIter """ sink: list[Any] = [] started = time.perf_counter() + # Pessimistic default, corrected once the body returns. Anything that escapes without setting + # it -- a timeout, a connection failure -- is an error, which is the right assumption to fail to. + outcome = "error" try: yield sink + outcome = "success" except asyncio.CancelledError: # Kept apart from "error": a cancellation means we walked away -- a client disconnected or # the process is shutting down -- not that PESU Academy failed. Counting it as an error # would spike the upstream error rate on every deploy and every abandoned request. - metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome="cancelled") - metrics.observe(UPSTREAM_LATENCY, time.perf_counter() - started, operation=operation) + outcome = "cancelled" raise - except BaseException: - metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome="error") + finally: + # In a finally, so every call is counted and timed exactly once however it ended + metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome=outcome) metrics.observe(UPSTREAM_LATENCY, time.perf_counter() - started, operation=operation) - raise - metrics.increment(UPSTREAM_REQUESTS, operation=operation, outcome="success") - metrics.observe(UPSTREAM_LATENCY, time.perf_counter() - started, operation=operation) - if sink and (status := getattr(sink[0], "status_code", None)) is not None: - metrics.increment(UPSTREAM_RESPONSES, operation=operation, status=str(status)) + # A status exists whenever a response came back, even if something later went wrong with it + if sink and (status := getattr(sink[0], "status_code", None)) is not None: + metrics.increment(UPSTREAM_RESPONSES, operation=operation, status=str(status)) async def _aclose_client(client: httpx2.AsyncClient, metrics: MetricsCollector) -> None: diff --git a/pyproject.toml b/pyproject.toml index b07d09b..279670f 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "pesu-auth" -version = "4.3.0" +version = "4.2.0" description = "A simple API to authenticate PESU credentials using PESU Academy." readme = "README.md" requires-python = ">=3.14" diff --git a/tests/unit/test_metrics_collector.py b/tests/unit/test_metrics_collector.py index f3b91b7..b7f4035 100644 --- a/tests/unit/test_metrics_collector.py +++ b/tests/unit/test_metrics_collector.py @@ -163,3 +163,51 @@ def test_a_label_cannot_shadow_the_observation(collector): family = MetricFamily("pesu_auth_odd_seconds", "doc", "summary", ("seconds",)) collector.observe(family, 1.5, seconds="x") assert collector.snapshot().value(f"{family.name}_sum", seconds="x") == 1.5 + + +def test_every_defined_family_is_registered(): + """`FAMILIES` drives both seeding and rendering. + + A family defined but left out of it would be collected into and then never exposed -- silently, + since nothing else would notice. This keeps the list from drifting from the module. + """ + from app.metrics import collector as module + + defined = { + value.name + for name, value in vars(module).items() + if isinstance(value, MetricFamily) and not name.startswith("_") + } + assert defined == {family.name for family in FAMILIES} + + +def test_family_names_are_unique(): + names = [family.name for family in FAMILIES] + assert len(names) == len(set(names)) + + +def test_no_family_name_collides_with_a_summary_series(): + """A counter named `x_sum` would be indistinguishable from the sum series of a summary `x`.""" + summary_series = { + f"{family.name}_{suffix}" + for family in FAMILIES + if family.metric_type == "summary" + for suffix in ("sum", "count") + } + assert summary_series.isdisjoint({family.name for family in FAMILIES}) + + +def test_every_family_name_is_a_valid_prometheus_identifier(): + import re + + for family in FAMILIES: + assert re.fullmatch(r"[a-zA-Z_:][a-zA-Z0-9_:]*", family.name), family.name + for label in family.labels: + assert re.fullmatch(r"[a-zA-Z_][a-zA-Z0-9_]*", label), (family.name, label) + + +def test_every_family_documents_itself_within_one_exposition_line(): + """HELP text is rendered into the docs example, which is linted at 120 characters.""" + for family in FAMILIES: + assert len(f"# HELP {family.name} {family.documentation}") <= 118, family.name + assert family.documentation.endswith("."), family.name diff --git a/tests/unit/test_metrics_model.py b/tests/unit/test_metrics_model.py index b70ea3a..48acd2f 100644 --- a/tests/unit/test_metrics_model.py +++ b/tests/unit/test_metrics_model.py @@ -146,7 +146,7 @@ def test_single_label_families_collapse_to_mappings(collector): collector.increment(FAILURES_BY_FAULT, fault="client") collector.increment(VALIDATION_ERRORS, field="username") - collector.increment(AUTHENTICATION_RESULTS, result="invalid_credentials") + collector.increment(AUTHENTICATION_RESULTS, result="failure") collector.increment(PROFILE_PARSE_ERRORS, reason="unknown_field") collector.increment(CSRF_CACHE, outcome="hit") collector.increment(HTTP_CLIENTS, event="created") @@ -154,7 +154,7 @@ def test_single_label_families_collapse_to_mappings(collector): model = MetricsModel.from_snapshot(collector.snapshot()) assert model.failures_by_fault == {"client": 1} assert model.validation_errors_by_field == {"username": 1} - assert model.authentication_results == {"invalid_credentials": 1} + assert model.authentication_results == {"failure": 1} assert model.profile_parse_errors == {"unknown_field": 1} assert model.csrf_cache == {"hit": 1} assert model.http_clients == {"created": 1} diff --git a/uv.lock b/uv.lock index 7f9bc05..38e3654 100644 --- a/uv.lock +++ b/uv.lock @@ -630,7 +630,7 @@ wheels = [ [[package]] name = "pesu-auth" -version = "4.3.0" +version = "4.2.0" source = { editable = "." } dependencies = [ { name = "fastapi" },