feat: /metrics with full app instrumentation, complete API docs, benchmark output paths, and six bug fixes

[aditeyabaral]

📌 Description

Closes #123, #129, and supersedes #143 and #132, whose review changes were never applied.

This builds directly on work by @niffy-artist2876 (#143) and @snigenigmatic (#132). Their diffs established what to build; the review comments on those PRs are the specification for how. Both PRs are a year old with changes requested and no path to a rebase, so this implements the reviewed requirements fresh against current dev.

#	Change	Commit
0	Every benchmark script has been broken on dev since #156	585c07e
1	Metrics collector, with typed families and labels instead of dynamic metric names	c30344b
2	Prometheus text exposition, hand-rolled — no new dependencies	5e36a01
3	A proper response model for the JSON view	0c8aff5
4	Middleware instrumentation, and the middleware/handler split that makes it correct	dc94f43
5	/metrics, serving either format by query parameter	3f23c1d, 0ae0a0a
6	Benchmark output paths, naming, --tag, and three adjacent bugs	f9b7088
7	Every path in the app instrumented — 9 metric families to 23	92db11e
8	A startup bug the new metrics found within minutes	688eb00
9	Three defects found reviewing the above	25a7a9a
10	Swagger documented a 422 this API can never return	25a7a9a
11	ResponseModel could not parse the responses it describes	7a37ec9
12	One fact recorded in two metric families	37357a9
13	The version bumped twice in one PR, and the guidance that caused it	776bad4

Important

scripts/benchmark/util.py still imported httpx, which #156 removed. All three benchmark scripts have been dying at import 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 run after that migration was a grep over app/, tests/, pyproject.toml, Dockerfile and README.md, which simply omitted scripts/. Production was never affected, since the Dockerfile copies only app/. Fixed first (585c07e) so it can be cherry-picked ahead of the rest.

🔭 Metrics (#129)

The middleware/handler split

The review asked for a middleware layer rather than per-route instrumentation, which is right — but the pseudo-code assumes the middleware's except sees handled errors. It does not, and the real layering cuts both ways. starlette/applications.py builds:

ServerErrorMiddleware     <- our @app.exception_handler(Exception) lives HERE (ABOVE us)
  metrics middleware      <- us
    ExceptionMiddleware   <- RequestValidationError + PESUAcademyError handlers (BELOW us)
      router

• A handled PESUAcademyError becomes a response below us, so call_next returns an ordinary 401 and the except branch never fires.
• An unhandled exception passes through us but its 500 is rendered above us, so we never see that response either — the except branch has to record status=500 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 exactly one error sample — nothing doubled, and the information a status code loses is recovered: CSRFTokenError and ProfileFetchError are both 502, and only errors_total tells them apart.

Two invariants you can check on a running instance, and there is a test for each:

sum(responses_total) == requests_success + requests_failed
sum(errors_total)     < requests_failed          # a router 404 runs no handler of ours

Other corrections to the pseudo-code

Problem	Fix
200 <= status < 300 as success	/readme returns 308, so every readme hit counted as a failure. < 400.
f"requests_failed_status_{code}"	Dynamic metric names cannot be rendered as Prometheus — each becomes its own family, and sum by (status) is impossible. Labels instead.
request_latency_sum with no count	A sum alone gives no average and no rate denominator. Sum and count, as a summary.
time.time()	Not monotonic; one NTP step backwards poisons a cumulative sum permanently. perf_counter().
scope["route"]	Only populated after call_next, and reached via getattr — plain Starlette routes (Swagger UI, /openapi.json) never set it.

Latency is also named for what it measures: call_next returns at http.response.start and the body streams afterwards, so this is time-to-response-start, not request duration.

Why no dependency

Answering "Are these dependencies necessary to be added?" from the review of #132: none are. prometheus_client installs a process-global default registry at import time — precisely the "global collector outside the entry point" the other review comment rejected — and it would become a second source of truth beside the snapshot needed anyway for the pydantic model. What it buys over ~50 lines is histogram buckets, which are not exposed.

Cardinality

Both attacker-controlled label values are clamped. The route is the matched template, never the raw path — otherwise a scanner walking /wp-login.php, /.env and friends mints a series per probe — with unmatched paths collapsed to <unmatched>, and the method clamped to the seven known verbs.

One path, two formats

GET /metrics?fmt=prometheus (the default) or ?fmt=json.

The default has to be Prometheus: a scraper pointed at this path with no query string must get the exposition format. fmt is a StrEnum, so FastAPI validates it, Swagger renders a dropdown, and an unrecognised value goes through the existing validation handler — an ordinary 400 that is itself counted like any other failed request rather than being a special case.

Content negotiation on Accept was the alternative and is worse: real scrapers, curl and browsers all hit the */* wildcard, so any resolution of it surprises half the callers and needs a hand-rolled q-value parser larger than the renderer itself.

response_model is None, since the response type depends on the parameter and cannot be declared once; both shapes are documented under responses=, which is what Swagger renders from anyway.

The model resolves the dynamic-key tension by noting dynamic keys do not need dynamic fields: dict[str, int] and dict[str, RouteMetricsModel] validate every value and generate correct additionalProperties. Note strict=True rejects a float for an int field and the collector stores floats, so every value is cast explicitly — that is the most likely source of a 500 here and has its own test.

The one deliberate exception to "middleware, not routes"

The profile split is recorded in the /authenticate handler. 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; only the split needs the body.

🔬 Every path instrumented

A second pass audited every request, response, error and background task in the app against what was being recorded. 9 metric families became 23.

Gap	Now measured
The upstream was entirely uninstrumented	Every call to PESU Academy — csrf_fetch, login, profile_fetch — with count, outcome, latency and the upstream status code
No client-vs-server attribution	failures_total{fault} splits 4xx from 5xx, so an alert can fire on only our own faults
No login success rate with a matching denominator	authentication_results_total{result}: success or failure. The reason stays in errors_total{type} — see the de-duplication note below
Validation said that something failed, not which	validation_errors_total{field}, bounded against a caller-controlled body
Profile parse failures opaque	profile_parse_errors_total{reason} — six reasons, including unknown_campus_code, which previously only logged a warning and raised nothing at all
Prefetch effectiveness invisible	csrf_cache_total{hit,miss} — the thing #156 was about
Background refresh untracked	csrf_refreshes_total{outcome} (present in #132, and I had dropped it)
Prefetch tasks untracked	prefetch_tasks_total{success,failure,cancelled}
No leak indicator	http_clients_total{created,closed,close_failed} — created minus closed is what is still open
The accounting gap unexplained	requests_in_flight
Restarts invisible beyond a timestamp	lifespan_events_total

The upstream one matters most: PESU Academy is the only dependency this service has and the only thing that can be slow or down, and its latency is now recorded separately from the API's own — so a slow request can be attributed rather than guessed at. It also separates "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, not theirs.

Every label value that could come from a caller is bounded — route templates, methods, request fields — so none of this opens a cardinality hole.

The metrics found a bug within minutes of existing

An idle process, seconds after boot, reported:

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 a wasted upstream round trip, and on Render, which restarts often, that is every restart.

Exactly the class of waste fixed in #156, and invisible for exactly the same reason: nothing counted the upstream calls. Fixed in 688eb00 by having the loop sleep before its first refresh, which is all it was ever meant to do — lifespan primes the cache, the loop keeps it fresh afterwards. Verified after: csrf_fetch: 1, created: 1, closed: 0. Kept as a separate commit so it can be dropped independently of the instrumentation that found it.

🔍 Self-review pass

Reviewing the above turned up three defects, each with a test that fails against the code as it was.

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 since it is the number documented as explaining the gap between total and success + failed, it would have actively misled. The cancellation test asserted total, success and failed but not the gauge, which is exactly why it passed:

E       AssertionError: assert 1.0 == 0.0
E        +  where 1.0 = value('pesu_auth_requests_in_flight')

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 instead. Both are positional-only now — which immediately caught a test that had been relying on that exact ambiguity.

A cancelled upstream call was counted as an upstream error. A disconnect or a shutdown is not PESU Academy failing; counting it as one would spike the upstream error rate on every deploy, which is precisely when someone is looking at the dashboard. It has its own outcome now.

Also closed 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 who passes exactly the default list counts as no filtering, which is what happened.

Verified on a live server afterwards, with the accounting identity holding:

total=5  success=2  failed=2  inFlight=1        ->  identity holds
sum(responsesByStatus) == success + failed      ->  true
httpClients {created: 3, closed: 2}             ->  1 open (the cached client)
upstream    csrf_fetch(2,0,0) login(2,0,0) profile_fetch(1,0,0)

📖 Swagger and README

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 therefore 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 that /authenticate's real 422 (a profile parse failure, using this API's own response model) is kept. HTTPValidationError and ValidationError leave the components with them.

Every response on every route now carries both an example and a schema — the /readme 308 and the /metrics text/plain body previously had neither. The /metrics examples were hand-written and had drifted from the model; both are generated from a real snapshot now, so the JSON example is complete and round-trips through MetricsModel.

	Codes	Every response has example + schema
POST /authenticate	200, 400, 401, 422, 500, 502	✅ (plus 3 request examples)
GET /health	200, 500	✅
GET /metrics	200, 400, 500	✅ (plus the fmt parameter)
GET /readme	308, 500	✅

tests/unit/test_openapi_docs.py makes the documentation self-checking, and is what found both defects above: 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.

One subtlety worth flagging for review: those examples are validated in JSON mode, not Python mode. The models are strict, and a strict Python-mode validation rejects the ISO string these responses actually carry in timestamp. JSON mode is the mode a caller parsing the body is in, so it is the honest check.

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.

📊 Benchmarks (#123)

All five review comments on #143 are implemented, plus "please incorporate similar changes in unauthenticated_csrf_token_expiry.py". resolve_output_path lives in the existing util.py rather than a new module, since both runners already import it.

Output is now benchmark/results/{script}_{date}_{time}[_{tag}].{ext}, anchored to the repository root so results land in one place regardless of cwd, with --output-dir, --tag and --output all honoured and parent directories created.

Three adjacent bugs fixed in the files being rewritten:

• make_request crashed on non-JSON routes. It ended in an unconditional response.json(), so --route readme (a 308 to GitHub returning HTML) killed the sequential runner and was silently swallowed as a failed request by the parallel one — skewing the very numbers being measured. This is what Feat metric logging #132's author was patching when a reviewer asked "why is this being added?" The answer is that it was a real bug.
• 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 lost everything on Ctrl-C. It wrote its CSV only after the loop ended, and that loop sleeps for hours between requests. Rows are now written as they are measured.

🧹 Two things the review changed its mind about

ResponseModel could not parse the responses it describes. timestamp is a datetime under a model-wide strict=True, but the API serializes an ISO string onto the wire — so a client holding a decoded dict (what every HTTP library returns) got a ValidationError from the schema this API publishes for exactly that purpose.

It also made the documentation tests weaker than they looked: they validated 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 instead of finding it. strict=False on that one field now accepts both forms; every other field stays strict, pinned by a test. The docs tests assert both modes rather than whichever passes.

One fact was being recorded in two families. authentication_results_total carried a value per failure class, duplicating what errors_total{type} already said about the same event — and three of the four were not a different vocabulary, just the class name in snake_case:

CSRFTokenError    -> csrf_token_error
ProfileFetchError -> profile_fetch_error
ProfileParseError -> profile_parse_error

Worse than redundant, it was a drift risk: a hand-written dict read through .get(type(exc), "other"), so a fifth exception class with a forgotten entry would have left two counters disagreeing, with the less informative one failing silently.

It is success or failure now, and the reason lives in exactly one place. The family survives because it answers the one thing nothing else can — the login success rate, with success and failure sharing a denominator (sum(authenticationResults) == authentication.total, pinned by a test). Deriving that from errorsByType would mean subtracting several error classes from a different family, which is the fragile cross-family arithmetic this avoids.

🔁 Final review pass

The version had 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 one 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.

Three more from re-reading the diff:

• The OpenAPI override restated FastAPI's argument list, calling get_openapi() with five arguments where FastAPI passes fourteen. Every missing one is 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 captures and delegates to FastAPI's own builder now.
• _upstream_call recorded in three places, once per branch. A finally with a pessimistic default makes "every call is counted and timed exactly once" structural instead of three copies that have to stay in step.
• 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.

FAMILIES is now guarded against the drift that made two of those possible: a family defined but left out of the registry would be collected into and never exposed, silently. Tests assert the registry matches the module, names are unique and valid Prometheus identifiers, no counter name collides with a summary's _sum/_count, and every HELP line fits the exposition example's line limit.

🧱 Type of Change

• 🐛 Bug fix – Non-breaking fix for a functional/logic error
• ✨ New feature – Adds functionality without breaking existing APIs
• 📝 Documentation update – README, docstrings, OpenAPI tags, etc.
• 🧪 Test suite change – Adds/updates unit, functional, or integration tests
• 🕵️ Debug/logging enhancement – Adds or improves logging/debug support
• 🔧 Developer tooling – Scripts, benchmarks, local testing improvements

🧪 How Has This Been Tested?

• Unit Tests (tests/unit/)
• Integration Tests (tests/integration/)
• Manual Testing

⚙️ Test Configuration:

• OS: Linux
• Python: 3.14.4 via uv
• Docker build tested

240 tests (was 101), 100.00% coverage maintained, 139 of them new across seven modules. The most valuable is test_an_unhandled_exception_records_a_500: that path runs through ServerErrorMiddleware, which sits above the metrics 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.

Verified against a running instance rather than only in tests:

requests      : {'total': 13, 'success': 9, 'failed': 3}
byStatus      : {'200': 7, '308': 2, '400': 1, '401': 1, '404': 1}
byType        : {'AuthenticationError': 1, 'RequestValidationError': 1}
byRoute       : {'GET /health': 5, 'GET /metrics': 2, 'GET /readme': 2,
                 'GET <unmatched>': 1, 'POST /authenticate': 2}

sum(byStatus) == success+failed : True
sum(byType)   <  failed         : True

The 308 counted as a success is the < 400 correction proven live; GET <unmatched> is the cardinality bucket; and the two error types being distinguishable while both appearing as status codes is the middleware/handler split working.

content-type: text/plain; version=0.0.4; charset=utf-8 confirmed over real HTTP — Starlette appends a charset only when one is absent, so it is not duplicated.

Benchmark scripts were run against a live server: default naming, --tag, --output-dir and explicit --output all land where intended, and --route readme and --route metrics both succeed where they previously could not.

✅ Checklist

• My code follows the CONTRIBUTING.md guidelines
• I've performed a self-review of my changes
• I've added/updated necessary comments and docstrings
• I've updated relevant docs (README or endpoint docs)
• No new warnings introduced
• I've added tests to cover my changes
• All tests pass locally (scripts/run_tests.py)
• I've run linting and formatting (pre-commit run --all-files)
• Docker image builds and runs correctly
• Changes are backwards compatible

🛠️ Affected API Behaviour

• app/app.py – Metrics middleware, three one-line handler increments, the profile split, two new routes

New endpoint: /metrics — Prometheus text by default, JSON with ?fmt=json

🧩 Models

• app/models/metrics.py – New: MetricsModel and four nested models

🐳 DevOps & Config

• pyproject.toml / uv.lock – Version 4.1.0 → 4.2.0. No dependency changes.
• .github/scripts/check_version_bump.py – guidance now states the rule in force: one bump per pull request
• README.md – full metrics reference: how collection works, what every metric means, generated examples of both formats

requirements.txt is deliberately untouched: it is a stale uv pip compile artefact (still pinning fastapi==0.136.1 against an installed 0.141.1) and the Dockerfile builds from uv.lock --frozen. The Dockerfile copies app wholesale, so app/metrics/ ships with no build change.

📊 Benchmarks & Analysis

• scripts/benchmark/util.py – resolve_output_path, plus the non-JSON fix and the httpx2 import
• scripts/benchmark/benchmark_requests.py, analyze_benchmark.py, unauthenticated_csrf_token_expiry.py

🧠 Additional Notes

#130 (Grafana) is unblocked by this — /metrics speaks Prometheus, so no exporter is needed later.

Commits are ordered so each builds and tests green alone. Reverting the middleware commit leaves the collector, renderer and model as dead but harmless code; reverting the endpoints commit keeps collecting but stops exposing.

Two things noted and deliberately not done:

• @app.middleware("http") means BaseHTTPMiddleware, which creates an anyio task group and a memory object stream per request. A pure ASGI middleware class would be cheaper and could read the status straight off http.response.start. With one middleware on a small API the difference is not worth the readability, and the decorator is what the review asked for.
• A client disconnect surfaces as cancellation and skips recording, so total exceeds success + failed while requests are in flight. Swallowing cancellation in a metrics layer would be worse than a small, self-documenting undercount.

🤖 Generated with Claude Code

https://claude.ai/code/session_01VU7YUhP71KSsotWQ1H7CRH