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/.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/README.md b/README.md index 502b835..d1044a2 100644 --- a/README.md +++ b/README.md @@ -102,6 +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. See `fmt` below. | | `/readme` | `GET` | Redirects to the project's official GitHub repository. | ### `/authenticate` @@ -163,6 +164,388 @@ 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 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 +``` + +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. + +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` 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)** + +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="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. errors_total says why one failed. +# TYPE pesu_auth_authentication_results_total counter +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 +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 +``` + +
+ +#### JSON response + +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. + +
+Full example (fmt=json) + +```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, + "ProfileFetchError": 2, + "RequestValidationError": 12 + }, + "requestsInFlight": 1, + "failuresByFault": { + "client": 172, + "server": 10 + }, + "validationErrorsByField": { + "password": 4, + "username": 8 + }, + "authenticationResults": { + "failure": 162, + "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 + } +} +``` + +
+ ### `/readme` This endpoint redirects to the project's official GitHub repository. This endpoint does not take any request parameters. diff --git a/app/app.py b/app/app.py index cca1d25..07f005f 100644 --- a/app/app.py +++ b/app/app.py @@ -8,28 +8,44 @@ 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.responses import JSONResponse, RedirectResponse +from fastapi.responses import JSONResponse, PlainTextResponse, RedirectResponse if TYPE_CHECKING: 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.docs import authenticate_docs, health_docs, metrics_docs, readme_docs from app.exceptions.base import PESUAcademyError -from app.models import RequestModel, ResponseModel +from app.metrics.collector 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 from app.pesu import PESUAcademy 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"}) async def _refresh_csrf_token() -> None: @@ -41,18 +57,25 @@ 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() except Exception: + metrics.increment(CSRF_REFRESHES, outcome="failure") logging.exception("Failed to refresh unauthenticated CSRF token in the background.") - await asyncio.sleep(CSRF_TOKEN_REFRESH_INTERVAL_SECONDS) + else: + metrics.increment(CSRF_REFRESHES, outcome="success") @asynccontextmanager 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 @@ -75,6 +98,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.") @@ -99,13 +123,71 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]: }, ], ) -pesu_academy = PESUAcademy() +metrics = MetricsCollector() +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. + + 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 = _build_openapi_schema() + 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.""" + # 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() + # 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. @@ -126,6 +208,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 +229,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, @@ -176,6 +260,34 @@ async def health() -> JSONResponse: ) +@app.get( + "/metrics", + # 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 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(snapshot), + media_type=PROMETHEUS_CONTENT_TYPE, + ) + + @app.get( "/readme", response_class=RedirectResponse, @@ -214,15 +326,32 @@ 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( - 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 Exception: + # 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") # Validate the response try: diff --git a/app/docs/__init__.py b/app/docs/__init__.py index a31c39c..712c989 100644 --- a/app/docs/__init__.py +++ b/app/docs/__init__.py @@ -2,10 +2,12 @@ from .authenticate import authenticate_docs from .health import health_docs +from .metrics import metrics_docs from .readme import readme_docs __all__ = [ "authenticate_docs", "health_docs", + "metrics_docs", "readme_docs", ] diff --git a/app/docs/metrics.py b/app/docs/metrics.py new file mode 100644 index 0000000..2851a01 --- /dev/null +++ b/app/docs/metrics.py @@ -0,0 +1,180 @@ +"""Custom docs for the /metrics PESUAuth endpoint.""" + +from app.docs.base import ApiDocs +from app.models import 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", + } + } + }, +} + +# 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 +# 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. errors_total says why one failed. +# TYPE pesu_auth_authentication_results_total counter +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 +# 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": 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, "ProfileFetchError": 2, "RequestValidationError": 12}, + "requestsInFlight": 1, + "failuresByFault": {"client": 172, "server": 10}, + "validationErrorsByField": {"password": 4, "username": 8}, + "authenticationResults": {"failure": 162, "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( + request_examples={}, + response_examples={ + 200: { + "description": "The collected metrics, in the format named by `fmt`.", + "content": { + "text/plain": {"schema": {"type": "string"}, "example": _PROMETHEUS_EXAMPLE}, + "application/json": {"example": _JSON_EXAMPLE}, + }, + }, + 400: { + "description": "Unrecognised value for `fmt`.", + "model": ResponseModel, + "content": { + "application/json": { + "example": { + "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", + } + } + }, + }, + 500: _INTERNAL_SERVER_ERROR, + }, +) 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 new file mode 100644 index 0000000..7da790c --- /dev/null +++ b/app/metrics/__init__.py @@ -0,0 +1,10 @@ +"""Metrics collection for the PESUAuth API. + +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. + +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 new file mode 100644 index 0000000..ab66fa8 --- /dev/null +++ b/app/metrics/collector.py @@ -0,0 +1,323 @@ +"""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", +) +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",), +) +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. errors_total says why one failed.", + "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", + "Upstream HTTP client lifecycle. created minus closed is how many are 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, ...] = ( + REQUESTS_TOTAL, + REQUESTS_SUCCESS, + REQUESTS_FAILED, + RESPONSES_BY_STATUS, + ROUTE_REQUESTS, + ERRORS_BY_TYPE, + AUTHENTICATION_REQUESTS, + AUTHENTICATION_RESULTS, + PROFILE_FIELD_FILTERING, + 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, +) + + +@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. 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: + """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/app/metrics/middleware.py b/app/metrics/middleware.py new file mode 100644 index 0000000..a725a60 --- /dev/null +++ b/app/metrics/middleware.py @@ -0,0 +1,154 @@ +"""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 ( + FAILURES_BY_FAULT, + REQUEST_LATENCY, + REQUESTS_FAILED, + REQUESTS_IN_FLIGHT, + 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 +# 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 = "" +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)) + 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) + + +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) + 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() + 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 + 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/metrics/prometheus.py b/app/metrics/prometheus.py new file mode 100644 index 0000000..eba86c5 --- /dev/null +++ b/app/metrics/prometheus.py @@ -0,0 +1,93 @@ +"""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 + +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" + + +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"}) +# 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/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..c5adb59 --- /dev/null +++ b/app/models/metrics.py @@ -0,0 +1,449 @@ +"""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, + AUTHENTICATION_RESULTS, + CSRF_CACHE, + CSRF_REFRESHES, + ERRORS_BY_TYPE, + FAILURES_BY_FAULT, + HTTP_CLIENTS, + LIFESPAN_EVENTS, + PREFETCH_TASKS, + PROCESS_START_TIME, + PROFILE_FIELD_FILTERING, + 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), + cancelled=counts.get("cancelled", 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.""" + + 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 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}, + ) + + 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", + 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.""" + + 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}}, + ) + + 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: "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( + ..., + 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", + 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. + + 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)}, + 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_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"), + 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/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/app/pesu.py b/app/pesu.py index e9fb655..04bcd28 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,20 @@ ProfileFetchError, ProfileParseError, ) +from app.metrics.collector import ( + CSRF_CACHE, + HTTP_CLIENTS, + PREFETCH_TASKS, + PROFILE_FIELD_FILTERING, + PROFILE_PARSE_ERRORS, + UPSTREAM_LATENCY, + UPSTREAM_REQUESTS, + UPSTREAM_RESPONSES, + MetricsCollector, +) + +if TYPE_CHECKING: + from collections.abc import AsyncIterator ProfileField = Literal[ "name", @@ -37,7 +55,48 @@ _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() + # 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. + outcome = "cancelled" + raise + 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) + # 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: """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 +104,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 +129,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 +166,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 +181,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 +200,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 +219,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 +244,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 +273,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 +301,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 +315,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 +345,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 +375,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 +393,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 +428,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 +488,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.") @@ -425,6 +519,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} @@ -435,4 +533,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/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/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..fc990ed 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"], 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 173856d..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 httpx +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", @@ -26,7 +69,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"), @@ -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 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 bfcb603..c25ebc2 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,41 @@ 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() + + +@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.collector 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/tests/unit/test_metrics_collector.py b/tests/unit/test_metrics_collector.py new file mode 100644 index 0000000..b7f4035 --- /dev/null +++ b/tests/unit/test_metrics_collector.py @@ -0,0 +1,213 @@ +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" + + +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 + + +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_endpoints.py b/tests/unit/test_metrics_endpoints.py new file mode 100644 index 0000000..9865900 --- /dev/null +++ b/tests/unit/test_metrics_endpoints.py @@ -0,0 +1,271 @@ +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", include_in_schema=False) +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_format_shape(client): + body = client.get("/metrics?fmt=json").json() + assert set(body) == { + "startTimeSeconds", + "uptimeSeconds", + "requests", + "requestsInFlight", + "latency", + "authentication", + "authenticationResults", + "responsesByStatus", + "requestsByRoute", + "errorsByType", + "failuresByFault", + "validationErrorsByField", + "profileFieldFiltering", + "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 + 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?fmt=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?fmt=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?fmt=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?fmt=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?fmt=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?fmt=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?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") +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?fmt=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?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_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 == {"success": 1, "failure": 3} + + +@patch("app.app.pesu_academy.authenticate") +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"}) + 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): + 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..42f9fcc --- /dev/null +++ b/tests/unit/test_metrics_instrumentation.py @@ -0,0 +1,242 @@ +"""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 + + +@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 new file mode 100644 index 0000000..c5b574b --- /dev/null +++ b/tests/unit/test_metrics_middleware.py @@ -0,0 +1,195 @@ +import asyncio + +import pytest + +from app.metrics.collector import ( + ERRORS_BY_TYPE, + REQUEST_LATENCY, + REQUESTS_FAILED, + REQUESTS_IN_FLIGHT, + 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 + # 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 +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 diff --git a/tests/unit/test_metrics_model.py b/tests/unit/test_metrics_model.py new file mode 100644 index 0000000..48acd2f --- /dev/null +++ b/tests/unit/test_metrics_model.py @@ -0,0 +1,185 @@ +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, 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 + 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 + + +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="failure") + 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 == {"failure": 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 + + +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_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) diff --git a/tests/unit/test_openapi_docs.py b/tests/unit/test_openapi_docs.py new file mode 100644 index 0000000..bf947a5 --- /dev/null +++ b/tests/unit/test_openapi_docs.py @@ -0,0 +1,213 @@ +"""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 **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): + 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"])) + model.model_validate(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 + RequestModel.model_validate(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 + + +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"}) 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" },